1025 lines
34 KiB
Text
1025 lines
34 KiB
Text
# SPDX-License-Identifier: GPL-2.0-or-later
|
|
#
|
|
# NOTE! This copyright does *not* cover user models that use these Nasal
|
|
# services by normal function calls - this is merely considered normal use
|
|
# of the code, and does *not* fall under the heading of "derived work."
|
|
#
|
|
# Copyright (C) 2003-2007 by andy
|
|
# Copyright (C) 2005-2008 by mfranz
|
|
# Copyright (C) 2012-2014 by Thomas Geymayer
|
|
# Copyright (C) 2017-2019 by Stuart Buchanan
|
|
# Copyright (C) 2019-2020 by Henning Stahlke
|
|
|
|
# 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
|
|
#
|
|
# 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
|
|
#
|
|
# 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)
|
|
#
|
|
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) {
|
|
if (isghost(p) and ghosttype(p) == "prop")
|
|
return props.wrapNode(p);
|
|
if (isscalar(p) 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";
|
|
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" : "";
|
|
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);
|
|
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 (isscalar(o)) {
|
|
return num(o) == nil ? _dump_string(o, color) : _num(o~"", color);
|
|
|
|
} elsif (isvec(o)) {
|
|
var s = "";
|
|
forindex (var i; o)
|
|
s ~= (i == 0 ? "" : ", ") ~ debug.string(o[i], color, ttl - 1);
|
|
return _bracket("[", color) ~ s ~ _bracket("]", color);
|
|
|
|
} elsif (ishash(o)) {
|
|
if (contains(o, "parents") and isvec(o.parents)
|
|
and size(o.parents) == 1 and o.parents[0] == props.Node)
|
|
return _angle("'<", color) ~ _dump_prop(o, color) ~ _angle(">'", color);
|
|
|
|
var k = keys(o);
|
|
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 (isghost(o)) {
|
|
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;
|
|
}
|
|
}
|
|
return "-unknown-";
|
|
}
|
|
|
|
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);
|
|
var filename = v[2];
|
|
var line = v[3];
|
|
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]))));
|
|
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)
|
|
print(_nil("ADD "), this.getPath());
|
|
elsif (type < 0)
|
|
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 (isvec(output)) {
|
|
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 (isvec(output)) {
|
|
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) {
|
|
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 (isvec(names)) {
|
|
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]);
|
|
}
|
|
|
|
|
|
var isnan = func {
|
|
call(math.sin, arg, var err = []);
|
|
return !!size(err);
|
|
}
|
|
|
|
# Probe class - collect statistics; controlled via property tree
|
|
# Data can be viewed / modified in the prop tree /_debug/nas/probe/<myLabel>/*
|
|
# ./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 = {
|
|
_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, "\\", "_");
|
|
return class~"-"~label;
|
|
},
|
|
|
|
# label: Used in property path
|
|
# prefix: Optional
|
|
new: func(label, class = "probe") {
|
|
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];
|
|
|
|
var obj = {
|
|
parents: [Probe],
|
|
uid: uid,
|
|
label: label,
|
|
hits: [0],
|
|
node: nil,
|
|
_enableN: nil,
|
|
_resetN: nil,
|
|
_hitsN: [],
|
|
_start_time: 0,
|
|
_stop_time: 0,
|
|
_timeoutN: nil, # > 0, disable probe after _timeout seconds
|
|
_L: [],
|
|
};
|
|
|
|
obj.node = props.globals.getNode("/_debug/nas/"~class~"/"~label, 1);
|
|
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)
|
|
);
|
|
|
|
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)
|
|
);
|
|
|
|
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]);
|
|
Probe._instances[obj.uid] = obj;
|
|
return obj;
|
|
},
|
|
|
|
del: func () {
|
|
foreach (var l; me._L) {
|
|
removelistener(l);
|
|
}
|
|
me.node.remove();
|
|
Probe._instances[me.uid] = nil;
|
|
},
|
|
|
|
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;
|
|
},
|
|
|
|
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)
|
|
# 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)) {
|
|
callback(me.hits);
|
|
}
|
|
}
|
|
return me;
|
|
},
|
|
};
|
|
|
|
# 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
|
|
#
|
|
# 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
|
|
# * 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:
|
|
# 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 Breakpoint = {
|
|
|
|
# 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: [Breakpoint, Probe.new(label, "bp")],
|
|
tokens: 0,
|
|
skip_level: num(skip_level+1), # +1 for Breakpoint.hit()
|
|
dump_locals: num(dump_locals),
|
|
};
|
|
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
|
|
#
|
|
# 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)
|
|
);
|
|
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;
|
|
},
|
|
|
|
disableTracing: func() {
|
|
me._enableN.setIntValue(0);
|
|
return me;
|
|
},
|
|
|
|
resetTrace: func () {
|
|
me.node.getNode("trace",1).remove();
|
|
},
|
|
|
|
|
|
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);
|
|
}
|
|
me._enableN.setValue(me.tokens);
|
|
me._trace(1);
|
|
}
|
|
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);
|
|
}
|
|
}
|
|
|
|
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;
|
|
}
|
|
|
|
#-- Init -----------------------------------------------------------------------
|
|
# General purpose breakpoint for the lazy ones.
|
|
var bp = 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);
|
|
|
|
# --prop:debug=1 enables debug mode with additional warnings
|
|
#
|
|
|
|
if (getprop("debug")) {
|
|
var writewarn = func(f, p, r) {
|
|
if (!r) {
|
|
var hint = "";
|
|
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",
|
|
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));
|
|
}
|