SPMI: Use diffed bytes for jit-analyze and print more info (#61254)
authorJakob Botsch Nielsen <Jakob.botsch.nielsen@gmail.com>
Tue, 9 Nov 2021 18:23:48 +0000 (19:23 +0100)
committerGitHub <noreply@github.com>
Tue, 9 Nov 2021 18:23:48 +0000 (19:23 +0100)
Fix the misleading total bytes displayed when diffing with SPMI. If one
of the JITs encountered missing data, the code bytes would not be
included, while the other JIT could still have it included if it did not
encounter missing data.

Also add more information about missing SPMI data/successful replays
printed. For replays that is useful to be able to gauge whether there is
still ok coverage after a large change. For diffs, we print a warning
for missing SPMI data that the diff summary may be misleading.

Example for a successful replay:
    Clean SuperPMI replay (219868 contexts processed)

Example for a replay with missing data:
    SuperPMI encountered missing data for 6 out of 27272 contexts

Example warning printed:
    Warning: SuperPMI encountered missing data during the diff. The diff
    summary printed above may be misleading.
    Missing with base JIT: 0. Missing with diff JIT: 6. Total contexts:
    27272.

src/coreclr/ToolBox/superpmi/superpmi/jitinstance.cpp
src/coreclr/ToolBox/superpmi/superpmi/metricssummary.cpp
src/coreclr/ToolBox/superpmi/superpmi/metricssummary.h
src/coreclr/ToolBox/superpmi/superpmi/superpmi.cpp
src/coreclr/scripts/superpmi.py

index 96484d4..07d9054 100644 (file)
@@ -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;
 }
 
index e7c725d..8af4e6f 100644 (file)
@@ -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;
 }
index 4f7d825..335c8b9 100644 (file)
@@ -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)
     {
     }
 
index 5410240..f71ee9c 100644 (file)
@@ -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)
index e919117..0c098ec 100755 (executable)
@@ -1471,7 +1471,7 @@ class SuperPMICollect:
 ################################################################################
 
 
-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
@@ -1479,8 +1479,7 @@ def print_superpmi_failure_code(return_code, coreclr_args):
         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 @@ class SuperPMIReplay:
                 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 @@ class SuperPMIReplayAsmDiffs:
                     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 @@ class SuperPMIReplayAsmDiffs:
                         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 @@ class SuperPMIReplayAsmDiffs:
                         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: