4987 - support `browse_trace` tool in SubX

I've extracted it into a separate binary, independent of my Mu prototype.

I also cleaned up my tracing layer to be a little nicer. Major improvements:

- Realized that incremental tracing really ought to be the default.
  And to minimize printing traces to screen.

- Finally figured out how to combine layers and call stack frames in a
  single dimension of depth. The answer: optimize for the experience of
  `browse_trace`. Instructions occupy a range of depths based on their call
  stack frame, and minor details of an instruction lie one level deeper
  in each case.

Other than that, I spent some time adjusting levels everywhere to make
`browse_trace` useful.

73 files changed, 1326 insertions, 998 deletions

diff --git a/003trace.cc b/003trace.cc
index 11b54818..3213effc 100644
--- a/003trace.cc
+++ b/003trace.cc
@@ -13,30 +13,31 @@
 //: longer valid. In both cases you end up having to reorganize code as well as
 //: tests, an error-prone activity.
 //:
-//: In response, this layer introduces the notion of *domain-driven* testing.
-//: We focus on the domain of inputs the whole program needs to handle rather
-//: than the correctness of individual functions. All tests invoke the program
-//: in a single way: by calling run() with some input. As the program operates
-//: on the input, it traces out a list of _facts_ deduced about the domain:
+//: In response, this layer introduces the notion of domain-driven *white-box*
+//: testing. We focus on the domain of inputs the whole program needs to
+//: handle rather than the correctness of individual functions. All white-box
+//: tests (we call them 'scenarios') invoke the program in a single way: by
+//: calling run() with some input. As the program operates on the input, it
+//: traces out a list of _facts_ deduced about the domain:
 //:   trace("label") << "fact 1: " << val;
 //:
-//: Tests can now check these facts:
+//: Scenarios can now check these facts:
 //:   :(scenario foo)
 //:   34  # call run() with this input
 //:   +label: fact 1: 34  # 'run' should have deduced this fact
 //:   -label: fact 1: 35  # the trace should not contain such a fact
 //:
 //: Since we never call anything but the run() function directly, we never have
-//: to rewrite the tests when we reorganize the internals of the program. We
+//: to rewrite the scenarios when we reorganize the internals of the program. We
 //: just have to make sure our rewrite deduces the same facts about the domain,
 //: and that's something we're going to have to do anyway.
 //:
 //: To avoid the combinatorial explosion of integration tests, each layer
-//: mainly logs facts to the trace with a common *label*. All tests in a layer
-//: tend to check facts with this label. Validating the facts logged with a
-//: specific label is like calling functions of that layer directly.
+//: mainly logs facts to the trace with a common *label*. All scenarios in a
+//: layer tend to check facts with this label. Validating the facts logged
+//: with a specific label is like calling functions of that layer directly.
 //:
-//: To build robust tests, trace facts about your domain rather than details of
+//: To build robust scenarios, trace facts about your domain rather than details of
 //: how you computed them.
 //:
 //: More details: http://akkartik.name/blog/tracing-tests
@@ -44,159 +45,188 @@
 //: ---
 //:
 //: Between layers and domain-driven testing, programming starts to look like a
-//: fundamentally different activity. Instead of a) superficial, b) local rules
-//: on c) code [like say http://blog.bbv.ch/2013/06/05/clean-code-cheat-sheet],
-//: we allow programmers to engage with the a) deep, b) global structure of the
-//: c) domain. If you can systematically track discontinuities in the domain,
-//: you don't care if the code used gotos as long as it passed the tests. If
-//: tests become more robust to run it becomes easier to try out radically
-//: different implementations for the same program. If code is super-easy to
-//: rewrite, it becomes less important what indentation style it uses, or that
-//: the objects are appropriately encapsulated, or that the functions are
-//: referentially transparent.
+//: fundamentally different activity. Instead of focusing on a) superficial,
+//: b) local rules on c) code [like say http://blog.bbv.ch/2013/06/05/clean-code-cheat-sheet],
+//: we allow programmers to engage with the a) deep, b) global structure of
+//: the c) domain. If you can systematically track discontinuities in the
+//: domain, you don't care if the code used gotos as long as it passed all
+//: scenarios. If scenarios become more robust to run, it becomes easier to
+//: try out radically different implementations for the same program. If code
+//: is super-easy to rewrite, it becomes less important what indentation style
+//: it uses, or that the objects are appropriately encapsulated, or that the
+//: functions are referentially transparent.
 //:
 //: Instead of plumbing, programming becomes building and gradually refining a
-//: map of the environment the program must operate under. Whether a program is
-//: 'correct' at a given point in time is a red herring; what matters is
-//: avoiding regression by monotonically nailing down the more 'eventful' parts
-//: of the terrain. It helps readers new and old, and rewards curiosity, to
-//: organize large programs in self-similar hierarchies of example scenarios
+//: map of the environment the program must operate under. Whether a program
+//: is 'correct' at a given point in time is a red herring; what matters is
+//: avoiding regression by monotonically nailing down the more 'eventful'
+//: parts of the terrain. It helps readers new and old, and rewards curiosity,
+//: to organize large programs in self-similar hierarchies of example scenarios
 //: colocated with the code that makes them work.
 //:
 //:   "Programming properly should be regarded as an activity by which
 //:   programmers form a mental model, rather than as production of a program."
 //:   -- Peter Naur (http://alistair.cockburn.us/ASD+book+extract%3A+%22Naur,+Ehn,+Musashi%22)
 
-:(before "End Types")
-struct trace_line {
-  int depth;  // optional field just to help browse traces later
-  string label;
-  string contents;
-  trace_line(string l, string c) :depth(0), label(l), contents(c) {}
-  trace_line(int d, string l, string c) :depth(d), label(l), contents(c) {}
-};
+//:: == Core data structures
 
-//: Support for tracing an entire run.
-//: Traces can have a lot of overhead, so only turn them on when asked.
-:(before "End Commandline Options(*arg)")
-else if (is_equal(*arg, "--trace")) {
-  Save_trace = true;
-}
-:(before "End Commandline Parsing")
-if (Save_trace) {
-  cerr << "initializing trace\n";
-  Trace_stream = new trace_stream;
-}
-:(code)
-void cleanup_main() {
-  if (!Trace_stream) return;
-  if (Save_trace)
-    Trace_stream->save();
-  delete Trace_stream;
-  Trace_stream = NULL;
-}
-:(before "End One-time Setup")
-atexit(cleanup_main);
+:(before "End Globals")
+trace_stream* Trace_stream = NULL;
 
 :(before "End Types")
-// Pre-define some global constants that trace_stream needs to know about.
-// Since they're in the Types section, they'll be included in any cleaved
-// compilation units. So no extern linkage.
-const int Max_depth = 9999;
-const int Error_depth = 0;  // definitely always print errors
-const int App_depth = 2;  // temporarily where all Mu code will trace to
-
 struct trace_stream {
   vector<trace_line> past_lines;
-  // accumulator for current line
-  ostringstream* curr_stream;
-  string curr_label;
-  int curr_depth;
-  int callstack_depth;
-  int collect_depth;
-  ofstream null_stream;  // never opens a file, so writes silently fail
-  trace_stream() :curr_stream(NULL), curr_depth(Max_depth), callstack_depth(0), collect_depth(Max_depth) {}
-  ~trace_stream() { if (curr_stream) delete curr_stream; }
-
-  ostream& stream(string label) {
-    return stream(Max_depth, label);
-  }
+  // End trace_stream Fields
 
-  ostream& stream(int depth, string label) {
-    if (depth > collect_depth) return null_stream;
-    curr_stream = new ostringstream;
-    curr_label = label;
-    curr_depth = depth;
-    return *curr_stream;
+  trace_stream() {
+    // End trace_stream Constructor
   }
-
-  void save() {
-    cerr << "saving trace to 'last_run'\n";
-    ofstream fout("last_run");
-    fout << readable_contents("");
-    fout.close();
+  ~trace_stream() {
+    // End trace_stream Destructor
   }
+  // End trace_stream Methods
+};
 
-  // be sure to call this before messing with curr_stream or curr_label
-  void newline();
-  // useful for debugging
-  string readable_contents(string label);  // empty label = show everything
+//:: == Adding to the trace
+
+//: Top-level method is trace() which can be used like an ostream. Usage:
+//:   trace(depth, label) << ... << end();
+//: Don't forget the 'end()' to actually append to the trace.
+:(before "End Includes")
+// No brackets around the expansion so that it prints nothing if Trace_stream
+// isn't initialized.
+#define trace(...)  !Trace_stream ? cerr : Trace_stream->stream(__VA_ARGS__)
+
+:(before "End trace_stream Fields")
+// accumulator for current trace_line
+ostringstream* curr_stream;
+string curr_label;
+int curr_depth;
+// other stuff
+int collect_depth;  // avoid tracing lower levels for speed
+ofstream null_stream;  // never opened, so writes to it silently fail
+
+//: Some constants.
+:(before "struct trace_stream")  // include constants in all cleaved compilation units
+const int Max_depth = 9999;
+// Most important traces are printed to the screen by default
+const int Error_depth = 0;
+:(before "End Globals")
+int Hide_errors = false;  // if set, don't print errors to screen
+:(before "End trace_stream Constructor")
+curr_stream = NULL;
+curr_depth = Max_depth;
+collect_depth = Max_depth;
+:(before "End Reset")
+Hide_errors = false;
+
+:(before "struct trace_stream")
+struct trace_line {
+  string contents;
+  string label;
+  int depth;  // 0 is 'sea level'; positive integers are progressively 'deeper' and lower level
+  trace_line(string c, string l) {
+    contents = c;
+    label = l;
+    depth = 0;
+  }
+  trace_line(string c, string l, int d) {
+    contents = c;
+    label = l;
+    depth = d;
+  }
 };
 
+//: Starting a new trace line.
+:(before "End trace_stream Methods")
+ostream& stream(string label) {
+  return stream(Max_depth, label);
+}
+
+ostream& stream(int depth, string label) {
+  if (depth > collect_depth) return null_stream;
+  curr_stream = new ostringstream;
+  curr_label = label;
+  curr_depth = depth;
+  return *curr_stream;
+}
+
+//: End of a trace line; append it to the trace.
+:(before "End Types")
+struct end {};
+:(code)
+ostream& operator<<(ostream& os, end /*unused*/) {
+  if (Trace_stream) Trace_stream->newline();
+  return os;
+}
+
+:(before "End trace_stream Methods")
+void newline();
 :(code)
 void trace_stream::newline() {
   if (!curr_stream) return;
   string curr_contents = curr_stream->str();
   if (!curr_contents.empty()) {
-    past_lines.push_back(trace_line(curr_depth, trim(curr_label), curr_contents));  // preserve indent in contents
-    if ((!Hide_errors && curr_label == "error")
-        || Dump_trace
-        || (!Dump_label.empty() && curr_label == Dump_label))
-      cerr << curr_label << ": " << curr_contents << '\n';
+    past_lines.push_back(trace_line(curr_contents, trim(curr_label), curr_depth));  // preserve indent in contents
+    // maybe incrementally dump trace
+    trace_line& t = past_lines.back();
+    if (!Hide_errors && curr_depth == Error_depth) {
+      cerr       << std::setw(4) << t.depth << ' ' << t.label << ": " << t.contents << '\n';
+    }
+    // End trace Commit
   }
+
+  // clean up
   delete curr_stream;
   curr_stream = NULL;
   curr_label.clear();
   curr_depth = Max_depth;
 }
 
-string trace_stream::readable_contents(string label) {
-  ostringstream output;
-  label = trim(label);
-  for (vector<trace_line>::iterator p = past_lines.begin();  p != past_lines.end();  ++p)
-    if (label.empty() || label == p->label)
-      output << std::setw(4) << p->depth << ' ' << p->label << ": " << p->contents << '\n';
-  return output.str();
-}
+//:: == Initializing the trace in scenarios
 
-:(before "End Globals")
-trace_stream* Trace_stream = NULL;
-int Trace_errors = 0;  // used only when Trace_stream is NULL
+:(before "End Includes")
+#define START_TRACING_UNTIL_END_OF_SCOPE  lease_tracer leased_tracer;
+:(before "End Test Setup")
+START_TRACING_UNTIL_END_OF_SCOPE
 
-:(before "End Globals")
-bool Hide_errors = false;  // if set, don't print even error trace lines to screen
-bool Dump_trace = false;  // if set, print trace lines to screen
-string Dump_label = "";  // if set, print trace lines matching a single label to screen
-:(before "End Reset")
-Hide_errors = false;
-Dump_trace = false;  // toggle this to print traces to screen as they are emitted
-Dump_label = "";
+//: Trace_stream is a resource, lease_tracer uses RAII to manage it.
+:(before "End Types")
+struct lease_tracer {
+  lease_tracer();
+  ~lease_tracer();
+};
+:(code)
+lease_tracer::lease_tracer() { Trace_stream = new trace_stream; }
+lease_tracer::~lease_tracer() {
+  delete Trace_stream;
+  Trace_stream = NULL;
+}
+
+//:: == Errors using traces
 
 :(before "End Includes")
-#define CLEAR_TRACE  delete Trace_stream, Trace_stream = new trace_stream;
+#define raise  (!Trace_stream ? (scroll_to_bottom_and_close_console(),++Trace_errors,cerr) /*do print*/ : Trace_stream->stream(Error_depth, "error"))
 
-// Top-level helper. IMPORTANT: can't nest
-#define trace(...)  !Trace_stream ? cerr /*print nothing*/ : Trace_stream->stream(__VA_ARGS__)
+:(before "End Globals")
+int Trace_errors = 0;  // used only when Trace_stream is NULL
 
-// Just for debugging; 'git log' should never show any calls to 'dbg'.
-#define dbg trace(0, "a")
-#define DUMP(label)  if (Trace_stream) cerr << Trace_stream->readable_contents(label);
+// Fail scenarios that displayed (unexpected) errors.
+// Expected errors should always be hidden and silently checked for.
+:(before "End Test Teardown")
+if (Passed && !Hide_errors && trace_contains_errors()) {
+  Passed = false;
+}
+:(code)
+bool trace_contains_errors() {
+  return Trace_errors > 0 || trace_count("error") > 0;
+}
 
-// Errors are a special layer.
-#define raise  (!Trace_stream ? (scroll_to_bottom_and_close_console(),++Trace_errors,cerr) /*do print*/ : Trace_stream->stream(Error_depth, "error"))
+:(before "End Includes")
 // If we aren't yet sure how to deal with some corner case, use assert_for_now
 // to indicate that it isn't an inviolable invariant.
 #define assert_for_now assert
+#define raise_for_now raise
 
 //: Automatically close the console in some situations.
 :(before "End One-time Setup")
@@ -209,57 +239,30 @@ void scroll_to_bottom_and_close_console() {
   cout << "\r\n";
   tb_shutdown();
 }
-
-// Inside tests, fail any tests that displayed (unexpected) errors.
-// Expected errors in tests should always be hidden and silently checked for.
-:(before "End Test Teardown")
-if (Passed && !Hide_errors && trace_contains_errors()) {
-  Passed = false;
-}
-:(code)
-bool trace_contains_errors() {
-  return Trace_errors > 0 || trace_count("error") > 0;
-}
-
-:(before "End Types")
-struct end {};
-:(code)
-ostream& operator<<(ostream& os, end /*unused*/) {
-  if (Trace_stream) Trace_stream->newline();
-  return os;
-}
-
-:(before "End Globals")
-bool Save_trace = false;  // if set, write out trace to disk
-
-// Trace_stream is a resource, lease_tracer uses RAII to manage it.
-:(before "End Types")
-struct lease_tracer {
-  lease_tracer();
-  ~lease_tracer();
-};
-:(code)
-lease_tracer::lease_tracer() { Trace_stream = new trace_stream; }
-lease_tracer::~lease_tracer() {
-  if (Save_trace) Trace_stream->save();
-  delete Trace_stream, Trace_stream = NULL;
-}
 :(before "End Includes")
-#define START_TRACING_UNTIL_END_OF_SCOPE  lease_tracer leased_tracer;
-:(before "End Test Setup")
-START_TRACING_UNTIL_END_OF_SCOPE
+#include "termbox/termbox.h"
+
+//:: == Other assertions on traces
+//: Primitives:
+//:   - CHECK_TRACE_CONTENTS(lines)
+//:     Assert that the trace contains the given lines (separated by newlines)
+//:     in order. There can be other intervening lines between them.
+//:   - CHECK_TRACE_DOESNT_CONTAIN(line)
+//:   - CHECK_TRACE_DOESNT_CONTAIN(label, contents)
+//:     Assert that the trace doesn't contain the given (single) line.
+//:   - CHECK_TRACE_COUNT(label, count)
+//:     Assert that the trace contains exactly 'count' lines with the given
+//:     'label'.
+//:   - CHECK_TRACE_CONTAINS_ERRORS()
+//:   - CHECK_TRACE_DOESNT_CONTAIN_ERRORS()
+//:   - trace_count_prefix(label, prefix)
+//:     Count the number of trace lines with the given 'label' that start with
+//:     the given 'prefix'.
 
 :(before "End Includes")
 #define CHECK_TRACE_CONTENTS(...)  check_trace_contents(__FUNCTION__, __FILE__, __LINE__, __VA_ARGS__)
 
-#define CHECK_TRACE_CONTAINS_ERRORS()  CHECK(trace_contains_errors())
-#define CHECK_TRACE_DOESNT_CONTAIN_ERRORS() \
-  if (Passed && trace_contains_errors()) { \
-    cerr << "\nF - " << __FUNCTION__ << "(" << __FILE__ << ":" << __LINE__ << "): unexpected errors\n"; \
-    DUMP("error"); \
-    Passed = false; \
-    return; \
-  }
+#define CHECK_TRACE_DOESNT_CONTAIN(...)  CHECK(trace_doesnt_contain(__VA_ARGS__))
 
 #define CHECK_TRACE_COUNT(label, count) \
   if (Passed && trace_count(label) != (count)) { \
@@ -270,7 +273,17 @@ START_TRACING_UNTIL_END_OF_SCOPE
     return;  /* Currently we stop at the very first failure. */ \
   }
 
-#define CHECK_TRACE_DOESNT_CONTAIN(...)  CHECK(trace_doesnt_contain(__VA_ARGS__))
+#define CHECK_TRACE_CONTAINS_ERRORS()  CHECK(trace_contains_errors())
+#define CHECK_TRACE_DOESNT_CONTAIN_ERRORS() \
+  if (Passed && trace_contains_errors()) { \
+    cerr << "\nF - " << __FUNCTION__ << "(" << __FILE__ << ":" << __LINE__ << "): unexpected errors\n"; \
+    DUMP("error"); \
+    Passed = false; \
+    return; \
+  }
+
+// Allow scenarios to ignore trace lines generated during setup.
+#define CLEAR_TRACE  delete Trace_stream, Trace_stream = new trace_stream
 
 :(code)
 bool check_trace_contents(string FUNCTION, string FILE, int LINE, string expected) {
@@ -305,25 +318,13 @@ bool check_trace_contents(string FUNCTION, string FILE, int LINE, string expecte
   return false;
 }
 
-void split_label_contents(const string& s, string* label, string* contents) {
-  static const string delim(": ");
-  size_t pos = s.find(delim);
-  if (pos == string::npos) {
-    *label = "";
-    *contents = trim(s);
-  }
-  else {
-    *label = trim(s.substr(0, pos));
-    *contents = trim(s.substr(pos+SIZE(delim)));
-  }
-}
-
-bool line_exists_anywhere(const string& label, const string& contents) {
-  for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
-    if (label != p->label) continue;
-    if (contents == trim(p->contents)) return true;
+bool trace_doesnt_contain(string expected) {
+  vector<string> tmp = split_first(expected, ": ");
+  if (SIZE(tmp) == 1) {
+    raise << expected << ": missing label or contents in trace line\n" << end();
+    assert(false);
   }
-  return false;
+  return trace_count(tmp.at(0), tmp.at(1)) == 0;
 }
 
 int trace_count(string label) {
@@ -354,17 +355,25 @@ int trace_count_prefix(string label, string prefix) {
   return result;
 }
 
-bool trace_doesnt_contain(string label, string line) {
-  return trace_count(label, line) == 0;
+void split_label_contents(const string& s, string* label, string* contents) {
+  static const string delim(": ");
+  size_t pos = s.find(delim);
+  if (pos == string::npos) {
+    *label = "";
+    *contents = trim(s);
+  }
+  else {
+    *label = trim(s.substr(0, pos));
+    *contents = trim(s.substr(pos+SIZE(delim)));
+  }
 }
 
-bool trace_doesnt_contain(string expected) {
-  vector<string> tmp = split_first(expected, ": ");
-  if (SIZE(tmp) == 1) {
-    raise << expected << ": missing label or contents in trace line\n" << end();
-    assert(false);
+bool line_exists_anywhere(const string& label, const string& contents) {
+  for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
+    if (label != p->label) continue;
+    if (contents == trim(p->contents)) return true;
   }
-  return trace_doesnt_contain(tmp.at(0), tmp.at(1));
+  return false;
 }
 
 vector<string> split(string s, string delim) {
@@ -391,6 +400,54 @@ vector<string> split_first(string s, string delim) {
   return result;
 }
 
+//:: == Helpers for debugging using traces
+
+:(before "End Includes")
+// To debug why a scenario is failing, dump its trace using '?'.
+#define DUMP(label)  if (Trace_stream) cerr << Trace_stream->readable_contents(label);
+
+// To add temporary prints to the trace, use 'dbg'.
+// `git log` should never show any calls to 'dbg'.
+#define dbg trace(0, "a")
+
+//: Dump the entire trace to file where it can be browsed offline.
+//: Dump the trace as it happens; that way you get something even if the
+//: program crashes.
+
+:(before "End Globals")
+ofstream Trace_file;
+:(before "End Commandline Options(*arg)")
+else if (is_equal(*arg, "--trace")) {
+  Trace_stream = new trace_stream;
+  cerr << "saving trace to 'last_run'\n";
+  Trace_file.open("last_run");
+}
+:(before "End trace Commit")
+if (Trace_file) {
+  Trace_file << std::setw(4) << t.depth << ' ' << t.label << ": " << t.contents << '\n';
+}
+:(before "End One-time Setup")
+atexit(cleanup_main);
+:(code)
+void cleanup_main() {
+  if (Trace_file) Trace_file.close();
+  // End cleanup_main
+}
+
+:(before "End trace_stream Methods")
+string readable_contents(string label) {
+  string trim(const string& s);  // prototype
+  ostringstream output;
+  label = trim(label);
+  for (vector<trace_line>::iterator p = past_lines.begin();  p != past_lines.end();  ++p)
+    if (label.empty() || label == p->label)
+      output << std::setw(4) << p->depth << ' ' << p->label << ": " << p->contents << '\n';
+  return output.str();
+}
+
+//: Miscellaneous helpers.
+
+:(code)
 string trim(const string& s) {
   string::const_iterator first = s.begin();
   while (first != s.end() && isspace(*first))
@@ -419,19 +476,3 @@ using std::ostringstream;
 #include <fstream>
 using std::ifstream;
 using std::ofstream;
-
-#include "termbox/termbox.h"
-
-:(before "End Globals")
-//: In future layers we'll use the depth field as follows:
-//:
-//: Errors will be depth 0.
-//: Mu 'applications' will be able to use depths 1-100 as they like.
-//: Primitive statements will occupy 101-9989
-extern const int Initial_callstack_depth = 101;
-extern const int Max_callstack_depth = 9989;
-//: Finally, details of primitive Mu statements will occupy depth 9990-9999
-//: (more on that later as well)
-//:
-//: This framework should help us hide some details at each level, mixing
-//: static ideas like layers with the dynamic notion of call-stack depth.
diff --git a/011load.cc b/011load.cc
index 666f1c6e..575509ea 100644
--- a/011load.cc
+++ b/011load.cc
@@ -63,13 +63,13 @@ int slurp_recipe(istream& in) {
   // End Recipe Refinements
   if (result.name.empty())
     raise << "empty result.name\n" << end();
-  trace(9991, "parse") << "--- defining " << result.name << end();
+  trace(101, "parse") << "--- defining " << result.name << end();
   if (!contains_key(Recipe_ordinal, result.name))
     put(Recipe_ordinal, result.name, Next_recipe_ordinal);
   result.ordinal = get(Recipe_ordinal, result.name);
   ++Next_recipe_ordinal;
   if (Recipe.find(get(Recipe_ordinal, result.name)) != Recipe.end()) {
-    trace(9991, "parse") << "already exists" << end();
+    trace(101, "parse") << "already exists" << end();
     if (should_check_for_redefine(result.name))
       raise << "redefining recipe " << result.name << "\n" << end();
     Recipe.erase(get(Recipe_ordinal, result.name));
@@ -90,7 +90,7 @@ void slurp_body(istream& in, recipe& result) {
   while (next_instruction(in, &curr)) {
     curr.original_string = to_original_string(curr);
     // End Rewrite Instruction(curr, recipe result)
-    trace(9992, "load") << "after rewriting: " << to_string(curr) << end();
+    trace(102, "load") << "after rewriting: " << to_string(curr) << end();
     if (!curr.is_empty()) result.steps.push_back(curr);
   }
 }
@@ -126,7 +126,7 @@ bool next_instruction(istream& in, instruction* curr) {
   if (SIZE(words) == 1 && is_label_word(words.at(0))) {
     curr->is_label = true;
     curr->label = words.at(0);
-    trace(9993, "parse") << "label: " << curr->label << end();
+    trace(103, "parse") << "label: " << curr->label << end();
     if (!has_data(in)) {
       raise << "incomplete recipe at end of file (3)\n" << end();
       return false;
@@ -151,12 +151,12 @@ bool next_instruction(istream& in, instruction* curr) {
   for (;  p != words.end();  ++p)
     curr->ingredients.push_back(reagent(*p));
 
-  trace(9993, "parse") << "instruction: " << curr->name << end();
-  trace(9993, "parse") << "  number of ingredients: " << SIZE(curr->ingredients) << end();
+  trace(103, "parse") << "instruction: " << curr->name << end();
+  trace(103, "parse") << "  number of ingredients: " << SIZE(curr->ingredients) << end();
   for (vector<reagent>::iterator p = curr->ingredients.begin();  p != curr->ingredients.end();  ++p)
-    trace(9993, "parse") << "  ingredient: " << to_string(*p) << end();
+    trace(103, "parse") << "  ingredient: " << to_string(*p) << end();
   for (vector<reagent>::iterator p = curr->products.begin();  p != curr->products.end();  ++p)
-    trace(9993, "parse") << "  product: " << to_string(*p) << end();
+    trace(103, "parse") << "  product: " << to_string(*p) << end();
   if (!has_data(in)) {
     raise << "9: unbalanced '[' for recipe\n" << end();
     return false;
diff --git a/012transform.cc b/012transform.cc
index f62349fa..758a286c 100644
--- a/012transform.cc
+++ b/012transform.cc
@@ -44,7 +44,7 @@ void initialize_transforms() {
 }
 
 void transform_all() {
-  trace(9990, "transform") << "=== transform_all()" << end();
+  trace(100, "transform") << "=== transform_all()" << end();
   // Begin transform_all
   for (int t = 0;  t < SIZE(Transform);  ++t) {
     for (map<recipe_ordinal, recipe>::iterator p = Recipe.begin();  p != Recipe.end();  ++p) {
@@ -72,7 +72,7 @@ int Num_calls_to_transform_all = 0;
 
 :(code)
 void parse_int_reagents() {
-  trace(9991, "transform") << "--- parsing any uninitialized reagents as integers" << end();
+  trace(101, "transform") << "--- parsing any uninitialized reagents as integers" << end();
   for (map<recipe_ordinal, recipe>::iterator p = Recipe.begin();  p != Recipe.end();  ++p) {
     recipe& r = p->second;
     if (r.steps.empty()) continue;
diff --git a/013update_operation.cc b/013update_operation.cc
index 8366439d..c5a736f6 100644
--- a/013update_operation.cc
+++ b/013update_operation.cc
@@ -6,7 +6,7 @@ Transform.push_back(update_instruction_operations);  // idempotent
 
 :(code)
 void update_instruction_operations(const recipe_ordinal r) {
-  trace(9991, "transform") << "--- compute instruction operations for recipe " << get(Recipe, r).name << end();
+  trace(101, "transform") << "--- compute instruction operations for recipe " << get(Recipe, r).name << end();
   recipe& caller = get(Recipe, r);
 //?   cerr << "--- compute instruction operations for recipe " << caller.name << '\n';
   for (int index = 0;  index < SIZE(caller.steps);  ++index) {
diff --git a/019type_abbreviations.cc b/019type_abbreviations.cc
index df797dfa..dfa214c9 100644
--- a/019type_abbreviations.cc
+++ b/019type_abbreviations.cc
@@ -50,7 +50,7 @@ void load_type_abbreviations(istream& in) {
     raise << "'type' conflict: '" << new_type_name << "' defined as both '" << names_to_string_without_quotes(get(Type_abbreviations, new_type_name)) << "' and '" << old << "'\n" << end();
     return;
   }
-  trace(9990, "type") << "alias " << new_type_name << " = " << old << end();
+  trace(100, "type") << "alias " << new_type_name << " = " << old << end();
   type_tree* old_type = new_type_tree(old);
   put(Type_abbreviations, new_type_name, old_type);
 }
@@ -168,17 +168,17 @@ void expand_type_abbreviations(const recipe_ordinal r) {
 }
 
 void expand_type_abbreviations(const recipe& caller) {
-  trace(9991, "transform") << "--- expand type abbreviations in recipe '" << caller.name << "'" << end();
+  trace(101, "transform") << "--- expand type abbreviations in recipe '" << caller.name << "'" << end();
   for (int i = 0;  i < SIZE(caller.steps);  ++i) {
     const instruction& inst = caller.steps.at(i);
-    trace(9991, "transform") << "instruction '" << to_original_string(inst) << end();
+    trace(102, "transform") << "instruction '" << to_original_string(inst) << end();
     for (long int i = 0;  i < SIZE(inst.ingredients);  ++i) {
       expand_type_abbreviations(inst.ingredients.at(i).type);
-      trace(9992, "transform") << "ingredient type after expanding abbreviations: " << names_to_string(inst.ingredients.at(i).type) << end();
+      trace(102, "transform") << "ingredient type after expanding abbreviations: " << names_to_string(inst.ingredients.at(i).type) << end();
     }
     for (long int i = 0;  i < SIZE(inst.products);  ++i) {
       expand_type_abbreviations(inst.products.at(i).type);
-      trace(9992, "transform") << "product type after expanding abbreviations: " << names_to_string(inst.products.at(i).type) << end();
+      trace(102, "transform") << "product type after expanding abbreviations: " << names_to_string(inst.products.at(i).type) << end();
     }
   }
   // End Expand Type Abbreviations(caller)
diff --git a/020run.cc b/020run.cc
index 74012216..5d466bbc 100644
--- a/020run.cc
+++ b/020run.cc
@@ -63,7 +63,7 @@ void run_current_routine() {
   while (should_continue_running(Current_routine)) {  // beware: may modify Current_routine
     // Running One Instruction
     if (current_instruction().is_label) { ++current_step_index();  continue; }
-    trace(Initial_callstack_depth + Trace_stream->callstack_depth, "run") << to_string(current_instruction()) << end();
+    trace(Callstack_depth, "run") << to_string(current_instruction()) << end();
 //?     if (Foo) cerr << "run: " << to_string(current_instruction()) << '\n';
     if (get_or_insert(Memory, 0) != 0) {
       raise << "something wrote to location 0; this should never happen\n" << end();
@@ -113,6 +113,26 @@ void run_current_routine() {
   stop_running_current_routine:;
 }
 
+//: Helpers for managing trace depths
+//:
+//: We're going to use trace depths primarily to segment code running at
+//: different frames of the call stack. This will make it easy for the trace
+//: browser to collapse over entire calls.
+//:
+//: The entire map of possible depths is as follows:
+//:
+//: Errors will be depth 0.
+//: Mu 'applications' will be able to use depths 1-99 as they like.
+//: Primitive statements will occupy 100 and up to Max_depth, organized by
+//: stack frames.
+:(before "End Globals")
+extern const int Initial_callstack_depth = 100;
+int Callstack_depth = Initial_callstack_depth;
+:(before "End Reset")
+Callstack_depth = Initial_callstack_depth;
+
+//: Other helpers for the VM.
+
 :(code)
 //: hook replaced in a later layer
 bool should_continue_running(const routine* current_routine) {
@@ -255,7 +275,7 @@ void load_file_or_directory(string filename) {
     cerr << "no such file '" << filename << "'\n" << end();  // don't raise, just warn. just in case it's just a name for a scenario to run.
     return;
   }
-  trace(9990, "load") << "=== " << filename << end();
+  trace(2, "load") << "=== " << filename << end();
   load(fin);
   fin.close();
 }
@@ -306,7 +326,7 @@ vector<double> read_memory(reagent/*copy*/ x) {
   int size = size_of(x);
   for (int offset = 0;  offset < size;  ++offset) {
     double val = get_or_insert(Memory, x.value+offset);
-    trace("mem") << "location " << x.value+offset << " is " << no_scientific(val) << end();
+    trace(Callstack_depth+1, "mem") << "location " << x.value+offset << " is " << no_scientific(val) << end();
     result.push_back(val);
   }
   return result;
@@ -333,7 +353,7 @@ void write_memory(reagent/*copy*/ x, const vector<double>& data) {
   // End write_memory(x) Special-cases
   for (int offset = 0;  offset < SIZE(data);  ++offset) {
     assert(x.value+offset > 0);
-    trace("mem") << "storing " << no_scientific(data.at(offset)) << " in location " << x.value+offset << end();
+    trace(Callstack_depth+1, "mem") << "storing " << no_scientific(data.at(offset)) << " in location " << x.value+offset << end();
 //?     if (Foo) cerr << "mem: storing " << no_scientific(data.at(offset)) << " in location " << x.value+offset << '\n';
     put(Memory, x.value+offset, data.at(offset));
   }
@@ -392,10 +412,7 @@ void run(const string& form) {
   vector<recipe_ordinal> tmp = load(form);
   transform_all();
   if (tmp.empty()) return;
-  if (trace_contains_errors()) {
-    if (Save_trace && Trace_stream) Trace_stream->save();
-    return;
-  }
+  if (trace_contains_errors()) return;
   // if a test defines main, it probably wants to start there regardless of
   // definition order
   if (contains_key(Recipe, get(Recipe_ordinal, "main")))
diff --git a/021check_instruction.cc b/021check_instruction.cc
index 6347dfb3..5bc7fa9c 100644
--- a/021check_instruction.cc
+++ b/021check_instruction.cc
@@ -13,7 +13,7 @@ Transform.push_back(check_instruction);  // idempotent
 
 :(code)
 void check_instruction(const recipe_ordinal r) {
-  trace(9991, "transform") << "--- perform checks for recipe " << get(Recipe, r).name << end();
+  trace(101, "transform") << "--- perform checks for recipe " << get(Recipe, r).name << end();
   map<string, vector<type_ordinal> > metadata;
   for (int i = 0;  i < SIZE(get(Recipe, r).steps);  ++i) {
     instruction& inst = get(Recipe, r).steps.at(i);
diff --git a/024jump.cc b/024jump.cc
index 14c14297..5b95fd19 100644
--- a/024jump.cc
+++ b/024jump.cc
@@ -33,7 +33,7 @@ case JUMP: {
 case JUMP: {
   assert(current_instruction().ingredients.at(0).initialized);
   current_step_index() += ingredients.at(0).at(0)+1;
-  trace(9998, "run") << "jumping to instruction " << current_step_index() << end();
+  trace(Callstack_depth+1, "run") << "jumping to instruction " << current_step_index() << end();
   // skip rest of this instruction
   write_products = false;
   fall_through_to_next_instruction = false;
@@ -91,11 +91,11 @@ case JUMP_IF: {
 case JUMP_IF: {
   assert(current_instruction().ingredients.at(1).initialized);
   if (!scalar_ingredient(ingredients, 0)) {
-    trace(9998, "run") << "jump-if fell through" << end();
+    trace(Callstack_depth+1, "run") << "jump-if fell through" << end();
     break;
   }
   current_step_index() += ingredients.at(1).at(0)+1;
-  trace(9998, "run") << "jumping to instruction " << current_step_index() << end();
+  trace(Callstack_depth+1, "run") << "jumping to instruction " << current_step_index() << end();
   // skip rest of this instruction
   write_products = false;
   fall_through_to_next_instruction = false;
@@ -162,11 +162,11 @@ case JUMP_UNLESS: {
 case JUMP_UNLESS: {
   assert(current_instruction().ingredients.at(1).initialized);
   if (scalar_ingredient(ingredients, 0)) {
-    trace(9998, "run") << "jump-unless fell through" << end();
+    trace(Callstack_depth+1, "run") << "jump-unless fell through" << end();
     break;
   }
   current_step_index() += ingredients.at(1).at(0)+1;
-  trace(9998, "run") << "jumping to instruction " << current_step_index() << end();
+  trace(Callstack_depth+1, "run") << "jumping to instruction " << current_step_index() << end();
   // skip rest of this instruction
   write_products = false;
   fall_through_to_next_instruction = false;
diff --git a/026call.cc b/026call.cc
index c6077cd9..1f130ef5 100644
--- a/026call.cc
+++ b/026call.cc
@@ -60,11 +60,9 @@ struct routine {
 };
 :(code)
 routine::routine(recipe_ordinal r) {
-  if (Trace_stream) {
-    ++Trace_stream->callstack_depth;
-    trace("trace") << "new routine; incrementing callstack depth to " << Trace_stream->callstack_depth << end();
-    assert(Trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
-  }
+  ++Callstack_depth;
+  trace(Callstack_depth+1, "trace") << "new routine; incrementing callstack depth to " << Callstack_depth << end();
+  assert(Callstack_depth < Max_depth);
   calls.push_front(call(r));
   // End routine Constructor
 }
@@ -151,11 +149,9 @@ if (!contains_key(Recipe, inst.operation)) {
 default: {
   if (contains_key(Recipe, current_instruction().operation)) {  // error already raised in Checks above
     // not a primitive; look up the book of recipes
-    if (Trace_stream) {
-      ++Trace_stream->callstack_depth;
-      trace("trace") << "incrementing callstack depth to " << Trace_stream->callstack_depth << end();
-      assert(Trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
-    }
+    ++Callstack_depth;
+    trace(Callstack_depth+1, "trace") << "incrementing callstack depth to " << Callstack_depth << end();
+    assert(Callstack_depth < Max_depth);
     const call& caller_frame = current_call();
     Current_routine->calls.push_front(call(to_instruction(caller_frame).operation));
     finish_call_housekeeping(to_instruction(caller_frame), ingredients);
@@ -202,11 +198,9 @@ const vector<instruction>& routine::steps() const {
 // it, and the one below that, and so on
 while (current_step_index() >= SIZE(Current_routine->steps())) {
   // Falling Through End Of Recipe
-  if (Trace_stream) {
-    trace("trace") << "fall-through: exiting " << current_recipe_name() << "; decrementing callstack depth from " << Trace_stream->callstack_depth << end();
-    --Trace_stream->callstack_depth;
-    assert(Trace_stream->callstack_depth >= 0);
-  }
+  trace(Callstack_depth+1, "trace") << "fall-through: exiting " << current_recipe_name() << "; decrementing callstack depth from " << Callstack_depth << end();
+  --Callstack_depth;
+  assert(Callstack_depth >= 0);
   Current_routine->calls.pop_front();
   if (Current_routine->calls.empty()) goto stop_running_current_routine;
   // Complete Call Fallthrough
diff --git a/028call_return.cc b/028call_return.cc
index c8c1bca6..af158884 100644
--- a/028call_return.cc
+++ b/028call_return.cc
@@ -37,19 +37,17 @@ case RETURN: {
 :(before "End Primitive Recipe Implementations")
 case RETURN: {
   // Begin Return
-  if (Trace_stream) {
-    trace("trace") << current_instruction().name << ": decrementing callstack depth from " << Trace_stream->callstack_depth << end();
-    --Trace_stream->callstack_depth;
-    if (Trace_stream->callstack_depth < 0) {
-      Current_routine->calls.clear();
-      goto stop_running_current_routine;
-    }
+  trace(Callstack_depth+1, "trace") << current_instruction().name << ": decrementing callstack depth from " << Callstack_depth << end();
+  --Callstack_depth;
+  if (Callstack_depth < 0) {
+    Current_routine->calls.clear();
+    goto stop_running_current_routine;
   }
   Current_routine->calls.pop_front();
   // just in case 'main' returns a value, drop it for now
   if (Current_routine->calls.empty()) goto stop_running_current_routine;
   for (int i = 0;  i < SIZE(ingredients);  ++i)
-    trace(9998, "run") << "result " << i << " is " << to_string(ingredients.at(i)) << end();
+    trace(Callstack_depth+1, "run") << "result " << i << " is " << to_string(ingredients.at(i)) << end();
   // make return products available to caller
   copy(ingredients.begin(), ingredients.end(), inserter(products, products.begin()));
   // End Return
diff --git a/029tools.cc b/029tools.cc
index be3c04e2..56ac861c 100644
--- a/029tools.cc
+++ b/029tools.cc
@@ -169,20 +169,6 @@ case _CLEAR_TRACE: {
   break;
 }
 
-:(before "End Primitive Recipe Declarations")
-_SAVE_TRACE,
-:(before "End Primitive Recipe Numbers")
-put(Recipe_ordinal, "$save-trace", _SAVE_TRACE);
-:(before "End Primitive Recipe Checks")
-case _SAVE_TRACE: {
-  break;
-}
-:(before "End Primitive Recipe Implementations")
-case _SAVE_TRACE: {
-  if (Save_trace) Trace_stream->save();
-  break;
-}
-
 //:: 'cheating' by using the host system
 
 :(before "End Primitive Recipe Declarations")
@@ -197,7 +183,7 @@ case _PRINT: {
 case _PRINT: {
   for (int i = 0;  i < SIZE(ingredients);  ++i) {
     if (is_literal(current_instruction().ingredients.at(i))) {
-      trace(9998, "run") << "$print: " << current_instruction().ingredients.at(i).name << end();
+      trace(Callstack_depth+1, "run") << "$print: " << current_instruction().ingredients.at(i).name << end();
       if (!has_property(current_instruction().ingredients.at(i), "newline")) {
         cout << current_instruction().ingredients.at(i).name;
       }
@@ -210,7 +196,7 @@ case _PRINT: {
     // End $print Special-cases
     else {
       for (int j = 0;  j < SIZE(ingredients.at(i));  ++j) {
-        trace(9998, "run") << "$print: " << ingredients.at(i).at(j) << end();
+        trace(Callstack_depth+1, "run") << "$print: " << ingredients.at(i).at(j) << end();
         if (j > 0) cout << " ";
         cout << no_scientific(ingredients.at(i).at(j));
       }
diff --git a/030container.cc b/030container.cc
index aff65a1d..ca2d6743 100644
--- a/030container.cc
+++ b/030container.cc
@@ -198,11 +198,11 @@ case GET: {
   int src = base_address;
   for (int i = 0; i < offset; ++i)
     src += size_of(element_type(base.type, i));
-  trace(9998, "run") << "address to copy is " << src << end();
+  trace(Callstack_depth+1, "run") << "address to copy is " << src << end();
   //: use base.type rather than base_type because later layers will introduce compound types
   reagent/*copy*/ element = element_type(base.type, offset);
   element.set_value(src);
-  trace(9998, "run") << "its type is " << names_to_string(element.type) << end();
+  trace(Callstack_depth+1, "run") << "its type is " << names_to_string(element.type) << end();
   // Read element
   products.push_back(read_memory(element));
   break;
@@ -355,13 +355,13 @@ case PUT: {
   int address = base_address;
   for (int i = 0; i < offset; ++i)
     address += size_of(element_type(base.type, i));
-  trace(9998, "run") << "address to copy to is " << address << end();
+  trace(Callstack_depth+1, "run") << "address to copy to is " << address << end();
   // optimization: directly write the element rather than updating 'product'
   // and writing the entire container
   // Write Memory in PUT in Run
   write_products = false;
   for (int i = 0;  i < SIZE(ingredients.at(2));  ++i) {
-    trace("mem") << "storing " << no_scientific(ingredients.at(2).at(i)) << " in location " << address+i << end();
+    trace(Callstack_depth+1, "mem") << "storing " << no_scientific(ingredients.at(2).at(i)) << " in location " << address+i << end();
     put(Memory, address+i, ingredients.at(2).at(i));
   }
   break;
@@ -452,12 +452,12 @@ void insert_container(const string& command, kind_of_type kind, istream& in) {
     return;
   }
   // End container Name Refinements
-  trace(9991, "parse") << "--- defining " << command << ' ' << name << end();
+  trace(101, "parse") << "--- defining " << command << ' ' << name << end();
   if (!contains_key(Type_ordinal, name)
       || get(Type_ordinal, name) == 0) {
     put(Type_ordinal, name, Next_type_ordinal++);
   }
-  trace("parse") << "type number: " << get(Type_ordinal, name) << end();
+  trace(102, "parse") << "type number: " << get(Type_ordinal, name) << end();
   skip_bracket(in, "'"+command+"' must begin with '['");
   type_info& info = get_or_insert(Type, get(Type_ordinal, name));
   if (info.Num_calls_to_transform_all_at_first_definition == -1) {
@@ -492,7 +492,7 @@ void insert_container(const string& command, kind_of_type kind, istream& in) {
     info.elements.push_back(reagent(element));
     expand_type_abbreviations(info.elements.back().type);  // todo: use abbreviation before declaration
     replace_unknown_types_with_unique_ordinals(info.elements.back().type, info);
-    trace(9993, "parse") << "  element: " << to_string(info.elements.back()) << end();
+    trace(103, "parse") << "  element: " << to_string(info.elements.back()) << end();
     // End Load Container Element Definition
   }
 }
@@ -602,7 +602,7 @@ Transform.push_back(check_or_set_invalid_types);  // idempotent
 :(code)
 void check_or_set_invalid_types(const recipe_ordinal r) {
   recipe& caller = get(Recipe, r);
-  trace(9991, "transform") << "--- check for invalid types in recipe " << caller.name << end();
+  trace(101, "transform") << "--- check for invalid types in recipe " << caller.name << end();
   for (int index = 0;  index < SIZE(caller.steps);  ++index) {
     instruction& inst = caller.steps.at(index);
     for (int i = 0;  i < SIZE(inst.ingredients);  ++i)
diff --git a/031merge.cc b/031merge.cc
index c56579a5..99b6846a 100644
--- a/031merge.cc
+++ b/031merge.cc
@@ -114,7 +114,7 @@ Transform.push_back(check_merge_calls);  // idempotent
 :(code)
 void check_merge_calls(const recipe_ordinal r) {
   const recipe& caller = get(Recipe, r);
-  trace(9991, "transform") << "--- type-check merge instructions in recipe " << caller.name << end();
+  trace(101, "transform") << "--- type-check merge instructions in recipe " << caller.name << end();
   for (int i = 0;  i < SIZE(caller.steps);  ++i) {
     const instruction& inst = caller.steps.at(i);
     if (inst.name != "merge") continue;
@@ -145,7 +145,7 @@ void check_merge_call(const vector<reagent>& ingredients, const reagent& product
   state.data.push(merge_check_point(product, 0));
   while (true) {
     assert(!state.data.empty());
-    trace("transform") << ingredient_index << " vs " << SIZE(ingredients) << end();
+    trace(102, "transform") << ingredient_index << " vs " << SIZE(ingredients) << end();
     if (ingredient_index >= SIZE(ingredients)) {
       raise << maybe(caller.name) << "too few ingredients in '" << to_original_string(inst) << "'\n" << end();
       return;
@@ -161,7 +161,7 @@ void check_merge_call(const vector<reagent>& ingredients, const reagent& product
         if (state.data.top().container_element_index == 0 && types_coercible(container, inst.ingredients.at(ingredient_index)))
           return;
         const reagent& expected_ingredient = element_type(container.type, state.data.top().container_element_index);
-        trace("transform") << "checking container " << to_string(container) << " || " << to_string(expected_ingredient) << " vs ingredient " << ingredient_index << end();
+        trace(102, "transform") << "checking container " << to_string(container) << " || " << to_string(expected_ingredient) << " vs ingredient " << ingredient_index << end();
         // if the current element is the ingredient we expect, move on to the next element/ingredient
         if (types_coercible(expected_ingredient, ingredients.at(ingredient_index))) {
           ++ingredient_index;
diff --git a/032array.cc b/032array.cc
index 25d91b60..7f36411f 100644
--- a/032array.cc
+++ b/032array.cc
@@ -57,10 +57,10 @@ case CREATE_ARRAY: {
     array_length_from_type = array_length_from_type->left;
   int array_length = to_integer(array_length_from_type->name);
   // initialize array length, so that size_of will work
-  trace("mem") << "storing " << array_length << " in location " << base_address << end();
+  trace(Callstack_depth+1, "mem") << "storing " << array_length << " in location " << base_address << end();
   put(Memory, base_address, array_length);  // in array elements
   int size = size_of(product);  // in locations
-  trace(9998, "run") << "creating array from " << size << " locations" << end();
+  trace(Callstack_depth+1, "run") << "creating array from " << size << " locations" << end();
   // initialize array
   for (int i = 1;  i <= size_of(product);  ++i)
     put(Memory, base_address+i, 0);
@@ -274,7 +274,7 @@ case INDEX: {
   reagent/*copy*/ base = current_instruction().ingredients.at(0);
   // Update INDEX base in Run
   int base_address = base.value;
-  trace(9998, "run") << "base address is " << base_address << end();
+  trace(Callstack_depth+1, "run") << "base address is " << base_address << end();
   if (base_address == 0) {
     raise << maybe(current_recipe_name()) << "tried to access location 0 in '" << to_original_string(current_instruction()) << "'\n" << end();
     break;
@@ -288,8 +288,8 @@ case INDEX: {
   }
   reagent/*local*/ element(copy_array_element(base.type));
   element.set_value(base_address + /*skip length*/1 + index_val.at(0)*size_of(element.type));
-  trace(9998, "run") << "address to copy is " << element.value << end();
-  trace(9998, "run") << "its type is " << to_string(element.type) << end();
+  trace(Callstack_depth+1, "run") << "address to copy is " << element.value << end();
+  trace(Callstack_depth+1, "run") << "its type is " << to_string(element.type) << end();
   // Read element
   products.push_back(read_memory(element));
   break;
@@ -451,14 +451,14 @@ case PUT_INDEX: {
     break;
   }
   int address = base_address + /*skip length*/1 + index_val.at(0)*size_of(array_element(base.type));
-  trace(9998, "run") << "address to copy to is " << address << end();
+  trace(Callstack_depth+1, "run") << "address to copy to is " << address << end();
   // optimization: directly write the element rather than updating 'product'
   // and writing the entire array
   write_products = false;
   vector<double> value = read_memory(current_instruction().ingredients.at(2));
   // Write Memory in PUT_INDEX in Run
   for (int i = 0;  i < SIZE(value);  ++i) {
-    trace("mem") << "storing " << no_scientific(value.at(i)) << " in location " << address+i << end();
+    trace(Callstack_depth+1, "mem") << "storing " << no_scientific(value.at(i)) << " in location " << address+i << end();
     put(Memory, address+i, value.at(i));
   }
   break;
diff --git a/033exclusive_container.cc b/033exclusive_container.cc
index c2d69f60..5c57972e 100644
--- a/033exclusive_container.cc
+++ b/033exclusive_container.cc
@@ -150,19 +150,19 @@ case MAYBE_CONVERT: {
   write_products = false;
   if (tag == static_cast<int>(get_or_insert(Memory, base_address))) {
     const reagent& variant = variant_type(base, tag);
-    trace("mem") << "storing 1 in location " << status.value << end();
+    trace(Callstack_depth+1, "mem") << "storing 1 in location " << status.value << end();
     put(Memory, status.value, 1);
     if (!is_dummy(product)) {
       // Write Memory in Successful MAYBE_CONVERT in Run
       for (int i = 0;  i < size_of(variant);  ++i) {
         double val = get_or_insert(Memory, base_address+/*skip tag*/1+i);
-        trace("mem") << "storing " << no_scientific(val) << " in location " << product.value+i << end();
+        trace(Callstack_depth+1, "mem") << "storing " << no_scientific(val) << " in location " << product.value+i << end();
         put(Memory, product.value+i, val);
       }
     }
   }
   else {
-    trace("mem") << "storing 0 in location " << status.value << end();
+    trace(Callstack_depth+1, "mem") << "storing 0 in location " << status.value << end();
     put(Memory, status.value, 0);
   }
   break;
@@ -305,7 +305,7 @@ $error: 0
 :(before "End check_merge_call Special-cases")
 case EXCLUSIVE_CONTAINER: {
   assert(state.data.top().container_element_index == 0);
-  trace("transform") << "checking exclusive container " << to_string(container) << " vs ingredient " << ingredient_index << end();
+  trace(102, "transform") << "checking exclusive container " << to_string(container) << " vs ingredient " << ingredient_index << end();
   // easy case: exact match
   if (types_strictly_match(container, inst.ingredients.at(ingredient_index)))
     return;
@@ -320,7 +320,7 @@ case EXCLUSIVE_CONTAINER: {
     return;
   }
   const reagent& variant = variant_type(container, ingredient.value);
-  trace("transform") << "tag: " << ingredient.value << end();
+  trace(102, "transform") << "tag: " << ingredient.value << end();
   // replace union with its variant
   state.data.pop();
   state.data.push(merge_check_point(variant, 0));
diff --git a/034address.cc b/034address.cc
index a71f5194..af98fc14 100644
--- a/034address.cc
+++ b/034address.cc
@@ -215,7 +215,7 @@ Transform.push_back(transform_new_to_allocate);  // idempotent
 
 :(code)
 void transform_new_to_allocate(const recipe_ordinal r) {
-  trace(9991, "transform") << "--- convert 'new' to 'allocate' for recipe " << get(Recipe, r).name << end();
+  trace(101, "transform") << "--- convert 'new' to 'allocate' for recipe " << get(Recipe, r).name << end();
   for (int i = 0;  i < SIZE(get(Recipe, r).steps);  ++i) {
     instruction& inst = get(Recipe, r).steps.at(i);
     // Convert 'new' To 'allocate'
@@ -224,7 +224,7 @@ void transform_new_to_allocate(const recipe_ordinal r) {
       inst.operation = ALLOCATE;
       type_tree* type = new_type_tree(inst.ingredients.at(0).name);
       inst.ingredients.at(0).set_value(size_of(type));
-      trace(9992, "new") << "size of '" << inst.ingredients.at(0).name << "' is " << inst.ingredients.at(0).value << end();
+      trace(102, "new") << "size of '" << inst.ingredients.at(0).name << "' is " << inst.ingredients.at(0).value << end();
       delete type;
     }
   }
@@ -245,7 +245,7 @@ int alloc, alloc_max;
 alloc = Memory_allocated_until;
 Memory_allocated_until += Initial_memory_per_routine;
 alloc_max = Memory_allocated_until;
-trace("new") << "routine allocated memory from " << alloc << " to " << alloc_max << end();
+trace(Callstack_depth+1, "new") << "routine allocated memory from " << alloc << " to " << alloc_max << end();
 
 :(before "End Primitive Recipe Declarations")
 ALLOCATE,
@@ -259,16 +259,16 @@ case ALLOCATE: {
   Next_alloc_id++;
   if (SIZE(ingredients) > 1) {
     // array allocation
-    trace("mem") << "array length is " << ingredients.at(1).at(0) << end();
+    trace(Callstack_depth+1, "mem") << "array length is " << ingredients.at(1).at(0) << end();
     size = /*space for length*/1 + size*ingredients.at(1).at(0);
   }
   int result = allocate(size);
   // initialize alloc-id in payload
-  trace("mem") << "storing alloc-id " << alloc_id << " in location " << result << end();
+  trace(Callstack_depth+1, "mem") << "storing alloc-id " << alloc_id << " in location " << result << end();
   put(Memory, result, alloc_id);
   if (SIZE(current_instruction().ingredients) > 1) {
     // initialize array length
-    trace("mem") << "storing array length " << ingredients.at(1).at(0) << " in location " << result+/*skip alloc id*/1 << end();
+    trace(Callstack_depth+1, "mem") << "storing array length " << ingredients.at(1).at(0) << " in location " << result+/*skip alloc id*/1 << end();
     put(Memory, result+/*skip alloc id*/1, ingredients.at(1).at(0));
   }
   products.resize(1);
@@ -280,7 +280,7 @@ case ALLOCATE: {
 int allocate(int size) {
   // include space for alloc id
   ++size;
-  trace("mem") << "allocating size " << size << end();
+  trace(Callstack_depth+1, "mem") << "allocating size " << size << end();
 //?   Total_alloc += size;
 //?   ++Num_alloc;
   // Allocate Special-cases
@@ -288,10 +288,10 @@ int allocate(int size) {
   // really crappy at the moment
   ensure_space(size);
   const int result = Current_routine->alloc;
-  trace("mem") << "new alloc: " << result << end();
+  trace(Callstack_depth+1, "mem") << "new alloc: " << result << end();
   // initialize allocated space
   for (int address = result;  address < result+size;  ++address) {
-    trace("mem") << "storing 0 in location " << address << end();
+    trace(Callstack_depth+1, "mem") << "storing 0 in location " << address << end();
     put(Memory, address, 0);
   }
   Current_routine->alloc += size;
@@ -325,7 +325,7 @@ void ensure_space(int size) {
     Current_routine->alloc = Memory_allocated_until;
     Memory_allocated_until += Initial_memory_per_routine;
     Current_routine->alloc_max = Memory_allocated_until;
-    trace("new") << "routine allocated memory from " << Current_routine->alloc << " to " << Current_routine->alloc_max << end();
+    trace(Callstack_depth+1, "new") << "routine allocated memory from " << Current_routine->alloc << " to " << Current_routine->alloc_max << end();
   }
 }
 
diff --git a/035lookup.cc b/035lookup.cc
index 02c2ab3f..b7c05201 100644
--- a/035lookup.cc
+++ b/035lookup.cc
@@ -88,7 +88,7 @@ void lookup_memory(reagent& x) {
 void lookup_memory_core(reagent& x, bool check_for_null) {
   double address = x.value + /*skip alloc id in address*/1;
   double new_value = get_or_insert(Memory, address);
-  trace("mem") << "location " << address << " contains " << no_scientific(new_value) << end();
+  trace(Callstack_depth+1, "mem") << "location " << address << " contains " << no_scientific(new_value) << end();
   // check for null
   if (check_for_null && new_value == 0) {
     if (Current_routine) {
diff --git a/036abandon.cc b/036abandon.cc
index c2b9125e..4dcf572f 100644
--- a/036abandon.cc
+++ b/036abandon.cc
@@ -67,7 +67,7 @@ void abandon(int address, int payload_size) {
   for (int curr = address+1;  curr < address+payload_size;  ++curr)
     put(Memory, curr, 0);
   // append existing free list to address
-  trace("abandon") << "saving " << address << " in free-list of size " << payload_size << end();
+  trace(Callstack_depth+1, "abandon") << "saving " << address << " in free-list of size " << payload_size << end();
   put(Memory, address+/*skip invalid alloc-id*/1, get_or_insert(Current_routine->free_list, payload_size));
   put(Current_routine->free_list, payload_size, address);
 }
@@ -80,9 +80,9 @@ int payload_size(reagent/*copy*/ x) {
 
 :(after "Allocate Special-cases")
 if (get_or_insert(Current_routine->free_list, size)) {
-  trace("abandon") << "picking up space from free-list of size " << size << end();
+  trace(Callstack_depth+1, "abandon") << "picking up space from free-list of size " << size << end();
   int result = get_or_insert(Current_routine->free_list, size);
-  trace("mem") << "new alloc from free list: " << result << end();
+  trace(Callstack_depth+1, "mem") << "new alloc from free list: " << result << end();
   put(Current_routine->free_list, size, get_or_insert(Memory, result+/*skip alloc id*/1));
   // clear 'deleted' tag
   put(Memory, result, 0);
diff --git a/038new_text.cc b/038new_text.cc
index 7e3c02f6..10b819a3 100644
--- a/038new_text.cc
+++ b/038new_text.cc
@@ -31,7 +31,7 @@ if (inst.name == "new" && !inst.ingredients.empty() && is_literal_text(inst.ingr
     products.resize(1);
     products.at(0).push_back(/*alloc id*/0);
     products.at(0).push_back(new_mu_text(current_instruction().ingredients.at(0).name));
-    trace("mem") << "new string alloc: " << products.at(0).at(0) << end();
+    trace(Callstack_depth+1, "mem") << "new string alloc: " << products.at(0).at(0) << end();
     break;
   }
 
@@ -44,7 +44,7 @@ int new_mu_text(const string& contents) {
   int result = allocate(/*array length*/1 + string_length);
   int curr_address = result;
   ++curr_address;  // skip alloc id
-  trace("mem") << "storing string length " << string_length << " in location " << curr_address << end();
+  trace(Callstack_depth+1, "mem") << "storing string length " << string_length << " in location " << curr_address << end();
   put(Memory, curr_address, string_length);
   ++curr_address;  // skip length
   int curr = 0;
@@ -53,7 +53,7 @@ int new_mu_text(const string& contents) {
     uint32_t curr_character;
     assert(curr < SIZE(contents));
     tb_utf8_char_to_unicode(&curr_character, &raw_contents[curr]);
-    trace("mem") << "storing string character " << curr_character << " in location " << curr_address << end();
+    trace(Callstack_depth+1, "mem") << "storing string character " << curr_character << " in location " << curr_address << end();
     put(Memory, curr_address, curr_character);
     curr += tb_utf8_char_length(raw_contents[curr]);
     ++curr_address;
diff --git a/040brace.cc b/040brace.cc
index b3006456..8eead4ab 100644
--- a/040brace.cc
+++ b/040brace.cc
@@ -39,15 +39,15 @@ void transform_braces(const recipe_ordinal r) {
   const bool OPEN = false, CLOSE = true;
   // use signed integer for step index because we'll be doing arithmetic on it
   list<pair<bool/*OPEN/CLOSE*/, /*step*/int> > braces;
-  trace(9991, "transform") << "--- transform braces for recipe " << get(Recipe, r).name << end();
+  trace(101, "transform") << "--- transform braces for recipe " << get(Recipe, r).name << end();
   for (int index = 0;  index < SIZE(get(Recipe, r).steps);  ++index) {
     const instruction& inst = get(Recipe, r).steps.at(index);
     if (inst.label == "{") {
-      trace(9993, "transform") << maybe(get(Recipe, r).name) << "push (open, " << index << ")" << end();
+      trace(103, "transform") << maybe(get(Recipe, r).name) << "push (open, " << index << ")" << end();
       braces.push_back(pair<bool,int>(OPEN, index));
     }
     if (inst.label == "}") {
-      trace(9993, "transform") << "push (close, " << index << ")" << end();
+      trace(103, "transform") << "push (close, " << index << ")" << end();
       braces.push_back(pair<bool,int>(CLOSE, index));
     }
   }
@@ -73,7 +73,7 @@ void transform_braces(const recipe_ordinal r) {
          && inst.name != "break"
          && inst.name != "break-if"
          && inst.name != "break-unless") {
-      trace(9992, "transform") << inst.name << " ..." << end();
+      trace(102, "transform") << inst.name << " ..." << end();
       continue;
     }
     // check for errors
@@ -101,14 +101,14 @@ void transform_braces(const recipe_ordinal r) {
     if (inst.name.find("-if") != string::npos || inst.name.find("-unless") != string::npos) {
       // conditional branches check arg 1
       if (SIZE(inst.ingredients) > 1 && is_literal(inst.ingredients.at(1))) {
-        trace(9992, "transform") << inst.name << ' ' << inst.ingredients.at(1).name << ":offset" << end();
+        trace(102, "transform") << inst.name << ' ' << inst.ingredients.at(1).name << ":offset" << end();
         continue;
       }
     }
     else {
       // unconditional branches check arg 0
       if (!inst.ingredients.empty() && is_literal(inst.ingredients.at(0))) {
-        trace(9992, "transform") << "jump " << inst.ingredients.at(0).name << ":offset" << end();
+        trace(102, "transform") << "jump " << inst.ingredients.at(0).name << ":offset" << end();
         continue;
       }
     }
@@ -124,9 +124,9 @@ void transform_braces(const recipe_ordinal r) {
     inst.ingredients.push_back(target);
     // log computed target
     if (inst.name == "jump")
-      trace(9992, "transform") << "jump " << no_scientific(target.value) << ":offset" << end();
+      trace(102, "transform") << "jump " << no_scientific(target.value) << ":offset" << end();
     else
-      trace(9992, "transform") << inst.name << ' ' << inst.ingredients.at(0).name << ", " << no_scientific(target.value) << ":offset" << end();
+      trace(102, "transform") << inst.name << ' ' << inst.ingredients.at(0).name << ", " << no_scientific(target.value) << ":offset" << end();
   }
 }
 
diff --git a/042name.cc b/042name.cc
index 88343495..5846b5b4 100644
--- a/042name.cc
+++ b/042name.cc
@@ -36,7 +36,7 @@ Name = Name_snapshot;
 :(code)
 void transform_names(const recipe_ordinal r) {
   recipe& caller = get(Recipe, r);
-  trace(9991, "transform") << "--- transform names for recipe " << caller.name << end();
+  trace(101, "transform") << "--- transform names for recipe " << caller.name << end();
   bool names_used = false;
   bool numeric_locations_used = false;
   map<string, int>& names = Name[r];
@@ -78,7 +78,7 @@ void transform_names(const recipe_ordinal r) {
       if (is_named_location(product)) names_used = true;
       if (is_integer(product.name)) continue;
       if (names.find(product.name) == names.end()) {
-        trace(9993, "name") << "assign " << product.name << " " << curr_idx << end();
+        trace(103, "name") << "assign " << product.name << " " << curr_idx << end();
         names[product.name] = curr_idx;
         curr_idx += size_of(product);
       }
@@ -282,7 +282,7 @@ if (inst.name == "get" || inst.name == "get-location" || inst.name == "put") {
     type_ordinal base_type = skip_addresses(inst.ingredients.at(0).type);
     if (contains_key(Type, base_type)) {  // otherwise we'll raise an error elsewhere
       inst.ingredients.at(1).set_value(find_element_offset(base_type, inst.ingredients.at(1).name, get(Recipe, r).name));
-      trace(9993, "name") << "element " << inst.ingredients.at(1).name << " of type " << get(Type, base_type).name << " is at offset " << no_scientific(inst.ingredients.at(1).value) << end();
+      trace(103, "name") << "element " << inst.ingredients.at(1).name << " of type " << get(Type, base_type).name << " is at offset " << no_scientific(inst.ingredients.at(1).value) << end();
     }
   }
 }
@@ -330,7 +330,7 @@ if (inst.name == "maybe-convert") {
     type_ordinal base_type = skip_addresses(inst.ingredients.at(0).type);
     if (contains_key(Type, base_type)) {  // otherwise we'll raise an error elsewhere
       inst.ingredients.at(1).set_value(find_element_offset(base_type, inst.ingredients.at(1).name, get(Recipe, r).name));
-      trace(9993, "name") << "variant " << inst.ingredients.at(1).name << " of type " << get(Type, base_type).name << " has tag " << no_scientific(inst.ingredients.at(1).value) << end();
+      trace(103, "name") << "variant " << inst.ingredients.at(1).name << " of type " << get(Type, base_type).name << " has tag " << no_scientific(inst.ingredients.at(1).value) << end();
     }
   }
 }
diff --git a/043space.cc b/043space.cc
index d348f736..6028ef0d 100644
--- a/043space.cc
+++ b/043space.cc
@@ -264,7 +264,7 @@ void check_default_space(const recipe_ordinal r) {
   // End check_default_space Special-cases
   // assume recipes with only numeric addresses know what they're doing (usually tests)
   if (!contains_non_special_name(r)) return;
-  trace(9991, "transform") << "--- check that recipe " << caller.name << " sets default-space" << end();
+  trace(101, "transform") << "--- check that recipe " << caller.name << " sets default-space" << end();
   if (caller.steps.empty()) return;
   if (!starts_by_setting_default_space(caller))
     raise << caller.name << " does not seem to start with 'local-scope' or 'default-space'\n" << end();
diff --git a/045closure_name.cc b/045closure_name.cc
index 6b2defd3..b4a8ea24 100644
--- a/045closure_name.cc
+++ b/045closure_name.cc
@@ -42,7 +42,7 @@ Transform.push_back(collect_surrounding_spaces);  // idempotent
 
 :(code)
 void collect_surrounding_spaces(const recipe_ordinal r) {
-  trace(9991, "transform") << "--- collect surrounding spaces for recipe " << get(Recipe, r).name << end();
+  trace(101, "transform") << "--- collect surrounding spaces for recipe " << get(Recipe, r).name << end();
   for (int i = 0;  i < SIZE(get(Recipe, r).steps);  ++i) {
     const instruction& inst = get(Recipe, r).steps.at(i);
     if (inst.is_label) continue;
@@ -69,7 +69,7 @@ void collect_surrounding_spaces(const recipe_ordinal r) {
         raise << "recipe '" << get(Recipe, r).name << "' can have only one 'surrounding' recipe but has '" << get(Recipe, get(Surrounding_space, r)).name << "' and '" << surrounding_recipe_name << "'\n" << end();
         continue;
       }
-      trace(9993, "name") << "lexically surrounding space for recipe " << get(Recipe, r).name << " comes from " << surrounding_recipe_name << end();
+      trace(103, "name") << "lexically surrounding space for recipe " << get(Recipe, r).name << " comes from " << surrounding_recipe_name << end();
       if (!contains_key(Recipe_ordinal, surrounding_recipe_name)) {
         raise << "can't find recipe providing surrounding space for '" << get(Recipe, r).name << "'; looking for '" << surrounding_recipe_name << "'\n" << end();
         continue;
diff --git a/046check_type_by_name.cc b/046check_type_by_name.cc
index ba40f521..6042068a 100644
--- a/046check_type_by_name.cc
+++ b/046check_type_by_name.cc
@@ -34,7 +34,7 @@ struct name_lt {
 :(code)
 void check_or_set_types_by_name(const recipe_ordinal r) {
   recipe& caller = get(Recipe, r);
-  trace(9991, "transform") << "--- deduce types for recipe " << caller.name << end();
+  trace(101, "transform") << "--- deduce types for recipe " << caller.name << end();
   for (int i = 0;  i < SIZE(caller.steps);  ++i) {
     instruction& inst = caller.steps.at(i);
     for (int in = 0;  in < SIZE(inst.ingredients);  ++in)
@@ -62,7 +62,7 @@ void deduce_missing_type(set<reagent, name_lt>& known_types, reagent& x, const r
   if (known_types.find(x) == known_types.end()) return;
   const reagent& exemplar = *known_types.find(x);
   x.type = new type_tree(*exemplar.type);
-  trace(9992, "transform") << x.name << " <= " << names_to_string(x.type) << end();
+  trace(102, "transform") << x.name << " <= " << names_to_string(x.type) << end();
   // spaces are special; their type includes their /names property
   if (is_mu_space(x) && !has_property(x, "names")) {
     if (!has_property(exemplar, "names")) {
@@ -82,7 +82,7 @@ void check_type(set<reagent, name_lt>& known_types, const reagent& x, const reci
     return;
   }
   if (known_types.find(x) == known_types.end()) {
-    trace(9992, "transform") << x.name << " => " << names_to_string(x.type) << end();
+    trace(102, "transform") << x.name << " => " << names_to_string(x.type) << end();
     known_types.insert(x);
   }
   if (!types_strictly_match(known_types.find(x)->type, x.type)) {
diff --git a/050scenario.cc b/050scenario.cc
index 791ac38a..4a4c9315 100644
--- a/050scenario.cc
+++ b/050scenario.cc
@@ -225,7 +225,6 @@ void run_mu_scenario(const scenario& s) {
   if (!Hide_errors && trace_contains_errors() && !Scenario_testing_scenario)
     Passed = false;
   if (not_already_inside_test && Trace_stream) {
-    if (Save_trace) Trace_stream->save();
     delete Trace_stream;
     Trace_stream = NULL;
   }
@@ -423,7 +422,7 @@ void check_memory(const string& s) {
     double value = to_double(rhs);
     if (contains_key(locations_checked, address))
       raise << maybe(current_recipe_name()) << "duplicate expectation for location '" << address << "'\n" << end();
-    trace("run") << "checking location " << address << end();
+    trace(Callstack_depth+1, "run") << "checking location " << address << end();
     if (get_or_insert(Memory, address) != value) {
       if (!Hide_errors) cerr << '\n';
       raise << "F - " << maybe(current_recipe_name()) << "expected location '" << address << "' to contain " << no_scientific(value) << " but saw " << no_scientific(get_or_insert(Memory, address)) << '\n' << end();
@@ -469,7 +468,7 @@ void check_type(const string& lhs, istream& in) {
 }
 
 void check_mu_text(int start, const string& literal) {
-  trace("run") << "checking text length at " << start << end();
+  trace(Callstack_depth+1, "run") << "checking text length at " << start << end();
   int array_length = static_cast<int>(get_or_insert(Memory, start));
   if (array_length != SIZE(literal)) {
     if (!Hide_errors) cerr << '\n';
@@ -479,7 +478,7 @@ void check_mu_text(int start, const string& literal) {
   }
   int curr = start+1;  // now skip length
   for (int i = 0;  i < SIZE(literal);  ++i) {
-    trace("run") << "checking location " << curr+i << end();
+    trace(Callstack_depth+1, "run") << "checking location " << curr+i << end();
     if (get_or_insert(Memory, curr+i) != literal.at(i)) {
       if (!Hide_errors) cerr << '\n';
       raise << "F - " << maybe(current_recipe_name()) << "expected location " << (curr+i) << " to contain " << literal.at(i) << " but saw " << no_scientific(get_or_insert(Memory, curr+i)) << '\n' << end();
@@ -620,16 +619,18 @@ void check_trace(const string& expected) {
 vector<trace_line> parse_trace(const string& expected) {
   vector<string> buf = split(expected, "\n");
   vector<trace_line> result;
+  const string separator = ": ";
   for (int i = 0;  i < SIZE(buf);  ++i) {
     buf.at(i) = trim(buf.at(i));
     if (buf.at(i).empty()) continue;
-    int delim = buf.at(i).find(": ");
+    int delim = buf.at(i).find(separator);
     if (delim == -1) {
       raise << maybe(current_recipe_name()) << "lines in 'trace-should-contain' should be of the form <label>: <contents>. Both parts are required.\n" << end();
       result.clear();
       return result;
     }
-    result.push_back(trace_line(trim(buf.at(i).substr(0, delim)),  trim(buf.at(i).substr(delim+2))));
+    result.push_back(trace_line(/*contents*/  trim(buf.at(i).substr(delim+SIZE(separator)        )),
+                                /*label*/     trim(buf.at(i).substr(0,                      delim))));
   }
   return result;
 }
diff --git a/052tangle.cc b/052tangle.cc
index 909fc9f7..d7d1ccc3 100644
--- a/052tangle.cc
+++ b/052tangle.cc
@@ -90,7 +90,7 @@ void insert_fragments(const recipe_ordinal r) {
 }
 
 void insert_fragments(recipe& r) {
-  trace(9991, "transform") << "--- insert fragments into recipe " << r.name << end();
+  trace(101, "transform") << "--- insert fragments into recipe " << r.name << end();
   bool made_progress = true;
   int pass = 0;
   while (made_progress) {
@@ -111,12 +111,12 @@ void insert_fragments(recipe& r) {
       // ok to use contains_key even though Before_fragments uses [],
       // because appending an empty recipe is a noop
       if (contains_key(Before_fragments, inst.label)) {
-        trace(9992, "transform") << "insert fragments before label " << inst.label << end();
+        trace(102, "transform") << "insert fragments before label " << inst.label << end();
         append_fragment(result, Before_fragments[inst.label].steps, prefix.str());
       }
       result.push_back(inst);
       if (contains_key(After_fragments, inst.label)) {
-        trace(9992, "transform") << "insert fragments after label " << inst.label << end();
+        trace(102, "transform") << "insert fragments after label " << inst.label << end();
         append_fragment(result, After_fragments[inst.label].steps, prefix.str());
       }
     }
diff --git a/053recipe_header.cc b/053recipe_header.cc
index e299d3c0..5102f690 100644
--- a/053recipe_header.cc
+++ b/053recipe_header.cc
@@ -24,7 +24,7 @@ has_header = false;
 
 :(before "End Recipe Refinements")
 if (in.peek() != '[') {
-  trace("parse") << "recipe has a header; parsing" << end();
+  trace(101, "parse") << "recipe has a header; parsing" << end();
   load_recipe_header(in, result);
 }
 
@@ -42,7 +42,7 @@ void load_recipe_header(istream& in, recipe& result) {
       raise << "recipe " << result.name << " should say '->' and not '<-'\n" << end();
     if (s == "->") break;
     result.ingredients.push_back(reagent(s));
-    trace("parse") << "header ingredient: " << result.ingredients.back().original_string << end();
+    trace(101, "parse") << "header ingredient: " << result.ingredients.back().original_string << end();
     skip_whitespace_but_not_newline(in);
   }
   while (has_data(in) && in.peek() != '[' && in.peek() != '\n') {
@@ -53,7 +53,7 @@ void load_recipe_header(istream& in, recipe& result) {
       return;
     }
     result.products.push_back(reagent(s));
-    trace("parse") << "header product: " << result.products.back().original_string << end();
+    trace(101, "parse") << "header product: " << result.products.back().original_string << end();
     skip_whitespace_but_not_newline(in);
   }
   // End Load Recipe Header(result)
@@ -149,7 +149,7 @@ if (!result.has_header) {
   }
 }
 if (result.has_header) {
-  trace("parse") << "recipe " << result.name << " has a header" << end();
+  trace(101, "parse") << "recipe " << result.name << " has a header" << end();
 }
 
 //: Support type abbreviations in headers.
@@ -288,7 +288,7 @@ Transform.push_back(check_calls_against_header);  // idempotent
 :(code)
 void check_calls_against_header(const recipe_ordinal r) {
   const recipe& caller = get(Recipe, r);
-  trace(9991, "transform") << "--- type-check calls inside recipe " << caller.name << end();
+  trace(101, "transform") << "--- type-check calls inside recipe " << caller.name << end();
   for (int i = 0;  i < SIZE(caller.steps);  ++i) {
     const instruction& inst = caller.steps.at(i);
     if (is_primitive(inst.operation)) continue;
@@ -332,7 +332,7 @@ Transform.push_back(check_return_instructions_against_header);  // idempotent
 void check_return_instructions_against_header(const recipe_ordinal r) {
   const recipe& caller_recipe = get(Recipe, r);
   if (!caller_recipe.has_header) return;
-  trace(9991, "transform") << "--- checking return instructions against header for " << caller_recipe.name << end();
+  trace(101, "transform") << "--- checking return instructions against header for " << caller_recipe.name << end();
   for (int i = 0;  i < SIZE(caller_recipe.steps);  ++i) {
     const instruction& inst = caller_recipe.steps.at(i);
     if (inst.name != "reply" && inst.name != "return") continue;
@@ -403,7 +403,7 @@ Transform.push_back(check_header_ingredients);  // idempotent
 void check_header_ingredients(const recipe_ordinal r) {
   recipe& caller_recipe = get(Recipe, r);
   caller_recipe.ingredient_index.clear();
-  trace(9991, "transform") << "--- checking return instructions against header for " << caller_recipe.name << end();
+  trace(101, "transform") << "--- checking return instructions against header for " << caller_recipe.name << end();
   for (int i = 0;  i < SIZE(caller_recipe.ingredients);  ++i) {
     if (caller_recipe.ingredients.at(i).type == NULL)
       raise << maybe(caller_recipe.name) << "ingredient '" << caller_recipe.ingredients.at(i).name << "' has no type\n" << end();
@@ -435,37 +435,37 @@ Transform.push_back(deduce_types_from_header);  // idempotent
 void deduce_types_from_header(const recipe_ordinal r) {
   recipe& caller_recipe = get(Recipe, r);
   if (caller_recipe.products.empty()) return;
-  trace(9991, "transform") << "--- deduce types from header for " << caller_recipe.name << end();
+  trace(101, "transform") << "--- deduce types from header for " << caller_recipe.name << end();
   map<string, const type_tree*> header_type;
   for (int i = 0;  i < SIZE(caller_recipe.ingredients);  ++i) {
     if (!caller_recipe.ingredients.at(i).type) continue;  // error handled elsewhere
     put(header_type, caller_recipe.ingredients.at(i).name, caller_recipe.ingredients.at(i).type);
-    trace(9993, "transform") << "type of " << caller_recipe.ingredients.at(i).name << " is " << names_to_string(caller_recipe.ingredients.at(i).type) << end();
+    trace(103, "transform") << "type of " << caller_recipe.ingredients.at(i).name << " is " << names_to_string(caller_recipe.ingredients.at(i).type) << end();
   }
   for (int i = 0;  i < SIZE(caller_recipe.products);  ++i) {
     if (!caller_recipe.products.at(i).type) continue;  // error handled elsewhere
     put(header_type, caller_recipe.products.at(i).name, caller_recipe.products.at(i).type);
-    trace(9993, "transform") << "type of " << caller_recipe.products.at(i).name << " is " << names_to_string(caller_recipe.products.at(i).type) << end();
+    trace(103, "transform") << "type of " << caller_recipe.products.at(i).name << " is " << names_to_string(caller_recipe.products.at(i).type) << end();
   }
   for (int i = 0;  i < SIZE(caller_recipe.steps);  ++i) {
     instruction& inst = caller_recipe.steps.at(i);
-    trace(9992, "transform") << "instruction: " << to_string(inst) << end();
+    trace(102, "transform") << "instruction: " << to_string(inst) << end();
     for (int i = 0;  i < SIZE(inst.ingredients);  ++i) {
       if (inst.ingredients.at(i).type) continue;
       if (header_type.find(inst.ingredients.at(i).name) == header_type.end())
         continue;
       if (!contains_key(header_type, inst.ingredients.at(i).name)) continue;  // error handled elsewhere
       inst.ingredients.at(i).type = new type_tree(*get(header_type, inst.ingredients.at(i).name));
-      trace(9993, "transform") << "type of " << inst.ingredients.at(i).name << " is " << names_to_string(inst.ingredients.at(i).type) << end();
+      trace(103, "transform") << "type of " << inst.ingredients.at(i).name << " is " << names_to_string(inst.ingredients.at(i).type) << end();
     }
     for (int i = 0;  i < SIZE(inst.products);  ++i) {
-      trace(9993, "transform") << "  product: " << to_string(inst.products.at(i)) << end();
+      trace(103, "transform") << "  product: " << to_string(inst.products.at(i)) << end();
       if (inst.products.at(i).type) continue;
       if (header_type.find(inst.products.at(i).name) == header_type.end())
         continue;
       if (!contains_key(header_type, inst.products.at(i).name)) continue;  // error handled elsewhere
       inst.products.at(i).type = new type_tree(*get(header_type, inst.products.at(i).name));
-      trace(9993, "transform") << "type of " << inst.products.at(i).name << " is " << names_to_string(inst.products.at(i).type) << end();
+      trace(103, "transform") << "type of " << inst.products.at(i).name << " is " << names_to_string(inst.products.at(i).type) << end();
     }
   }
 }
@@ -491,7 +491,7 @@ Transform.push_back(fill_in_return_ingredients);  // idempotent
 :(code)
 void fill_in_return_ingredients(const recipe_ordinal r) {
   recipe& caller_recipe = get(Recipe, r);
-  trace(9991, "transform") << "--- fill in return ingredients from header for recipe " << caller_recipe.name << end();
+  trace(101, "transform") << "--- fill in return ingredients from header for recipe " << caller_recipe.name << end();
   if (!caller_recipe.has_header) return;
   for (int i = 0;  i < SIZE(caller_recipe.steps);  ++i) {
     instruction& inst = caller_recipe.steps.at(i);
@@ -624,7 +624,7 @@ Transform.push_back(check_recipe_header_constraints);
 void check_recipe_header_constraints(const recipe_ordinal r) {
   const recipe& caller = get(Recipe, r);
   if (caller.name != "main") return;
-  trace(9992, "transform") << "check recipe header constraints for recipe " << caller.name << end();
+  trace(102, "transform") << "check recipe header constraints for recipe " << caller.name << end();
   if (!caller.has_header) return;
   reagent/*local*/ expected_ingredient("x:address:array:character");
   for (int i = 0; i < SIZE(caller.ingredients); ++i) {
diff --git a/054static_dispatch.cc b/054static_dispatch.cc
index 17ffc755..cdd23e4f 100644
--- a/054static_dispatch.cc
+++ b/054static_dispatch.cc
@@ -41,7 +41,7 @@ if (result.name != "main" && contains_key(Recipe_ordinal, result.name)) {
       put(Recipe_ordinal, new_name, Next_recipe_ordinal++);
       get_or_insert(Recipe_variants, result.name).push_back(get(Recipe_ordinal, new_name));
     }
-    trace("load") << "switching " << result.name << " to " << new_name << end();
+    trace(101, "load") << "switching " << result.name << " to " << new_name << end();
     result.name = new_name;
     result.is_autogenerated = true;
   }
@@ -162,7 +162,7 @@ list<call> Resolve_stack;
 :(code)
 void resolve_ambiguous_calls(const recipe_ordinal r) {
   recipe& caller_recipe = get(Recipe, r);
-  trace(9991, "transform") << "--- resolve ambiguous calls for recipe " << caller_recipe.name << end();
+  trace(101, "transform") << "--- resolve ambiguous calls for recipe " << caller_recipe.name << end();
   for (int index = 0;  index < SIZE(caller_recipe.steps);  ++index) {
     instruction& inst = caller_recipe.steps.at(index);
     if (inst.is_label) continue;
@@ -173,7 +173,7 @@ void resolve_ambiguous_calls(const recipe_ordinal r) {
 void resolve_ambiguous_call(const recipe_ordinal r, int index, instruction& inst, const recipe& caller_recipe) {
   // End resolve_ambiguous_call(r, index, inst, caller_recipe) Special-cases
   if (non_ghost_size(get_or_insert(Recipe_variants, inst.name)) == 0) return;
-  trace(9992, "transform") << "instruction " << to_original_string(inst) << end();
+  trace(102, "transform") << "instruction " << to_original_string(inst) << end();
   Resolve_stack.push_front(call(r, index));
   string new_name = best_variant(inst, caller_recipe);
   if (!new_name.empty())
@@ -241,7 +241,7 @@ vector<recipe_ordinal> strictly_matching_variants(const instruction& inst, const
   vector<recipe_ordinal> result;
   for (int i = 0;  i < SIZE(variants);  ++i) {
     if (variants.at(i) == -1) continue;
-    trace(9992, "transform") << "checking variant (strict) " << i << ": " << header_label(variants.at(i)) << end();
+    trace(102, "transform") << "checking variant (strict) " << i << ": " << header_label(variants.at(i)) << end();
     if (all_header_reagents_strictly_match(inst, get(Recipe, variants.at(i))))
       result.push_back(variants.at(i));
   }
@@ -251,14 +251,14 @@ vector<recipe_ordinal> strictly_matching_variants(const instruction& inst, const
 bool all_header_reagents_strictly_match(const instruction& inst, const recipe& variant) {
   for (int i = 0;  i < min(SIZE(inst.ingredients), SIZE(variant.ingredients));  ++i) {
     if (!types_strictly_match(variant.ingredients.at(i), inst.ingredients.at(i))) {
-      trace(9993, "transform") << "strict match failed: ingredient " << i << end();
+      trace(103, "transform") << "strict match failed: ingredient " << i << end();
       return false;
     }
   }
   for (int i = 0;  i < min(SIZE(inst.products), SIZE(variant.products));  ++i) {
     if (is_dummy(inst.products.at(i))) continue;
     if (!types_strictly_match(variant.products.at(i), inst.products.at(i))) {
-      trace(9993, "transform") << "strict match failed: product " << i << end();
+      trace(103, "transform") << "strict match failed: product " << i << end();
       return false;
     }
   }
@@ -270,7 +270,7 @@ vector<recipe_ordinal> matching_variants(const instruction& inst, const vector<r
   vector<recipe_ordinal> result;
   for (int i = 0;  i < SIZE(variants);  ++i) {
     if (variants.at(i) == -1) continue;
-    trace(9992, "transform") << "checking variant " << i << ": " << header_label(variants.at(i)) << end();
+    trace(102, "transform") << "checking variant " << i << ": " << header_label(variants.at(i)) << end();
     if (all_header_reagents_match(inst, get(Recipe, variants.at(i))))
       result.push_back(variants.at(i));
   }
@@ -280,14 +280,14 @@ vector<recipe_ordinal> matching_variants(const instruction& inst, const vector<r
 bool all_header_reagents_match(const instruction& inst, const recipe& variant) {
   for (int i = 0;  i < min(SIZE(inst.ingredients), SIZE(variant.ingredients));  ++i) {
     if (!types_match(variant.ingredients.at(i), inst.ingredients.at(i))) {
-      trace(9993, "transform") << "match failed: ingredient " << i << end();
+      trace(103, "transform") << "match failed: ingredient " << i << end();
       return false;
     }
   }
   for (int i = 0;  i < min(SIZE(variant.products), SIZE(inst.products));  ++i) {
     if (is_dummy(inst.products.at(i))) continue;
     if (!types_match(variant.products.at(i), inst.products.at(i))) {
-      trace(9993, "transform") << "match failed: product " << i << end();
+      trace(103, "transform") << "match failed: product " << i << end();
       return false;
     }
   }
diff --git a/055shape_shifting_container.cc b/055shape_shifting_container.cc
index c3d0246f..1fb5f176 100644
--- a/055shape_shifting_container.cc
+++ b/055shape_shifting_container.cc
@@ -132,7 +132,7 @@ if (!info.type_ingredient_names.empty()) continue;
 
 :(before "End container Name Refinements")
 if (name.find(':') != string::npos) {
-  trace("parse") << "container has type ingredients; parsing" << end();
+  trace(101, "parse") << "container has type ingredients; parsing" << end();
   if (!read_type_ingredients(name, command)) {
     // error; skip rest of the container definition and continue
     slurp_balanced_bracket(in);
diff --git a/056shape_shifting_recipe.cc b/056shape_shifting_recipe.cc
index cb1a40b9..7eb5f0e3 100644
--- a/056shape_shifting_recipe.cc
+++ b/056shape_shifting_recipe.cc
@@ -50,10 +50,10 @@ if (contains_type_ingredient_name(to)) return false;
 candidates = strictly_matching_shape_shifting_variants(inst, variants);
 if (!candidates.empty()) {
   recipe_ordinal exemplar = best_shape_shifting_variant(inst, candidates);
-  trace(9992, "transform") << "found variant to specialize: " << exemplar << ' ' << get(Recipe, exemplar).name << end();
+  trace(102, "transform") << "found variant to specialize: " << exemplar << ' ' << get(Recipe, exemplar).name << end();
   string new_recipe_name = insert_new_variant(exemplar, inst, caller_recipe);
   if (new_recipe_name != "") {
-    trace(9992, "transform") << "new specialization: " << new_recipe_name << end();
+    trace(102, "transform") << "new specialization: " << new_recipe_name << end();
     return new_recipe_name;
   }
 }
@@ -84,14 +84,14 @@ vector<recipe_ordinal> strictly_matching_shape_shifting_variants(const instructi
 bool all_concrete_header_reagents_strictly_match(const instruction& inst, const recipe& variant) {
   for (int i = 0;  i < min(SIZE(inst.ingredients), SIZE(variant.ingredients));  ++i) {
     if (!concrete_type_names_strictly_match(variant.ingredients.at(i), inst.ingredients.at(i))) {
-      trace(9993, "transform") << "concrete-type match failed: ingredient " << i << end();
+      trace(103, "transform") << "concrete-type match failed: ingredient " << i << end();
       return false;
     }
   }
   for (int i = 0;  i < min(SIZE(inst.products), SIZE(variant.products));  ++i) {
     if (is_dummy(inst.products.at(i))) continue;
     if (!concrete_type_names_strictly_match(variant.products.at(i), inst.products.at(i))) {
-      trace(9993, "transform") << "concrete-type match failed: product " << i << end();
+      trace(103, "transform") << "concrete-type match failed: product " << i << end();
       return false;
     }
   }
@@ -250,10 +250,10 @@ string insert_new_variant(recipe_ordinal exemplar, const instruction& inst, cons
   new_recipe.name = new_name;
   new_recipe.ordinal = new_recipe_ordinal;
   new_recipe.is_autogenerated = true;
-  trace(9993, "transform") << "switching " << inst.name << " to specialized " << header_label(new_recipe) << end();
+  trace(103, "transform") << "switching " << inst.name << " to specialized " << header_label(new_recipe) << end();
 
-  trace(9992, "transform") << "transforming new specialization: " << new_recipe.name << end();
-  trace(9992, "transform") << new_recipe.name << ": performing transforms until check_or_set_types_by_name" << end();
+  trace(102, "transform") << "transforming new specialization: " << new_recipe.name << end();
+  trace(102, "transform") << new_recipe.name << ": performing transforms until check_or_set_types_by_name" << end();
   int transform_index = 0;
   for (transform_index = 0;  transform_index < SIZE(Transform);  ++transform_index) {
     if (Transform.at(transform_index) == check_or_set_types_by_name) break;
@@ -261,11 +261,11 @@ string insert_new_variant(recipe_ordinal exemplar, const instruction& inst, cons
   }
   new_recipe.transformed_until = transform_index-1;
 
-  trace(9992, "transform") << new_recipe.name << ": performing type-ingredient-aware version of transform check_or_set_types_by_name" << end();
+  trace(102, "transform") << new_recipe.name << ": performing type-ingredient-aware version of transform check_or_set_types_by_name" << end();
   compute_type_names(new_recipe);
   new_recipe.transformed_until++;
 
-  trace(9992, "transform") << new_recipe.name << ": replacing type ingredients" << end();
+  trace(102, "transform") << new_recipe.name << ": replacing type ingredients" << end();
   {
     map<string, const type_tree*> mappings;
     bool error = false;
@@ -278,9 +278,9 @@ string insert_new_variant(recipe_ordinal exemplar, const instruction& inst, cons
   }
   ensure_all_concrete_types(new_recipe, get(Recipe, exemplar));
 
-  trace(9992, "transform") << new_recipe.name << ": recording the new variant before recursively calling resolve_ambiguous_calls" << end();
+  trace(102, "transform") << new_recipe.name << ": recording the new variant before recursively calling resolve_ambiguous_calls" << end();
   get(Recipe_variants, inst.name).push_back(new_recipe_ordinal);
-  trace(9992, "transform") << new_recipe.name << ": performing remaining transforms (including resolve_ambiguous_calls)" << end();
+  trace(102, "transform") << new_recipe.name << ": performing remaining transforms (including resolve_ambiguous_calls)" << end();
   for (/*nada*/;  transform_index < SIZE(Transform);  ++transform_index)
     (*Transform.at(transform_index))(new_recipe_ordinal);
   new_recipe.transformed_until = SIZE(Transform)-1;
@@ -288,7 +288,7 @@ string insert_new_variant(recipe_ordinal exemplar, const instruction& inst, cons
 }
 
 void compute_type_names(recipe& variant) {
-  trace(9993, "transform") << "-- compute type names: " << variant.name << end();
+  trace(103, "transform") << "-- compute type names: " << variant.name << end();
   map<string, type_tree*> type_names;
   for (int i = 0;  i < SIZE(variant.ingredients);  ++i)
     save_or_deduce_type_name(variant.ingredients.at(i), type_names, variant, "");
@@ -296,7 +296,7 @@ void compute_type_names(recipe& variant) {
     save_or_deduce_type_name(variant.products.at(i), type_names, variant, "");
   for (int i = 0;  i < SIZE(variant.steps);  ++i) {
     instruction& inst = variant.steps.at(i);
-    trace(9993, "transform") << "  instruction: " << to_string(inst) << end();
+    trace(103, "transform") << "  instruction: " << to_string(inst) << end();
     for (int in = 0;  in < SIZE(inst.ingredients);  ++in)
       save_or_deduce_type_name(inst.ingredients.at(in), type_names, variant, " in '" + to_original_string(inst) + "'");
     for (int out = 0;  out < SIZE(inst.products);  ++out)
@@ -305,10 +305,10 @@ void compute_type_names(recipe& variant) {
 }
 
 void save_or_deduce_type_name(reagent& x, map<string, type_tree*>& type, const recipe& variant, const string& context) {
-  trace(9994, "transform") << "    checking " << to_string(x) << ": " << names_to_string(x.type) << end();
+  trace(104, "transform") << "    checking " << to_string(x) << ": " << names_to_string(x.type) << end();
   if (!x.type && contains_key(type, x.name)) {
     x.type = new type_tree(*get(type, x.name));
-    trace(9994, "transform") << "    deducing type to " << names_to_string(x.type) << end();
+    trace(104, "transform") << "    deducing type to " << names_to_string(x.type) << end();
     return;
   }
   // Type Check in Type-ingredient-aware check_or_set_types_by_name
@@ -322,7 +322,7 @@ void save_or_deduce_type_name(reagent& x, map<string, type_tree*>& type, const r
   if (contains_key(type, x.name)) return;
   if (x.type->name == "offset" || x.type->name == "variant") return;  // special-case for container-access instructions
   put(type, x.name, x.type);
-  trace(9993, "transform") << "type of '" << x.name << "' is " << names_to_string(x.type) << end();
+  trace(103, "transform") << "type of '" << x.name << "' is " << names_to_string(x.type) << end();
 }
 
 void compute_type_ingredient_mappings(const recipe& exemplar, const instruction& inst, map<string, const type_tree*>& mappings, const recipe& caller_recipe, bool* error) {
@@ -372,7 +372,7 @@ void accumulate_type_ingredients(const type_tree* exemplar_type, const type_tree
         curr_refinement_type = new type_tree(*refinement_type->left);
       }
       if (!contains_key(mappings, exemplar_type->name)) {
-        trace(9993, "transform") << "adding mapping from " << exemplar_type->name << " to " << to_string(curr_refinement_type) << end();
+        trace(103, "transform") << "adding mapping from " << exemplar_type->name << " to " << to_string(curr_refinement_type) << end();
         put(mappings, exemplar_type->name, new type_tree(*curr_refinement_type));
       }
       else {
@@ -399,16 +399,16 @@ void accumulate_type_ingredients(const type_tree* exemplar_type, const type_tree
 void replace_type_ingredients(recipe& new_recipe, const map<string, const type_tree*>& mappings) {
   // update its header
   if (mappings.empty()) return;
-  trace(9993, "transform") << "replacing in recipe header ingredients" << end();
+  trace(103, "transform") << "replacing in recipe header ingredients" << end();
   for (int i = 0;  i < SIZE(new_recipe.ingredients);  ++i)
     replace_type_ingredients(new_recipe.ingredients.at(i), mappings, new_recipe);
-  trace(9993, "transform") << "replacing in recipe header products" << end();
+  trace(103, "transform") << "replacing in recipe header products" << end();
   for (int i = 0;  i < SIZE(new_recipe.products);  ++i)
     replace_type_ingredients(new_recipe.products.at(i), mappings, new_recipe);
   // update its body
   for (int i = 0;  i < SIZE(new_recipe.steps);  ++i) {
     instruction& inst = new_recipe.steps.at(i);
-    trace(9993, "transform") << "replacing in instruction '" << to_string(inst) << "'" << end();
+    trace(103, "transform") << "replacing in instruction '" << to_string(inst) << "'" << end();
     for (int j = 0;  j < SIZE(inst.ingredients);  ++j)
       replace_type_ingredients(inst.ingredients.at(j), mappings, new_recipe);
     for (int j = 0;  j < SIZE(inst.products);  ++j)
@@ -425,7 +425,7 @@ void replace_type_ingredients(recipe& new_recipe, const map<string, const type_t
 
 void replace_type_ingredients(reagent& x, const map<string, const type_tree*>& mappings, const recipe& caller) {
   string before = to_string(x);
-  trace(9993, "transform") << "replacing in ingredient " << x.original_string << end();
+  trace(103, "transform") << "replacing in ingredient " << x.original_string << end();
   if (!x.type) {
     raise << "specializing " << caller.original_name << ": missing type for '" << x.original_string << "'\n" << end();
     return;
@@ -449,7 +449,7 @@ void replace_type_ingredients(type_tree* type, const map<string, const type_tree
   if (!contains_key(mappings, type->name))
     return;
   const type_tree* replacement = get(mappings, type->name);
-  trace(9993, "transform") << type->name << " => " << names_to_string(replacement) << end();
+  trace(103, "transform") << type->name << " => " << names_to_string(replacement) << end();
   if (replacement->atom) {
     if (!contains_key(Type_ordinal, replacement->name)) {
       // error in program; should be reported elsewhere
@@ -510,7 +510,7 @@ void dump_inspect(const type_tree* x, ostream& out) {
 }
 
 void ensure_all_concrete_types(/*const*/ recipe& new_recipe, const recipe& exemplar) {
-  trace(9993, "transform") << "-- ensure all concrete types in recipe " << new_recipe.name << end();
+  trace(103, "transform") << "-- ensure all concrete types in recipe " << new_recipe.name << end();
   for (int i = 0;  i < SIZE(new_recipe.ingredients);  ++i)
     ensure_all_concrete_types(new_recipe.ingredients.at(i), exemplar);
   for (int i = 0;  i < SIZE(new_recipe.products);  ++i)
diff --git a/057immutable.cc b/057immutable.cc
index d1f1df71..e1feac7a 100644
--- a/057immutable.cc
+++ b/057immutable.cc
@@ -344,7 +344,7 @@ void check_immutable_ingredients(const recipe_ordinal r) {
   //   b) we never call 'put' or 'put-index' on it, and
   //   c) any non-primitive recipe calls in the body aren't returning it as a product
   const recipe& caller = get(Recipe, r);
-  trace(9991, "transform") << "--- check mutability of ingredients in recipe " << caller.name << end();
+  trace(101, "transform") << "--- check mutability of ingredients in recipe " << caller.name << end();
   if (!caller.has_header) return;  // skip check for old-style recipes calling next-ingredient directly
   for (int i = 0;  i < SIZE(caller.ingredients);  ++i) {
     const reagent& current_ingredient = caller.ingredients.at(i);
diff --git a/060rewrite_literal_string.cc b/060rewrite_literal_string.cc
index 95e38924..7bfc45cb 100644
--- a/060rewrite_literal_string.cc
+++ b/060rewrite_literal_string.cc
@@ -38,7 +38,7 @@ void initialize_transform_rewrite_literal_string_to_text() {
 
 void rewrite_literal_string_to_text(const recipe_ordinal r) {
   recipe& caller = get(Recipe, r);
-  trace(9991, "transform") << "--- rewrite literal strings in recipe " << caller.name << end();
+  trace(101, "transform") << "--- rewrite literal strings in recipe " << caller.name << end();
   if (contains_numeric_locations(caller)) return;
   vector<instruction> new_instructions;
   for (int i = 0;  i < SIZE(caller.steps);  ++i) {
diff --git a/062convert_ingredients_to_text.cc b/062convert_ingredients_to_text.cc
index d3d3291a..8739f47b 100644
--- a/062convert_ingredients_to_text.cc
+++ b/062convert_ingredients_to_text.cc
@@ -59,7 +59,7 @@ Transform.push_back(convert_ingredients_to_text);  // idempotent
 :(code)
 void convert_ingredients_to_text(const recipe_ordinal r) {
   recipe& caller = get(Recipe, r);
-  trace(9991, "transform") << "--- convert some ingredients to text in recipe " << caller.name << end();
+  trace(101, "transform") << "--- convert some ingredients to text in recipe " << caller.name << end();
   // in recipes without named locations, 'stash' is still not extensible
   if (contains_numeric_locations(caller)) return;
   convert_ingredients_to_text(caller);
@@ -100,7 +100,7 @@ void convert_ingredients_to_text(recipe& caller) {
         }
       }
     }
-    trace(9993, "transform") << to_string(inst) << end();
+    trace(103, "transform") << to_string(inst) << end();
     new_instructions.push_back(inst);
   }
   caller.steps.swap(new_instructions);
@@ -125,7 +125,7 @@ void convert_ingredient_to_text(reagent& r, vector<instruction>& out, const stri
     def.ingredients.push_back(r);
   }
   def.products.push_back(reagent(tmp_var));
-  trace(9993, "transform") << to_string(def) << end();
+  trace(103, "transform") << to_string(def) << end();
   out.push_back(def);
   r.clear();  // reclaim old memory
   r = reagent(tmp_var);
diff --git a/069hash.cc b/069hash.cc
index c810f98b..3a371233 100644
--- a/069hash.cc
+++ b/069hash.cc
@@ -55,7 +55,7 @@ size_t hash_mu_scalar(size_t h, const reagent& r) {
 
 size_t hash_mu_address(size_t h, reagent& r) {
   if (r.value == 0) return 0;
-  trace("mem") << "location " << r.value << " is " << no_scientific(get_or_insert(Memory, r.value)) << end();
+  trace(Callstack_depth+1, "mem") << "location " << r.value << " is " << no_scientific(get_or_insert(Memory, r.value)) << end();
   r.set_value(get_or_insert(Memory, r.value));
   drop_from_type(r, "address");
   return hash(h, r);
diff --git a/072recipe.cc b/072recipe.cc
index 439b2000..43b1d013 100644
--- a/072recipe.cc
+++ b/072recipe.cc
@@ -79,11 +79,9 @@ case CALL: {
 :(before "End Primitive Recipe Implementations")
 case CALL: {
   // Begin Call
-  if (Trace_stream) {
-    ++Trace_stream->callstack_depth;
-    trace("trace") << "indirect 'call': incrementing callstack depth to " << Trace_stream->callstack_depth << end();
-    assert(Trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
-  }
+  trace(Callstack_depth+1, "trace") << "indirect 'call': incrementing callstack depth to " << Callstack_depth << end();
+  ++Callstack_depth;
+  assert(Callstack_depth < Max_depth);
   if (!ingredients.at(0).at(0)) {
     raise << maybe(current_recipe_name()) << "tried to call empty recipe in '" << to_string(current_instruction()) << "'" << end();
     break;
@@ -224,7 +222,7 @@ void resolve_indirect_ambiguous_call(const recipe_ordinal r, int index, instruct
 Transform.push_back(check_indirect_calls_against_header);  // idempotent
 :(code)
 void check_indirect_calls_against_header(const recipe_ordinal r) {
-  trace(9991, "transform") << "--- type-check 'call' instructions inside recipe " << get(Recipe, r).name << end();
+  trace(101, "transform") << "--- type-check 'call' instructions inside recipe " << get(Recipe, r).name << end();
   const recipe& caller = get(Recipe, r);
   for (int i = 0;  i < SIZE(caller.steps);  ++i) {
     const instruction& inst = caller.steps.at(i);
diff --git a/073scheduler.cc b/073scheduler.cc
index aa22bcfb..4270ecb1 100644
--- a/073scheduler.cc
+++ b/073scheduler.cc
@@ -69,7 +69,7 @@ void run(routine* rr) {
     skip_to_next_routine();
     assert(Current_routine);
     assert(Current_routine->state == RUNNING);
-    trace(9990, "schedule") << current_routine_label() << end();
+    trace(100, "schedule") << current_routine_label() << end();
     run_current_routine();
     // Scheduler State Transitions
     if (Current_routine->completed())
@@ -465,7 +465,7 @@ DISCONTINUED,
 :(before "End Scheduler State Transitions")
 if (Current_routine->limit >= 0) {
   if (Current_routine->limit <= Scheduling_interval) {
-    trace("schedule") << "discontinuing routine " << Current_routine->id << end();
+    trace(100, "schedule") << "discontinuing routine " << Current_routine->id << end();
     Current_routine->state = DISCONTINUED;
     Current_routine->limit = 0;
   }
diff --git a/074wait.cc b/074wait.cc
index aa3b59af..0a32c994 100644
--- a/074wait.cc
+++ b/074wait.cc
@@ -89,13 +89,13 @@ case WAIT_FOR_RESET_THEN_SET: {
 :(before "End Primitive Recipe Implementations")
 case WAIT_FOR_RESET_THEN_SET: {
   int loc = static_cast<int>(ingredients.at(0).at(0));
-  trace(9998, "run") << "wait: *" << loc << " = " << get_or_insert(Memory, loc) << end();
+  trace(Callstack_depth+1, "run") << "wait: *" << loc << " = " << get_or_insert(Memory, loc) << end();
   if (get_or_insert(Memory, loc) == 0) {
-    trace(9998, "run") << "location " << loc << " is already 0; setting" << end();
+    trace(Callstack_depth+1, "run") << "location " << loc << " is already 0; setting" << end();
     put(Memory, loc, 1);
     break;
   }
-  trace(9998, "run") << "waiting for location " << loc << " to reset" << end();
+  trace(Callstack_depth+1, "run") << "waiting for location " << loc << " to reset" << end();
   Current_routine->state = WAITING;
   Current_routine->waiting_on_location = loc;
   break;
@@ -121,7 +121,7 @@ case RESET: {
 case RESET: {
   int loc = static_cast<int>(ingredients.at(0).at(0));
   put(Memory, loc, 0);
-  trace(9998, "run") << "reset: *" << loc << " = " << get_or_insert(Memory, loc) << end();
+  trace(Callstack_depth+1, "run") << "reset: *" << loc << " = " << get_or_insert(Memory, loc) << end();
   break;
 }
 
@@ -132,7 +132,7 @@ for (int i = 0;  i < SIZE(Routines);  ++i) {
   if (Routines.at(i)->state != WAITING) continue;
   int loc = Routines.at(i)->waiting_on_location;
   if (loc && get_or_insert(Memory, loc) == 0) {
-    trace("schedule") << "waking up routine " << Routines.at(i)->id << end();
+    trace(100, "schedule") << "waking up routine " << Routines.at(i)->id << end();
     put(Memory, loc, 1);
     Routines.at(i)->state = RUNNING;
     Routines.at(i)->waiting_on_location = 0;
@@ -212,7 +212,7 @@ case GET_LOCATION: {
   int result = base_address;
   for (int i = 0;  i < offset;  ++i)
     result += size_of(element_type(base.type, i));
-  trace(9998, "run") << "address to copy is " << result << end();
+  trace(Callstack_depth+1, "run") << "address to copy is " << result << end();
   products.resize(1);
   products.at(0).push_back(result);
   break;
@@ -338,7 +338,7 @@ case WAIT_FOR_ROUTINE: {
   }
   Current_routine->state = WAITING;
   Current_routine->waiting_on_routine = ingredients.at(0).at(0);
-  trace(9998, "run") << "waiting for routine " << ingredients.at(0).at(0) << end();
+  trace(Callstack_depth+1, "run") << "waiting for routine " << ingredients.at(0).at(0) << end();
   break;
 }
 
@@ -356,7 +356,7 @@ for (int i = 0;  i < SIZE(Routines);  ++i) {
     const routine* waitee = Routines.at(j);
     if (waitee->id == id && waitee->state != RUNNING && waitee->state != WAITING) {
       // routine is COMPLETED or DISCONTINUED
-      trace("schedule") << "waking up routine " << waiter->id << end();
+      trace(100, "schedule") << "waking up routine " << waiter->id << end();
       waiter->state = RUNNING;
       waiter->waiting_on_routine = 0;
     }
@@ -500,7 +500,7 @@ case WAIT_FOR_ROUTINE_TO_BLOCK: {
   }
   Current_routine->state = WAITING;
   Current_routine->waiting_on_routine_to_block = ingredients.at(0).at(0);
-  trace(9998, "run") << "waiting for routine " << ingredients.at(0).at(0) << " to block" << end();
+  trace(Callstack_depth+1, "run") << "waiting for routine " << ingredients.at(0).at(0) << " to block" << end();
   break;
 }
 
@@ -516,7 +516,7 @@ for (int i = 0;  i < SIZE(Routines);  ++i) {
     const routine* waitee = Routines.at(j);
     if (waitee->id != id) continue;
     if (waitee->state != RUNNING || waitee->blocked) {
-      trace("schedule") << "waking up routine " << waiter->id << " because routine " << waitee->id << " is blocked" << end();
+      trace(100, "schedule") << "waking up routine " << waiter->id << " because routine " << waitee->id << " is blocked" << end();
       waiter->state = RUNNING;
       waiter->waiting_on_routine_to_block = 0;
     }
diff --git a/076continuation.cc b/076continuation.cc
index 7a328a11..49916ef2 100644
--- a/076continuation.cc
+++ b/076continuation.cc
@@ -132,11 +132,9 @@ case CALL_WITH_CONTINUATION_MARK: {
 case CALL_WITH_CONTINUATION_MARK: {
   // like call, but mark the current call as a 'base of continuation' call
   // before pushing the next one on it
-  if (Trace_stream) {
-    ++Trace_stream->callstack_depth;
-    trace("trace") << "delimited continuation; incrementing callstack depth to " << Trace_stream->callstack_depth << end();
-    assert(Trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
-  }
+  trace(Callstack_depth+1, "trace") << "delimited continuation; incrementing callstack depth to " << Callstack_depth << end();
+  ++Callstack_depth;
+  assert(Callstack_depth < Max_depth);
   instruction/*copy*/ caller_instruction = current_instruction();
   Current_routine->calls.front().continuation_mark_tag = current_instruction().ingredients.at(0).value;
   Current_routine->calls.push_front(call(ingredients.at(1).at(0)));
@@ -213,13 +211,11 @@ case RETURN_CONTINUATION_UNTIL_MARK: {
       raise << maybe(current_recipe_name()) << "  " << get(Recipe, p->running_recipe).name << '\n' << end();
     break;
   }
-  trace("run") << "creating continuation " << Next_delimited_continuation_id << end();
+  trace(Callstack_depth+1, "run") << "creating continuation " << Next_delimited_continuation_id << end();
   put(Delimited_continuation, Next_delimited_continuation_id, delimited_continuation(Current_routine->calls.begin(), base));
   while (Current_routine->calls.begin() != base) {
-    if (Trace_stream) {
-      --Trace_stream->callstack_depth;
-      assert(Trace_stream->callstack_depth >= 0);
-    }
+    --Callstack_depth;
+    assert(Callstack_depth >= 0);
     Current_routine->calls.pop_front();
   }
   // return it as the result of the marked call
@@ -243,17 +239,15 @@ call_stack::iterator find_base_of_continuation(call_stack& c, int mark_tag) {
 if (is_mu_continuation(current_instruction().ingredients.at(0))) {
   // copy multiple calls on to current call stack
   assert(scalar(ingredients.at(0)));
-  trace("run") << "calling continuation " << ingredients.at(0).at(0) << end();
+  trace(Callstack_depth+1, "run") << "calling continuation " << ingredients.at(0).at(0) << end();
   if (!contains_key(Delimited_continuation, ingredients.at(0).at(0)))
     raise << maybe(current_recipe_name()) << "no such delimited continuation " << current_instruction().ingredients.at(0).original_string << '\n' << end();
   const call_stack& new_frames = get(Delimited_continuation, ingredients.at(0).at(0)).frames;
   for (call_stack::const_reverse_iterator p = new_frames.rbegin(); p != new_frames.rend(); ++p)
     Current_routine->calls.push_front(*p);
-  if (Trace_stream) {
-    Trace_stream->callstack_depth += SIZE(new_frames);
-    trace("trace") << "calling delimited continuation; growing callstack depth to " << Trace_stream->callstack_depth << end();
-    assert(Trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
-  }
+  trace(Callstack_depth+1, "trace") << "calling delimited continuation; growing callstack depth to " << Callstack_depth+SIZE(new_frames) << end();
+  Callstack_depth += SIZE(new_frames);
+  assert(Callstack_depth < Max_depth);
   // no call housekeeping; continuations don't support next-ingredient
   copy(/*drop continuation*/++ingredients.begin(), ingredients.end(), inserter(products, products.begin()));
   break;  // record results of resuming 'return-continuation-until-mark' instruction
diff --git a/085scenario_console.cc b/085scenario_console.cc
index 31aa4fe7..af6e44c2 100644
--- a/085scenario_console.cc
+++ b/085scenario_console.cc
@@ -66,7 +66,7 @@ case ASSUME_CONSOLE: {
   for (int i = 0;  i < SIZE(r.steps);  ++i) {
     const instruction& inst = r.steps.at(i);
     if (inst.name == "left-click") {
-      trace("mem") << "storing 'left-click' event starting at " << Current_routine->alloc << end();
+      trace(Callstack_depth+1, "mem") << "storing 'left-click' event starting at " << Current_routine->alloc << end();
       put(Memory, curr_address, /*tag for 'touch-event' variant of 'event' exclusive-container*/2);
       put(Memory, curr_address+/*skip tag*/1+/*offset of 'type' in 'mouse-event'*/0, TB_KEY_MOUSE_LEFT);
       put(Memory, curr_address+/*skip tag*/1+/*offset of 'row' in 'mouse-event'*/1, to_integer(inst.ingredients.at(0).name));
@@ -74,7 +74,7 @@ case ASSUME_CONSOLE: {
       curr_address += size_of_event();
     }
     else if (inst.name == "press") {
-      trace("mem") << "storing 'press' event starting at " << curr_address << end();
+      trace(Callstack_depth+1, "mem") << "storing 'press' event starting at " << curr_address << end();
       string key = inst.ingredients.at(0).name;
       if (is_integer(key))
         put(Memory, curr_address+1, to_integer(key));
@@ -95,18 +95,18 @@ case ASSUME_CONSOLE: {
     else {
       // keyboard input
       assert(inst.name == "type");
-      trace("mem") << "storing 'type' event starting at " << curr_address << end();
+      trace(Callstack_depth+1, "mem") << "storing 'type' event starting at " << curr_address << end();
       const string& contents = inst.ingredients.at(0).name;
       const char* raw_contents = contents.c_str();
       int num_keyboard_events = unicode_length(contents);
       int curr = 0;
       for (int i = 0;  i < num_keyboard_events;  ++i) {
-        trace("mem") << "storing 'text' tag at " << curr_address << end();
+        trace(Callstack_depth+1, "mem") << "storing 'text' tag at " << curr_address << end();
         put(Memory, curr_address, /*tag for 'text' variant of 'event' exclusive-container*/0);
         uint32_t curr_character;
         assert(curr < SIZE(contents));
         tb_utf8_char_to_unicode(&curr_character, &raw_contents[curr]);
-        trace("mem") << "storing character " << curr_character << " at " << curr_address+/*skip exclusive container tag*/1 << end();
+        trace(Callstack_depth+1, "mem") << "storing character " << curr_character << " at " << curr_address+/*skip exclusive container tag*/1 << end();
         put(Memory, curr_address+/*skip exclusive container tag*/1, curr_character);
         curr += tb_utf8_char_length(raw_contents[curr]);
         curr_address += size_of_event();
@@ -116,9 +116,9 @@ case ASSUME_CONSOLE: {
   assert(curr_address == event_data_address+/*skip alloc id*/1+size);
   // wrap the array of events in a console object
   int console_address = allocate(size_of_console());
-  trace("mem") << "storing console in " << console_address << end();
+  trace(Callstack_depth+1, "mem") << "storing console in " << console_address << end();
   put(Memory, CONSOLE+/*skip alloc id*/1, console_address);
-  trace("mem") << "storing console data in " << console_address+/*offset of 'data' in container 'events'*/1 << end();
+  trace(Callstack_depth+1, "mem") << "storing console data in " << console_address+/*offset of 'data' in container 'events'*/1 << end();
   put(Memory, console_address+/*skip alloc id*/1+/*offset of 'data' in container 'events'*/1+/*skip alloc id of 'data'*/1, event_data_address);
   break;
 }
diff --git a/089scenario_filesystem.cc b/089scenario_filesystem.cc
index bacb61be..b0429ea7 100644
--- a/089scenario_filesystem.cc
+++ b/089scenario_filesystem.cc
@@ -208,24 +208,24 @@ void construct_resources_object(const map<string, string>& contents) {
   for (map<string, string>::const_iterator p = contents.begin();  p != contents.end();  ++p) {
     ++curr;  // skip alloc id of resource.name
     put(Memory, curr, new_mu_text(p->first));
-    trace("mem") << "storing file name " << get(Memory, curr) << " in location " << curr << end();
+    trace(Callstack_depth+1, "mem") << "storing file name " << get(Memory, curr) << " in location " << curr << end();
     ++curr;
     ++curr;  // skip alloc id of resource.contents
     put(Memory, curr, new_mu_text(p->second));
-    trace("mem") << "storing file contents " << get(Memory, curr) << " in location " << curr << end();
+    trace(Callstack_depth+1, "mem") << "storing file contents " << get(Memory, curr) << " in location " << curr << end();
     ++curr;
   }
   curr = resources_data_address + /*skip alloc id of resources.data*/1;
   put(Memory, curr, SIZE(contents));  // array length
-  trace("mem") << "storing resources size " << get(Memory, curr) << " in location " << curr << end();
+  trace(Callstack_depth+1, "mem") << "storing resources size " << get(Memory, curr) << " in location " << curr << end();
   // wrap the resources data in a 'resources' object
   int resources_address = allocate(size_of_resources());
   curr = resources_address+/*alloc id*/1+/*offset of 'data' element*/1+/*skip alloc id of 'data' element*/1;
   put(Memory, curr, resources_data_address);
-  trace("mem") << "storing resources data address " << resources_data_address << " in location " << curr << end();
+  trace(Callstack_depth+1, "mem") << "storing resources data address " << resources_data_address << " in location " << curr << end();
   // save in product
   put(Memory, RESOURCES+/*skip alloc id*/1, resources_address);
-  trace("mem") << "storing resources address " << resources_address << " in location " << RESOURCES << end();
+  trace(Callstack_depth+1, "mem") << "storing resources address " << resources_address << " in location " << RESOURCES << end();
 }
 
 int size_of_resources() {
diff --git a/099hardware_checks.cc b/099hardware_checks.cc
index cee68bdb..f84837d2 100644
--- a/099hardware_checks.cc
+++ b/099hardware_checks.cc
@@ -35,7 +35,7 @@ void check_for_misuse_of_real_hardware(const recipe_ordinal r) {
   const recipe& caller = get(Recipe, r);
   if (caller.name == "main") return;
   if (starts_with(caller.name, "scenario_")) return;
-  trace(9991, "transform") << "--- check if recipe " << caller.name << " has any dependency-injection mistakes" << end();
+  trace(101, "transform") << "--- check if recipe " << caller.name << " has any dependency-injection mistakes" << end();
   for (int index = 0;  index < SIZE(caller.steps);  ++index) {
     const instruction& inst = caller.steps.at(index);
     if (is_primitive(inst.operation)) continue;
diff --git a/101run_sandboxed.cc b/101run_sandboxed.cc
index 99310219..5a9db896 100644
--- a/101run_sandboxed.cc
+++ b/101run_sandboxed.cc
@@ -91,6 +91,7 @@ Most_recent_products = "";
 :(before "End Globals")
 trace_stream* Save_trace_stream = NULL;
 string Save_trace_file;
+int Save_callstack_depth = 0;
 :(code)
 // reads a string, tries to call it as code (treating it as a test), saving
 // all errors.
@@ -127,9 +128,9 @@ bool run_interactive(int address) {
   // now call 'sandbox' which will run 'interactive' in a separate routine,
   // and wait for it
   if (Save_trace_stream) {
-    ++Save_trace_stream->callstack_depth;
-    trace(9999, "trace") << "run-sandboxed: incrementing callstack depth to " << Save_trace_stream->callstack_depth << end();
-    assert(Save_trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
+    ++Save_callstack_depth;
+    trace(Save_callstack_depth+1, "trace") << "run-sandboxed: incrementing callstack depth to " << Save_callstack_depth << end();
+    assert(Save_callstack_depth < Max_depth);
   }
   Current_routine->calls.push_front(call(get(Recipe_ordinal, "sandbox")));
   return true;
@@ -149,6 +150,9 @@ map<string, type_tree*> Type_abbreviations_snapshot_stash;
 vector<scenario> Scenarios_snapshot_stash;
 set<string> Scenario_names_snapshot_stash;
 
+:(before "End Types")  //: include in all cleaved compilation units
+const int App_depth = 1;  // where all Mu code will trace to by default
+
 :(code)
 void run_code_begin(bool should_stash_snapshots) {
   // stuff to undo later, in run_code_end()
@@ -159,6 +163,7 @@ void run_code_begin(bool should_stash_snapshots) {
   if (should_stash_snapshots)
     stash_snapshots();
   Save_trace_stream = Trace_stream;
+  Save_callstack_depth = Callstack_depth;
   Trace_stream = new trace_stream;
   Trace_stream->collect_depth = App_depth;
 }
@@ -175,6 +180,7 @@ void run_code_end() {
   Trace_stream = Save_trace_stream;
   Save_trace_stream = NULL;
   Save_trace_file.clear();
+  Save_callstack_depth = 0;
   Recipe.erase(get(Recipe_ordinal, "interactive"));  // keep past sandboxes from inserting errors
   if (!Recipe_snapshot_stash.empty())
     unstash_snapshots();
diff --git a/999spaces.cc b/999spaces.cc
index 219e695d..adbbf8a9 100644
--- a/999spaces.cc
+++ b/999spaces.cc
@@ -25,12 +25,10 @@ assert(Next_recipe_ordinal == 1000);
 
 //:: Depths for tracing
 //:
-//: 0 - unused
-//: 1-100 - app-level trace statements in Mu
-//: 101-9989 - call-stack statements (mostly label run)
-assert(Initial_callstack_depth == 101);
-assert(Max_callstack_depth == 9989);
-//: 9990-9999 - intra-instruction lines (mostly label mem)
+//: 0 - errors
+//: 1-99 - app-level trace statements in Mu
+//: 100-9999 - call-stack statements (mostly label run)
+assert(Initial_callstack_depth == 100);
 
 //:: Summary of transforms and their dependencies
 //: begin transforms
diff --git a/Readme.md b/Readme.md
index 54af1049..f1dd1be6 100644
--- a/Readme.md
+++ b/Readme.md
@@ -403,7 +403,19 @@ c) Try running the tests:
 d) Check out [the programming environment](https://github.com/akkartik/mu/tree/master/edit#readme),
 the largest app built so far in Mu.
 
-e) Look at the `build` scripts. Mu's compilation process is itself designed to
+e) Check out the tracing infrastructure which gives you a maps-like zoomable
+UI for browsing Mu's traces:
+
+  ```shell
+  $ ./mu --trace nqueens.mu  # just an example
+  saving trace to 'last_run'
+  $ ./browse_trace/browse_trace last_run
+  # hit 'q' to exit
+  ```
+
+For more details see the [Readme](browse_trace/Readme.md).
+
+f) Look at the `build` scripts. Mu's compilation process is itself designed to
 support staged learning. Each of the scripts (`build0`, `build1`, `build2`,
 etc.) is self-contained and can compile the project by itself. Successive
 versions add new features and configurability -- and complexity -- to the
diff --git a/browse_trace/Readme.md b/browse_trace/Readme.md
new file mode 100644
index 00000000..ccfbdca7
--- /dev/null
+++ b/browse_trace/Readme.md
@@ -0,0 +1,78 @@
+### A debugging helper that lets you zoom in/out on a trace.
+
+To try it out, first create an example trace (from the top-level `mu/`
+directory):
+
+  ```shell
+  ./mu --trace nqueens.mu
+  ```
+
+This command will save a trace of its execution in a file called `last_run`.
+The trace consists of a series of lines, each starting with an integer depth
+and a single-word 'label', followed by a colon and whitespace.
+
+Now browse this trace:
+
+  ```shell
+  ./browse_trace/browse_trace last_run
+  ```
+
+You should now find yourself in a UI showing a subsequence of lines from the
+trace, each line starting with a numeric depth, and ending with a parenthetical
+count of trace lines hidden after it with greater depths.
+
+For example, this line:
+
+  ```
+  2 app: line1 (30)
+  ```
+
+indicates that it was logged with depth 2, and that 30 following lines have
+been hidden at a depth greater than 2.
+
+(As an experiment, hidden counts of 1000 or more are highlighted in red.)
+
+The UI provides the following hotkeys:
+
+* `q` or `ctrl-c`: Quit.
+
+* `Enter`: 'Zoom into' this line. Expand lines hidden after it that were at
+  the next higher level.
+
+* `Backspace`: 'Zoom out' on a line after zooming in, collapsing lines below
+  expanded by some series of `Enter` commands.
+
+* `j` or `down-arrow`: Move/scroll cursor down one line.
+* `k` or `up-arrow`: Move/scroll cursor up one line.
+* `J` or `ctrl-f` or `page-down`: Scroll cursor down one page.
+* `K` or `ctrl-b` or `page-up`: Scroll cursor up one page.
+* `h` or `left-arrow`: Scroll cursor left one character.
+* `l` or `right-arrow`: Scroll cursor right one character.
+* `H`: Scroll cursor left one screen-width.
+* `L`: Scroll cursor right one screen-width.
+
+* `g` or `home`: Move cursor to start of trace.
+* `G` or `end`: Move cursor to end of trace.
+
+* `t`: Move cursor to top line on screen.
+* `c`: Move cursor to center line on screen.
+* `b`: Move cursor to bottom line on screen.
+* `T`: Scroll line at cursor to top of screen.
+
+* `/`: Search forward for a pattern.
+* '?': Search backward for a pattern.
+* `n`: Repeat the previous '/' or '?'.
+* `N`: Repeat the previous '/' or '?' in the opposite direction.
+
+After hitting `/`, the mini-editor on the bottom-most line supports the
+following hotkeys:
+* ascii characters: add the key to the pattern.
+* `Enter`: search for the pattern.
+* `Esc` or `ctrl-c`: cancel the current search, setting the screen back
+  to its state before the search.
+* `left-arrow`: move cursor left.
+* `right-arrow`: move cursor right.
+* `ctrl-a` or `home`: move cursor to start of search pattern.
+* `ctrl-e` or `end`: move cursor to end of search pattern.
+* `ctrl-u`: clear search pattern before cursor
+* `ctrl-k`: clear search pattern at and after cursor
diff --git a/browse_trace/browse_trace b/browse_trace/browse_trace
new file mode 100755
index 00000000..f80ea659
--- /dev/null
+++ b/browse_trace/browse_trace
@@ -0,0 +1,7 @@
+#!/bin/sh
+set -e
+
+cd `dirname $0`
+./build
+cd -
+`dirname $0`/browse_trace_bin $*
diff --git a/100trace_browser.cc b/browse_trace/browse_trace.cc
index 8b0f949e..cc03f5ce 100644
--- a/100trace_browser.cc
+++ b/browse_trace/browse_trace.cc
@@ -1,105 +1,113 @@
-//: A debugging helper that lets you zoom in/out on a trace.
-//: Warning: this tool has zero automated tests.
-//:
-//: To try it out, first create an example trace:
-//:   mu --trace nqueens.mu
-//: Then to browse the trace, which was stored in a file called 'last_run':
-//:   mu browse-trace last_run
-//:
-//: You should now find yourself in a UI showing a subsequence of lines from
-//: the trace, each line starting with a numeric depth, and ending with a
-//: parenthetical count of trace lines hidden after it with greater depths.
-//:
-//: For example, this line:
-//:   2 app: line1 (30)
-//: indicates that it was logged with depth 2, and that 30 following lines
-//: have been hidden at a depth greater than 2.
-//:
-//: As an experiment, hidden counts of 1000 or more are in red to highlight
-//: where you might be particularly interested in expanding.
-//:
-//: The UI provides the following hotkeys:
-//:
-//:   `q` or `ctrl-c`: Quit.
-//:
-//:   `Enter`: 'Zoom into' this line. Expand some or all of the hidden lines
-//:   at the next higher level, updating parenthetical counts of hidden lines.
-//:
-//:   `Backspace`: 'Zoom out' on a line after zooming in, collapsing expanded
-//:   lines below by some series of <Enter> commands.
-//:
-//:   `j` or `down-arrow`: Move/scroll cursor down one line.
-//:   `k` or `up-arrow`: Move/scroll cursor up one line.
-//:   `J` or `ctrl-f` or `page-down`: Scroll cursor down one page.
-//:   `K` or `ctrl-b` or `page-up`: Scroll cursor up one page.
-//:   `h` or `left-arrow`: Scroll cursor left one character.
-//:   `l` or `right-arrow`: Scroll cursor right one character.
-//:   `H`: Scroll cursor left one screen-width.
-//:   `L`: Scroll cursor right one screen-width.
-//:
-//:   `g` or `home`: Move cursor to start of trace.
-//:   `G` or `end`: Move cursor to end of trace.
-//:
-//:   `t`: Move cursor to top line on screen.
-//:   `c`: Move cursor to center line on screen.
-//:   `b`: Move cursor to bottom line on screen.
-//:   `T`: Scroll line at cursor to top of screen.
-//:
-//:   `/`: Search forward for a pattern.
-//:   '?': Search backward for a pattern.
-//:   `n`: Repeat the previous '/' or '?'.
-//:   `N`: Repeat the previous '/' or '?' in the opposite direction.
-//:
-//:   After hitting `/`, a small editor on the bottom-most line supports the
-//:   following hotkeys:
-//:     ascii characters: add the key to the pattern.
-//:     `Enter`: search for the pattern.
-//:     `Esc` or `ctrl-c`: cancel the current search, setting the screen back
-//:       to its state before the search.
-//:     `left-arrow`: move cursor left.
-//:     `right-arrow`: move cursor right.
-//:     `ctrl-a` or `home`: move cursor to start of search pattern.
-//:     `ctrl-e` or `end`: move cursor to end of search pattern.
-//:     `ctrl-u`: clear search pattern before cursor
-//:     `ctrl-k`: clear search pattern at and after cursor
+// Warning: zero automated tests
 
-:(before "End Primitive Recipe Declarations")
-_BROWSE_TRACE,
-:(before "End Primitive Recipe Numbers")
-put(Recipe_ordinal, "$browse-trace", _BROWSE_TRACE);
-:(before "End Primitive Recipe Checks")
-case _BROWSE_TRACE: {
-  break;
+// Includes
+#include "../termbox/termbox.h"
+
+#include <stdlib.h>
+#define SIZE(X) (assert((X).size() < (1LL<<(sizeof(int)*8-2))), static_cast<int>((X).size()))
+
+#include <assert.h>
+#include <iostream>
+using std::istream;
+using std::ostream;
+using std::iostream;
+using std::cin;
+using std::cout;
+using std::cerr;
+#include <iomanip>
+#include <string.h>
+#include <string>
+using std::string;
+#include <vector>
+using std::vector;
+#include <set>
+using std::set;
+#include <sstream>
+using std::ostringstream;
+#include <fstream>
+using std::ifstream;
+using std::ofstream;
+#include <map>
+using std::map;
+#include <utility>
+using std::pair;
+// End Includes
+
+// Types
+struct trace_line {
+  string contents;
+  string label;
+  int depth;  // 0 is 'sea level'; positive integers are progressively 'deeper' and lower level
+  trace_line(string c, string l, int d) {
+    contents = c;
+    label = l;
+    depth = d;
+  }
+};
+
+struct trace_stream {
+  vector<trace_line> past_lines;
+};
+
+enum search_direction { FORWARD, BACKWARD };
+// End Types
+
+// Function prototypes are auto-generated in the 'build*' scripts; define your
+// functions in any order. Just be sure to declare each function header all on
+// one line, ending with the '{'. Our auto-generation scripts are too minimal
+// and simple-minded to handle anything else.
+#include "function_list"  // by convention, files ending with '_list' are auto-generated
+
+// from http://stackoverflow.com/questions/152643/idiomatic-c-for-reading-from-a-const-map
+template<typename T> typename T::mapped_type& get(T& map, typename T::key_type const& key) {
+  typename T::iterator iter(map.find(key));
+  assert(iter != map.end());
+  return iter->second;
 }
-:(before "End Primitive Recipe Implementations")
-case _BROWSE_TRACE: {
-  start_trace_browser();
-  break;
+template<typename T> typename T::mapped_type const& get(const T& map, typename T::key_type const& key) {
+  typename T::const_iterator iter(map.find(key));
+  assert(iter != map.end());
+  return iter->second;
 }
-
-//: browse a trace loaded from a file
-:(after "Commandline Parsing")
-if (argc == 3 && is_equal(argv[1], "browse-trace")) {
-  load_trace(argv[2]);
-  start_trace_browser();
-  return 0;
+template<typename T> typename T::mapped_type const& put(T& map, typename T::key_type const& key, typename T::mapped_type const& value) {
+  // map[key] requires mapped_type to have a zero-arg (default) constructor
+  map.insert(std::make_pair(key, value)).first->second = value;
+  return value;
+}
+template<typename T> bool contains_key(T& map, typename T::key_type const& key) {
+  return map.find(key) != map.end();
 }
+template<typename T> typename T::mapped_type& get_or_insert(T& map, typename T::key_type const& key) {
+  return map[key];
+}
+
+// Globals
+trace_stream* Trace_stream = NULL;
 
-:(before "End Globals")
+ofstream Trace_file;
+int Display_row = 0;
+int Display_column = 0;
 set<int> Visible;
 int Top_of_screen = 0;
 int Left_of_screen = 0;
 int Last_printed_row = 0;
 map<int, int> Trace_index;  // screen row -> trace index
+
 string Current_search_pattern = "";
-:(before "End Types")
-enum search_direction { FORWARD, BACKWARD };
-:(before "End Globals")
 search_direction Current_search_direction = FORWARD;
+// End Globals
+
+bool has_data(istream& in) {
+  return in && !in.eof();
+}
 
-:(code)
-void start_trace_browser() {
-  if (!Trace_stream) return;
+int main(int argc, char* argv[]) {
+  if (argc != 2) {
+    cerr << "Usage: browse_trace <trace file>\n";
+    return 1;
+  }
+  load_trace(argv[1]);
+  if (!Trace_stream) return 1;
   cerr << "computing min depth to display\n";
   int min_depth = 9999;
   for (int i = 0;  i < SIZE(Trace_stream->past_lines);  ++i) {
@@ -266,6 +274,7 @@ void start_trace_browser() {
     }
   }
   tb_shutdown();
+  return 0;
 }
 
 bool start_search_editor(search_direction dir) {
@@ -514,7 +523,7 @@ void load_trace(const char* filename) {
     if (*--label.end() == ':') label.erase(--label.end());
     string line;
     getline(tin, line);
-    Trace_stream->past_lines.push_back(trace_line(depth, label, line));
+    Trace_stream->past_lines.push_back(trace_line(line, label, depth));
   }
   cerr << "lines read: " << Trace_stream->past_lines.size() << '\n';
 }
@@ -526,3 +535,12 @@ int read_key() {
   } while (event.type != TB_EVENT_KEY);
   return event.key ? event.key : event.ch;
 }
+
+void skip_whitespace_but_not_newline(istream& in) {
+  while (true) {
+    if (!has_data(in)) break;
+    else if (in.peek() == '\n') break;
+    else if (isspace(in.peek())) in.get();
+    else break;
+  }
+}
diff --git a/browse_trace/build b/browse_trace/build
new file mode 100755
index 00000000..6047cc2b
--- /dev/null
+++ b/browse_trace/build
@@ -0,0 +1,83 @@
+#!/bin/sh
+# For details on the basic form of this script, see https://notabug.org/akkartik/basic-build.
+
+set -e  # stop immediately on error
+
+# Some environment variables that can be passed in. For example, to turn off
+# optimization:
+#   $ CFLAGS=-g ./build2
+test "$CXX" || export CXX=c++
+test "$CC" || export CC=cc
+test "$CFLAGS" || export CFLAGS="-g -O2"
+export CFLAGS="$CFLAGS -Wall -Wextra -ftrapv -fno-strict-aliasing"
+
+# there's two mechanisms for fast builds here:
+# - if a command is quick to run, always run it but update the result only on any change
+# - otherwise run it only if the output is 'older_than' the inputs
+#
+# avoid combining both mechanisms for a single file
+# otherwise you'll see spurious messages about files being updated
+# risk: a file may unnecessarily update without changes, causing unnecessary work downstream
+
+# return 1 if $1 is older than _any_ of the remaining args
+older_than() {
+  local target=$1
+  shift
+  if [ ! -e $target ]
+  then
+#?     echo "$target doesn't exist"
+    echo "updating $target" >&2
+    return 0  # success
+  fi
+  local f
+  for f in $*
+  do
+    if [ $f -nt $target ]
+    then
+      echo "updating $target" >&2
+      return 0  # success
+    fi
+  done
+  return 1  # failure
+}
+
+# redirect to $1, unless it's already identical
+update() {
+  if [ ! -e $1 ]
+  then
+    cat > $1
+  else
+    cat > $1.tmp
+    diff -q $1 $1.tmp >/dev/null  &&  rm $1.tmp  ||  mv $1.tmp $1
+  fi
+}
+
+noisy_cd() {
+  cd $1
+  echo "-- `pwd`" >&2
+}
+
+older_than browse_trace_bin browse_trace.cc *_list ../termbox/*  &&  {
+  # missing some deps here
+  noisy_cd ../termbox
+    older_than ../termbox/libtermbox.a ../termbox/*.c  &&  {
+      older_than utf8.o utf8.c && {
+        $CC $CFLAGS -c utf8.c
+      }
+      older_than termbox.o termbox.c termbox.h input.inl output.inl bytebuffer.inl && {
+        $CC $CFLAGS -c termbox.c
+      }
+      older_than libtermbox.a *.o && {
+        ar rcs libtermbox.a *.o
+      }
+    }
+  noisy_cd ../browse_trace
+
+  grep -h "^[^[:space:]#].*) {$" browse_trace.cc  |grep -v ":.*("  |sed 's/ {.*/;/'  |update function_list
+  # auto-generate list of tests to run
+  grep -h "^\s*void test_" browse_trace.cc  |sed 's/^\s*void \(.*\)() {.*/\1,/'  |update test_list
+  grep -h "^\s*void test_" browse_trace.cc  |sed 's/^\s*void \(.*\)() {.*/"\1",/'  |update test_name_list
+  $CXX $CFLAGS browse_trace.cc ../termbox/libtermbox.a -o browse_trace_bin
+}
+
+exit 0
diff --git a/browse_trace/clean b/browse_trace/clean
new file mode 100755
index 00000000..69b30478
--- /dev/null
+++ b/browse_trace/clean
@@ -0,0 +1,6 @@
+#!/bin/sh
+set -e
+
+set -v
+rm -rf browse_trace_bin* *_list
+rm -rf termbox/*.o termbox/libtermbox.a
diff --git a/subx/003trace.cc b/subx/003trace.cc
index e2080898..b794cab9 100644
--- a/subx/003trace.cc
+++ b/subx/003trace.cc
@@ -13,30 +13,31 @@
 //: longer valid. In both cases you end up having to reorganize code as well as
 //: tests, an error-prone activity.
 //:
-//: In response, this layer introduces the notion of *domain-driven* testing.
-//: We focus on the domain of inputs the whole program needs to handle rather
-//: than the correctness of individual functions. All tests invoke the program
-//: in a single way: by calling run() with some input. As the program operates
-//: on the input, it traces out a list of _facts_ deduced about the domain:
+//: In response, this layer introduces the notion of domain-driven *white-box*
+//: testing. We focus on the domain of inputs the whole program needs to
+//: handle rather than the correctness of individual functions. All white-box
+//: tests (we call them 'scenarios') invoke the program in a single way: by
+//: calling run() with some input. As the program operates on the input, it
+//: traces out a list of _facts_ deduced about the domain:
 //:   trace("label") << "fact 1: " << val;
 //:
-//: Tests can now check these facts:
+//: Scenarios can now check these facts:
 //:   :(scenario foo)
 //:   34  # call run() with this input
 //:   +label: fact 1: 34  # 'run' should have deduced this fact
 //:   -label: fact 1: 35  # the trace should not contain such a fact
 //:
 //: Since we never call anything but the run() function directly, we never have
-//: to rewrite the tests when we reorganize the internals of the program. We
+//: to rewrite the scenarios when we reorganize the internals of the program. We
 //: just have to make sure our rewrite deduces the same facts about the domain,
 //: and that's something we're going to have to do anyway.
 //:
 //: To avoid the combinatorial explosion of integration tests, each layer
-//: mainly logs facts to the trace with a common *label*. All tests in a layer
-//: tend to check facts with this label. Validating the facts logged with a
-//: specific label is like calling functions of that layer directly.
+//: mainly logs facts to the trace with a common *label*. All scenarios in a
+//: layer tend to check facts with this label. Validating the facts logged
+//: with a specific label is like calling functions of that layer directly.
 //:
-//: To build robust tests, trace facts about your domain rather than details of
+//: To build robust scenarios, trace facts about your domain rather than details of
 //: how you computed them.
 //:
 //: More details: http://akkartik.name/blog/tracing-tests
@@ -44,158 +45,183 @@
 //: ---
 //:
 //: Between layers and domain-driven testing, programming starts to look like a
-//: fundamentally different activity. Instead of a) superficial, b) local rules
-//: on c) code [like say http://blog.bbv.ch/2013/06/05/clean-code-cheat-sheet],
-//: we allow programmers to engage with the a) deep, b) global structure of the
-//: c) domain. If you can systematically track discontinuities in the domain,
-//: you don't care if the code used gotos as long as it passed the tests. If
-//: tests become more robust to run it becomes easier to try out radically
-//: different implementations for the same program. If code is super-easy to
-//: rewrite, it becomes less important what indentation style it uses, or that
-//: the objects are appropriately encapsulated, or that the functions are
-//: referentially transparent.
+//: fundamentally different activity. Instead of focusing on a) superficial,
+//: b) local rules on c) code [like say http://blog.bbv.ch/2013/06/05/clean-code-cheat-sheet],
+//: we allow programmers to engage with the a) deep, b) global structure of
+//: the c) domain. If you can systematically track discontinuities in the
+//: domain, you don't care if the code used gotos as long as it passed all
+//: scenarios. If scenarios become more robust to run, it becomes easier to
+//: try out radically different implementations for the same program. If code
+//: is super-easy to rewrite, it becomes less important what indentation style
+//: it uses, or that the objects are appropriately encapsulated, or that the
+//: functions are referentially transparent.
 //:
 //: Instead of plumbing, programming becomes building and gradually refining a
-//: map of the environment the program must operate under. Whether a program is
-//: 'correct' at a given point in time is a red herring; what matters is
-//: avoiding regression by monotonically nailing down the more 'eventful' parts
-//: of the terrain. It helps readers new and old, and rewards curiosity, to
-//: organize large programs in self-similar hierarchies of example scenarios
+//: map of the environment the program must operate under. Whether a program
+//: is 'correct' at a given point in time is a red herring; what matters is
+//: avoiding regression by monotonically nailing down the more 'eventful'
+//: parts of the terrain. It helps readers new and old, and rewards curiosity,
+//: to organize large programs in self-similar hierarchies of example scenarios
 //: colocated with the code that makes them work.
 //:
 //:   "Programming properly should be regarded as an activity by which
 //:   programmers form a mental model, rather than as production of a program."
 //:   -- Peter Naur (http://alistair.cockburn.us/ASD+book+extract%3A+%22Naur,+Ehn,+Musashi%22)
 
+//:: == Core data structures
+
+:(before "End Globals")
+trace_stream* Trace_stream = NULL;
+
 :(before "End Types")
-struct trace_line {
-  int depth;  // optional field just to help browse traces later
-  string label;
-  string contents;
-  trace_line(string l, string c) :depth(0), label(l), contents(c) {}
-  trace_line(int d, string l, string c) :depth(d), label(l), contents(c) {}
+struct trace_stream {
+  vector<trace_line> past_lines;
+  // End trace_stream Fields
+
+  trace_stream() {
+    // End trace_stream Constructor
+  }
+  ~trace_stream() {
+    // End trace_stream Destructor
+  }
+  // End trace_stream Methods
 };
 
-:(code)
-void cleanup_main() {
-  if (!Trace_stream) return;
-  delete Trace_stream;
-  Trace_stream = NULL;
-}
-:(before "End One-time Setup")
-atexit(cleanup_main);
+//:: == Adding to the trace
 
-:(before "End Types")
-// Pre-define some global constants that trace_stream needs to know about.
-// Since they're in the Types section, they'll be included in any cleaved
-// compilation units. So no extern linkage.
+//: Top-level method is trace() which can be used like an ostream. Usage:
+//:   trace(depth, label) << ... << end();
+//: Don't forget the 'end()' to actually append to the trace.
+:(before "End Includes")
+// No brackets around the expansion so that it prints nothing if Trace_stream
+// isn't initialized.
+#define trace(...)  !Trace_stream ? cerr : Trace_stream->stream(__VA_ARGS__)
+
+:(before "End trace_stream Fields")
+// accumulator for current trace_line
+ostringstream* curr_stream;
+string curr_label;
+int curr_depth;
+// other stuff
+int collect_depth;  // avoid tracing lower levels for speed
+ofstream null_stream;  // never opened, so writes to it silently fail
+
+//: Some constants.
+:(before "struct trace_stream")  // include constants in all cleaved compilation units
 const int Max_depth = 9999;
-const int Error_depth = 0;  // definitely always print errors
+// Most important traces are printed to the screen by default
+const int Error_depth = 0;
 const int Warn_depth = 1;
+:(before "End Globals")
+int Hide_errors = false;  // if set, don't print errors or warnings to screen
+int Hide_warnings = false;  // if set, don't print warnings to screen
+:(before "End trace_stream Constructor")
+curr_stream = NULL;
+curr_depth = Max_depth;
+collect_depth = Max_depth;
+:(before "End Reset")
+Hide_errors = false;
+Hide_warnings = false;
+//: Never dump warnings in scenarios
+:(before "End Test Setup")
+Hide_warnings = true;
 
-struct trace_stream {
-  vector<trace_line> past_lines;
-  // accumulator for current line
-  ostringstream* curr_stream;
-  string curr_label;
-  int curr_depth;
-  int collect_depth;
-  ofstream null_stream;  // never opens a file, so writes silently fail
-  trace_stream() :curr_stream(NULL), curr_depth(Max_depth), collect_depth(Max_depth) {}
-  ~trace_stream() { if (curr_stream) delete curr_stream; }
-
-  ostream& stream(string label) {
-    return stream(Max_depth, label);
+:(before "struct trace_stream")
+struct trace_line {
+  string contents;
+  string label;
+  int depth;  // 0 is 'sea level'; positive integers are progressively 'deeper' and lower level
+  trace_line(string c, string l) {
+    contents = c;
+    label = l;
+    depth = 0;
   }
-
-  ostream& stream(int depth, string label) {
-    if (depth > collect_depth) return null_stream;
-    curr_stream = new ostringstream;
-    curr_label = label;
-    curr_depth = depth;
-    (*curr_stream) << std::hex;
-    return *curr_stream;
+  trace_line(string c, string l, int d) {
+    contents = c;
+    label = l;
+    depth = d;
   }
-
-  // be sure to call this before messing with curr_stream or curr_label
-  void newline();
-  // useful for debugging
-  string readable_contents(string label);  // empty label = show everything
 };
 
+//: Starting a new trace line.
+:(before "End trace_stream Methods")
+ostream& stream(string label) {
+  return stream(Max_depth, label);
+}
+
+ostream& stream(int depth, string label) {
+  if (depth > collect_depth) return null_stream;
+  curr_stream = new ostringstream;
+  curr_label = label;
+  curr_depth = depth;
+  (*curr_stream) << std::hex;  // printing addresses is the common case
+  return *curr_stream;
+}
+
+//: End of a trace line; append it to the trace.
+:(before "End Types")
+struct end {};
+:(code)
+ostream& operator<<(ostream& os, end /*unused*/) {
+  if (Trace_stream) Trace_stream->newline();
+  return os;
+}
+
+:(before "End trace_stream Methods")
+void newline();
 :(code)
 void trace_stream::newline() {
   if (!curr_stream) return;
   string curr_contents = curr_stream->str();
   if (!curr_contents.empty()) {
-    past_lines.push_back(trace_line(curr_depth, trim(curr_label), curr_contents));  // preserve indent in contents
+    past_lines.push_back(trace_line(curr_contents, trim(curr_label), curr_depth));  // preserve indent in contents
+    // maybe incrementally dump trace
+    trace_line& t = past_lines.back();
     if ((!Hide_errors && curr_depth == Error_depth)
-        || (!Hide_warnings && !Hide_errors && curr_depth == Warn_depth)
-        || Dump_trace
-        || (!Dump_label.empty() && curr_label == Dump_label))
-      cerr << curr_label << ": " << curr_contents << '\n';
+        || (!Hide_warnings && !Hide_errors && curr_depth == Warn_depth)) {
+      cerr       << std::setw(4) << t.depth << ' ' << t.label << ": " << t.contents << '\n';
+    }
+    // End trace Commit
   }
+
+  // clean up
   delete curr_stream;
   curr_stream = NULL;
   curr_label.clear();
   curr_depth = Max_depth;
 }
 
-string trace_stream::readable_contents(string label) {
-  ostringstream output;
-  label = trim(label);
-  for (vector<trace_line>::iterator p = past_lines.begin();  p != past_lines.end();  ++p)
-    if (label.empty() || label == p->label)
-      output << std::setw(4) << p->depth << ' ' << p->label << ": " << p->contents << '\n';
-  return output.str();
-}
+//:: == Initializing the trace in scenarios
 
-:(before "End Globals")
-trace_stream* Trace_stream = NULL;
-int Trace_errors = 0;  // used only when Trace_stream is NULL
+:(before "End Includes")
+#define START_TRACING_UNTIL_END_OF_SCOPE  lease_tracer leased_tracer;
+:(before "End Test Setup")
+START_TRACING_UNTIL_END_OF_SCOPE
 
-//: commandline flag to print trace incrementally to stderr
-:(before "End Globals")
-bool Flag_dump_trace = false;
-:(before "End Commandline Options(*arg)")
-else if (is_equal(*arg, "--trace")) {
-  Flag_dump_trace = true;
+//: Trace_stream is a resource, lease_tracer uses RAII to manage it.
+:(before "End Types")
+struct lease_tracer {
+  lease_tracer();
+  ~lease_tracer();
+};
+:(code)
+lease_tracer::lease_tracer() { Trace_stream = new trace_stream; }
+lease_tracer::~lease_tracer() {
+  delete Trace_stream;
+  Trace_stream = NULL;
 }
 
-:(before "End Globals")
-bool Hide_errors = false;  // if set, don't print even error trace lines to screen
-bool Hide_warnings = false;  // if set, don't print warnings to screen
-bool Dump_trace = false;  // if set, print trace lines to screen
-string Dump_label = "";  // if set, print trace lines matching a single label to screen
-:(before "End Reset")
-Hide_errors = false;
-Hide_warnings = false;
-Dump_trace = Flag_dump_trace;
-Dump_label = "";
-//: Never dump warnings in scenarios
-:(before "End Test Setup")
-Hide_warnings = true;
+//:: == Errors and warnings using traces
 
 :(before "End Includes")
-#define CLEAR_TRACE  delete Trace_stream, Trace_stream = new trace_stream;
-
-// Top-level helper. IMPORTANT: can't nest
-#define trace(...)  !Trace_stream ? cerr /*print nothing*/ : Trace_stream->stream(__VA_ARGS__)
-
-// Just for debugging; 'git log' should never show any calls to 'dbg'.
-#define dbg trace(0, "a")
-#define DUMP(label)  if (Trace_stream) cerr << Trace_stream->readable_contents(label);
-
-// Errors and warnings are special layers.
 #define raise  (!Trace_stream ? (++Trace_errors,cerr) /*do print*/ : Trace_stream->stream(Error_depth, "error"))
 #define warn (!Trace_stream ? (++Trace_errors,cerr) /*do print*/ : Trace_stream->stream(Warn_depth, "warn"))
-// If we aren't yet sure how to deal with some corner case, use assert_for_now
-// to indicate that it isn't an inviolable invariant.
-#define assert_for_now assert
-#define raise_for_now raise
 
-// Inside tests, fail any tests that displayed (unexpected) errors.
-// Expected errors in tests should always be hidden and silently checked for.
+:(before "End Globals")
+int Trace_errors = 0;  // used only when Trace_stream is NULL
+
+// Fail scenarios that displayed (unexpected) errors.
+// Expected errors should always be hidden and silently checked for.
 :(before "End Test Teardown")
 if (Passed && !Hide_errors && trace_contains_errors()) {
   Passed = false;
@@ -205,41 +231,33 @@ bool trace_contains_errors() {
   return Trace_errors > 0 || trace_count("error") > 0;
 }
 
-:(before "End Types")
-struct end {};
-:(code)
-ostream& operator<<(ostream& os, end /*unused*/) {
-  if (Trace_stream) Trace_stream->newline();
-  return os;
-}
-
-// Trace_stream is a resource, lease_tracer uses RAII to manage it.
-:(before "End Types")
-struct lease_tracer {
-  lease_tracer();
-  ~lease_tracer();
-};
-:(code)
-lease_tracer::lease_tracer() { Trace_stream = new trace_stream; }
-lease_tracer::~lease_tracer() {
-  delete Trace_stream, Trace_stream = NULL;
-}
 :(before "End Includes")
-#define START_TRACING_UNTIL_END_OF_SCOPE  lease_tracer leased_tracer;
-:(before "End Test Setup")
-START_TRACING_UNTIL_END_OF_SCOPE
+// If we aren't yet sure how to deal with some corner case, use assert_for_now
+// to indicate that it isn't an inviolable invariant.
+#define assert_for_now assert
+#define raise_for_now raise
+
+//:: == Other assertions on traces
+//: Primitives:
+//:   - CHECK_TRACE_CONTENTS(lines)
+//:     Assert that the trace contains the given lines (separated by newlines)
+//:     in order. There can be other intervening lines between them.
+//:   - CHECK_TRACE_DOESNT_CONTAIN(line)
+//:   - CHECK_TRACE_DOESNT_CONTAIN(label, contents)
+//:     Assert that the trace doesn't contain the given (single) line.
+//:   - CHECK_TRACE_COUNT(label, count)
+//:     Assert that the trace contains exactly 'count' lines with the given
+//:     'label'.
+//:   - CHECK_TRACE_CONTAINS_ERRORS()
+//:   - CHECK_TRACE_DOESNT_CONTAIN_ERRORS()
+//:   - trace_count_prefix(label, prefix)
+//:     Count the number of trace lines with the given 'label' that start with
+//:     the given 'prefix'.
 
 :(before "End Includes")
 #define CHECK_TRACE_CONTENTS(...)  check_trace_contents(__FUNCTION__, __FILE__, __LINE__, __VA_ARGS__)
 
-#define CHECK_TRACE_CONTAINS_ERRORS()  CHECK(trace_contains_errors())
-#define CHECK_TRACE_DOESNT_CONTAIN_ERRORS() \
-  if (Passed && trace_contains_errors()) { \
-    cerr << "\nF - " << __FUNCTION__ << "(" << __FILE__ << ":" << __LINE__ << "): unexpected errors\n"; \
-    DUMP("error"); \
-    Passed = false; \
-    return; \
-  }
+#define CHECK_TRACE_DOESNT_CONTAIN(...)  CHECK(trace_doesnt_contain(__VA_ARGS__))
 
 #define CHECK_TRACE_COUNT(label, count) \
   if (Passed && trace_count(label) != (count)) { \
@@ -250,7 +268,17 @@ START_TRACING_UNTIL_END_OF_SCOPE
     return;  /* Currently we stop at the very first failure. */ \
   }
 
-#define CHECK_TRACE_DOESNT_CONTAIN(...)  CHECK(trace_doesnt_contain(__VA_ARGS__))
+#define CHECK_TRACE_CONTAINS_ERRORS()  CHECK(trace_contains_errors())
+#define CHECK_TRACE_DOESNT_CONTAIN_ERRORS() \
+  if (Passed && trace_contains_errors()) { \
+    cerr << "\nF - " << __FUNCTION__ << "(" << __FILE__ << ":" << __LINE__ << "): unexpected errors\n"; \
+    DUMP("error"); \
+    Passed = false; \
+    return; \
+  }
+
+// Allow scenarios to ignore trace lines generated during setup.
+#define CLEAR_TRACE  delete Trace_stream, Trace_stream = new trace_stream
 
 :(code)
 bool check_trace_contents(string FUNCTION, string FILE, int LINE, string expected) {
@@ -285,25 +313,13 @@ bool check_trace_contents(string FUNCTION, string FILE, int LINE, string expecte
   return false;
 }
 
-void split_label_contents(const string& s, string* label, string* contents) {
-  static const string delim(": ");
-  size_t pos = s.find(delim);
-  if (pos == string::npos) {
-    *label = "";
-    *contents = trim(s);
-  }
-  else {
-    *label = trim(s.substr(0, pos));
-    *contents = trim(s.substr(pos+SIZE(delim)));
-  }
-}
-
-bool line_exists_anywhere(const string& label, const string& contents) {
-  for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
-    if (label != p->label) continue;
-    if (contents == trim(p->contents)) return true;
+bool trace_doesnt_contain(string expected) {
+  vector<string> tmp = split_first(expected, ": ");
+  if (SIZE(tmp) == 1) {
+    raise << expected << ": missing label or contents in trace line\n" << end();
+    assert(false);
   }
-  return false;
+  return trace_count(tmp.at(0), tmp.at(1)) == 0;
 }
 
 int trace_count(string label) {
@@ -334,17 +350,25 @@ int trace_count_prefix(string label, string prefix) {
   return result;
 }
 
-bool trace_doesnt_contain(string label, string line) {
-  return trace_count(label, line) == 0;
+void split_label_contents(const string& s, string* label, string* contents) {
+  static const string delim(": ");
+  size_t pos = s.find(delim);
+  if (pos == string::npos) {
+    *label = "";
+    *contents = trim(s);
+  }
+  else {
+    *label = trim(s.substr(0, pos));
+    *contents = trim(s.substr(pos+SIZE(delim)));
+  }
 }
 
-bool trace_doesnt_contain(string expected) {
-  vector<string> tmp = split_first(expected, ": ");
-  if (SIZE(tmp) == 1) {
-    raise << expected << ": missing label or contents in trace line\n" << end();
-    assert(false);
+bool line_exists_anywhere(const string& label, const string& contents) {
+  for (vector<trace_line>::iterator p = Trace_stream->past_lines.begin();  p != Trace_stream->past_lines.end();  ++p) {
+    if (label != p->label) continue;
+    if (contents == trim(p->contents)) return true;
   }
-  return trace_doesnt_contain(tmp.at(0), tmp.at(1));
+  return false;
 }
 
 vector<string> split(string s, string delim) {
@@ -371,6 +395,53 @@ vector<string> split_first(string s, string delim) {
   return result;
 }
 
+//:: == Helpers for debugging using traces
+
+:(before "End Includes")
+// To debug why a scenario is failing, dump its trace using '?'.
+#define DUMP(label)  if (Trace_stream) cerr << Trace_stream->readable_contents(label);
+
+// To add temporary prints to the trace, use 'dbg'.
+// `git log` should never show any calls to 'dbg'.
+#define dbg trace(0, "a")
+
+//: Dump the entire trace to file where it can be browsed offline.
+//: Dump the trace as it happens; that way you get something even if the
+//: program crashes.
+
+:(before "End Globals")
+ofstream Trace_file;
+:(before "End Commandline Options(*arg)")
+else if (is_equal(*arg, "--trace")) {
+  cerr << "saving trace to 'last_run'\n";
+  Trace_file.open("last_run");
+}
+:(before "End trace Commit")
+if (Trace_file) {
+  Trace_file << std::setw(4) << t.depth << ' ' << t.label << ": " << t.contents << '\n';
+}
+:(before "End One-time Setup")
+atexit(cleanup_main);
+:(code)
+void cleanup_main() {
+  if (Trace_file) Trace_file.close();
+  // End cleanup_main
+}
+
+:(before "End trace_stream Methods")
+string readable_contents(string label) {
+  string trim(const string& s);  // prototype
+  ostringstream output;
+  label = trim(label);
+  for (vector<trace_line>::iterator p = past_lines.begin();  p != past_lines.end();  ++p)
+    if (label.empty() || label == p->label)
+      output << std::setw(4) << p->depth << ' ' << p->label << ": " << p->contents << '\n';
+  return output.str();
+}
+
+//: Miscellaneous helpers.
+
+:(code)
 string trim(const string& s) {
   string::const_iterator first = s.begin();
   while (first != s.end() && isspace(*first))
diff --git a/subx/010---vm.cc b/subx/010---vm.cc
index 0d30f3cd..4c346a3d 100644
--- a/subx/010---vm.cc
+++ b/subx/010---vm.cc
@@ -92,7 +92,7 @@ SF = ZF = OF = false;
   /* arg1 and arg2 must be signed */ \
   int64_t tmp = arg1 op arg2; \
   arg1 = arg1 op arg2; \
-  trace(90, "run") << "storing 0x" << HEXWORD << arg1 << end(); \
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << arg1 << end(); \
   SF = (arg1 < 0); \
   ZF = (arg1 == 0); \
   OF = (arg1 != tmp); \
@@ -103,7 +103,7 @@ SF = ZF = OF = false;
 #define BINARY_BITWISE_OP(op, arg1, arg2) { \
   /* arg1 and arg2 must be unsigned */ \
   arg1 = arg1 op arg2; \
-  trace(90, "run") << "storing 0x" << HEXWORD << arg1 << end(); \
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << arg1 << end(); \
   SF = (arg1 >> 31); \
   ZF = (arg1 == 0); \
   OF = false; \
@@ -296,13 +296,13 @@ inline bool already_allocated(uint32_t addr) {
 void run_one_instruction() {
   uint8_t op=0, op2=0, op3=0;
   // Run One Instruction
-  if (Dump_trace) {
+  if (Trace_file) {
     dump_registers();
     // End Dump Info for Instruction
   }
-  trace(90, "run") << "inst: 0x" << HEXWORD << EIP << end();
+  uint32_t inst_start_address = EIP;
   op = next();
-  trace(90, "run") << "opcode: " << HEXBYTE << NUM(op) << end();
+  trace(Callstack_depth, "run") << "0x" << HEXWORD << inst_start_address << " opcode: " << HEXBYTE << NUM(op) << (op == 0xe8 ? "/call" : "") << end();
   switch (op) {
   case 0xf4:  // hlt
     EIP = End_of_program;
@@ -372,7 +372,7 @@ void dump_registers() {
     out << "  " << i << ": " << std::hex << std::setw(8) << std::setfill('_') << Reg[i].u;
   }
   out << " -- SF: " << SF << "; ZF: " << ZF << "; OF: " << OF;
-  trace(90, "run") << out.str() << end();
+  trace(Callstack_depth+1, "run") << out.str() << end();
 }
 
 //: start tracking supported opcodes
@@ -409,6 +409,24 @@ if (key == "opcodes") {
 :(before "End Help Contents")
 cerr << "  opcodes\n";
 
+//: Helpers for managing trace depths
+//:
+//: We're going to use trace depths primarily to segment code running at
+//: different frames of the call stack. This will make it easy for the trace
+//: browser to collapse over entire calls.
+//:
+//: Errors will be at depth 0.
+//: Warnings will be at depth 1.
+//: SubX instructions will occupy depth 2 and up to Max_depth, organized by
+//: stack frames. Each instruction's internal details will be one level deeper
+//: than its 'main' depth. So 'call' instruction details will be at the same
+//: depth as the instructions of the function it calls.
+:(before "End Globals")
+extern const int Initial_callstack_depth = 2;
+int Callstack_depth = Initial_callstack_depth;
+:(before "End Reset")
+Callstack_depth = Initial_callstack_depth;
+
 :(before "End Includes")
 #include <iomanip>
 #define HEXBYTE  std::hex << std::setw(2) << std::setfill('0')
diff --git a/subx/011run.cc b/subx/011run.cc
index 45a6699e..90af649b 100644
--- a/subx/011run.cc
+++ b/subx/011run.cc
@@ -127,7 +127,6 @@ struct word {
 :(code)
 void parse(istream& fin, program& out) {
   vector<line> l;
-  trace(99, "parse") << "begin" << end();
   while (has_data(fin)) {
     string line_data;
     line curr;
@@ -151,7 +150,7 @@ void parse(istream& fin, program& out) {
           s.start = parse_int(segment_title);
           sanity_check_program_segment(out, s.start);
           if (trace_contains_errors()) continue;
-          trace(99, "parse") << "new segment from 0x" << HEXWORD << s.start << end();
+          trace(3, "parse") << "new segment from 0x" << HEXWORD << s.start << end();
           out.segments.push_back(s);
         }
         // End Segment Parsing Special-cases(segment_title)
@@ -226,16 +225,13 @@ vector<transform_fn> Transform;
 
 :(code)
 void transform(program& p) {
-  trace(99, "transform") << "begin" << end();
   for (int t = 0;  t < SIZE(Transform);  ++t)
     (*Transform.at(t))(p);
-  trace(99, "transform") << "done" << end();
 }
 
 //:: load
 
 void load(const program& p) {
-  trace(99, "load") << "begin" << end();
   if (p.segments.empty()) {
     raise << "no code to run\n" << end();
     return;
@@ -265,7 +261,6 @@ void load(const program& p) {
   }
   EIP = p.segments.at(0).start;
   // End Initialize EIP
-  trace(99, "load") << "done" << end();
 }
 
 uint8_t hex_byte(const string& s) {
@@ -331,7 +326,7 @@ put_new(Name, "05", "add imm32 to EAX (add)");
 :(before "End Single-Byte Opcodes")
 case 0x05: {  // add imm32 to EAX
   int32_t arg2 = next32();
-  trace(90, "run") << "add imm32 0x" << HEXWORD << arg2 << " to reg EAX" << end();
+  trace(Callstack_depth+1, "run") << "add imm32 0x" << HEXWORD << arg2 << " to reg EAX" << end();
   BINARY_ARITHMETIC_OP(+, Reg[EAX].i, arg2);
   break;
 }
diff --git a/subx/012elf.cc b/subx/012elf.cc
index 5220d18d..c9bbfc70 100644
--- a/subx/012elf.cc
+++ b/subx/012elf.cc
@@ -6,6 +6,7 @@
 assert(argc > 1);
 if (is_equal(argv[1], "run")) {
   START_TRACING_UNTIL_END_OF_SCOPE;
+  trace(2, "run") << "=== Starting to run" << end();
   assert(argc > 2);
   reset();
   cerr << std::hex;
@@ -88,8 +89,8 @@ void load_elf_contents(uint8_t* elf_contents, size_t size, int argc, char* argv[
 
 void push(uint32_t val) {
   Reg[ESP].u -= 4;
-  trace(90, "run") << "decrementing ESP to 0x" << HEXWORD << Reg[ESP].u << end();
-  trace(90, "run") << "pushing value 0x" << HEXWORD << val << end();
+  trace(Callstack_depth+1, "run") << "decrementing ESP to 0x" << HEXWORD << Reg[ESP].u << end();
+  trace(Callstack_depth+1, "run") << "pushing value 0x" << HEXWORD << val << end();
   write_mem_u32(Reg[ESP].u, val);
 }
 
@@ -142,12 +143,12 @@ const int ARGV_DATA_SEGMENT = 0x0c000000;
 :(code)
 void dump_stack() {
   ostringstream out;
-  trace(91, "run") << "stack:" << end();
+  trace(Callstack_depth+1, "run") << "stack:" << end();
   for (uint32_t a = AFTER_STACK-4;  a > Reg[ESP].u;  a -= 4)
-    trace(91, "run") << "  0x" << HEXWORD << a << " => 0x" << HEXWORD << read_mem_u32(a) << end();
-  trace(91, "run") << "  0x" << HEXWORD << Reg[ESP].u << " => 0x" << HEXWORD << read_mem_u32(Reg[ESP].u) << "  <=== ESP" << end();
+    trace(Callstack_depth+1, "run") << "  0x" << HEXWORD << a << " => 0x" << HEXWORD << read_mem_u32(a) << end();
+  trace(Callstack_depth+1, "run") << "  0x" << HEXWORD << Reg[ESP].u << " => 0x" << HEXWORD << read_mem_u32(Reg[ESP].u) << "  <=== ESP" << end();
   for (uint32_t a = Reg[ESP].u-4;  a > Reg[ESP].u-40;  a -= 4)
-    trace(91, "run") << "  0x" << HEXWORD << a << " => 0x" << HEXWORD << read_mem_u32(a) << end();
+    trace(Callstack_depth+1, "run") << "  0x" << HEXWORD << a << " => 0x" << HEXWORD << read_mem_u32(a) << end();
 }
 
 inline uint32_t u32_in(uint8_t* p) {
diff --git a/subx/013direct_addressing.cc b/subx/013direct_addressing.cc
index b7146835..40f9f52e 100644
--- a/subx/013direct_addressing.cc
+++ b/subx/013direct_addressing.cc
@@ -18,7 +18,7 @@ put_new(Name, "01", "add r32 to rm32 (add)");
 case 0x01: {  // add r32 to r/m32
   uint8_t modrm = next();
   uint8_t arg2 = (modrm>>3)&0x7;
-  trace(90, "run") << "add " << rname(arg2) << " to r/m32" << end();
+  trace(Callstack_depth+1, "run") << "add " << rname(arg2) << " to r/m32" << end();
   int32_t* arg1 = effective_address(modrm);
   BINARY_ARITHMETIC_OP(+, *arg1, Reg[arg2].i);
   break;
@@ -34,7 +34,7 @@ int32_t* effective_address(uint8_t modrm) {
   const uint8_t rm = modrm & 0x7;
   if (mod == 3) {
     // mod 3 is just register direct addressing
-    trace(90, "run") << "r/m32 is " << rname(rm) << end();
+    trace(Callstack_depth+1, "run") << "r/m32 is " << rname(rm) << end();
     return &Reg[rm].i;
   }
   return mem_addr_i32(effective_address_number(modrm));
@@ -94,7 +94,7 @@ put_new(Name, "29", "subtract r32 from rm32 (sub)");
 case 0x29: {  // subtract r32 from r/m32
   const uint8_t modrm = next();
   const uint8_t arg2 = (modrm>>3)&0x7;
-  trace(90, "run") << "subtract " << rname(arg2) << " from r/m32" << end();
+  trace(Callstack_depth+1, "run") << "subtract " << rname(arg2) << " from r/m32" << end();
   int32_t* arg1 = effective_address(modrm);
   BINARY_ARITHMETIC_OP(-, *arg1, Reg[arg2].i);
   break;
@@ -120,17 +120,17 @@ put_new(Name, "f7", "negate/multiply rm32 (with EAX if necessary) depending on s
 :(before "End Single-Byte Opcodes")
 case 0xf7: {
   const uint8_t modrm = next();
-  trace(90, "run") << "operate on r/m32" << end();
+  trace(Callstack_depth+1, "run") << "operate on r/m32" << end();
   int32_t* arg1 = effective_address(modrm);
   const uint8_t subop = (modrm>>3)&0x7;  // middle 3 'reg opcode' bits
   switch (subop) {
   case 4: {  // mul unsigned EAX by r/m32
-    trace(90, "run") << "subop: multiply EAX by r/m32" << end();
+    trace(Callstack_depth+1, "run") << "subop: multiply EAX by r/m32" << end();
     const uint64_t result = Reg[EAX].u * static_cast<uint32_t>(*arg1);
     Reg[EAX].u = result & 0xffffffff;
     Reg[EDX].u = result >> 32;
     OF = (Reg[EDX].u != 0);
-    trace(90, "run") << "storing 0x" << HEXWORD << Reg[EAX].u << end();
+    trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << Reg[EAX].u << end();
     break;
   }
   // End Op f7 Subops
@@ -161,7 +161,7 @@ put_new(Name_0f, "af", "multiply rm32 into r32 (imul)");
 case 0xaf: {  // multiply r32 into r/m32
   const uint8_t modrm = next();
   const uint8_t arg2 = (modrm>>3)&0x7;
-  trace(90, "run") << "multiply r/m32 into " << rname(arg2) << end();
+  trace(Callstack_depth+1, "run") << "multiply r/m32 into " << rname(arg2) << end();
   const int32_t* arg1 = effective_address(modrm);
   BINARY_ARITHMETIC_OP(*, Reg[arg2].i, *arg1);
   break;
@@ -182,17 +182,17 @@ case 0xaf: {  // multiply r32 into r/m32
 
 :(before "End Op f7 Subops")
 case 3: {  // negate r/m32
-  trace(90, "run") << "subop: negate" << end();
+  trace(Callstack_depth+1, "run") << "subop: negate" << end();
   // one case that can overflow
   if (static_cast<uint32_t>(*arg1) == 0x80000000) {
-    trace(90, "run") << "overflow" << end();
+    trace(Callstack_depth+1, "run") << "overflow" << end();
     SF = true;
     ZF = false;
     OF = true;
     break;
   }
   *arg1 = -(*arg1);
-  trace(90, "run") << "storing 0x" << HEXWORD << *arg1 << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << *arg1 << end();
   SF = (*arg1 >> 31);
   ZF = (*arg1 == 0);
   OF = false;
@@ -230,12 +230,12 @@ put_new(Name, "d3", "shift rm32 by CL bits depending on subop (sal/sar/shl/shr)"
 :(before "End Single-Byte Opcodes")
 case 0xd3: {
   const uint8_t modrm = next();
-  trace(90, "run") << "operate on r/m32" << end();
+  trace(Callstack_depth+1, "run") << "operate on r/m32" << end();
   int32_t* arg1 = effective_address(modrm);
   const uint8_t subop = (modrm>>3)&0x7;  // middle 3 'reg opcode' bits
   switch (subop) {
   case 4: {  // shift left r/m32 by CL
-    trace(90, "run") << "subop: shift left by CL bits" << end();
+    trace(Callstack_depth+1, "run") << "subop: shift left by CL bits" << end();
     uint8_t count = Reg[ECX].u & 0x1f;
     // OF is only defined if count is 1
     if (count == 1) {
@@ -246,7 +246,7 @@ case 0xd3: {
     *arg1 = (*arg1 << count);
     ZF = (*arg1 == 0);
     SF = (*arg1 < 0);
-    trace(90, "run") << "storing 0x" << HEXWORD << *arg1 << end();
+    trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << *arg1 << end();
     break;
   }
   // End Op d3 Subops
@@ -273,14 +273,14 @@ case 0xd3: {
 
 :(before "End Op d3 Subops")
 case 7: {  // shift right r/m32 by CL, preserving sign
-  trace(90, "run") << "subop: shift right by CL bits, while preserving sign" << end();
+  trace(Callstack_depth+1, "run") << "subop: shift right by CL bits, while preserving sign" << end();
   uint8_t count = Reg[ECX].u & 0x1f;
   *arg1 = (*arg1 >> count);
   ZF = (*arg1 == 0);
   SF = (*arg1 < 0);
   // OF is only defined if count is 1
   if (count == 1) OF = false;
-  trace(90, "run") << "storing 0x" << HEXWORD << *arg1 << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << *arg1 << end();
   break;
 }
 
@@ -326,7 +326,7 @@ case 7: {  // shift right r/m32 by CL, preserving sign
 
 :(before "End Op d3 Subops")
 case 5: {  // shift right r/m32 by CL, preserving sign
-  trace(90, "run") << "subop: shift right by CL bits, while padding zeroes" << end();
+  trace(Callstack_depth+1, "run") << "subop: shift right by CL bits, while padding zeroes" << end();
   uint8_t count = Reg[ECX].u & 0x1f;
   // OF is only defined if count is 1
   if (count == 1) {
@@ -339,7 +339,7 @@ case 5: {  // shift right r/m32 by CL, preserving sign
   ZF = (*uarg1 == 0);
   // result is always positive by definition
   SF = false;
-  trace(90, "run") << "storing 0x" << HEXWORD << *arg1 << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << *arg1 << end();
   break;
 }
 
@@ -388,7 +388,7 @@ put_new(Name, "21", "rm32 = bitwise AND of r32 with rm32 (and)");
 case 0x21: {  // and r32 with r/m32
   const uint8_t modrm = next();
   const uint8_t arg2 = (modrm>>3)&0x7;
-  trace(90, "run") << "and " << rname(arg2) << " with r/m32" << end();
+  trace(Callstack_depth+1, "run") << "and " << rname(arg2) << " with r/m32" << end();
   int32_t* arg1 = effective_address(modrm);
   BINARY_BITWISE_OP(&, *arg1, Reg[arg2].u);
   break;
@@ -414,7 +414,7 @@ put_new(Name, "09", "rm32 = bitwise OR of r32 with rm32 (or)");
 case 0x09: {  // or r32 with r/m32
   const uint8_t modrm = next();
   const uint8_t arg2 = (modrm>>3)&0x7;
-  trace(90, "run") << "or " << rname(arg2) << " with r/m32" << end();
+  trace(Callstack_depth+1, "run") << "or " << rname(arg2) << " with r/m32" << end();
   int32_t* arg1 = effective_address(modrm);
   BINARY_BITWISE_OP(|, *arg1, Reg[arg2].u);
   break;
@@ -440,7 +440,7 @@ put_new(Name, "31", "rm32 = bitwise XOR of r32 with rm32 (xor)");
 case 0x31: {  // xor r32 with r/m32
   const uint8_t modrm = next();
   const uint8_t arg2 = (modrm>>3)&0x7;
-  trace(90, "run") << "xor " << rname(arg2) << " with r/m32" << end();
+  trace(Callstack_depth+1, "run") << "xor " << rname(arg2) << " with r/m32" << end();
   int32_t* arg1 = effective_address(modrm);
   BINARY_BITWISE_OP(^, *arg1, Reg[arg2].u);
   break;
@@ -461,9 +461,9 @@ case 0x31: {  // xor r32 with r/m32
 
 :(before "End Op f7 Subops")
 case 2: {  // not r/m32
-  trace(90, "run") << "subop: not" << end();
+  trace(Callstack_depth+1, "run") << "subop: not" << end();
   *arg1 = ~(*arg1);
-  trace(90, "run") << "storing 0x" << HEXWORD << *arg1 << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << *arg1 << end();
   SF = (*arg1 >> 31);
   ZF = (*arg1 == 0);
   OF = false;
@@ -490,7 +490,7 @@ put_new(Name, "39", "compare: set SF if rm32 < r32 (cmp)");
 case 0x39: {  // set SF if r/m32 < r32
   const uint8_t modrm = next();
   const uint8_t reg2 = (modrm>>3)&0x7;
-  trace(90, "run") << "compare " << rname(reg2) << " with r/m32" << end();
+  trace(Callstack_depth+1, "run") << "compare " << rname(reg2) << " with r/m32" << end();
   const int32_t* arg1 = effective_address(modrm);
   const int32_t arg2 = Reg[reg2].i;
   const int32_t tmp1 = *arg1 - arg2;
@@ -498,7 +498,7 @@ case 0x39: {  // set SF if r/m32 < r32
   ZF = (tmp1 == 0);
   const int64_t tmp2 = *arg1 - arg2;
   OF = (tmp1 != tmp2);
-  trace(90, "run") << "SF=" << SF << "; ZF=" << ZF << "; OF=" << OF << end();
+  trace(Callstack_depth+1, "run") << "SF=" << SF << "; ZF=" << ZF << "; OF=" << OF << end();
   break;
 }
 
@@ -543,10 +543,10 @@ put_new(Name, "89", "copy r32 to rm32 (mov)");
 case 0x89: {  // copy r32 to r/m32
   const uint8_t modrm = next();
   const uint8_t rsrc = (modrm>>3)&0x7;
-  trace(90, "run") << "copy " << rname(rsrc) << " to r/m32" << end();
+  trace(Callstack_depth+1, "run") << "copy " << rname(rsrc) << " to r/m32" << end();
   int32_t* dest = effective_address(modrm);
   *dest = Reg[rsrc].i;
-  trace(90, "run") << "storing 0x" << HEXWORD << *dest << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << *dest << end();
   break;
 }
 
@@ -571,13 +571,13 @@ put_new(Name, "87", "swap the contents of r32 and rm32 (xchg)");
 case 0x87: {  // exchange r32 with r/m32
   const uint8_t modrm = next();
   const uint8_t reg2 = (modrm>>3)&0x7;
-  trace(90, "run") << "exchange " << rname(reg2) << " with r/m32" << end();
+  trace(Callstack_depth+1, "run") << "exchange " << rname(reg2) << " with r/m32" << end();
   int32_t* arg1 = effective_address(modrm);
   const int32_t tmp = *arg1;
   *arg1 = Reg[reg2].i;
   Reg[reg2].i = tmp;
-  trace(90, "run") << "storing 0x" << HEXWORD << *arg1 << " in r/m32" << end();
-  trace(90, "run") << "storing 0x" << HEXWORD << Reg[reg2].i << " in " << rname(reg2) << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << *arg1 << " in r/m32" << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << Reg[reg2].i << " in " << rname(reg2) << end();
   break;
 }
 
@@ -611,9 +611,9 @@ case 0x45:
 case 0x46:
 case 0x47: {  // increment r32
   const uint8_t reg = op & 0x7;
-  trace(90, "run") << "increment " << rname(reg) << end();
+  trace(Callstack_depth+1, "run") << "increment " << rname(reg) << end();
   ++Reg[reg].u;
-  trace(90, "run") << "storing value 0x" << HEXWORD << Reg[reg].u << end();
+  trace(Callstack_depth+1, "run") << "storing value 0x" << HEXWORD << Reg[reg].u << end();
   break;
 }
 
@@ -636,10 +636,10 @@ case 0xff: {
   const uint8_t subop = (modrm>>3)&0x7;  // middle 3 'reg opcode' bits
   switch (subop) {
     case 0: {  // increment r/m32
-      trace(90, "run") << "increment r/m32" << end();
+      trace(Callstack_depth+1, "run") << "increment r/m32" << end();
       int32_t* arg = effective_address(modrm);
       ++*arg;
-      trace(90, "run") << "storing value 0x" << HEXWORD << *arg << end();
+      trace(Callstack_depth+1, "run") << "storing value 0x" << HEXWORD << *arg << end();
       break;
     }
     default:
@@ -681,9 +681,9 @@ case 0x4d:
 case 0x4e:
 case 0x4f: {  // decrement r32
   const uint8_t reg = op & 0x7;
-  trace(90, "run") << "decrement " << rname(reg) << end();
+  trace(Callstack_depth+1, "run") << "decrement " << rname(reg) << end();
   --Reg[reg].u;
-  trace(90, "run") << "storing value 0x" << HEXWORD << Reg[reg].u << end();
+  trace(Callstack_depth+1, "run") << "storing value 0x" << HEXWORD << Reg[reg].u << end();
   break;
 }
 
@@ -699,10 +699,10 @@ case 0x4f: {  // decrement r32
 
 :(before "End Op ff Subops")
 case 1: {  // decrement r/m32
-  trace(90, "run") << "decrement r/m32" << end();
+  trace(Callstack_depth+1, "run") << "decrement r/m32" << end();
   int32_t* arg = effective_address(modrm);
   --*arg;
-  trace(90, "run") << "storing value 0x" << HEXWORD << *arg << end();
+  trace(Callstack_depth+1, "run") << "storing value 0x" << HEXWORD << *arg << end();
   break;
 }
 
@@ -738,7 +738,7 @@ case 0x55:
 case 0x56:
 case 0x57: {  // push r32 to stack
   uint8_t reg = op & 0x7;
-  trace(90, "run") << "push " << rname(reg) << end();
+  trace(Callstack_depth+1, "run") << "push " << rname(reg) << end();
 //?   cerr << "push: " << NUM(reg) << ": " << Reg[reg].u << " => " << Reg[ESP].u << '\n';
   push(Reg[reg].u);
   break;
@@ -779,7 +779,7 @@ case 0x5d:
 case 0x5e:
 case 0x5f: {  // pop stack into r32
   const uint8_t reg = op & 0x7;
-  trace(90, "run") << "pop into " << rname(reg) << end();
+  trace(Callstack_depth+1, "run") << "pop into " << rname(reg) << end();
 //?   cerr << "pop from " << Reg[ESP].u << '\n';
   Reg[reg].u = pop();
 //?   cerr << "=> " << NUM(reg) << ": " << Reg[reg].u << '\n';
@@ -788,8 +788,8 @@ case 0x5f: {  // pop stack into r32
 :(code)
 uint32_t pop() {
   const uint32_t result = read_mem_u32(Reg[ESP].u);
-  trace(90, "run") << "popping value 0x" << HEXWORD << result << end();
+  trace(Callstack_depth+1, "run") << "popping value 0x" << HEXWORD << result << end();
   Reg[ESP].u += 4;
-  trace(90, "run") << "incrementing ESP to 0x" << HEXWORD << Reg[ESP].u << end();
+  trace(Callstack_depth+1, "run") << "incrementing ESP to 0x" << HEXWORD << Reg[ESP].u << end();
   return result;
 }
diff --git a/subx/014indirect_addressing.cc b/subx/014indirect_addressing.cc
index cbd9afbc..448f4231 100644
--- a/subx/014indirect_addressing.cc
+++ b/subx/014indirect_addressing.cc
@@ -18,7 +18,7 @@
 case 0:  // indirect addressing
   switch (rm) {
   default:  // address in register
-    trace(90, "run") << "effective address is 0x" << HEXWORD << Reg[rm].u << " (" << rname(rm) << ")" << end();
+    trace(Callstack_depth+1, "run") << "effective address is 0x" << HEXWORD << Reg[rm].u << " (" << rname(rm) << ")" << end();
     addr = Reg[rm].u;
     break;
   // End Mod 0 Special-cases(addr)
@@ -47,7 +47,7 @@ put_new(Name, "03", "add rm32 to r32 (add)");
 case 0x03: {  // add r/m32 to r32
   const uint8_t modrm = next();
   const uint8_t arg1 = (modrm>>3)&0x7;
-  trace(90, "run") << "add r/m32 to " << rname(arg1) << end();
+  trace(Callstack_depth+1, "run") << "add r/m32 to " << rname(arg1) << end();
   const int32_t* arg2 = effective_address(modrm);
   BINARY_ARITHMETIC_OP(+, Reg[arg1].i, *arg2);
   break;
@@ -90,7 +90,7 @@ put_new(Name, "2b", "subtract rm32 from r32 (sub)");
 case 0x2b: {  // subtract r/m32 from r32
   const uint8_t modrm = next();
   const uint8_t arg1 = (modrm>>3)&0x7;
-  trace(90, "run") << "subtract r/m32 from " << rname(arg1) << end();
+  trace(Callstack_depth+1, "run") << "subtract r/m32 from " << rname(arg1) << end();
   const int32_t* arg2 = effective_address(modrm);
   BINARY_ARITHMETIC_OP(-, Reg[arg1].i, *arg2);
   break;
@@ -133,7 +133,7 @@ ff 00 00 00  # 0xff
 case 0x23: {  // and r/m32 with r32
   const uint8_t modrm = next();
   const uint8_t arg1 = (modrm>>3)&0x7;
-  trace(90, "run") << "and r/m32 with " << rname(arg1) << end();
+  trace(Callstack_depth+1, "run") << "and r/m32 with " << rname(arg1) << end();
   const int32_t* arg2 = effective_address(modrm);
   BINARY_BITWISE_OP(&, Reg[arg1].u, *arg2);
   break;
@@ -176,7 +176,7 @@ put_new(Name, "0b", "r32 = bitwise OR of r32 with rm32 (or)");
 case 0x0b: {  // or r/m32 with r32
   const uint8_t modrm = next();
   const uint8_t arg1 = (modrm>>3)&0x7;
-  trace(90, "run") << "or r/m32 with " << rname(arg1) << end();
+  trace(Callstack_depth+1, "run") << "or r/m32 with " << rname(arg1) << end();
   const int32_t* arg2 = effective_address(modrm);
   BINARY_BITWISE_OP(|, Reg[arg1].u, *arg2);
   break;
@@ -219,7 +219,7 @@ put_new(Name, "33", "r32 = bitwise XOR of r32 with rm32 (xor)");
 case 0x33: {  // xor r/m32 with r32
   const uint8_t modrm = next();
   const uint8_t arg1 = (modrm>>3)&0x7;
-  trace(90, "run") << "xor r/m32 with " << rname(arg1) << end();
+  trace(Callstack_depth+1, "run") << "xor r/m32 with " << rname(arg1) << end();
   const int32_t* arg2 = effective_address(modrm);
   BINARY_BITWISE_OP(|, Reg[arg1].u, *arg2);
   break;
@@ -303,7 +303,7 @@ put_new(Name, "3b", "compare: set SF if r32 < rm32 (cmp)");
 case 0x3b: {  // set SF if r32 < r/m32
   const uint8_t modrm = next();
   const uint8_t reg1 = (modrm>>3)&0x7;
-  trace(90, "run") << "compare r/m32 with " << rname(reg1) << end();
+  trace(Callstack_depth+1, "run") << "compare r/m32 with " << rname(reg1) << end();
   const int32_t arg1 = Reg[reg1].i;
   const int32_t* arg2 = effective_address(modrm);
   const int32_t tmp1 = arg1 - *arg2;
@@ -311,7 +311,7 @@ case 0x3b: {  // set SF if r32 < r/m32
   ZF = (tmp1 == 0);
   int64_t tmp2 = arg1 - *arg2;
   OF = (tmp1 != tmp2);
-  trace(90, "run") << "SF=" << SF << "; ZF=" << ZF << "; OF=" << OF << end();
+  trace(Callstack_depth+1, "run") << "SF=" << SF << "; ZF=" << ZF << "; OF=" << OF << end();
   break;
 }
 
@@ -375,10 +375,10 @@ af 00 00 00  # 0xaf
 case 0x8b: {  // copy r32 to r/m32
   const uint8_t modrm = next();
   const uint8_t rdest = (modrm>>3)&0x7;
-  trace(90, "run") << "copy r/m32 to " << rname(rdest) << end();
+  trace(Callstack_depth+1, "run") << "copy r/m32 to " << rname(rdest) << end();
   const int32_t* src = effective_address(modrm);
   Reg[rdest].i = *src;
-  trace(90, "run") << "storing 0x" << HEXWORD << *src << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << *src << end();
   break;
 }
 
@@ -394,19 +394,19 @@ case 0x8b: {  // copy r32 to r/m32
   05                              00 00 00 02
 == 0x2000  # data segment
 08 00 00 00  # 8
-+run: inst: 0x00000001
++run: 0x00000001 opcode: ff
 +run: jump to r/m32
 +run: effective address is 0x00002000 (EAX)
 +run: jumping to 0x00000008
-+run: inst: 0x00000008
--run: inst: 0x00000003
++run: 0x00000008 opcode: 05
+-run: 0x00000003 opcode: 05
 
 :(before "End Op ff Subops")
 case 4: {  // jump to r/m32
-  trace(90, "run") << "jump to r/m32" << end();
+  trace(Callstack_depth+1, "run") << "jump to r/m32" << end();
   const int32_t* arg2 = effective_address(modrm);
   EIP = *arg2;
-  trace(90, "run") << "jumping to 0x" << HEXWORD << EIP << end();
+  trace(Callstack_depth+1, "run") << "jumping to 0x" << HEXWORD << EIP << end();
   break;
 }
 
@@ -428,7 +428,7 @@ af 00 00 00  # 0xaf
 
 :(before "End Op ff Subops")
 case 6: {  // push r/m32 to stack
-  trace(90, "run") << "push r/m32" << end();
+  trace(Callstack_depth+1, "run") << "push r/m32" << end();
   const int32_t* val = effective_address(modrm);
   push(*val);
   break;
@@ -459,7 +459,7 @@ case 0x8f: {  // pop stack into r/m32
   const uint8_t subop = (modrm>>3)&0x7;
   switch (subop) {
     case 0: {
-      trace(90, "run") << "pop into r/m32" << end();
+      trace(Callstack_depth+1, "run") << "pop into r/m32" << end();
       int32_t* dest = effective_address(modrm);
       *dest = pop();
       break;
@@ -485,7 +485,7 @@ case 0x8f: {  // pop stack into r/m32
 :(before "End Mod 0 Special-cases(addr)")
 case 5:  // exception: mod 0b00 rm 0b101 => incoming disp32
   addr = next32();
-  trace(90, "run") << "effective address is 0x" << HEXWORD << addr << " (disp32)" << end();
+  trace(Callstack_depth+1, "run") << "effective address is 0x" << HEXWORD << addr << " (disp32)" << end();
   break;
 
 //:
@@ -509,13 +509,13 @@ case 1:  // indirect + disp8 addressing
   switch (rm) {
   default:
     addr = Reg[rm].u;
-    trace(90, "run") << "effective address is initially 0x" << HEXWORD << addr << " (" << rname(rm) << ")" << end();
+    trace(Callstack_depth+1, "run") << "effective address is initially 0x" << HEXWORD << addr << " (" << rname(rm) << ")" << end();
     break;
   // End Mod 1 Special-cases(addr)
   }
   if (addr > 0) {
     addr += static_cast<int8_t>(next());
-    trace(90, "run") << "effective address is 0x" << HEXWORD << addr << " (after adding disp8)" << end();
+    trace(Callstack_depth+1, "run") << "effective address is 0x" << HEXWORD << addr << " (after adding disp8)" << end();
   }
   break;
 
@@ -554,13 +554,13 @@ case 2:  // indirect + disp32 addressing
   switch (rm) {
   default:
     addr = Reg[rm].u;
-    trace(90, "run") << "effective address is initially 0x" << HEXWORD << addr << " (" << rname(rm) << ")" << end();
+    trace(Callstack_depth+1, "run") << "effective address is initially 0x" << HEXWORD << addr << " (" << rname(rm) << ")" << end();
     break;
   // End Mod 2 Special-cases(addr)
   }
   if (addr > 0) {
     addr += next32();
-    trace(90, "run") << "effective address is 0x" << HEXWORD << addr << " (after adding disp32)" << end();
+    trace(Callstack_depth+1, "run") << "effective address is 0x" << HEXWORD << addr << " (after adding disp32)" << end();
   }
   break;
 
@@ -596,7 +596,7 @@ put_new(Name, "8d", "copy address in rm32 into r32 (lea)");
 case 0x8d: {  // copy address of m32 to r32
   const uint8_t modrm = next();
   const uint8_t arg1 = (modrm>>3)&0x7;
-  trace(90, "run") << "copy address into " << rname(arg1) << end();
+  trace(Callstack_depth+1, "run") << "copy address into " << rname(arg1) << end();
   Reg[arg1].u = effective_address_number(modrm);
   break;
 }
diff --git a/subx/015immediate_addressing.cc b/subx/015immediate_addressing.cc
index 55b4fa37..93dd699b 100644
--- a/subx/015immediate_addressing.cc
+++ b/subx/015immediate_addressing.cc
@@ -17,15 +17,15 @@ put_new(Name, "81", "combine rm32 with imm32 based on subop (add/sub/and/or/xor/
 
 :(before "End Single-Byte Opcodes")
 case 0x81: {  // combine imm32 with r/m32
-  trace(90, "run") << "combine imm32 with r/m32" << end();
+  trace(Callstack_depth+1, "run") << "combine imm32 with r/m32" << end();
   const uint8_t modrm = next();
   int32_t* arg1 = effective_address(modrm);
   const int32_t arg2 = next32();
-  trace(90, "run") << "imm32 is 0x" << HEXWORD << arg2 << end();
+  trace(Callstack_depth+1, "run") << "imm32 is 0x" << HEXWORD << arg2 << end();
   const uint8_t subop = (modrm>>3)&0x7;  // middle 3 'reg opcode' bits
   switch (subop) {
   case 0:
-    trace(90, "run") << "subop add" << end();
+    trace(Callstack_depth+1, "run") << "subop add" << end();
     BINARY_ARITHMETIC_OP(+, *arg1, arg2);
     break;
   // End Op 81 Subops
@@ -68,7 +68,7 @@ put_new(Name, "2d", "subtract imm32 from EAX (sub)");
 :(before "End Single-Byte Opcodes")
 case 0x2d: {  // subtract imm32 from EAX
   const int32_t arg2 = next32();
-  trace(90, "run") << "subtract imm32 0x" << HEXWORD << arg2 << " from EAX" << end();
+  trace(Callstack_depth+1, "run") << "subtract imm32 0x" << HEXWORD << arg2 << " from EAX" << end();
   BINARY_ARITHMETIC_OP(-, Reg[EAX].i, arg2);
   break;
 }
@@ -91,7 +91,7 @@ case 0x2d: {  // subtract imm32 from EAX
 
 :(before "End Op 81 Subops")
 case 5: {
-  trace(90, "run") << "subop subtract" << end();
+  trace(Callstack_depth+1, "run") << "subop subtract" << end();
   BINARY_ARITHMETIC_OP(-, *arg1, arg2);
   break;
 }
@@ -129,12 +129,12 @@ put_new(Name, "c1", "shift rm32 by imm8 bits depending on subop (sal/sar/shl/shr
 :(before "End Single-Byte Opcodes")
 case 0xc1: {
   const uint8_t modrm = next();
-  trace(90, "run") << "operate on r/m32" << end();
+  trace(Callstack_depth+1, "run") << "operate on r/m32" << end();
   int32_t* arg1 = effective_address(modrm);
   const uint8_t subop = (modrm>>3)&0x7;  // middle 3 'reg opcode' bits
   switch (subop) {
   case 4: {  // shift left r/m32 by CL
-    trace(90, "run") << "subop: shift left by CL bits" << end();
+    trace(Callstack_depth+1, "run") << "subop: shift left by CL bits" << end();
     uint8_t count = next() & 0x1f;
     // OF is only defined if count is 1
     if (count == 1) {
@@ -145,7 +145,7 @@ case 0xc1: {
     *arg1 = (*arg1 << count);
     ZF = (*arg1 == 0);
     SF = (*arg1 < 0);
-    trace(90, "run") << "storing 0x" << HEXWORD << *arg1 << end();
+    trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << *arg1 << end();
     break;
   }
   // End Op c1 Subops
@@ -171,14 +171,14 @@ case 0xc1: {
 
 :(before "End Op c1 Subops")
 case 7: {  // shift right r/m32 by CL, preserving sign
-  trace(90, "run") << "subop: shift right by CL bits, while preserving sign" << end();
+  trace(Callstack_depth+1, "run") << "subop: shift right by CL bits, while preserving sign" << end();
   uint8_t count = next() & 0x1f;
   *arg1 = (*arg1 >> count);
   ZF = (*arg1 == 0);
   SF = (*arg1 < 0);
   // OF is only defined if count is 1
   if (count == 1) OF = false;
-  trace(90, "run") << "storing 0x" << HEXWORD << *arg1 << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << *arg1 << end();
   break;
 }
 
@@ -221,7 +221,7 @@ case 7: {  // shift right r/m32 by CL, preserving sign
 
 :(before "End Op c1 Subops")
 case 5: {  // shift right r/m32 by CL, preserving sign
-  trace(90, "run") << "subop: shift right by CL bits, while padding zeroes" << end();
+  trace(Callstack_depth+1, "run") << "subop: shift right by CL bits, while padding zeroes" << end();
   uint8_t count = next() & 0x1f;
   // OF is only defined if count is 1
   if (count == 1) {
@@ -234,7 +234,7 @@ case 5: {  // shift right r/m32 by CL, preserving sign
   ZF = (*uarg1 == 0);
   // result is always positive by definition
   SF = false;
-  trace(90, "run") << "storing 0x" << HEXWORD << *arg1 << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXWORD << *arg1 << end();
   break;
 }
 
@@ -277,7 +277,7 @@ put_new(Name, "25", "EAX = bitwise AND of imm32 with EAX (and)");
 :(before "End Single-Byte Opcodes")
 case 0x25: {  // and imm32 with EAX
   const int32_t arg2 = next32();
-  trace(90, "run") << "and imm32 0x" << HEXWORD << arg2 << " with EAX" << end();
+  trace(Callstack_depth+1, "run") << "and imm32 0x" << HEXWORD << arg2 << " with EAX" << end();
   BINARY_BITWISE_OP(&, Reg[EAX].i, arg2);
   break;
 }
@@ -300,7 +300,7 @@ ff 00 00 00  # 0xff
 
 :(before "End Op 81 Subops")
 case 4: {
-  trace(90, "run") << "subop and" << end();
+  trace(Callstack_depth+1, "run") << "subop and" << end();
   BINARY_BITWISE_OP(&, *arg1, arg2);
   break;
 }
@@ -335,7 +335,7 @@ put_new(Name, "0d", "EAX = bitwise OR of imm32 with EAX (or)");
 :(before "End Single-Byte Opcodes")
 case 0x0d: {  // or imm32 with EAX
   const int32_t arg2 = next32();
-  trace(90, "run") << "or imm32 0x" << HEXWORD << arg2 << " with EAX" << end();
+  trace(Callstack_depth+1, "run") << "or imm32 0x" << HEXWORD << arg2 << " with EAX" << end();
   BINARY_BITWISE_OP(|, Reg[EAX].i, arg2);
   break;
 }
@@ -358,7 +358,7 @@ a0 b0 c0 d0  # 0xd0c0b0a0
 
 :(before "End Op 81 Subops")
 case 1: {
-  trace(90, "run") << "subop or" << end();
+  trace(Callstack_depth+1, "run") << "subop or" << end();
   BINARY_BITWISE_OP(|, *arg1, arg2);
   break;
 }
@@ -391,7 +391,7 @@ put_new(Name, "35", "EAX = bitwise XOR of imm32 with EAX (xor)");
 :(before "End Single-Byte Opcodes")
 case 0x35: {  // xor imm32 with EAX
   const int32_t arg2 = next32();
-  trace(90, "run") << "xor imm32 0x" << HEXWORD << arg2 << " with EAX" << end();
+  trace(Callstack_depth+1, "run") << "xor imm32 0x" << HEXWORD << arg2 << " with EAX" << end();
   BINARY_BITWISE_OP(^, Reg[EAX].i, arg2);
   break;
 }
@@ -414,7 +414,7 @@ a0 b0 c0 d0  # 0xd0c0b0a0
 
 :(before "End Op 81 Subops")
 case 6: {
-  trace(90, "run") << "subop xor" << end();
+  trace(Callstack_depth+1, "run") << "subop xor" << end();
   BINARY_BITWISE_OP(^, *arg1, arg2);
   break;
 }
@@ -448,13 +448,13 @@ put_new(Name, "3d", "compare: set SF if EAX < imm32 (cmp)");
 case 0x3d: {  // compare EAX with imm32
   const int32_t arg1 = Reg[EAX].i;
   const int32_t arg2 = next32();
-  trace(90, "run") << "compare EAX and imm32 0x" << HEXWORD << arg2 << end();
+  trace(Callstack_depth+1, "run") << "compare EAX and imm32 0x" << HEXWORD << arg2 << end();
   const int32_t tmp1 = arg1 - arg2;
   SF = (tmp1 < 0);
   ZF = (tmp1 == 0);
   const int64_t tmp2 = arg1 - arg2;
   OF = (tmp1 != tmp2);
-  trace(90, "run") << "SF=" << SF << "; ZF=" << ZF << "; OF=" << OF << end();
+  trace(Callstack_depth+1, "run") << "SF=" << SF << "; ZF=" << ZF << "; OF=" << OF << end();
   break;
 }
 
@@ -489,13 +489,13 @@ case 0x3d: {  // compare EAX with imm32
 
 :(before "End Op 81 Subops")
 case 7: {
-  trace(90, "run") << "subop compare" << end();
+  trace(Callstack_depth+1, "run") << "subop compare" << end();
   const int32_t tmp1 = *arg1 - arg2;
   SF = (tmp1 < 0);
   ZF = (tmp1 == 0);
   const int64_t tmp2 = *arg1 - arg2;
   OF = (tmp1 != tmp2);
-  trace(90, "run") << "SF=" << SF << "; ZF=" << ZF << "; OF=" << OF << end();
+  trace(Callstack_depth+1, "run") << "SF=" << SF << "; ZF=" << ZF << "; OF=" << OF << end();
   break;
 }
 
@@ -590,7 +590,7 @@ case 0xbe:
 case 0xbf: {  // copy imm32 to r32
   const uint8_t rdest = op & 0x7;
   const int32_t src = next32();
-  trace(90, "run") << "copy imm32 0x" << HEXWORD << src << " to " << rname(rdest) << end();
+  trace(Callstack_depth+1, "run") << "copy imm32 0x" << HEXWORD << src << " to " << rname(rdest) << end();
   Reg[rdest].i = src;
   break;
 }
@@ -613,7 +613,7 @@ put_new(Name, "c7", "copy imm32 to rm32 (mov)");
 :(before "End Single-Byte Opcodes")
 case 0xc7: {  // copy imm32 to r32
   const uint8_t modrm = next();
-  trace(90, "run") << "copy imm32 to r/m32" << end();
+  trace(Callstack_depth+1, "run") << "copy imm32 to r/m32" << end();
   const uint8_t subop = (modrm>>3)&0x7;  // middle 3 'reg opcode' bits
   if (subop != 0) {
     cerr << "unrecognized subop for opcode c7: " << NUM(subop) << " (only 0/copy currently implemented)\n";
@@ -621,7 +621,7 @@ case 0xc7: {  // copy imm32 to r32
   }
   int32_t* dest = effective_address(modrm);
   const int32_t src = next32();
-  trace(90, "run") << "imm32 is 0x" << HEXWORD << src << end();
+  trace(Callstack_depth+1, "run") << "imm32 is 0x" << HEXWORD << src << end();
   *dest = src;
   break;
 }
@@ -643,10 +643,10 @@ put_new(Name, "68", "push imm32 to stack (push)");
 :(before "End Single-Byte Opcodes")
 case 0x68: {
   const uint32_t val = static_cast<uint32_t>(next32());
-  trace(90, "run") << "push imm32 0x" << HEXWORD << val << end();
+  trace(Callstack_depth+1, "run") << "push imm32 0x" << HEXWORD << val << end();
 //?   cerr << "push: " << val << " => " << Reg[ESP].u << '\n';
   push(val);
-  trace(90, "run") << "ESP is now 0x" << HEXWORD << Reg[ESP].u << end();
-  trace(90, "run") << "contents at ESP: 0x" << HEXWORD << read_mem_u32(Reg[ESP].u) << end();
+  trace(Callstack_depth+1, "run") << "ESP is now 0x" << HEXWORD << Reg[ESP].u << end();
+  trace(Callstack_depth+1, "run") << "contents at ESP: 0x" << HEXWORD << read_mem_u32(Reg[ESP].u) << end();
   break;
 }
diff --git a/subx/016index_addressing.cc b/subx/016index_addressing.cc
index 0fe2aa71..9fb3e9bb 100644
--- a/subx/016index_addressing.cc
+++ b/subx/016index_addressing.cc
@@ -26,22 +26,22 @@ uint32_t effective_address_from_sib(uint8_t mod) {
   uint32_t addr = 0;
   if (base != EBP || mod != 0) {
     addr = Reg[base].u;
-    trace(90, "run") << "effective address is initially 0x" << HEXWORD << addr << " (" << rname(base) << ")" << end();
+    trace(Callstack_depth+1, "run") << "effective address is initially 0x" << HEXWORD << addr << " (" << rname(base) << ")" << end();
   }
   else {
     // base == EBP && mod == 0
     addr = next32();  // ignore base
-    trace(90, "run") << "effective address is initially 0x" << HEXWORD << addr << " (disp32)" << end();
+    trace(Callstack_depth+1, "run") << "effective address is initially 0x" << HEXWORD << addr << " (disp32)" << end();
   }
   const uint8_t index = (sib>>3)&0x7;
   if (index == ESP) {
     // ignore index and scale
-    trace(90, "run") << "effective address is 0x" << HEXWORD << addr << end();
+    trace(Callstack_depth+1, "run") << "effective address is 0x" << HEXWORD << addr << end();
   }
   else {
     const uint8_t scale = (1 << (sib>>6));
     addr += Reg[index].i*scale;  // treat index register as signed. Maybe base as well? But we'll always ensure it's non-negative.
-    trace(90, "run") << "effective address is 0x" << HEXWORD << addr << " (after adding " << rname(index) << "*" << NUM(scale) << ")" << end();
+    trace(Callstack_depth+1, "run") << "effective address is 0x" << HEXWORD << addr << " (after adding " << rname(index) << "*" << NUM(scale) << ")" << end();
   }
   return addr;
 }
diff --git a/subx/017jump_disp8.cc b/subx/017jump_disp8.cc
index b7bb9300..24467f5c 100644
--- a/subx/017jump_disp8.cc
+++ b/subx/017jump_disp8.cc
@@ -11,15 +11,15 @@ put_new(Name, "eb", "jump disp8 bytes away (jmp)");
   eb                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: eb
 +run: jump 5
-+run: inst: 0x00000008
--run: inst: 0x00000003
++run: 0x00000008 opcode: 05
+-run: 0x00000003 opcode: 05
 
 :(before "End Single-Byte Opcodes")
 case 0xeb: {  // jump rel8
   int8_t offset = static_cast<int>(next());
-  trace(90, "run") << "jump " << NUM(offset) << end();
+  trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
   EIP += offset;
   break;
 }
@@ -36,16 +36,16 @@ put_new(Name, "74", "jump disp8 bytes away if equal, if ZF is set (jcc/jz/je)");
   74                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 74
 +run: jump 5
-+run: inst: 0x00000008
--run: inst: 0x00000003
++run: 0x00000008 opcode: 05
+-run: 0x00000003 opcode: 05
 
 :(before "End Single-Byte Opcodes")
 case 0x74: {  // jump rel8 if ZF
   const int8_t offset = static_cast<int>(next());
   if (ZF) {
-    trace(90, "run") << "jump " << NUM(offset) << end();
+    trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
     EIP += offset;
   }
   break;
@@ -58,9 +58,9 @@ case 0x74: {  // jump rel8 if ZF
   74                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
-+run: inst: 0x00000003
-+run: inst: 0x00000008
++run: 0x00000001 opcode: 74
++run: 0x00000003 opcode: 05
++run: 0x00000008 opcode: 05
 -run: jump 5
 
 //:: jump if not equal/not zero
@@ -75,16 +75,16 @@ put_new(Name, "75", "jump disp8 bytes away if not equal, if ZF is not set (jcc/j
   75                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 75
 +run: jump 5
-+run: inst: 0x00000008
--run: inst: 0x00000003
++run: 0x00000008 opcode: 05
+-run: 0x00000003 opcode: 05
 
 :(before "End Single-Byte Opcodes")
 case 0x75: {  // jump rel8 unless ZF
   const int8_t offset = static_cast<int>(next());
   if (!ZF) {
-    trace(90, "run") << "jump " << NUM(offset) << end();
+    trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
     EIP += offset;
   }
   break;
@@ -97,9 +97,9 @@ case 0x75: {  // jump rel8 unless ZF
   75                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
-+run: inst: 0x00000003
-+run: inst: 0x00000008
++run: 0x00000001 opcode: 75
++run: 0x00000003 opcode: 05
++run: 0x00000008 opcode: 05
 -run: jump 5
 
 //:: jump if greater
@@ -116,16 +116,16 @@ put_new(Name, "7f", "jump disp8 bytes away if greater, if ZF is unset and SF ==
   7f                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 7f
 +run: jump 5
-+run: inst: 0x00000008
--run: inst: 0x00000003
++run: 0x00000008 opcode: 05
+-run: 0x00000003 opcode: 05
 
 :(before "End Single-Byte Opcodes")
 case 0x7f: {  // jump rel8 if !SF and !ZF
   const int8_t offset = static_cast<int>(next());
   if (!ZF && SF == OF) {
-    trace(90, "run") << "jump " << NUM(offset) << end();
+    trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
     EIP += offset;
   }
   break;
@@ -140,9 +140,9 @@ case 0x7f: {  // jump rel8 if !SF and !ZF
   7f                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
-+run: inst: 0x00000003
-+run: inst: 0x00000008
++run: 0x00000001 opcode: 7f
++run: 0x00000003 opcode: 05
++run: 0x00000008 opcode: 05
 -run: jump 5
 
 //:: jump if greater or equal
@@ -158,16 +158,16 @@ put_new(Name, "7d", "jump disp8 bytes away if greater or equal, if SF == OF (jcc
   7d                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 7d
 +run: jump 5
-+run: inst: 0x00000008
--run: inst: 0x00000003
++run: 0x00000008 opcode: 05
+-run: 0x00000003 opcode: 05
 
 :(before "End Single-Byte Opcodes")
 case 0x7d: {  // jump rel8 if !SF
   const int8_t offset = static_cast<int>(next());
   if (SF == OF) {
-    trace(90, "run") << "jump " << NUM(offset) << end();
+    trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
     EIP += offset;
   }
   break;
@@ -181,9 +181,9 @@ case 0x7d: {  // jump rel8 if !SF
   7d                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
-+run: inst: 0x00000003
-+run: inst: 0x00000008
++run: 0x00000001 opcode: 7d
++run: 0x00000003 opcode: 05
++run: 0x00000008 opcode: 05
 -run: jump 5
 
 //:: jump if lesser
@@ -200,16 +200,16 @@ put_new(Name, "7c", "jump disp8 bytes away if lesser, if SF != OF (jcc/jl/jnge)"
   7c                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 7c
 +run: jump 5
-+run: inst: 0x00000008
--run: inst: 0x00000003
++run: 0x00000008 opcode: 05
+-run: 0x00000003 opcode: 05
 
 :(before "End Single-Byte Opcodes")
 case 0x7c: {  // jump rel8 if SF and !ZF
   const int8_t offset = static_cast<int>(next());
   if (SF != OF) {
-    trace(90, "run") << "jump " << NUM(offset) << end();
+    trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
     EIP += offset;
   }
   break;
@@ -224,9 +224,9 @@ case 0x7c: {  // jump rel8 if SF and !ZF
   7c                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
-+run: inst: 0x00000003
-+run: inst: 0x00000008
++run: 0x00000001 opcode: 7c
++run: 0x00000003 opcode: 05
++run: 0x00000008 opcode: 05
 -run: jump 5
 
 //:: jump if lesser or equal
@@ -243,10 +243,10 @@ put_new(Name, "7e", "jump disp8 bytes away if lesser or equal, if ZF is set or S
   7e                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 7e
 +run: jump 5
-+run: inst: 0x00000008
--run: inst: 0x00000003
++run: 0x00000008 opcode: 05
+-run: 0x00000003 opcode: 05
 
 :(scenario jle_rel8_lesser)
 % ZF = false;
@@ -257,16 +257,16 @@ put_new(Name, "7e", "jump disp8 bytes away if lesser or equal, if ZF is set or S
   7e                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 7e
 +run: jump 5
-+run: inst: 0x00000008
--run: inst: 0x00000003
++run: 0x00000008 opcode: 05
+-run: 0x00000003 opcode: 05
 
 :(before "End Single-Byte Opcodes")
 case 0x7e: {  // jump rel8 if SF or ZF
   const int8_t offset = static_cast<int>(next());
   if (ZF || SF != OF) {
-    trace(90, "run") << "jump " << NUM(offset) << end();
+    trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
     EIP += offset;
   }
   break;
@@ -281,7 +281,7 @@ case 0x7e: {  // jump rel8 if SF or ZF
   7e                05                        # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
-+run: inst: 0x00000003
-+run: inst: 0x00000008
++run: 0x00000001 opcode: 7e
++run: 0x00000003 opcode: 05
++run: 0x00000008 opcode: 05
 -run: jump 5
diff --git a/subx/018jump_disp32.cc b/subx/018jump_disp32.cc
index fd0bc33d..c86cd2df 100644
--- a/subx/018jump_disp32.cc
+++ b/subx/018jump_disp32.cc
@@ -11,15 +11,15 @@ put_new(Name, "e9", "jump disp32 bytes away (jmp)");
   e9                05 00 00 00               # skip 1 instruction
   05                              00 00 00 01
   05                              00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: e9
 +run: jump 5
-+run: inst: 0x0000000b
--run: inst: 0x00000006
++run: 0x0000000b opcode: 05
+-run: 0x00000006 opcode: 05
 
 :(before "End Single-Byte Opcodes")
 case 0xe9: {  // jump disp32
   const int32_t offset = next32();
-  trace(90, "run") << "jump " << offset << end();
+  trace(Callstack_depth+1, "run") << "jump " << offset << end();
   EIP += offset;
   break;
 }
@@ -36,16 +36,16 @@ put_new(Name_0f, "84", "jump disp32 bytes away if equal, if ZF is set (jcc/jz/je
   0f 84                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 0f
 +run: jump 5
-+run: inst: 0x0000000c
--run: inst: 0x00000007
++run: 0x0000000c opcode: 05
+-run: 0x00000007 opcode: 05
 
 :(before "End Two-Byte Opcodes Starting With 0f")
 case 0x84: {  // jump disp32 if ZF
   const int32_t offset = next32();
   if (ZF) {
-    trace(90, "run") << "jump " << NUM(offset) << end();
+    trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
     EIP += offset;
   }
   break;
@@ -58,9 +58,9 @@ case 0x84: {  // jump disp32 if ZF
   0f 84                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
-+run: inst: 0x00000007
-+run: inst: 0x0000000c
++run: 0x00000001 opcode: 0f
++run: 0x00000007 opcode: 05
++run: 0x0000000c opcode: 05
 -run: jump 5
 
 //:: jump if not equal/not zero
@@ -75,16 +75,16 @@ put_new(Name_0f, "85", "jump disp32 bytes away if not equal, if ZF is not set (j
   0f 85                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 0f
 +run: jump 5
-+run: inst: 0x0000000c
--run: inst: 0x00000007
++run: 0x0000000c opcode: 05
+-run: 0x00000007 opcode: 05
 
 :(before "End Two-Byte Opcodes Starting With 0f")
 case 0x85: {  // jump disp32 unless ZF
   const int32_t offset = next32();
   if (!ZF) {
-    trace(90, "run") << "jump " << NUM(offset) << end();
+    trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
     EIP += offset;
   }
   break;
@@ -97,9 +97,9 @@ case 0x85: {  // jump disp32 unless ZF
   0f 85                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
-+run: inst: 0x00000007
-+run: inst: 0x0000000c
++run: 0x00000001 opcode: 0f
++run: 0x00000007 opcode: 05
++run: 0x0000000c opcode: 05
 -run: jump 5
 
 //:: jump if greater
@@ -116,16 +116,16 @@ put_new(Name_0f, "8f", "jump disp32 bytes away if greater, if ZF is unset and SF
   0f 8f                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 0f
 +run: jump 5
-+run: inst: 0x0000000c
--run: inst: 0x00000007
++run: 0x0000000c opcode: 05
+-run: 0x00000007 opcode: 05
 
 :(before "End Two-Byte Opcodes Starting With 0f")
 case 0x8f: {  // jump disp32 if !SF and !ZF
   const int32_t offset = next32();
   if (!ZF && SF == OF) {
-    trace(90, "run") << "jump " << NUM(offset) << end();
+    trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
     EIP += offset;
   }
   break;
@@ -140,9 +140,9 @@ case 0x8f: {  // jump disp32 if !SF and !ZF
   0f 8f                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
-+run: inst: 0x00000007
-+run: inst: 0x0000000c
++run: 0x00000001 opcode: 0f
++run: 0x00000007 opcode: 05
++run: 0x0000000c opcode: 05
 -run: jump 5
 
 //:: jump if greater or equal
@@ -158,16 +158,16 @@ put_new(Name_0f, "8d", "jump disp32 bytes away if greater or equal, if SF == OF
   0f 8d                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 0f
 +run: jump 5
-+run: inst: 0x0000000c
--run: inst: 0x00000007
++run: 0x0000000c opcode: 05
+-run: 0x00000007 opcode: 05
 
 :(before "End Two-Byte Opcodes Starting With 0f")
 case 0x8d: {  // jump disp32 if !SF
   const int32_t offset = next32();
   if (SF == OF) {
-    trace(90, "run") << "jump " << NUM(offset) << end();
+    trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
     EIP += offset;
   }
   break;
@@ -181,9 +181,9 @@ case 0x8d: {  // jump disp32 if !SF
   0f 8d                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
-+run: inst: 0x00000007
-+run: inst: 0x0000000c
++run: 0x00000001 opcode: 0f
++run: 0x00000007 opcode: 05
++run: 0x0000000c opcode: 05
 -run: jump 5
 
 //:: jump if lesser
@@ -200,16 +200,16 @@ put_new(Name_0f, "8c", "jump disp32 bytes away if lesser, if SF != OF (jcc/jl/jn
   0f 8c                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 0f
 +run: jump 5
-+run: inst: 0x0000000c
--run: inst: 0x00000007
++run: 0x0000000c opcode: 05
+-run: 0x00000007 opcode: 05
 
 :(before "End Two-Byte Opcodes Starting With 0f")
 case 0x8c: {  // jump disp32 if SF and !ZF
   const int32_t offset = next32();
   if (SF != OF) {
-    trace(90, "run") << "jump " << NUM(offset) << end();
+    trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
     EIP += offset;
   }
   break;
@@ -224,9 +224,9 @@ case 0x8c: {  // jump disp32 if SF and !ZF
   0f 8c                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
-+run: inst: 0x00000007
-+run: inst: 0x0000000c
++run: 0x00000001 opcode: 0f
++run: 0x00000007 opcode: 05
++run: 0x0000000c opcode: 05
 -run: jump 5
 
 //:: jump if lesser or equal
@@ -243,10 +243,10 @@ put_new(Name_0f, "8e", "jump disp32 bytes away if lesser or equal, if ZF is set
   0f 8e                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 0f
 +run: jump 5
-+run: inst: 0x0000000c
--run: inst: 0x00000007
++run: 0x0000000c opcode: 05
+-run: 0x00000007 opcode: 05
 
 :(scenario jle_disp32_lesser)
 % ZF = false;
@@ -257,16 +257,16 @@ put_new(Name_0f, "8e", "jump disp32 bytes away if lesser or equal, if ZF is set
   0f 8e                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
++run: 0x00000001 opcode: 0f
 +run: jump 5
-+run: inst: 0x0000000c
--run: inst: 0x00000007
++run: 0x0000000c opcode: 05
+-run: 0x00000007 opcode: 05
 
 :(before "End Two-Byte Opcodes Starting With 0f")
 case 0x8e: {  // jump disp32 if SF or ZF
   const int32_t offset = next32();
   if (ZF || SF != OF) {
-    trace(90, "run") << "jump " << NUM(offset) << end();
+    trace(Callstack_depth+1, "run") << "jump " << NUM(offset) << end();
     EIP += offset;
   }
   break;
@@ -281,7 +281,7 @@ case 0x8e: {  // jump disp32 if SF or ZF
   0f 8e                 05 00 00 00               # skip 1 instruction
   05                                  00 00 00 01
   05                                  00 00 00 02
-+run: inst: 0x00000001
-+run: inst: 0x00000007
-+run: inst: 0x0000000c
++run: 0x00000001 opcode: 0f
++run: 0x00000007 opcode: 05
++run: 0x0000000c opcode: 05
 -run: jump 5
diff --git a/subx/019functions.cc b/subx/019functions.cc
index bdeafad1..66cfe384 100644
--- a/subx/019functions.cc
+++ b/subx/019functions.cc
@@ -17,11 +17,12 @@ put_new(Name, "e8", "call disp32 (call)");
 :(before "End Single-Byte Opcodes")
 case 0xe8: {  // call disp32 relative to next EIP
   const int32_t offset = next32();
-  trace(90, "run") << "call imm32 0x" << HEXWORD << offset << end();
+  ++Callstack_depth;
+  trace(Callstack_depth+1, "run") << "call imm32 0x" << HEXWORD << offset << end();
 //?   cerr << "push: EIP: " << EIP << " => " << Reg[ESP].u << '\n';
   push(EIP);
   EIP += offset;
-  trace(90, "run") << "jumping to 0x" << HEXWORD << EIP << end();
+  trace(Callstack_depth+1, "run") << "jumping to 0x" << HEXWORD << EIP << end();
   break;
 }
 
@@ -42,11 +43,12 @@ case 0xe8: {  // call disp32 relative to next EIP
 
 :(before "End Op ff Subops")
 case 2: {  // call function pointer at r/m32
-  trace(90, "run") << "call to r/m32" << end();
+  trace(Callstack_depth+1, "run") << "call to r/m32" << end();
   const int32_t* offset = effective_address(modrm);
   push(EIP);
   EIP += *offset;
-  trace(90, "run") << "jumping to 0x" << HEXWORD << EIP << end();
+  trace(Callstack_depth+1, "run") << "jumping to 0x" << HEXWORD << EIP << end();
+  ++Callstack_depth;
   break;
 }
 
@@ -83,8 +85,9 @@ put_new(Name, "c3", "return from most recent unfinished call (ret)");
 
 :(before "End Single-Byte Opcodes")
 case 0xc3: {  // return from a call
-  trace(90, "run") << "return" << end();
+  trace(Callstack_depth+1, "run") << "return" << end();
+  --Callstack_depth;
   EIP = pop();
-  trace(90, "run") << "jumping to 0x" << HEXWORD << EIP << end();
+  trace(Callstack_depth+1, "run") << "jumping to 0x" << HEXWORD << EIP << end();
   break;
 }
diff --git a/subx/020syscalls.cc b/subx/020syscalls.cc
index 675fb526..a17e9525 100644
--- a/subx/020syscalls.cc
+++ b/subx/020syscalls.cc
@@ -3,7 +3,7 @@ put_new(Name, "cd", "software interrupt (int)");
 
 :(before "End Single-Byte Opcodes")
 case 0xcd: {  // int imm8 (software interrupt)
-  trace(90, "run") << "syscall" << end();
+  trace(Callstack_depth+1, "run") << "syscall" << end();
   uint8_t code = next();
   if (code != 0x80) {
     raise << "Unimplemented interrupt code " << HEXBYTE << code << '\n' << end();
@@ -21,67 +21,67 @@ void process_int80() {
     exit(/*exit code*/Reg[EBX].u);
     break;
   case 3:
-    trace(91, "run") << "read: " << Reg[EBX].u << ' ' << Reg[ECX].u << ' ' << Reg[EDX].u << end();
+    trace(Callstack_depth+1, "run") << "read: " << Reg[EBX].u << ' ' << Reg[ECX].u << ' ' << Reg[EDX].u << end();
     Reg[EAX].i = read(/*file descriptor*/Reg[EBX].u, /*memory buffer*/mem_addr_u8(Reg[ECX].u), /*size*/Reg[EDX].u);
-    trace(91, "run") << "result: " << Reg[EAX].i << end();
+    trace(Callstack_depth+1, "run") << "result: " << Reg[EAX].i << end();
     if (Reg[EAX].i == -1) raise << strerror(errno) << '\n' << end();
     break;
   case 4:
-    trace(91, "run") << "write: " << Reg[EBX].u << ' ' << Reg[ECX].u << ' ' << Reg[EDX].u << end();
-    trace(91, "run") << Reg[ECX].u << " => " << mem_addr_string(Reg[ECX].u, Reg[EDX].u) << end();
+    trace(Callstack_depth+1, "run") << "write: " << Reg[EBX].u << ' ' << Reg[ECX].u << ' ' << Reg[EDX].u << end();
+    trace(Callstack_depth+1, "run") << Reg[ECX].u << " => " << mem_addr_string(Reg[ECX].u, Reg[EDX].u) << end();
     Reg[EAX].i = write(/*file descriptor*/Reg[EBX].u, /*memory buffer*/mem_addr_u8(Reg[ECX].u), /*size*/Reg[EDX].u);
-    trace(91, "run") << "result: " << Reg[EAX].i << end();
+    trace(Callstack_depth+1, "run") << "result: " << Reg[EAX].i << end();
     if (Reg[EAX].i == -1) raise << strerror(errno) << '\n' << end();
     break;
   case 5: {
     check_flags(ECX);
     check_mode(EDX);
-    trace(91, "run") << "open: " << Reg[EBX].u << ' ' << Reg[ECX].u << end();
-    trace(91, "run") << Reg[EBX].u << " => " << mem_addr_kernel_string(Reg[EBX].u) << end();
+    trace(Callstack_depth+1, "run") << "open: " << Reg[EBX].u << ' ' << Reg[ECX].u << end();
+    trace(Callstack_depth+1, "run") << Reg[EBX].u << " => " << mem_addr_kernel_string(Reg[EBX].u) << end();
     Reg[EAX].i = open(/*filename*/mem_addr_kernel_string(Reg[EBX].u), /*flags*/Reg[ECX].u, /*mode*/0640);
-    trace(91, "run") << "result: " << Reg[EAX].i << end();
+    trace(Callstack_depth+1, "run") << "result: " << Reg[EAX].i << end();
     if (Reg[EAX].i == -1) raise << strerror(errno) << '\n' << end();
     break;
   }
   case 6:
-    trace(91, "run") << "close: " << Reg[EBX].u << end();
+    trace(Callstack_depth+1, "run") << "close: " << Reg[EBX].u << end();
     Reg[EAX].i = close(/*file descriptor*/Reg[EBX].u);
-    trace(91, "run") << "result: " << Reg[EAX].i << end();
+    trace(Callstack_depth+1, "run") << "result: " << Reg[EAX].i << end();
     if (Reg[EAX].i == -1) raise << strerror(errno) << '\n' << end();
     break;
   case 8:
     check_mode(ECX);
-    trace(91, "run") << "creat: " << Reg[EBX].u << end();
-    trace(91, "run") << Reg[EBX].u << " => " << mem_addr_kernel_string(Reg[EBX].u) << end();
+    trace(Callstack_depth+1, "run") << "creat: " << Reg[EBX].u << end();
+    trace(Callstack_depth+1, "run") << Reg[EBX].u << " => " << mem_addr_kernel_string(Reg[EBX].u) << end();
     Reg[EAX].i = creat(/*filename*/mem_addr_kernel_string(Reg[EBX].u), /*mode*/0640);
-    trace(91, "run") << "result: " << Reg[EAX].i << end();
+    trace(Callstack_depth+1, "run") << "result: " << Reg[EAX].i << end();
     if (Reg[EAX].i == -1) raise << strerror(errno) << '\n' << end();
     break;
   case 10:
-    trace(91, "run") << "unlink: " << Reg[EBX].u << end();
-    trace(91, "run") << Reg[EBX].u << " => " << mem_addr_kernel_string(Reg[EBX].u) << end();
+    trace(Callstack_depth+1, "run") << "unlink: " << Reg[EBX].u << end();
+    trace(Callstack_depth+1, "run") << Reg[EBX].u << " => " << mem_addr_kernel_string(Reg[EBX].u) << end();
     Reg[EAX].i = unlink(/*filename*/mem_addr_kernel_string(Reg[EBX].u));
-    trace(91, "run") << "result: " << Reg[EAX].i << end();
+    trace(Callstack_depth+1, "run") << "result: " << Reg[EAX].i << end();
     if (Reg[EAX].i == -1) raise << strerror(errno) << '\n' << end();
     break;
   case 38:
-    trace(91, "run") << "rename: " << Reg[EBX].u << " -> " << Reg[ECX].u << end();
-    trace(91, "run") << Reg[EBX].u << " => " << mem_addr_kernel_string(Reg[EBX].u) << end();
-    trace(91, "run") << Reg[ECX].u << " => " << mem_addr_kernel_string(Reg[ECX].u) << end();
+    trace(Callstack_depth+1, "run") << "rename: " << Reg[EBX].u << " -> " << Reg[ECX].u << end();
+    trace(Callstack_depth+1, "run") << Reg[EBX].u << " => " << mem_addr_kernel_string(Reg[EBX].u) << end();
+    trace(Callstack_depth+1, "run") << Reg[ECX].u << " => " << mem_addr_kernel_string(Reg[ECX].u) << end();
     Reg[EAX].i = rename(/*old filename*/mem_addr_kernel_string(Reg[EBX].u), /*new filename*/mem_addr_kernel_string(Reg[ECX].u));
-    trace(91, "run") << "result: " << Reg[EAX].i << end();
+    trace(Callstack_depth+1, "run") << "result: " << Reg[EAX].i << end();
     if (Reg[EAX].i == -1) raise << strerror(errno) << '\n' << end();
     break;
   case 45:  // brk: modify size of data segment
-    trace(91, "run") << "grow data segment to " << Reg[EBX].u << end();
+    trace(Callstack_depth+1, "run") << "grow data segment to " << Reg[EBX].u << end();
     grow_data_segment(/*new end address*/Reg[EBX].u);
     break;
   case 90:  // mmap: allocate memory outside existing segment allocations
-    trace(91, "run") << "mmap: allocate new segment" << end();
+    trace(Callstack_depth+1, "run") << "mmap: allocate new segment" << end();
     // Ignore most arguments for now: address hint, protection flags, sharing flags, fd, offset.
     // We only support anonymous maps.
     Reg[EAX].u = new_segment(/*length*/read_mem_u32(Reg[EBX].u+0x4));
-    trace(91, "run") << "result: " << Reg[EAX].u << end();
+    trace(Callstack_depth+1, "run") << "result: " << Reg[EAX].u << end();
     break;
   default:
     raise << HEXWORD << EIP << ": unimplemented syscall " << Reg[EAX].u << '\n' << end();
diff --git a/subx/021byte_addressing.cc b/subx/021byte_addressing.cc
index fba9a827..c96bc9c1 100644
--- a/subx/021byte_addressing.cc
+++ b/subx/021byte_addressing.cc
@@ -23,7 +23,7 @@ uint8_t* effective_byte_address(uint8_t modrm) {
   uint8_t rm = modrm & 0x7;
   if (mod == 3) {
     // select an 8-bit register
-    trace(90, "run") << "r/m8 is " << rname_8bit(rm) << end();
+    trace(Callstack_depth+1, "run") << "r/m8 is " << rname_8bit(rm) << end();
     return reg_8bit(rm);
   }
   // the rest is as usual
@@ -58,12 +58,12 @@ f0 cc bb aa
 case 0x88: {  // copy r8 to r/m8
   const uint8_t modrm = next();
   const uint8_t rsrc = (modrm>>3)&0x7;
-  trace(90, "run") << "copy " << rname_8bit(rsrc) << " to r8/m8-at-r32" << end();
+  trace(Callstack_depth+1, "run") << "copy " << rname_8bit(rsrc) << " to r8/m8-at-r32" << end();
   // use unsigned to zero-extend 8-bit value to 32 bits
   uint8_t* dest = reinterpret_cast<uint8_t*>(effective_byte_address(modrm));
   const uint8_t* src = reg_8bit(rsrc);
   *dest = *src;
-  trace(90, "run") << "storing 0x" << HEXBYTE << NUM(*dest) << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXBYTE << NUM(*dest) << end();
   break;
 }
 
@@ -91,14 +91,14 @@ ab ff ff ff  # 0xab with more data in following bytes
 case 0x8a: {  // copy r/m8 to r8
   const uint8_t modrm = next();
   const uint8_t rdest = (modrm>>3)&0x7;
-  trace(90, "run") << "copy r8/m8-at-r32 to " << rname_8bit(rdest) << end();
+  trace(Callstack_depth+1, "run") << "copy r8/m8-at-r32 to " << rname_8bit(rdest) << end();
   // use unsigned to zero-extend 8-bit value to 32 bits
   const uint8_t* src = reinterpret_cast<uint8_t*>(effective_byte_address(modrm));
   uint8_t* dest = reg_8bit(rdest);
-  trace(90, "run") << "storing 0x" << HEXBYTE << NUM(*src) << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXBYTE << NUM(*src) << end();
   *dest = *src;
   const uint8_t rdest_32bit = rdest & 0x3;
-  trace(90, "run") << rname(rdest_32bit) << " now contains 0x" << HEXWORD << Reg[rdest_32bit].u << end();
+  trace(Callstack_depth+1, "run") << rname(rdest_32bit) << " now contains 0x" << HEXWORD << Reg[rdest_32bit].u << end();
   break;
 }
 
@@ -137,8 +137,8 @@ f0 cc bb aa
 case 0xc6: {  // copy imm8 to r/m8
   const uint8_t modrm = next();
   const uint8_t src = next();
-  trace(90, "run") << "copy imm8 to r8/m8-at-r32" << end();
-  trace(90, "run") << "imm8 is 0x" << HEXWORD << src << end();
+  trace(Callstack_depth+1, "run") << "copy imm8 to r8/m8-at-r32" << end();
+  trace(Callstack_depth+1, "run") << "imm8 is 0x" << HEXWORD << src << end();
   const uint8_t subop = (modrm>>3)&0x7;  // middle 3 'reg opcode' bits
   if (subop != 0) {
     cerr << "unrecognized subop for opcode c6: " << NUM(subop) << " (only 0/copy currently implemented)\n";
@@ -147,6 +147,6 @@ case 0xc6: {  // copy imm8 to r/m8
   // use unsigned to zero-extend 8-bit value to 32 bits
   uint8_t* dest = reinterpret_cast<uint8_t*>(effective_byte_address(modrm));
   *dest = src;
-  trace(90, "run") << "storing 0x" << HEXBYTE << NUM(*dest) << end();
+  trace(Callstack_depth+1, "run") << "storing 0x" << HEXBYTE << NUM(*dest) << end();
   break;
 }
diff --git a/subx/028translate.cc b/subx/028translate.cc
index d4b1a3a5..42b94632 100644
--- a/subx/028translate.cc
+++ b/subx/028translate.cc
@@ -34,6 +34,7 @@ if (is_equal(argv[1], "translate")) {
       output_filename = argv[i];
     }
     else {
+      trace(2, "parse") << argv[i] << end();
       ifstream fin(argv[i]);
       if (!fin) {
         cerr << "could not open " << argv[i] << '\n';
@@ -53,8 +54,10 @@ if (is_equal(argv[1], "translate")) {
     cerr << "must provide a filename to write to using '-o'\n";
     exit(1);
   }
+  trace(2, "transform") << "begin" << end();
   transform(p);
   if (trace_contains_errors()) return 1;
+  trace(2, "translate") << "begin" << end();
   save_elf(p, output_filename);
   if (trace_contains_errors()) {
     unlink(output_filename.c_str());
diff --git a/subx/030---operands.cc b/subx/030---operands.cc
index 6d156035..085cf1b2 100644
--- a/subx/030---operands.cc
+++ b/subx/030---operands.cc
@@ -156,7 +156,7 @@ void pack_operands(program& p) {
   if (p.segments.empty()) return;
   segment& code = p.segments.at(0);
   // Pack Operands(segment code)
-  trace(99, "transform") << "-- pack operands" << end();
+  trace(3, "transform") << "-- pack operands" << end();
   for (int i = 0;  i < SIZE(code.lines);  ++i) {
     line& inst = code.lines.at(i);
     if (all_hex_bytes(inst)) continue;
diff --git a/subx/031check_operands.cc b/subx/031check_operands.cc
index 3f3b780a..bc76fca5 100644
--- a/subx/031check_operands.cc
+++ b/subx/031check_operands.cc
@@ -13,7 +13,7 @@ if (trace_contains_errors()) return;
 
 :(code)
 void check_operands(const segment& code) {
-  trace(99, "transform") << "-- check operands" << end();
+  trace(3, "transform") << "-- check operands" << end();
   for (int i = 0;  i < SIZE(code.lines);  ++i) {
     check_operands(code.lines.at(i));
     if (trace_contains_errors()) return;  // stop at the first mal-formed instruction
diff --git a/subx/032check_operand_bounds.cc b/subx/032check_operand_bounds.cc
index b2276a8c..58b7c7b9 100644
--- a/subx/032check_operand_bounds.cc
+++ b/subx/032check_operand_bounds.cc
@@ -27,7 +27,7 @@ check_operand_bounds(code);
 if (trace_contains_errors()) return;
 :(code)
 void check_operand_bounds(const segment& code) {
-  trace(99, "transform") << "-- check operand bounds" << end();
+  trace(3, "transform") << "-- check operand bounds" << end();
   for (int i = 0;  i < SIZE(code.lines);  ++i) {
     const line& inst = code.lines.at(i);
     for (int j = first_operand(inst);  j < SIZE(inst.words);  ++j)
diff --git a/subx/034compute_segment_address.cc b/subx/034compute_segment_address.cc
index 2798e040..79c6e45d 100644
--- a/subx/034compute_segment_address.cc
+++ b/subx/034compute_segment_address.cc
@@ -31,7 +31,7 @@ Currently_parsing_segment_index = -1;
 if (!starts_with(segment_title, "0x")) {
   Currently_parsing_named_segment = true;
   if (!contains_key(Segment_index, segment_title)) {
-    trace(99, "parse") << "new segment '" << segment_title << "'" << end();
+    trace(3, "parse") << "new segment '" << segment_title << "'" << end();
     if (out.segments.empty() && segment_title != "code") {
       raise << "first segment must be 'code' but is '" << segment_title << "'\n" << end();
       return;
@@ -44,7 +44,7 @@ if (!starts_with(segment_title, "0x")) {
     out.segments.push_back(segment());
   }
   else {
-    trace(99, "parse") << "appending to segment '" << segment_title << "'" << end();
+    trace(3, "parse") << "appending to segment '" << segment_title << "'" << end();
   }
   Currently_parsing_segment_index = get(Segment_index, segment_title);
 }
@@ -52,7 +52,7 @@ if (!starts_with(segment_title, "0x")) {
 :(before "End flush(p, lines) Special-cases")
 if (Currently_parsing_named_segment) {
   assert(!p.segments.empty());
-  trace(99, "parse") << "flushing segment" << end();
+  trace(3, "parse") << "flushing segment" << end();
   vector<line>& curr_segment_data = p.segments.at(Currently_parsing_segment_index).lines;
   curr_segment_data.insert(curr_segment_data.end(), lines.begin(), lines.end());
   lines.clear();
@@ -107,7 +107,7 @@ Transform.push_back(compute_segment_starts);
 
 :(code)
 void compute_segment_starts(program& p) {
-  trace(99, "transform") << "-- compute segment addresses" << end();
+  trace(3, "transform") << "-- compute segment addresses" << end();
   uint32_t p_offset = /*size of ehdr*/0x34 + SIZE(p.segments)*0x20/*size of each phdr*/;
   for (size_t i = 0;  i < p.segments.size();  ++i) {
     segment& curr = p.segments.at(i);
diff --git a/subx/035labels.cc b/subx/035labels.cc
index e86441cf..4c5ea641 100644
--- a/subx/035labels.cc
+++ b/subx/035labels.cc
@@ -26,8 +26,8 @@
 05 0x0d0c0b0a/imm32
 Entry:
 05 0x0d0c0b0a/imm32
-+run: inst: 0x00000006
--run: inst: 0x00000001
++run: 0x00000006 opcode: 05
+-run: 0x00000001 opcode: 05
 
 :(before "End Globals")
 uint32_t Entry_address = 0;
@@ -97,7 +97,7 @@ loop:
 Transform.push_back(rewrite_labels);
 :(code)
 void rewrite_labels(program& p) {
-  trace(99, "transform") << "-- rewrite labels" << end();
+  trace(3, "transform") << "-- rewrite labels" << end();
   if (p.segments.empty()) return;
   segment& code = p.segments.at(0);
   map<string, int32_t> byte_index;  // values are unsigned, but we're going to do subtractions on them so they need to fit in 31 bits
diff --git a/subx/036global_variables.cc b/subx/036global_variables.cc
index 78824262..2d20ca43 100644
--- a/subx/036global_variables.cc
+++ b/subx/036global_variables.cc
@@ -18,7 +18,7 @@ x:
 Transform.push_back(rewrite_global_variables);
 :(code)
 void rewrite_global_variables(program& p) {
-  trace(99, "transform") << "-- rewrite global variables" << end();
+  trace(3, "transform") << "-- rewrite global variables" << end();
   // Begin rewrite_global_variables
   map<string, uint32_t> address;
   compute_addresses_for_global_variables(p, address);
diff --git a/subx/038---literal_strings.cc b/subx/038---literal_strings.cc
index 7077a685..ce46a119 100644
--- a/subx/038---literal_strings.cc
+++ b/subx/038---literal_strings.cc
@@ -23,7 +23,7 @@ Transform.push_back(transform_literal_strings);
 int Next_auto_global = 1;
 :(code)
 void transform_literal_strings(program& p) {
-  trace(99, "transform") << "-- move literal strings to data segment" << end();
+  trace(3, "transform") << "-- move literal strings to data segment" << end();
   if (p.segments.empty()) return;
   segment& code = p.segments.at(0);
   segment data;
diff --git a/subx/039debug.cc b/subx/039debug.cc
index 4b7e3363..9078acf2 100644
--- a/subx/039debug.cc
+++ b/subx/039debug.cc
@@ -22,7 +22,7 @@ void load_map(const string& map_filename) {
 
 :(after "Run One Instruction")
 if (contains_key(Symbol_name, EIP))
-  trace(90, "run") << "== label " << get(Symbol_name, EIP) << end();
+  trace(Callstack_depth, "run") << "== label " << get(Symbol_name, EIP) << end();
 
 //: If a label starts with '$watch-', make a note of the effective address
 //: computed by the next instruction. Start dumping out its contents to the
diff --git a/subx/040---tests.cc b/subx/040---tests.cc
index 24819993..e6f2f489 100644
--- a/subx/040---tests.cc
+++ b/subx/040---tests.cc
@@ -26,13 +26,13 @@ test-foo:  # offset 7
   c3/return
 
 # check that code in test-foo ran (implicitly called by run-tests)
-+run: inst: 0x00000007
++run: 0x00000007 opcode: 01
 
 :(code)
 void create_test_function(program& p) {
   if (p.segments.empty()) return;
   segment& code = p.segments.at(0);
-  trace(99, "transform") << "-- create 'run-tests'" << end();
+  trace(3, "transform") << "-- create 'run-tests'" << end();
   vector<line> new_insts;
   for (int i = 0;  i < SIZE(code.lines);  ++i) {
     line& inst = code.lines.at(i);
diff --git a/subx/drun b/subx/drun
index 82584772..15c7f747 100755
--- a/subx/drun
+++ b/subx/drun
@@ -12,9 +12,9 @@ fi
 
 if [[ $1 == 'ex'* ]]
 then
-  CFLAGS=-g ./subx --map --trace run examples/$* 2>x
+  CFLAGS=-g ./subx --map --trace run examples/$*
   exit $?
 fi
 
-CFLAGS=-g ./subx --map --trace run apps/$* 2>x
+CFLAGS=-g ./subx --map --trace run apps/$*
 exit $?