dotnet · jakobbotsch · Nov 9, 2021 · Nov 5, 2021
diff --git a/src/coreclr/ToolBox/superpmi/superpmi/jitinstance.cpp b/src/coreclr/ToolBox/superpmi/superpmi/jitinstance.cpp
@@ -369,15 +369,12 @@ JitInstance::Result JitInstance::CompileMethod(MethodContext* MethodToCompile, i
 
             pParam->pThis->mc->cr->recMessageLog("Successful Compile");
 
-            pParam->metrics->SuccessfulCompiles++;
             pParam->metrics->NumCodeBytes += NCodeSizeBlock;
         }
         else
         {
             LogDebug("compileMethod failed with result %d", jitResult);
             pParam->result = RESULT_ERROR;
-
-            pParam->metrics->FailingCompiles++;
         }
     }
     PAL_EXCEPT_FILTER(FilterSuperPMIExceptions_CaptureExceptionAndStop)
@@ -408,6 +405,20 @@ JitInstance::Result JitInstance::CompileMethod(MethodContext* MethodToCompile, i
 
     mc->cr->secondsToCompile = stj.GetSeconds();
 
+    if (param.result == RESULT_SUCCESS)
+    {
+        metrics->SuccessfulCompiles++;
+    }
+    else
+    {
+        metrics->FailingCompiles++;
+    }
+
+    if (param.result == RESULT_MISSING)
+    {
+        metrics->MissingCompiles++;
+    }
+
     return param.result;
 }
 

diff --git a/src/coreclr/ToolBox/superpmi/superpmi/metricssummary.cpp b/src/coreclr/ToolBox/superpmi/superpmi/metricssummary.cpp
@@ -41,8 +41,11 @@ bool MetricsSummary::SaveToFile(const char* path)
 
     char buffer[4096];
     int len =
-        sprintf_s(buffer, sizeof(buffer), "Successful compiles,Failing compiles,Code bytes\n%d,%d,%lld\n",
-            SuccessfulCompiles, FailingCompiles, NumCodeBytes);
+        sprintf_s(
+            buffer, sizeof(buffer),
+            "Successful compiles,Failing compiles,Missing compiles,Code bytes,Diffed code bytes\n"
+            "%d,%d,%d,%lld,%lld\n",
+            SuccessfulCompiles, FailingCompiles, MissingCompiles, NumCodeBytes, NumDiffedCodeBytes);
     DWORD numWritten;
     if (!WriteFile(file.get(), buffer, static_cast<DWORD>(len), &numWritten, nullptr) || numWritten != static_cast<DWORD>(len))
     {
@@ -73,18 +76,21 @@ bool MetricsSummary::LoadFromFile(const char* path, MetricsSummary* metrics)
         return false;
     }
 
-    if (sscanf_s(content.data(), "Successful compiles,Failing compiles,Code bytes\n%d,%d,%lld\n",
-        &metrics->SuccessfulCompiles, &metrics->FailingCompiles, &metrics->NumCodeBytes) != 3)
-    {
-        return false;
-    }
+    int scanResult =
+        sscanf_s(
+            content.data(),
+            "Successful compiles,Failing compiles,Missing compiles,Code bytes,Diffed code bytes\n"
+            "%d,%d,%d,%lld,%lld\n",
+            &metrics->SuccessfulCompiles, &metrics->FailingCompiles, &metrics->MissingCompiles, &metrics->NumCodeBytes, &metrics->NumDiffedCodeBytes);
 
-    return true;
+    return scanResult == 5;
 }
 
 void MetricsSummary::AggregateFrom(const MetricsSummary& other)
 {
     SuccessfulCompiles += other.SuccessfulCompiles;
     FailingCompiles += other.FailingCompiles;
+    MissingCompiles += other.MissingCompiles;
     NumCodeBytes += other.NumCodeBytes;
+    NumDiffedCodeBytes += other.NumDiffedCodeBytes;
 }
diff --git a/src/coreclr/ToolBox/superpmi/superpmi/metricssummary.h b/src/coreclr/ToolBox/superpmi/superpmi/metricssummary.h
@@ -7,14 +7,23 @@
 class MetricsSummary
 {
 public:
+    // Number of methods successfully jitted.
     int SuccessfulCompiles;
+    // Number of methods that failed jitting.
     int FailingCompiles;
+    // Number of methods that failed jitting due to missing SPMI data.
+    int MissingCompiles;
+    // Number of code bytes produced by the JIT for the successful compiles.
     long long NumCodeBytes;
+    // Number of code bytes that were diffed with the other compiler in diff mode.
+    long long NumDiffedCodeBytes;
 
     MetricsSummary()
         : SuccessfulCompiles(0)
         , FailingCompiles(0)
+        , MissingCompiles(0)
         , NumCodeBytes(0)
+        , NumDiffedCodeBytes(0)
     {
     }
 

diff --git a/src/coreclr/ToolBox/superpmi/superpmi/superpmi.cpp b/src/coreclr/ToolBox/superpmi/superpmi/superpmi.cpp
@@ -265,8 +265,8 @@ int __cdecl main(int argc, char* argv[])
         }
     }
 
