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