1
0
Fork 0
fgdata/Nasal/debug.nas

1017 lines
33 KiB
Text
Raw Normal View History

# debug.nas -- debugging helpers
#------------------------------------------------------------------------------
#
# debug.dump(<variable>) ... dumps contents of variable to terminal;
# abbreviation for print(debug.string(v))
#
# debug.local([<frame:int>]) ... dump local variables of current
# or given frame
#
2019-01-13 19:55:56 +00:00
# debug.backtrace([<comment:string>], [<dump:bool=1>], [<skip_level:int=0>]}
# ... writes backtrace (similar to gdb's "bt full)
# dump=0: only call stack
# dump=1 (default): with local variables
# skip_level: remove this many levels from
# call stack
#
# debug.proptrace([<property [, <frames>]]) ... trace property write/add/remove
# events under the <property> subtree for
# a number of frames. Defaults are "/" and
# 2 frames (of which the first one is incomplete).
#
# debug.tree([<property> [, <mode>]) ... dump property tree under property path
# or props.Node hash (default: root). If
# <mode> is unset or 0, use flat mode
# (similar to props.dump()), otherwise
# use space indentation
#
# debug.bt() ... abbreviation for debug.backtrace()
#
# debug.string(<variable>) ... returns contents of variable as string
#
# debug.attributes(<property> [, <verb>]) ... returns attribute string for a given property.
# <verb>ose is by default 1, and suppressed the
# node's refcounter if 0.
#
# debug.isnan() returns 1 if argument is an invalid number (NaN),
# 0 if it's a valid number, and nil in all other cases
#
# debug.benchmark(<label:string>, <func> [, <repeat:int> [, <output:vector>]])
# ... runs function <repeat> times (default: nil)
# and prints total execution time in seconds,
# prefixed with <label>, while adding results
# to <output>, or returning the only result
# if <repeat> is nil.
#
# debug.benchmark_time(<func> [, <repeat:int> [, <output:vector>]])
# ... like debug.benchmark, but returns total
# execution time and does not print anything.
#
# debug.rank(<list:vector> [, <repeat:int>])
# ... sorts the list of functions based on execution
# time over <repeat> samples (default: 1).
#
# debug.print_rank(<result:vector>, <names:int>)
# ... prints the <result> of debug.rank with <names>
# (which can be a vector of [name, func] or
# [func, name], or a hash of name:func).
#
# debug.printerror(<err-vector>) ... prints error vector as set by call()
#
# debug.warn(<message>, <level>) ... generate debug message followed by caller stack trace
# skipping <level> caller levels (default: 0).
#
# debug.propify(<variable>) ... turn about everything into a props.Node
#
2019-01-31 11:53:28 +00:00
# debug.Probe class ... base class to collect stats; details below
# debug.Breakpoint class ... conditional backtrace; details below
#
# debug.addProbeToFunc(label, func) ... wraps a function with a probe
# debug.findFunctions(ns, recursive=0) ... find all functions in a hash (namespace)
#
# debug.addProbesToNamespace(ns, label="", recursive=0)
# ... combines findFunctions and addProbeToFunc
#
# CAVE: this file makes extensive use of ANSI color codes. These are
# interpreted by UNIX shells and MS Windows with ANSI.SYS extension
# installed. If the color codes aren't interpreted correctly, then
# set property /sim/startup/terminal-ansi-colors=0
#
# ANSI color code wrappers (see $ man console_codes)
2007-01-29 16:24:58 +00:00
#
var _title = func(s, color=nil) globals.string.color("33;42;1", s, color); # backtrace header
var _section = func(s, color=nil) globals.string.color("37;41;1", s, color); # backtrace frame
var _error = func(s, color=nil) globals.string.color("31;1", s, color); # internal errors
var _bench = func(s, color=nil) globals.string.color("37;45;1", s); # benchmark info
var _nil = func(s, color=nil) globals.string.color("32", s, color); # nil
var _string = func(s, color=nil) globals.string.color("31", s, color); # "foo"
var _num = func(s, color=nil) globals.string.color("31", s, color); # 0.0
var _bracket = func(s, color=nil) globals.string.color("", s, color); # [ ]
var _brace = func(s, color=nil) globals.string.color("", s, color); # { }
var _angle = func(s, color=nil) globals.string.color("", s, color); # < >
var _vartype = func(s, color=nil) globals.string.color("33", s, color); # func ghost
var _proptype = func(s, color=nil) globals.string.color("34", s, color); # BOOL INT LONG DOUBLE ...
var _path = func(s, color=nil) globals.string.color("36", s, color); # /some/property/path
var _internal = func(s, color=nil) globals.string.color("35", s, color); # me parents
var _varname = func(s, color=nil) s; # variable_name
##
# Turn p into props.Node (if it isn't yet), or return nil.
#
var propify = func(p, create = 0) {
var type = typeof(p);
if (type == "ghost" and ghosttype(p) == "prop")
return props.wrapNode(p);
if (type == "scalar" and num(p) == nil)
return props.globals.getNode(p, create);
if (isa(p, props.Node))
return p;
return nil;
}
var tree = func(n = "", graph = 1) {
n = propify(n);
if (n == nil)
return dump(n);
_tree(n, graph);
}
var _tree = func(n, graph = 1, prefix = "", level = 0) {
var path = n.getPath();
var children = n.getChildren();
var s = "";
if (graph) {
s = prefix ~ n.getName();
var index = n.getIndex();
if (index)
s ~= "[" ~ index ~ "]";
} else {
s = n.getPath();
}
if (size(children)) {
s ~= "/";
if (n.getType() != "NONE")
s ~= " = " ~ debug.string(n.getValue()) ~ " " ~ attributes(n)
~ " " ~ _section(" PARENT-VALUE ");
} else {
s ~= " = " ~ debug.string(n.getValue()) ~ " " ~ attributes(n);
}
if ((var a = n.getAliasTarget()) != nil)
s ~= " " ~ _title(" alias to ") ~ " " ~ a.getPath();
print(s);
if (n.getType() != "ALIAS")
forindex (var i; children)
_tree(children[i], graph, prefix ~ ". ", level + 1);
}
var attributes = func(p, verbose = 1, color=nil) {
var r = p.getAttribute("readable") ? "" : "r";
var w = p.getAttribute("writable") ? "" : "w";
2007-01-30 23:22:36 +00:00
var R = p.getAttribute("trace-read") ? "R" : "";
var W = p.getAttribute("trace-write") ? "W" : "";
var A = p.getAttribute("archive") ? "A" : "";
var U = p.getAttribute("userarchive") ? "U" : "";
var P = p.getAttribute("preserve") ? "P" : "";
2007-01-30 23:22:36 +00:00
var T = p.getAttribute("tied") ? "T" : "";
var attr = r ~ w ~ R ~ W ~ A ~ U ~ P ~ T;
var type = "(" ~ p.getType();
if (size(attr))
type ~= ", " ~ attr;
if (var l = p.getAttribute("listeners"))
type ~= ", L" ~ l;
if (verbose and (var c = p.getAttribute("references")) > 2)
type ~= ", #" ~ (c - 2);
return _proptype(type ~ ")", color);
}
var _dump_prop = func(p, color=nil) {
_path(p.getPath(), color) ~ " = " ~ debug.string(p.getValue(), color)
~ " " ~ attributes(p, 1, color);
}
var _dump_var = func(v, color=nil) {
if (v == "me" or v == "parents")
return _internal(v, color);
else
return _varname(v, color);
}
var _dump_string = func(str, color=nil) {
var s = "'";
for (var i = 0; i < size(str); i += 1) {
var c = str[i];
if (c == `\``)
s ~= "\\`";
elsif (c == `\n`)
s ~= "\\n";
elsif (c == `\r`)
s ~= "\\r";
elsif (c == `\t`)
s ~= "\\t";
elsif (globals.string.isprint(c))
s ~= chr(c);
else
s ~= sprintf("\\x%02x", c);
}
return _string(s ~ "'", color);
}
# dump hash keys as variables if they are valid variable names, or as string otherwise
var _dump_key = func(s, color=nil) {
if (num(s) != nil)
return _num(s, color);
2008-10-25 14:24:26 +00:00
if (!size(s))
return _dump_string(s, color);
if (!globals.string.isalpha(s[0]) and s[0] != `_`)
return _dump_string(s, color);
for (var i = 1; i < size(s); i += 1)
if (!globals.string.isalnum(s[i]) and s[i] != `_`)
return _dump_string(s, color);
_dump_var(s, color);
}
var string = func(o, color=nil, ttl=5) {
if (o == globals and ttl < 5) return "<globals>"; # do not loop int globals
if (!ttl) return "<...>";
var t = typeof(o);
if (t == "nil") {
return _nil("null", color);
} elsif (t == "scalar") {
return num(o) == nil ? _dump_string(o, color) : _num(o~"", color);
} elsif (t == "vector") {
2007-01-30 23:22:36 +00:00
var s = "";
forindex (var i; o)
s ~= (i == 0 ? "" : ", ") ~ debug.string(o[i], color, ttl - 1);
return _bracket("[", color) ~ s ~ _bracket("]", color);
} elsif (t == "hash") {
if (contains(o, "parents") and typeof(o.parents) == "vector"
2007-06-12 21:27:48 +00:00
and size(o.parents) == 1 and o.parents[0] == props.Node)
return _angle("'<", color) ~ _dump_prop(o, color) ~ _angle(">'", color);
2007-06-12 21:27:48 +00:00
var k = keys(o);
2007-01-30 23:22:36 +00:00
var s = "";
forindex (var i; k)
s ~= (i == 0 ? "" : ", ") ~ _dump_key(k[i], color) ~ ": " ~ debug.string(o[k[i]], color, ttl - 1);
return _brace("{", color) ~ " " ~ s ~ " " ~ _brace("}", color);
} elsif (t == "ghost") {
return _angle("'<", color) ~ _nil(ghosttype(o), color) ~ _angle(">'", color);
} else {
return _angle("'<", color) ~ _vartype(t, color) ~ _angle(">'", color);
}
}
var dump = func(vars...) {
if (!size(vars))
return local(1);
if (size(vars) == 1)
return print(debug.string(vars[0]));
forindex (var i; vars)
print(globals.string.color("33;40;1", "#" ~ i) ~ " ", debug.string(vars[i]));
}
var local = func(frame = 0) {
var v = caller(frame + 1);
print(v == nil ? _error("<no such frame>") : debug.string(v[0]));
return v;
}
# According to the Nasal design doc funtions do not have unique internal names.
# Nevertheless you can sometimes find a matching symbol, so funcname may help to
# make debug output more helpful, but unfortunately you cannot rely on it.
var funcname = func(f) {
if (!isfunc(f)) return "";
var namespace = closure(f);
foreach (var k; keys(namespace)) {
if (isfunc(namespace[k])) {
if (namespace[k] == f)
return k;
}
}
2020-04-24 13:55:11 +00:00
return "-unknown-";
}
2019-01-13 19:55:56 +00:00
var backtrace = func(desc = nil, dump_vars = 1, skip_level = 0) {
var d = (desc == nil) ? "" : " '" ~ desc ~ "'";
print("");
print(_title("### backtrace" ~ d ~ " ###"));
skip_level += 1;
for (var i = skip_level; 1; i += 1) {
if ((var v = caller(i)) == nil) return caller(i - 1);
2020-03-27 21:34:26 +00:00
var filename = v[2];
var line = v[3];
2020-03-27 21:34:26 +00:00
if (size(filename) > 50)
filename = substr(filename, 0, 5)~"[...]"~substr(filename, -40);
print(_section(sprintf("#%-2d called from %s:%d (%s) (locals %s):",
i - skip_level, filename, line, funcname(v[1]), id(v[0]))));
2019-01-13 19:55:56 +00:00
if (dump_vars) dump(v[0]);
}
}
var bt = backtrace;
var proptrace = func(root = "/", frames = 2) {
var events = 0;
var trace = setlistener(propify(root), func(this, base, type) {
events += 1;
if (type > 0)
2007-10-16 18:54:25 +00:00
print(_nil("ADD "), this.getPath());
elsif (type < 0)
2007-10-16 18:54:25 +00:00
print(_num("DEL "), this.getPath());
else
print("SET ", this.getPath(), " = ", debug.string(this.getValue()), " ", attributes(this));
}, 0, 2);
var mark = setlistener("/sim/signals/frame", func {
print("-------------------- FRAME --------------------");
if (!frames) {
removelistener(trace);
removelistener(mark);
print("proptrace: stop (", events, " calls)");
}
frames -= 1;
});
}
##
# Executes function fn "repeat" times and prints execution time in seconds. If repeat
# is an integer and an optional "output" argument is specified, each test's result
# is appended to that vector, then the vector is returned. If repeat is nil, then
# the function is run once and the result returned. Otherwise, the result is discarded.
# Examples:
#
# var test = func { getprop("/sim/aircraft"); }
# debug.benchmark("test()/1", test, 1000);
# debug.benchmark("test()/2", func setprop("/sim/aircraft", ""), 1000);
#
# var results = debug.benchmark("test()", test, 1000, []);
# print(" Results were:");
# print(" ", debug.string(results));
#
var benchmark = func(label, fn, repeat = nil, output=nil) {
var start = var end = nil;
if (repeat == nil) {
start = systime();
output = fn();
} elsif (typeof(output) == 'vector') {
start = systime();
for (var i = 0; i < repeat; i += 1)
append(output, fn());
} else {
start = systime();
for (var i = 0; i < repeat; i += 1)
fn();
}
end = systime();
print(_bench(sprintf(" %s --> %.6f s ", label, end - start)));
return output;
}
var benchmark_time = func(fn, repeat = 1, output = nil) {
var start = var end = nil;
if (repeat == nil) {
start = systime();
output = fn();
} elsif (typeof(output) == 'vector') {
start = systime();
for (var i = 0; i < repeat; i += 1)
append(output, fn());
} else {
start = systime();
for (var i = 0; i < repeat; i += 1)
fn();
}
end = systime();
return end - start;
}
##
# Executes each function in the list and returns a sorted vector with the fastest
# on top (i.e. first). Each position in the result is a vector of [func, time].
#
var rank = func(list, repeat = nil) {
var result = [];
foreach (var fn; list) {
var time = benchmark_time(fn, repeat);
append(result, [fn, time]);
}
return sort(result, func(a,b) a[1] < b[1] ? -1 : a[1] > b[1] ? 1 : 0);
}
var print_rank = func(label, list, names) {
var _vec = (typeof(names) == 'vector');
print("Test results for "~label);
var first = 1;
var longest = list[-1][1];
foreach (var item; list) {
var (fn, time) = item;
var name = nil;
if (_vec) {
foreach (var l; names) {
if (l[1] == fn) {
name = l[0]; break;
} elsif (l[0] == fn) {
name = l[1]; break;
}
}
} else {
foreach (var name; keys(names)) {
if (names[name] == fn) break;
else name = nil;
}
}
if (name == nil) die("function not found");
print(" "~name~(first?" (fastest)":"")~" took "~(time*1000)~" ms ("~(time/longest*100)~"%) time");
first = 0;
}
return list;
}
##
# print error vector as set by call(). By using call() one can execute
# code that catches "exceptions" (by a die() call or errors). The Nasal
# code doesn't abort in this case. Example:
#
# var possibly_buggy = func { ... }
# call(possibly_buggy, nil, var err = []);
# debug.printerror(err);
#
var printerror = func(err) {
if (!size(err))
return;
printf("%s:\n at %s, line %d", err[0], err[1], err[2]);
for (var i = 3; i < size(err); i += 2)
printf(" called from: %s, line %d", err[i], err[i + 1]);
}
# like die(), but code execution continues. The level argument defines
# how many caller() levels to omit. One is automatically omitted, as
# this would only point to debug.warn(), where the event in question
# didn't happen.
#
var warn = func(msg, level = 0) {
var c = caller(level += 1);
if (c == nil)
die("debug.warn with invalid level argument");
printf("%s:\n at %s, line %d", msg, c[2], c[3]);
while ((c = caller(level += 1)) != nil)
printf(" called from: %s, line %d", c[2], c[3]);
}
2009-04-24 08:12:21 +00:00
var isnan = func {
call(math.sin, arg, var err = []);
return !!size(err);
}
2019-01-31 11:53:28 +00:00
# Probe class - collect statistics; controlled via property tree
2020-05-12 07:21:37 +00:00
# Data can be viewed / modified in the prop tree /_debug/nas/probe/<myLabel>/*
2019-01-31 11:53:28 +00:00
# ./enable bool,
# ./reset bool, reset hit counters to 0 and _start_time to now
# ./hits[i] number of hits, by default i=0 -> hits
# secondary counters can be added under the same path
# with addCounter()
# ./time after generateStats() show how long the probe was enabled
# ./hps after generateStats() show avg. hits/second
# ./hitratio after generateStats() if two counters: hits[1]/hits[0]
#
# == Example ==
# var myProbe = debug.Probe.new("myLabel").enable();
# var cnt2 = myProbe.addCounter(); # create a 2nd counter
#
# #at the place of interest (e.g. in some loop or class method) insert:
# myProbe.hit(); # count how often this place in the code is hit
# if (condition)
# myProbe.hit(cnt2); # count how often condition is true
#
# print(myProbe.getHits());
# print(myProbe.getHits(cnt2)/myProbe.getHits()); # print hit ratio
#
var Probe = {
2020-04-24 13:55:11 +00:00
_instances: {},
_uid: func(label, class) {
class = globals.string.replace(class, " ", "_");
label = globals.string.replace(label, " ", "_");
label = globals.string.replace(label, "/", "_");
label = globals.string.replace(label, "\\", "_");
2020-04-24 13:55:11 +00:00
return class~"-"~label;
},
2019-01-31 11:53:28 +00:00
# label: Used in property path
# prefix: Optional
new: func(label, class = "probe") {
2020-04-24 13:55:11 +00:00
if (!isscalar(label) or !isscalar(class)) {
die("Invalid argument type to Probe.new");
}
var uid = me._uid(label,class);
if (Probe._instances[uid] != nil) return Probe._instances[uid];
2019-01-31 11:53:28 +00:00
var obj = {
parents: [Probe],
2020-04-24 13:55:11 +00:00
uid: uid,
label: label,
2019-01-31 11:53:28 +00:00
hits: [0],
node: nil,
_enableN: nil,
_resetN: nil,
_hitsN: [],
_start_time: 0,
_stop_time: 0,
_timeoutN: nil, # > 0, disable probe after _timeout seconds
_L: [],
};
2020-04-24 13:55:11 +00:00
2020-05-12 07:21:37 +00:00
obj.node = props.globals.getNode("/_debug/nas/"~class~"/"~label, 1);
2019-01-31 11:53:28 +00:00
obj.node.removeChildren();
obj._enableN = obj.node.addChild("enable");
obj._enableN.setBoolValue(0);
append(obj._L,
setlistener(obj._enableN, func(n) {
if (n.getValue()) obj.enable();
else obj.disable();
}, 0, 0)
);
2019-01-31 11:53:28 +00:00
obj._resetN = obj.node.addChild("reset");
obj._resetN.setBoolValue(0);
append(obj._L,
setlistener(obj._resetN, func(n) {
if (n.getValue()) {
obj.reset();
n.setValue(0);
}
}, 0, 0)
);
2019-01-31 11:53:28 +00:00
append(obj._hitsN, obj.node.addChild("hits"));
obj._hitsN[0].setIntValue(0);
# for live monitoring via prop browser, alias all hit counters in one place
props.globals.getNode("/_debug/nas/_stats/"~obj.uid, 1)
.alias(obj._hitsN[0]);
2020-04-24 13:55:11 +00:00
Probe._instances[obj.uid] = obj;
2019-01-31 11:53:28 +00:00
return obj;
},
2020-04-24 13:55:11 +00:00
del: func () {
foreach (var l; me._L) {
removelistener(l);
}
me.node.remove();
Probe._instances[me.uid] = nil;
},
2019-01-31 11:53:28 +00:00
reset: func {
forindex (var i; me.hits) {
me.hits[i] = 0;
me._hitsN[i].setValue(0);
}
me._start_time = systime();
},
# set timeout, next hit() after timeout will disable()
setTimeout: func(seconds) {
if (!isa(me._timeoutN, props.Node))
me._timeoutN = me.node.getNode("timeout", 1);
me._timeoutN.setValue(num(seconds) or 0);
return me;
},
#enable counting
enable: func {
me._enableN.setValue(1);
me._start_time = systime();
return me;
},
#disable counting, write time and hit/s to property tree
disable: func {
me._enableN.setValue(0);
me._stop_time = systime();
me.generateStats();
return me;
},
2019-01-31 11:53:28 +00:00
generateStats: func {
if (me._start_time) {
if (me._enableN.getValue())
me._stop_time = systime();
var dt = me._stop_time - me._start_time;
me.node.getNode("time", 1).setValue(dt);
me.node.getNode("hps", 1).setValue(me.hits[0] / dt );
if (size(me.hits) == 2)
me.node.getNode("hitratio",1).setValue(me.hits[1] / me.hits[0] or 1);
}
},
getHits: func(counter_id = 0) {
return me.hits[counter_id];
},
# add secondary counter(s)
# returns counter id
addCounter: func {
append(me._hitsN, me.node.addChild("hits"));
append(me.hits, 0);
return size(me._hitsN) - 1;
},
# increment counter (if enabled)
2019-01-31 11:53:28 +00:00
# use addCounter() before using counter_id > 0
hit: func(counter_id = 0, callback = nil) {
if (me._enableN.getValue()) {
if (counter_id >= size(me._hitsN)) {
print("debug.Probe.hit(): Invalid counter_id");
me.disable();
return nil;
}
if (isa(me._timeoutN, props.Node)) {
var timeout = me._timeoutN.getValue();
if (timeout and systime() - me._start_time > timeout) {
return me.disable();
}
}
me.hits[counter_id] += 1;
me._hitsN[counter_id].increment();
if (isfunc(callback)) {
2019-01-31 11:53:28 +00:00
callback(me.hits);
}
}
return me;
},
2019-01-31 11:53:28 +00:00
};
2019-01-13 19:55:56 +00:00
# Breakpoint (BP) - do conditional backtrace (BT) controlled via property tree
# * count how often the BP was hit
# * do only a limited number of BT, avoid flooding the log / console
#
2020-05-12 07:21:37 +00:00
# Data can be viewed / modified in the prop tree /_debug/nas/bp/<myLabel>/*
# * tokens: number of backtraces to do; each hit will decrement this by 1
2019-01-13 19:55:56 +00:00
# * hits: total number of hits
#
# == Example ==
# var myBP = debug.Breakpoint.new("myLabel", 0);
# myBP.enable(4); # allow 4 hits, then be quiet
#
# #at the place of interest (e.g. in some loop or class method) insert:
2019-01-22 07:39:03 +00:00
# myBP.hit(); # do backtrace here if tokens > 0, reduce tokens by 1
# myBP.hit(myFunction); # same but call myFunction instead of backtrace
#
2019-01-13 19:55:56 +00:00
# print(myBP.getHits()); # print total number of hits
#
var Breakpoint = {
2020-04-24 13:55:11 +00:00
2019-01-13 19:55:56 +00:00
# label: Used in property path and as text for backtrace.
# dump_locals: bool passed to backtrace. Dump variables in BT.
# skip_level: int passed to backtrace.
new: func(label, dump_locals = 0, skip_level=0) {
2019-01-13 19:55:56 +00:00
var obj = {
2019-01-31 11:53:28 +00:00
parents: [Breakpoint, Probe.new(label, "bp")],
tokens: 0,
skip_level: num(skip_level+1), # +1 for Breakpoint.hit()
2019-01-13 19:55:56 +00:00
dump_locals: num(dump_locals),
};
2019-01-31 11:53:28 +00:00
obj._enableN.remove();
obj._enableN = obj.node.getNode("tokens", 1);
obj._enableN.setIntValue(0);
return obj;
},
# enable BP and set hit limit;
# tokens: int > 0; default: 1 (single shot); 0 allowed (=disable);
enable: func(tokens = 1) {
if (num(tokens) == nil) tokens = 1;
if (tokens < 0) tokens = 0;
me.tokens = tokens;
me._enableN.setIntValue(tokens);
return me;
},
# hit the breakpoint, e.g. do backtrace if we have tokens available
hit: func(callback = nil) {
me.hits[0] += 1;
me._hitsN[0].increment();
me.tokens = me._enableN.getValue() or 0;
if (me.tokens > 0) {
me.tokens -= 1;
if (isfunc(callback)) {
callback(me.hits[0], me.tokens);
}
else {
debug.backtrace(me.label, me.dump_locals, me.skip_level);
}
me._enableN.setValue(me.tokens);
}
return me;
},
};
# Tracer - perform conditional backtraces / statistics controlled via property tree
# * backtraces are written to property tree
# * do only a limited number of BT, avoid flooding the log / console
# * trace statistics can be dumped to XML file
#
2020-05-12 07:21:37 +00:00
# Data can be viewed / modified in the prop tree /_debug/nas/trc/<myLabel>/*
# * tokens: number of backtraces to do; each hit will decrement this by 1
# * hits: total number of hits
#
# == Example ==
# var myBP = debug.Tracer.new("myLabel", 0);
# myBP.enable(4); # allow 4 hits, then be quiet
#
# #at the place of interest (e.g. in some loop or class method) insert:
# myBP.hit(); # do backtrace here if tokens > 0, reduce tokens by 1
# myBP.hit(myFunction); # same but call myFunction instead of backtrace
#
# print(myBP.getHits()); # print total number of hits
#
var Tracer = {
# label: Used in property path and as text for backtrace.
# dump_locals: bool passed to backtrace. Dump variables in BT.
# skip_level: int passed to backtrace.
new: func(label, dump_locals = 0, skip_level=0) {
var obj = {
parents: [Tracer, Probe.new(label, "trc")],
tokens: 0,
skip_level: num(skip_level+1), # +1 for Tracer.hit()
dump_locals: num(dump_locals),
};
obj._enableN.remove();
obj._enableN = obj.node.getNode("tokens", 1);
obj._enableN.setIntValue(0);
obj._dumpN = obj.node.addChild("dump-trace");
obj._dumpN.setBoolValue(0);
append(obj._L,
setlistener(obj._dumpN, func(n) {
if (n.getValue() == 1) obj.dumpTrace();
n.setBoolValue(0);
}, 0, 0)
);
obj._resetTraceN = obj.node.addChild("reset-trace");
obj._resetTraceN.setBoolValue(0);
append(obj._L,
setlistener(obj._resetTraceN, func(n) {
if (n.getValue() == 1) obj.resetTrace();
n.setBoolValue(0);
}, 0, 0)
);
2019-01-13 19:55:56 +00:00
return obj;
},
2019-01-31 11:53:28 +00:00
2019-01-13 19:55:56 +00:00
# enable BP and set hit limit;
# tokens: int > 0; default: 1 (single shot); 0 allowed (=disable);
enable: func(tokens = 1) {
if (num(tokens) == nil) tokens = 1;
if (tokens < 0) tokens = 0;
me.tokens = tokens;
2019-01-31 11:53:28 +00:00
me._enableN.setIntValue(tokens);
2019-01-13 19:55:56 +00:00
return me;
},
disableTracing: func() {
me._enableN.setIntValue(0);
return me;
},
resetTrace: func () {
me.node.getNode("trace",1).remove();
},
2019-01-22 07:39:03 +00:00
hit: func(callback = nil) {
2019-01-31 11:53:28 +00:00
me.hits[0] += 1;
me._hitsN[0].increment();
2020-04-24 13:55:11 +00:00
me.tokens = me._enableN.getValue() or 0;
2019-01-13 19:55:56 +00:00
if (me.tokens > 0) {
2019-01-22 07:39:03 +00:00
me.tokens -= 1;
if (isfunc(callback)) {
2019-01-31 11:53:28 +00:00
callback(me.hits[0], me.tokens);
2019-01-22 07:39:03 +00:00
}
2019-01-31 11:53:28 +00:00
me._enableN.setValue(me.tokens);
me._trace(1);
2019-01-13 19:55:56 +00:00
}
return me;
},
#write backtrace to prop tree with counters
_trace: func(skip=0) {
var flat_mode = 0;
if (!me._enableN.getValue()) return;
me._enableN.decrement();
var tn = me.node.getNode("trace",1);
for (var i = skip + 1; 1; i += 1) {
var c = caller(i);
if (c == nil) break;
var fn = io.basename(c[2]);
#invalid chars are : [ ] < > =
fn = globals.string.replace(fn,":","_");
fn = globals.string.replace(fn,"#","_");
fn = globals.string.replace(fn,"<","_");
fn = globals.string.replace(fn,">","_");
if (!fn) fn = "_unknown_";
var line = num(c[3]);
var sid = fn~":"~line;
if (flat_mode) {
if (tn.getChild(fn,line) == nil) {
tn.getChild(fn,line,1).setIntValue(1);
}
else {
tn.getChild(fn,line).increment();
}
}
else {
tn = tn.getChild(fn,line,1);
if (tn.getNode("hits") == nil) {
tn.getNode("hits",1).setIntValue(1);
}
else {
tn.getNode("hits").increment();
}
}
}
},
dumpTrace: func (path = nil) {
#props.dump(me.node.getNode("trace",1));
if (path == nil) {
path = getprop("/sim/fg-home")~"/Export/dumpTrace-"~me.uid~".xml";
}
me.node.getNode("dump-result", 1).setValue(
io.write_properties(path, me.node.getNode("trace",1))
);
},
}; #Tracer
# addProbeToFunc - wrap a function with a debug probe
# f: function to wrap with a debug probe (hit counter)
# label: description, passed to probe
#
# WARNING: call() currently breaks the call stack which affects backtrace and
# the use of caller(i>0). Do not use addProbeToFunc on functions which rely on
# caller (which is probably bad coding style, but allowed).
#
var addProbeToFunc = func (f, label) {
if (!isfunc(f)) {
logprint(DEV_ALERT, "wrapFunc() error: argument is not a function.");
return nil;
}
if (!isstr(label)) {
logprint(DEV_ALERT, "wrapFunc() error: argument is not a string.");
return nil;
}
var __probe = Probe.new(label).enable();
var wrapped = func() {
__probe.hit();
return call(f, arg, me, );
}
return wrapped;
}
# addTracerToFunc - wrap a function with a debug breakpoint for tracing
# f: function to wrap with a tracer
# label: description, passed to breakpoint
#
# WARNING: call() currently breaks the call stack which affects backtrace and
# the use of caller(i>0). Do not use addTracerToFunc on functions which rely on
# caller (which is probably bad coding style, but allowed).
#
var addTracerToFunc = func (f, label) {
if (!isfunc(f)) {
logprint(DEV_ALERT, "wrapFunc() error: argument is not a function.");
return nil;
}
if (!isstr(label)) {
logprint(DEV_ALERT, "wrapFunc() error: argument is not a string.");
return nil;
}
var __trc = Tracer.new(label).enable();
var wrapped = func() {
__trc.hit();
return call(f, arg, me, );
}
return wrapped;
}
# scan a hash for function references
# ns: the hash to be searched
# recursive: if you want to search sub hashes (e.g. classes), set this to 1
var findFunctions = func (ns, recursive = 0) {
var functions = {};
foreach (var key; keys(ns)) {
if (recursive and ishash(ns[key]) and id(ns) != id(ns[key])) {
print(key);
var f = findFunctions(ns[key]);
foreach (var k; keys(f)) {
functions[key~"."~k] = f[k];
}
}
if (isfunc(ns[key])) {
functions[key] = ns[key];
}
}
return functions;
}
# add probes to all functions in a namespace for finding hotspots
# use property browser at runtime to check /_debug/nas/_stats/
# ns: hash
# label: description, passed to probe
var _probed_ns = {};
var addProbesToNamespace = func (ns, label = "") {
var nsid = id(ns);
if (_probed_ns[nsid] != nil) return;
else _probed_ns[nsid] = {};
var funcs = findFunctions(ns, 0);
foreach (var key; keys(funcs)) {
_probed_ns[nsid][key] = funcs[key];
ns[key] = addProbeToFunc(funcs[key], label~"-"~key);
}
}
2019-01-31 11:53:28 +00:00
var removeProbesFromNamespace = func (ns) {
var nsid = id(ns);
if (_probed_ns[nsid] == nil) {
logprint(DEV_ALERT, "removeProbesFromNamespace: namespace not found");
return;
}
foreach (var key; keys(_probed_ns[nsid])) {
ns[key] = _probed_ns[nsid][key];
}
_probed_ns[nsid] = nil;
}
# dump a sorted list of hit counters to console
var dumpProbeStats = func () {
var nodes = props.getNode("/_debug/nas/_stats/", 1).getChildren();
var data = [];
foreach (var n; nodes) {
append(data, {name: n.getName(), value: n.getValue()});
}
var mysort = func(a,b) {
if (a.value > b.value) return -1;
elsif (a.value == b.value) return 0;
else return 1;
}
foreach (var probe; sort(data, mysort)) {
print(probe.name," ",probe.value);
}
return;
}
# --prop:debug=1 enables debug mode with additional warnings
#
_setlistener("sim/signals/nasal-dir-initialized", func {
2020-04-24 13:55:11 +00:00
# General purpose breakpoint for the lazy ones.
debug.bp = debug.Breakpoint.new("default", 0);
var dumpN = props.getNode("/_debug/nas/_dumpstats", 1);
dumpN.setBoolValue(0);
setlistener(dumpN, func(n) {
n.setBoolValue(0);
debug.dumpProbeStats();
}, 0, 0);
2020-04-24 13:55:11 +00:00
if (!getprop("debug"))
return;
var writewarn = func(f, p, r) {
if (!r) {
var hint = "";
2009-02-08 21:58:31 +00:00
if ((var n = props.globals.getNode(p)) != nil) {
if (!n.getAttribute("writable"))
hint = " (write protected)";
elsif (n.getAttribute("tied"))
hint = " (tied)";
}
warn("Warning: " ~ f ~ " -> writing to " ~ p ~ " failed" ~ hint, 2);
}
return r;
}
setprop = (func { var _ = setprop; func writewarn("setprop",
2009-02-09 00:24:23 +00:00
globals.string.join("", arg[:-2]), call(_, arg)) })();
props.Node.setDoubleValue = func writewarn("setDoubleValue", me.getPath(),
props._setDoubleValue(me._g, arg));
props.Node.setBoolValue = func writewarn("setBoolValue", me.getPath(),
props._setBoolValue(me._g, arg));
props.Node.setIntValue = func writewarn("setIntValue", me.getPath(),
props._setIntValue(me._g, arg));
props.Node.setValue = func writewarn("setValue", me.getPath(),
props._setValue(me._g, arg));
});