3888 - beginnings of a profiler

Time to make my ad hoc commented out code fragments a first-class feature.

020run.cc

@@ -48,9 +48,6 @@ struct routine {
 
 :(before "End Globals")
 routine* Current_routine = NULL;
-map<string, int> Instructions_running;
-map<string, int> Locations_read;
-map<string, int> Locations_read_by_instruction;
 :(before "End Setup")
 Current_routine = NULL;
 
@@ -65,7 +62,6 @@ void run(const recipe_ordinal r) {
 void run_current_routine() {
   while (should_continue_running(Current_routine)) {  // beware: may modify Current_routine
     // Running One Instruction
-//?     Instructions_running[current_recipe_name()]++;
     if (current_instruction().is_label) { ++current_step_index();  continue; }
     trace(Initial_callstack_depth + Trace_stream->callstack_depth, "run") << to_string(current_instruction()) << end();
     if (get_or_insert(Memory, 0) != 0) {
@@ -138,6 +134,11 @@ int& current_step_index() {
   return Current_routine->running_step_index;
 }
 
+//: hook replaced in a later layer
+recipe_ordinal currently_running_recipe() {
+  return Current_routine->running_recipe;
+}
+
 //: hook replaced in a later layer
 const string& current_recipe_name() {
   return get(Recipe, Current_routine->running_recipe).name;
@@ -231,23 +232,6 @@ else if (is_equal(*arg, "--trace")) {
   Start_tracing = true;
 }
 
-:(code)
-void dump_profile() {
-  for (map<string, int>::iterator p = Instructions_running.begin();  p != Instructions_running.end();  ++p) {
-    cerr << p->first << ": " << p->second << '\n';
-  }
-  cerr << "== locations read\n";
-  for (map<string, int>::iterator p = Locations_read.begin();  p != Locations_read.end();  ++p) {
-    cerr << p->first << ": " << p->second << '\n';
-  }
-  cerr << "== locations read by instruction\n";
-  for (map<string, int>::iterator p = Locations_read_by_instruction.begin();  p != Locations_read_by_instruction.end();  ++p) {
-    cerr << p->first << ": " << p->second << '\n';
-  }
-}
-:(before "End One-time Setup")
-//? atexit(dump_profile);
-
 :(code)
 void cleanup_main() {
   if (Save_trace && Trace_stream) {
@@ -456,3 +440,46 @@ def main [
   1:num, 2:num <- copy 2 ,2
 ]
 +mem: storing 2 in location 1
+
+//:: Counters for trying to understand where Mu programs are spending their
+//:: time.
+
+:(before "End Globals")
+bool Run_profiler = false;
+// We'll key profile information by recipe_ordinal rather than name because
+// it's more efficient, and because later layers will show more than just the
+// name of a recipe.
+//
+// One drawback: if you're clearing recipes your profile will be inaccurate.
+// So far that happens in tests, and in `run-sandboxed` in a later layer.
+map<recipe_ordinal, int> Instructions_running;
+:(before "End Commandline Options(*arg)")
+else if (is_equal(*arg, "--profile")) {
+  Run_profiler = true;
+}
+:(after "Running One Instruction")
+if (Run_profiler) Instructions_running[currently_running_recipe()]++;
+:(before "End One-time Setup")
+atexit(dump_profile);
+:(code)
+void dump_profile() {
+  if (!Run_profiler) return;
+  if (Run_tests) {
+    cerr << "It's not a good idea to profile a run with tests, since tests can create conflicting recipes and mislead you. To try it anyway, comment out this check in the code.\n";
+    return;
+  }
+  ofstream fout;
+  fout.open("profile.instructions");
+  if (fout) {
+    for (map<recipe_ordinal, int>::iterator p = Instructions_running.begin();  p != Instructions_running.end();  ++p) {
+      fout << std::setw(9) << p->second << ' ' << header_label(p->first) << '\n';
+    }
+  }
+  fout.close();
+  // End dump_profile
+}
+
+// overridden in a later layer
+string header_label(const recipe_ordinal r) {
+  return get(Recipe, r).name;
+}

026call.cc

@@ -79,6 +79,11 @@ int& current_step_index() {
   assert(!Current_routine->calls.empty());
   return current_call().running_step_index;
 }
+:(replace{} "recipe_ordinal currently_running_recipe()")
+recipe_ordinal currently_running_recipe() {
+  assert(!Current_routine->calls.empty());
+  return current_call().running_recipe;
+}
 :(replace{} "const string& current_recipe_name()")
 const string& current_recipe_name() {
   assert(!Current_routine->calls.empty());

054static_dispatch.cc

@@ -566,10 +566,11 @@ def foo x:num -> y:num [
 # number variant is preferred
 +mem: storing 35 in location 1
 
-:(code)
+:(replace{} "string header_label(const recipe_ordinal r)")
 string header_label(const recipe_ordinal r) {
   return header_label(get(Recipe, r));
 }
+:(code)
 string header_label(const recipe& caller) {
   ostringstream out;
   out << "recipe " << caller.name;

101run_sandboxed.cc

@@ -130,6 +130,7 @@ bool run_interactive(int address) {
 //: Carefully update all state to exactly how it was -- including snapshots.
 
 :(before "End Globals")
+bool Run_profiler_stash = false;
 map<string, recipe_ordinal> Recipe_ordinal_snapshot_stash;
 map<recipe_ordinal, recipe> Recipe_snapshot_stash;
 map<string, type_ordinal> Type_ordinal_snapshot_stash;
@@ -145,6 +146,8 @@ void run_code_begin(bool should_stash_snapshots) {
   // stuff to undo later, in run_code_end()
   Hide_errors = true;
   Disable_redefine_checks = true;
+  Run_profiler_stash = Run_profiler;
+  Run_profiler = false;
   if (should_stash_snapshots)
     stash_snapshots();
   Save_trace_stream = Trace_stream;
@@ -155,6 +158,8 @@ void run_code_begin(bool should_stash_snapshots) {
 void run_code_end() {
   Hide_errors = false;
   Disable_redefine_checks = false;
+  Run_profiler = Run_profiler_stash;
+  Run_profiler_stash = false;
 //?   ofstream fout("sandbox.log");
 //?   fout << Trace_stream->readable_contents("");
 //?   fout.close();