-    MetricsSummary baseMetrics;
-    MetricsSummary diffMetrics;
+    MetricsSummary totalBaseMetrics;
+    MetricsSummary totalDiffMetrics;
 
     while (true)
     {
@@ -362,17 +362,22 @@ int __cdecl main(int argc, char* argv[])
             }
         }
 
+        MetricsSummary baseMetrics;
         jittedCount++;
         st3.Start();
         res = jit->CompileMethod(mc, reader->GetMethodContextIndex(), collectThroughput, &baseMetrics);
         st3.Stop();
         LogDebug("Method %d compiled in %fms, result %d", reader->GetMethodContextIndex(), st3.GetMilliseconds(), res);
 
+        totalBaseMetrics.AggregateFrom(baseMetrics);
+
         if ((res == JitInstance::RESULT_SUCCESS) && Logger::IsLogLevelEnabled(LOGLEVEL_DEBUG))
         {
             mc->cr->dumpToConsole(); // Dump the compile results if doing debug logging
         }
 
+        MetricsSummary diffMetrics;
+
         if (o.nameOfJit2 != nullptr)
         {
             // Lets get the results for the 2nd JIT
@@ -387,6 +392,8 @@ int __cdecl main(int argc, char* argv[])
             LogDebug("Method %d compiled by JIT2 in %fms, result %d", reader->GetMethodContextIndex(),
                      st4.GetMilliseconds(), res2);
 
+            totalDiffMetrics.AggregateFrom(diffMetrics);
+
             if ((res2 == JitInstance::RESULT_SUCCESS) && Logger::IsLogLevelEnabled(LOGLEVEL_DEBUG))
             {
                 mc->cr->dumpToConsole(); // Dump the compile results if doing debug logging
@@ -529,6 +536,9 @@ int __cdecl main(int argc, char* argv[])
                 else
                 {
                     InvokeNearDiffer(&nearDiffer, &o, &mc, &crl, &matchCount, &reader, &failingToReplayMCL, &diffMCL);
+
+                    totalBaseMetrics.NumDiffedCodeBytes += baseMetrics.NumCodeBytes;
+                    totalDiffMetrics.NumDiffedCodeBytes += diffMetrics.NumCodeBytes;
                 }
             }
         }
@@ -609,12 +619,12 @@ int __cdecl main(int argc, char* argv[])
 
     if (o.baseMetricsSummaryFile != nullptr)
     {
-        baseMetrics.SaveToFile(o.baseMetricsSummaryFile);
+        totalBaseMetrics.SaveToFile(o.baseMetricsSummaryFile);
     }
 
     if (o.diffMetricsSummaryFile != nullptr)
     {
-        diffMetrics.SaveToFile(o.diffMetricsSummaryFile);
+        totalDiffMetrics.SaveToFile(o.diffMetricsSummaryFile);
     }
 
     if (methodStatsEmitter != nullptr)

diff --git a/src/coreclr/scripts/superpmi.py b/src/coreclr/scripts/superpmi.py
@@ -1471,16 +1471,15 @@ def __verify_final_mch__(self):
 ################################################################################
 
 
-def print_superpmi_failure_code(return_code, coreclr_args):
+def print_superpmi_result(return_code, coreclr_args, base_metrics, diff_metrics):
     """ Print a description of a superpmi return (error) code. If the return code is
         zero, meaning success, don't print anything.
         Note that Python treats process return codes (at least on Windows) as
         unsigned integers, so compare against both signed and unsigned numbers for
         those return codes.
     """
     if return_code == 0:
-        # Don't print anything if the code is zero, which is success.
-        pass
+        logging.info("Clean SuperPMI {} ({} contexts processed)".format("replay" if diff_metrics is None else "diff", base_metrics["Successful compiles"]))
     elif return_code == -1 or return_code == 4294967295:
         logging.error("General fatal error")
     elif return_code == -2 or return_code == 4294967294:
@@ -1490,7 +1489,15 @@ def print_superpmi_failure_code(return_code, coreclr_args):
     elif return_code == 2:
         logging.warning("Asm diffs found")
     elif return_code == 3:
-        logging.warning("SuperPMI missing data encountered")
+        missing_base = int(base_metrics["Missing compiles"])
+        total_contexts = int(base_metrics["Successful compiles"]) + int(base_metrics["Failing compiles"])
+
+        if diff_metrics is None:
+            logging.warning("SuperPMI encountered missing data for {} out of {} contexts".format(missing_base, total_contexts))
+        else:
+            missing_diff = int(diff_metrics["Missing compiles"])
+            logging.warning("SuperPMI encountered missing data. Missing with base JIT: {}. Missing with diff JIT: {}. Total contexts: {}.".format(missing_base, missing_diff, total_contexts))
+
     elif return_code == 139 and coreclr_args.host_os != "windows":
         logging.error("Fatal error, SuperPMI has returned SIGSEGV (segmentation fault)")
     else:
@@ -1636,16 +1643,20 @@ def replay(self):
                 flags = common_flags.copy()
 
                 fail_mcl_file = os.path.join(temp_location, os.path.basename(mch_file) + "_fail.mcl")
