Fix parallel SuperPMI output handling (#84219)

Previously, parallel SuperPMI parsed very few kinds of output from
the child processes, and ignored and discarded the rest. Change this
so all output from the child processes is output by the parent
process.

For example, this allows the child process JIT to print out statistics,
disasm, etc., and have it visible by the parent invoker.

src/coreclr/tools/superpmi/superpmi-shared/logging.cpp

@@ -175,7 +175,7 @@ void Logger::LogVprintf(
     }
 
     // Early out if we're not logging at this level.
-    if ((level & GetLogLevel()) == 0)
+    if (!IsPassThrough(level) && ((level & GetLogLevel()) == 0))
     {
         return;
     }
@@ -189,15 +189,20 @@ void Logger::LogVprintf(
     _vsnprintf_s(fullMsg, fullMsgLen, fullMsgLen, msg, argList);
     va_end(argList);
 
-    const char* logLevelStr = "INVALID_LOGLEVEL";
+    // Where to write messages? Default to stdout.
+    FILE* dest = stdout;
+
+    const char* logLevelStr = "";
     switch (level)
     {
         case LOGLEVEL_ERROR:
             logLevelStr = "ERROR";
+            dest = stderr;
             break;
 
         case LOGLEVEL_WARNING:
             logLevelStr = "WARNING";
+            dest = stderr;
             break;
 
         case LOGLEVEL_MISSING:
@@ -219,6 +224,19 @@ void Logger::LogVprintf(
         case LOGLEVEL_DEBUG:
             logLevelStr = "DEBUG";
             break;
+
+        case LOGLEVEL_PASSTHROUGH_STDOUT:
+            logLevelStr = "STDOUT";
+            break;
+
+        case LOGLEVEL_PASSTHROUGH_STDERR:
+            logLevelStr = "STDERR";
+            dest = stderr;
+            break;
+
+        default:
+            logLevelStr = "INVALID_LOGLEVEL";
+            break;
     }
 
     // NOTE: This implementation doesn't guarantee that log messages will be written in chronological
@@ -228,9 +246,6 @@ void Logger::LogVprintf(
 
     EnterCriticalSection(&s_critSec);
 
-    // Sends error messages to stderr instead out stdout
-    FILE* dest = (level <= LOGLEVEL_WARNING) ? stderr : stdout;
-
     if (level < LOGLEVEL_INFO)
         fprintf(dest, "%s: ", logLevelStr);
 
@@ -262,15 +277,16 @@ void Logger::LogVprintf(
 #endif // TARGET_UNIX
 
         const char logEntryFmtStr[] = "%s - %s [%s:%d] - %s - %s\r\n";
-        size_t logEntryBuffSize = sizeof(logEntryFmtStr) + strlen(timeStr) + strlen(function) + strlen(file) + 10 +
+        size_t logEntryBuffSize = sizeof(logEntryFmtStr) + strlen(timeStr) + strlen(function) + strlen(file) + /* line number */ 10 +
                                   strlen(logLevelStr) + strlen(fullMsg);
 
         char* logEntry = new char[logEntryBuffSize];
         sprintf_s(logEntry, logEntryBuffSize, logEntryFmtStr, timeStr, function, file, line, logLevelStr, fullMsg);
+        size_t logEntryLen = strlen(logEntry);
 
         DWORD bytesWritten;
 
-        if (!WriteFile(s_logFile, logEntry, (DWORD)logEntryBuffSize - 1, &bytesWritten, nullptr))
+        if (!WriteFile(s_logFile, logEntry, (DWORD)logEntryLen, &bytesWritten, nullptr))
             fprintf(stderr, "WARNING: [Logger::LogVprintf] Failed to write to log file. GetLastError()=%u\n",
                     GetLastError());
 

src/coreclr/tools/superpmi/superpmi-shared/logging.h

@@ -20,6 +20,9 @@
 #define LogVerbose(...) LogMessage(LOGLEVEL_VERBOSE, __VA_ARGS__)
 #define LogDebug(...) LogMessage(LOGLEVEL_DEBUG, __VA_ARGS__)
 
+#define LogPassThroughStdout(...) LogMessage(LOGLEVEL_PASSTHROUGH_STDOUT, __VA_ARGS__)
+#define LogPassThroughStderr(...) LogMessage(LOGLEVEL_PASSTHROUGH_STDERR, __VA_ARGS__)
+
 #define LogIssue(issue, msg, ...) IssueLogger::LogIssueHelper(__FUNCTION__, __FILE__, __LINE__, issue, msg, __VA_ARGS__)
 
 // Captures the exception message before throwing so we can log it at the point of occurrence
@@ -33,13 +36,15 @@
 // These are specified as flags so subsets of the logging functionality can be enabled/disabled at once
 enum LogLevel : UINT32
 {
-    LOGLEVEL_ERROR   = 0x00000001, // Internal fatal errors that are non-recoverable
-    LOGLEVEL_WARNING = 0x00000002, // Internal conditions that are unusual, but not serious
-    LOGLEVEL_MISSING = 0x00000004, // Failures to due to missing JIT-EE details
-    LOGLEVEL_ISSUE   = 0x00000008, // Issues found with the JIT, e.g. asm diffs, asserts
-    LOGLEVEL_INFO    = 0x00000010, // Notifications/summaries, e.g. 'Loaded 5  Jitted 4  FailedCompile 1'
-    LOGLEVEL_VERBOSE = 0x00000020, // Status messages, e.g. 'Jit startup took 151.12ms'
-    LOGLEVEL_DEBUG   = 0x00000040  // Detailed output that's only useful for SuperPMI debugging
+    LOGLEVEL_ERROR              = 0x00000001, // Internal fatal errors that are non-recoverable
+    LOGLEVEL_WARNING            = 0x00000002, // Internal conditions that are unusual, but not serious
+    LOGLEVEL_MISSING            = 0x00000004, // Failures to due to missing JIT-EE details
+    LOGLEVEL_ISSUE              = 0x00000008, // Issues found with the JIT, e.g. asm diffs, asserts
+    LOGLEVEL_INFO               = 0x00000010, // Notifications/summaries, e.g. 'Loaded 5  Jitted 4  FailedCompile 1'
+    LOGLEVEL_VERBOSE            = 0x00000020, // Status messages, e.g. 'Jit startup took 151.12ms'
+    LOGLEVEL_DEBUG              = 0x00000040, // Detailed output that's only useful for SuperPMI debugging
+    LOGLEVEL_PASSTHROUGH_STDOUT = 0x00000080, // Special: pass through parallel SuperPMI stdout
+    LOGLEVEL_PASSTHROUGH_STDERR = 0x00000100  // Special: pass through parallel SuperPMI stderr
 };
 
 // Preset log level combinations
@@ -78,6 +83,10 @@ public:
     {
         return s_logLevel;
     }
+    static bool IsPassThrough(LogLevel level)
+    {
+        return (level == LOGLEVEL_PASSTHROUGH_STDOUT) || (level == LOGLEVEL_PASSTHROUGH_STDERR);
+    }
 
     // Return true if all specified log levels are enabled.
     static bool IsLogLevelEnabled(UINT32 logLevelMask)

src/coreclr/tools/superpmi/superpmi/commandline.cpp

@@ -365,7 +365,8 @@ bool CommandLine::Parse(int argc, char* argv[], /* OUT */ Options* o)
                     return false;
                 }
 
-                Logger::SetLogLevel(Logger::ParseLogLevelString(argv[i]));
+                o->verbosity = argv[i];
+                Logger::SetLogLevel(Logger::ParseLogLevelString(o->verbosity));
             }
             else if ((_strnicmp(&argv[i][1], "writeLogFile", argLen) == 0))
             {

src/coreclr/tools/superpmi/superpmi/commandline.h

@@ -17,6 +17,7 @@ public:
             : nameOfJit(nullptr)
             , nameOfJit2(nullptr)
             , nameOfInputMethodContextFile(nullptr)
+            , verbosity(nullptr)
             , writeLogFile(nullptr)
             , reproName(nullptr)
             , breakOnError(false)
@@ -55,6 +56,7 @@ public:
         char* nameOfJit;
         char* nameOfJit2;
         char* nameOfInputMethodContextFile;
+        char* verbosity;
         char* writeLogFile;
         char* reproName;
         bool  breakOnError;

src/coreclr/tools/superpmi/superpmi/parallelsuperpmi.cpp

@@ -197,12 +197,7 @@ void ProcessChildStdErr(char* stderrFilename)
         if (buff[buffLen - 1] == '\n')
             buff[buffLen - 1] = 0;
 
-        if (strncmp(buff, "ERROR: ", 7) == 0)
-            LogError("%s", &buff[7]); // log as Error and remove the "ERROR: " in front
-        else if (strncmp(buff, "WARNING: ", 9) == 0)
-            LogWarning("%s", &buff[9]); // log as Warning and remove the "WARNING: " in front
-        else if (strlen(buff) > 0)
-            LogWarning("%s", buff); // unknown output, log it as a warning
+        LogPassThroughStderr(buff);
     }
 
 Cleanup:
@@ -237,26 +232,10 @@ void ProcessChildStdOut(const CommandLine::Options& o,
         if (buff[buffLen - 1] == '\n')
             buff[buffLen - 1] = 0;
 
-        if (strncmp(buff, "MISSING: ", 9) == 0)
-            LogMissing("%s", &buff[9]); // log as Missing and remove the "MISSING: " in front
-        else if (strncmp(buff, "ISSUE: ", 7) == 0)
-        {
-            if (strncmp(&buff[7], "<ASM_DIFF> ", 11) == 0)
-                LogIssue(ISSUE_ASM_DIFF, "%s", &buff[18]); // log as Issue and remove the "ISSUE: <ASM_DIFF>" in front
-            else if (strncmp(&buff[7], "<ASSERT> ", 9) == 0)
-                LogIssue(ISSUE_ASSERT, "%s", &buff[16]); // log as Issue and remove the "ISSUE: <ASSERT>" in front
-        }
-        else if (strncmp(buff, g_SuperPMIUsageFirstLine, strlen(g_SuperPMIUsageFirstLine)) == 0)
+        if (strncmp(buff, g_SuperPMIUsageFirstLine, strlen(g_SuperPMIUsageFirstLine)) == 0)
         {
             *usageError = true; // Signals that we had a SuperPMI command line usage error
-
-            // Read the entire stdout file and printf it
-            printf("%s", buff);
-            while (fgets(buff, MAX_LOG_LINE_SIZE, fp) != NULL)
-            {
-                printf("%s", buff);
-            }
-            break;
+            LogPassThroughStdout(buff);
         }
         else if (strncmp(buff, g_AllFormatStringFixedPrefix, strlen(g_AllFormatStringFixedPrefix)) == 0)
         {
@@ -290,6 +269,12 @@ void ProcessChildStdOut(const CommandLine::Options& o,
             *excluded += childExcluded;
             *missing += childMissing;
         }
+        else
+        {
+            // Do output pass-through.
+            // Note that the same logging verbosity level is passed to the child processes.
+            LogPassThroughStdout(buff);
+        }
     }
 
 Cleanup:
@@ -473,9 +458,6 @@ char* ConstructChildProcessArgs(const CommandLine::Options& o)
     char* spmiArgs     = new char[MAX_CMDLINE_SIZE];
     *spmiArgs          = '\0';
 
-// We don't pass through /parallel, /skipCleanup, /verbosity, /failingMCList, or /diffMCList. Everything else we need to
-// reconstruct and pass through.
-
 #define ADDSTRING(s)                                                                                                   \
     if (s != nullptr)                                                                                                  \
     {                                                                                                                  \
@@ -492,13 +474,33 @@ char* ConstructChildProcessArgs(const CommandLine::Options& o)
         bytesWritten += sprintf_s(spmiArgs + bytesWritten, MAX_CMDLINE_SIZE - bytesWritten, " %s %s", arg, s);         \
     }
 
+    // We don't pass through:
+    //
+    //    -parallel
+    //    -writeLogFile (the parent process writes the log file based on the output of the child processes)
+    //    -reproName
+    //    -coredistools
+    //    -skipCleanup
+    //    -metricsSummary
+    //    -baseMetricsSummary
+    //    -diffMetricsSummary
+    //    -failingMCList
+    //    -diffMCList
+    //    -failureLimit
+    //
+    // Everything else we need to reconstruct and pass through.
+    //
+    // Note that for -verbosity, if the level includes LOGLEVEL_INFO, the process will output a
+    // "Loaded/Jitted/FailedCompile/Excluded/Missing[/Diffs]" line which is parsed and summarized by
+    // the parent process. If it isn't output, the summary doesn't happen.
+
     ADDARG_BOOL(o.breakOnError, "-boe");
     ADDARG_BOOL(o.breakOnAssert, "-boa");
     ADDARG_BOOL(o.breakOnException, "-box");
     ADDARG_BOOL(o.ignoreStoredConfig, "-ignoreStoredConfig");
     ADDARG_BOOL(o.applyDiff, "-applyDiff");
+    ADDARG_STRING(o.verbosity, "-verbosity");
     ADDARG_STRING(o.reproName, "-reproName");
-    ADDARG_STRING(o.writeLogFile, "-writeLogFile");
     ADDARG_STRING(o.methodStatsTypes, "-emitMethodStats");
     ADDARG_STRING(o.hash, "-matchHash");
     ADDARG_STRING(o.targetArchitecture, "-target");