Lots more stats

Include/cpython/pystats.h

@@ -100,6 +100,8 @@ typedef struct _uop_stats {
     uint64_t execution_count;
 } UOpStats;
 
+#define _Py_UOP_HIST_SIZE 5
+
 typedef struct _optimization_stats {
     uint64_t attempts;
     uint64_t traces_created;
@@ -112,6 +114,9 @@ typedef struct _optimization_stats {
     uint64_t recursive_call;
     UOpStats opcode[512];
     uint64_t unsupported_opcode[256];
+    uint64_t trace_length_hist[_Py_UOP_HIST_SIZE];
+    uint64_t trace_run_length_hist[_Py_UOP_HIST_SIZE];
+    uint64_t optimized_trace_length_hist[_Py_UOP_HIST_SIZE];
 } OptimizationStats;
 
 typedef struct _stats {

Include/internal/pycore_code.h

@@ -285,6 +285,7 @@ extern int _PyStaticCode_Init(PyCodeObject *co);
 #define OPT_STAT_INC(name) do { if (_Py_stats) _Py_stats->optimization_stats.name++; } while (0)
 #define UOP_EXE_INC(opname) do { if (_Py_stats) _Py_stats->optimization_stats.opcode[opname].execution_count++; } while (0)
 #define OPT_UNSUPPORTED_OPCODE(opname) do { if (_Py_stats) _Py_stats->optimization_stats.unsupported_opcode[opname]++; } while (0)
+#define OPT_HIST(length, name) do { if (_Py_stats) _Py_stats->optimization_stats.name[_Py_bit_length((length - 1) >> 2)]++; } while (0)
 
 // Export for '_opcode' shared extension
 PyAPI_FUNC(PyObject*) _Py_GetSpecializationStats(void);
@@ -302,6 +303,7 @@ PyAPI_FUNC(PyObject*) _Py_GetSpecializationStats(void);
 #define OPT_STAT_INC(name) ((void)0)
 #define UOP_EXE_INC(opname) ((void)0)
 #define OPT_UNSUPPORTED_OPCODE(opname) ((void)0)
+#define OPT_HIST(length, name) ((void)0)
 #endif  // !Py_STATS
 
 // Utility functions for reading/writing 32/64-bit values in the inline caches.

Python/bytecodes.c

@@ -2244,7 +2244,7 @@ dummy_func(
                 // Double-check that the opcode isn't instrumented or something:
                 here->op.code == JUMP_BACKWARD)
             {
-                OPTIMIZATION_STAT_INC(attempts);
+                OPT_STAT_INC(attempts);
                 int optimized = _PyOptimizer_BackEdge(frame, here, next_instr, stack_pointer);
                 ERROR_IF(optimized < 0, error);
                 if (optimized) {
@@ -3913,6 +3913,7 @@ dummy_func(
             frame->prev_instr--;  // Back up to just before destination
             _PyFrame_SetStackPointer(frame, stack_pointer);
             Py_DECREF(self);
+            OPT_HIST(pc, trace_run_length_hist);
             return frame;
         }
 

Python/executor.c

@@ -2,6 +2,7 @@
 
 #include "opcode.h"
 
+#include "pycore_bitutils.h"
 #include "pycore_call.h"
 #include "pycore_ceval.h"
 #include "pycore_dict.h"
@@ -82,7 +83,6 @@ _PyUopExecute(_PyExecutorObject *executor, _PyInterpreterFrame *frame, PyObject
                 (int)(stack_pointer - _PyFrame_Stackbase(frame)));
         pc++;
         OPT_STAT_INC(uops_executed);
-        assert(opcode < 512);
         UOP_EXE_INC(opcode);
         switch (opcode) {
 
@@ -116,6 +116,7 @@ _PyUopExecute(_PyExecutorObject *executor, _PyInterpreterFrame *frame, PyObject
     // On ERROR_IF we return NULL as the frame.
     // The caller recovers the frame from tstate->current_frame.
     DPRINTF(2, "Error: [Opcode %d, operand %" PRIu64 "]\n", opcode, operand);
+    OPT_HIST(pc, trace_run_length_hist);
     _PyFrame_SetStackPointer(frame, stack_pointer);
     Py_DECREF(self);
     return NULL;
@@ -124,6 +125,7 @@ _PyUopExecute(_PyExecutorObject *executor, _PyInterpreterFrame *frame, PyObject
     // On DEOPT_IF we just repeat the last instruction.
     // This presumes nothing was popped from the stack (nor pushed).
     DPRINTF(2, "DEOPT: [Opcode %d, operand %" PRIu64 "]\n", opcode, operand);
+    OPT_HIST(pc, trace_run_length_hist);
     frame->prev_instr--;  // Back up to just before destination
     _PyFrame_SetStackPointer(frame, stack_pointer);
     Py_DECREF(self);

Python/optimizer.c

@@ -750,7 +750,7 @@ translate_bytecode_to_trace(
                     break;
                 }
                 DPRINTF(2, "Unsupported opcode %s\n", uop_name(opcode));
-                OPTIMIZE_UNSUPPORTED_OPCODE(opcode);
+                OPT_UNSUPPORTED_OPCODE(opcode);
                 goto done;  // Break out of loop
             }  // End default
 
@@ -898,6 +898,7 @@ uop_optimize(
         // Error or nothing translated
         return trace_length;
     }
+    OPT_HIST(trace_length, trace_length_hist);
     OPT_STAT_INC(traces_created);
     char *uop_optimize = Py_GETENV("PYTHONUOPSOPTIMIZE");
     if (uop_optimize != NULL && *uop_optimize > '0') {
@@ -908,6 +909,7 @@ uop_optimize(
     if (executor == NULL) {
         return -1;
     }
+    OPT_HIST(trace_length, optimized_trace_length_hist);
     executor->base.execute = _PyUopExecute;
     memcpy(executor->trace, trace, trace_length * sizeof(_PyUOpInstruction));
     *exec_ptr = (_PyExecutorObject *)executor;

Python/specialize.c

@@ -211,6 +211,14 @@ print_gc_stats(FILE *out, GCStats *stats)
     }
 }
 
+static void
+print_histogram(FILE *out, const char *name, uint64_t hist[_Py_UOP_HIST_SIZE])
+{
+    for (int i = 0; i < _Py_UOP_HIST_SIZE; i++) {
+        fprintf(out, "%s[%d]: %" PRIu64 "\n", name, (1 << (i + 2)), hist[i]);
+    }
+}
+
 static void
 print_optimization_stats(FILE *out, OptimizationStats *stats)
 {
@@ -224,7 +232,11 @@ print_optimization_stats(FILE *out, OptimizationStats *stats)
     fprintf(out, "Optimization inner loop: %" PRIu64 "\n", stats->inner_loop);
     fprintf(out, "Optimization recursive call: %" PRIu64 "\n", stats->recursive_call);
 
-    char* const* names;
+    print_histogram(out, "Trace length", stats->trace_length_hist);
+    print_histogram(out, "Trace run length", stats->trace_run_length_hist);
+    print_histogram(out, "Optimized trace length", stats->optimized_trace_length_hist);
+
+    const char* const* names;
     for (int i = 0; i < 512; i++) {
         if (i < 256) {
             names = _PyOpcode_OpName;
@@ -238,7 +250,12 @@ print_optimization_stats(FILE *out, OptimizationStats *stats)
 
     for (int i = 0; i < 256; i++) {
         if (stats->unsupported_opcode[i]) {
-            fprintf(out, "unsupported_opcode[%s].count : %" PRIu64 "\n", _PyOpcode_OpName[i]);
+            fprintf(
+                out, 
+                "unsupported_opcode[%s].count : %" PRIu64 "\n", 
+                _PyOpcode_OpName[i], 
+                stats->unsupported_opcode[i]
+            );
         }
     }
 }

Tools/scripts/summarize_stats.py

@@ -13,6 +13,7 @@
 from datetime import date
 import itertools
 import sys
+import re
 
 if os.name == "nt":
     DEFAULT_DIR = "c:\\temp\\py_stats\\"
@@ -320,6 +321,15 @@ def emit_table(header, rows):
         print("|", " | ".join(to_str(i) for i in row), "|")
     print()
 
+def emit_histogram(title, stats, key, total):
+    rows = []
+    for k, v in stats.items():
+        if k.startswith(key):
+            entry = int(re.match(r".+\[([0-9]+)\]", k).groups()[0])
+            rows.append((f"<= {entry}", int(v), format_ratio(int(v), total)))
+    print(f"**{title}**\n")
+    emit_table(("Range", "Count:", "Ratio:"), rows)
+
 def calculate_execution_counts(opcode_stats, total):
     counts = []
     for name, opcode_stat in opcode_stats.items():
@@ -671,6 +681,25 @@ def emit_optimization_stats(stats):
             rows = calculate_optimization_stats(stats)
             emit_table(("", "Count:", "Ratio:"), rows)
 
+        emit_histogram(
+            "Trace length histogram", 
+            stats, 
+            "Trace length",
+            stats["Optimization traces created"]
+        )
+        emit_histogram(
+            "Optimized trace length histogram",
+            stats,
+            "Optimized trace length",
+            stats["Optimization traces created"]
+        )
+        emit_histogram(
+            "Trace run length histogram", 
+            stats, 
+            "Trace run length",
+            stats["Optimization traces executed"]
+        )
+
         with Section("Uop stats", level=3):
             rows = calculate_uop_execution_counts(uop_stats)
             emit_table(
@@ -689,22 +718,7 @@ def emit_optimization_stats(stats):
 
 
 def emit_comparative_optimization_stats(base_stats, head_stats):
-    if not all("Optimization attempts" in stats for stats in (base_stats, head_stats)):
-        return
-
-    base_uop_stats = extract_opcode_stats(base_stats, "uop")
-    head_uop_stats = extract_opcode_stats(head_stats, "uop")
-
-    with Section("Optimization (Tier 2) stats", summary="statistics about the Tier 2 optimizer"):
-        with Section("Overall stats", level=3):
-            base_rows = calculate_optimization_stats(base_stats)
-            head_rows = calculate_optimization_stats(head_stats)
-            emit_table(("", "Base Count:", "Base Ratio:", "Head Count:", "Head Ratio:"), join_rows(base_rows, head_rows))
-
-        with Section("Uop stats", level=3):
-            base_rows = calculate_uop_execution_counts(base_uop_stats)
-            head_rows = calculate_uop_execution_counts(head_uop_stats)
-            _emit_comparative_execution_counts(base_rows, head_rows)
+    print("## Comparative optimization stats not implemented\n\n")
 
 
 def output_single_stats(stats):