+                metrics_summary_file = os.path.join(temp_location, os.path.basename(mch_file) + "_metrics.csv")
+
                 flags += [
-                    "-f", fail_mcl_file  # Failing mc List
+                    "-f", fail_mcl_file,  # Failing mc List
+                    "-metricsSummary", metrics_summary_file
                 ]
 
                 command = [self.superpmi_path] + flags + [self.jit_path, mch_file]
                 return_code = run_and_log(command)
-                print_superpmi_failure_code(return_code, self.coreclr_args)
-                if return_code == 0:
-                    logging.info("Clean SuperPMI replay")
-                else:
+
+                metrics = read_csv_metrics(metrics_summary_file)
+
+                print_superpmi_result(return_code, self.coreclr_args, metrics, None)
+                if return_code != 0:
                     result = False
                     # Don't report as replay failure missing data (return code 3).
                     # Anything else, such as compilation failure (return code 1, typically a JIT assert) will be
@@ -1859,16 +1870,19 @@ def replay_with_asm_diffs(self):
                     with ChangeDir(self.coreclr_args.core_root):
                         command = [self.superpmi_path] + flags + [self.base_jit_path, self.diff_jit_path, mch_file]
                         return_code = run_and_log(command)
-                        print_superpmi_failure_code(return_code, self.coreclr_args)
-                        if return_code == 0:
-                            logging.info("Clean SuperPMI diff")
-                        else:
-                            result = False
-                            # Don't report as replay failure asm diffs (return code 2) or missing data (return code 3).
-                            # Anything else, such as compilation failure (return code 1, typically a JIT assert) will be
-                            # reported as a replay failure.
-                            if return_code != 2 and return_code != 3:
-                                files_with_replay_failures.append(mch_file)
+
+                    base_metrics = read_csv_metrics(base_metrics_summary_file)
+                    diff_metrics = read_csv_metrics(diff_metrics_summary_file)
+
+                    print_superpmi_result(return_code, self.coreclr_args, base_metrics, diff_metrics)
+
+                    if return_code != 0:
+                        result = False
+                        # Don't report as replay failure asm diffs (return code 2) or missing data (return code 3).
+                        # Anything else, such as compilation failure (return code 1, typically a JIT assert) will be
+                        # reported as a replay failure.
+                        if return_code != 2 and return_code != 3:
+                            files_with_replay_failures.append(mch_file)
 
                 artifacts_base_name = create_artifacts_base_name(self.coreclr_args, mch_file)
 
@@ -1983,16 +1997,13 @@ async def create_one_artifact(jit_path: str, location: str, flags) -> str:
                         logging.debug(item)
                     logging.debug("")
 
-                    base_metrics = read_csv_metrics(base_metrics_summary_file)
-                    diff_metrics = read_csv_metrics(diff_metrics_summary_file)
-
-                    if base_metrics is not None and "Code bytes" in base_metrics and diff_metrics is not None and "Code bytes" in diff_metrics:
-                        base_bytes = int(base_metrics["Code bytes"])
-                        diff_bytes = int(diff_metrics["Code bytes"])
-                        logging.info("Total Code bytes of base: {}".format(base_bytes))
-                        logging.info("Total Code bytes of diff: {}".format(diff_bytes))
+                    if base_metrics is not None and diff_metrics is not None:
+                        base_bytes = int(base_metrics["Diffed code bytes"])
+                        diff_bytes = int(diff_metrics["Diffed code bytes"])
+                        logging.info("Total bytes of base: {}".format(base_bytes))
+                        logging.info("Total bytes of diff: {}".format(diff_bytes))
                         delta_bytes = diff_bytes - base_bytes
-                        logging.info("Total Code bytes of delta: {} ({:.2%} of base)".format(delta_bytes, delta_bytes / base_bytes))
+                        logging.info("Total bytes of delta: {} ({:.2%} of base)".format(delta_bytes, delta_bytes / base_bytes))
 
                     try:
                         current_text_diff = text_differences.get_nowait()
@@ -2044,6 +2055,15 @@ async def create_one_artifact(jit_path: str, location: str, flags) -> str:
                         else:
                             logging.warning("No textual differences found in generated JitDump. Is this an issue with coredistools?")
 
+                    if base_metrics is not None and diff_metrics is not None:
+                        missing_base = int(base_metrics["Missing compiles"])
+                        missing_diff = int(diff_metrics["Missing compiles"])
+                        total_contexts = int(base_metrics["Successful compiles"]) + int(base_metrics["Failing compiles"])
+
+                        if missing_base > 0 or missing_diff > 0:
+                            logging.warning("Warning: SuperPMI encountered missing data during the diff. The diff summary printed above may be misleading.")
+                            logging.warning("Missing with base JIT: {}. Missing with diff JIT: {}. Total contexts: {}.".format(missing_base, missing_diff, total_contexts))
+
                 ################################################################################################ end of processing asm diffs (if is_nonzero_length_file(diff_mcl_file)...
 
                 if not self.coreclr_args.skip_cleanup: