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.

24 files changed, 539 insertions, 448 deletions

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 $?