add profiling code

This commit is contained in:
John Alanbrook 2024-09-23 18:17:46 -05:00
parent af6824e6db
commit d62a1ca0db
4 changed files with 141 additions and 37 deletions

View file

@ -297,6 +297,7 @@ globalThis.use = function use(file) {
var fn = os.eval(file, script); var fn = os.eval(file, script);
use_cache[file] = fn; use_cache[file] = fn;
var ret = fn(); var ret = fn();
profile.endcache(); profile.endcache();
return ret; return ret;
@ -350,7 +351,6 @@ if (!profile.enabled)
Object.assign(globalThis, use("scripts/prosperon.js")); Object.assign(globalThis, use("scripts/prosperon.js"));
app.interval(_ => { app.interval(_ => {
profile.frame("hotreload"); profile.frame("hotreload");
actor.hotreload(); actor.hotreload();

View file

@ -1,6 +1,13 @@
/* /*
TYPES OF PROFILING TYPES OF PROFILING
cpu gathering - gets stack frames randomly for a few seconds
frames - user defined to see how long engine takes
cache - can see specific events that happened
memory - can see how much memory is allocated and from where
*/ */
var t_units = ["ns", "us", "ms", "s", "ks", "Ms"]; var t_units = ["ns", "us", "ms", "s", "ks", "Ms"];
@ -41,6 +48,7 @@ profile.cpu = function profile_cpu(fn, times = 1, q = "unnamed") {
profile.ms = function(t) { return profile.secs(t)*1000; } profile.ms = function(t) { return profile.secs(t)*1000; }
var callgraph = {}; var callgraph = {};
profile.rawstacks = {};
profile.cpu_cg = callgraph; profile.cpu_cg = callgraph;
function add_callgraph(fn, line, time) { function add_callgraph(fn, line, time) {
@ -61,21 +69,32 @@ var hittar = 500; // number of call instructions before getting a new frame
var hitpct = 0.2; // amount to randomize it var hitpct = 0.2; // amount to randomize it
var start_gather = profile.now(); var start_gather = profile.now();
var cpu_start; profile.cpu_start = undefined;
profile.clear_cpu = function()
{
callgraph = {};
}
profile.start_cpu_gather = function(gathertime = 5) // gather cpu frames for 'time' seconds profile.start_cpu_gather = function(gathertime = 5) // gather cpu frames for 'time' seconds
{ {
if (cpu_start) return; if (profile.cpu_start) return;
cpu_start = profile.now(); profile.cpu_start = profile.now();
var st = cpu_start; var st = profile.cpu_start;
profile.gather(hittar, function() { profile.gather(hittar, function() {
var time = profile.now()-st; var time = profile.now()-st;
var err = new Error(); var err = new Error();
var stack = err.stack.split("\n"); var stack = err.stack.split("\n").slice(1);
var rawstack = stack.join('\n');
profile.rawstacks[rawstack] ??= {
time: 0,
hits: 0
};
profile.rawstacks[rawstack].hits++;
profile.rawstacks[rawstack].time += time;
stack = stack.slice(1);
stack = stack.map(x => x.slice(7).split(' ')); stack = stack.map(x => x.slice(7).split(' '));
var fns = stack.map(x => x[0]).filter(x=>x); var fns = stack.map(x => x[0]).filter(x=>x);
@ -86,11 +105,11 @@ profile.start_cpu_gather = function(gathertime = 5) // gather cpu frames for 'ti
add_callgraph(fns[i], lines[i], time); add_callgraph(fns[i], lines[i], time);
st = profile.now(); st = profile.now();
if (profile.secs(st-cpu_start) < gathertime) if (profile.secs(st-profile.cpu_start) < gathertime)
profile.gather_rate(Math.variate(hittar,hitpct)); profile.gather_rate(Math.variate(hittar,hitpct));
else { else {
profile.gather_stop(); profile.gather_stop();
cpu_start = undefined; profile.cpu_start = undefined;
var e = Object.values(callgraph); var e = Object.values(callgraph);
e = e.sort((a,b) => { e = e.sort((a,b) => {
if (a.time > b.time) return -1; if (a.time > b.time) return -1;
@ -99,9 +118,12 @@ profile.start_cpu_gather = function(gathertime = 5) // gather cpu frames for 'ti
for (var x of e) { for (var x of e) {
var ffs = x.line.split(':'); var ffs = x.line.split(':');
var time = profile.best_t(x.time); x.timestr = profile.best_t(x.time);
var pct = profile.secs(x.time)/gathertime*100; var pct = profile.secs(x.time)/gathertime*100;
x.log =`${x.line}::${x.fn}:: ${time} (${pct.toPrecision(3)}%) (${x.hits} hits) --> ${get_line(ffs[0], ffs[1])}`; x.timeper = x.time / x.hits;
x.timeperstr = profile.best_t(x.timeper);
x.fncall = get_line(ffs[0], ffs[1]);
x.log =`${x.line}::${x.fn}:: ${x.timestr} (${pct.toPrecision(3)}%) (${x.hits} hits) --> ${get_line(ffs[0], ffs[1])}`;
} }
profile.cpu_instr = e; profile.cpu_instr = e;
@ -118,12 +140,12 @@ function push_time(arr, ob, max)
} }
profile.cpu_frames = []; profile.cpu_frames = [];
profile.last_cpu_frame = undefined;
profile.cpu_frame = function() profile.cpu_frame = function()
{ {
if (gathering_cpu) return;
profile.gather(Math.random_range(300,600), function() { profile.gather(Math.random_range(300,600), function() {
push_time(profile.cpu_frames, console.stack(2)); var err = new Error();
profile.last_cpu_frame = err.stack;//.split('\n').slicconsole.stack(2);
profile.gather_stop(); profile.gather_stop();
}); });
} }
@ -221,6 +243,7 @@ var profile_stack = [];
profile.frame = function profile_frame(title) profile.frame = function profile_frame(title)
{ {
if (profile.cpu_start) return;
if (!frame_avg) return; if (!frame_avg) return;
if (!profile_cframe) { if (!profile_cframe) {
@ -265,7 +288,6 @@ profile.print_frame_avg = function()
say("\n"); say("\n");
} }
/* /*
Cache reporting is to measure how long specific events take, that are NOT every frame Cache reporting is to measure how long specific events take, that are NOT every frame
Useful to measure things like how long it takes to make a specific creature Useful to measure things like how long it takes to make a specific creature

View file

@ -632,6 +632,7 @@ function flush()
nextflush = undefined; nextflush = undefined;
} }
// If flush_fn was already on deck, it does not flush. Otherwise, flushes and then sets the flush fn
function check_flush(flush_fn) function check_flush(flush_fn)
{ {
if (!nextflush) if (!nextflush)
@ -675,6 +676,11 @@ function flush_poly()
poly_idx = 0; poly_idx = 0;
} }
function flush_image()
{
}
render.line = function render_line(points, color = Color.white, thickness = 1) { render.line = function render_line(points, color = Color.white, thickness = 1) {
for (var i = 0; i < points.length-1; i++) { for (var i = 0; i < points.length-1; i++) {
var a = points[i]; var a = points[i];
@ -780,27 +786,63 @@ render.text = function(str, pos, size = 1, color = Color.white, wrap = -1, ancho
return bb; return bb;
}; };
render.image = function(tex, pos, scale = [tex.width, tex.height], rotation = 0, color = Color.white) { var lasttex = undefined;
var img_cache = [];
var img_idx = 0;
function flush_img()
{
if (img_idx === 0) return;
render.use_shader(spritessboshader);
render.use_mat({diffuse:lasttex});
render.make_sprite_ssbo(img_cache.slice(0,img_idx), poly_ssbo);
render.draw(shape.quad, poly_ssbo, img_idx);
lasttex = undefined;
img_idx = 0;
}
function img_e()
{
img_idx++;
if (img_idx > img_cache.length) {
e = {
transform: os.make_transform(),
shade: Color.white,
rect: [0,0,1,1]
};
img_cache.push(e);
return e;
}
var e = img_cache[img_idx-1];
e.transform.unit();
return e;
}
render.image = function(tex, pos, scale, rotation = 0, color = Color.white) {
if (typeof tex === 'string') { if (typeof tex === 'string') {
tex = game.texture(tex); tex = game.texture(tex);
scale.x ??= tex.width; scale.x ??= tex.width;
scale.y ??= tex.height; scale.y ??= tex.height;
} }
if (!tex) return; if (!tex) return;
flush();
var t = os.make_transform();
t.pos = pos;
t.scale = [scale.x/tex.width,scale.y/tex.height,1];
render.use_shader(render.spriteshader);
set_model(t);
render.use_mat({
shade: color,
diffuse: tex,
rect:[0,0,1,1]
});
render.draw(shape.quad); if (!lasttex) {
check_flush(flush_img);
lasttex = tex;
}
if (lasttex !== tex) {
flush_img();
lasttex = tex;
}
var e = img_e();
e.transform.move(pos);
if (scale)
e.transform.scale = scale.div([tex.width, tex.height]);
e.shade = color;
return;
var bb = {}; var bb = {};
bb.b = pos.y; bb.b = pos.y;
bb.l = pos.x; bb.l = pos.x;

View file

@ -64,19 +64,53 @@ JSC_CCALL(imgui_menuitem,
) )
JSC_SCALL(imgui_plot, JSC_SCALL(imgui_plot,
ImPlot::SetNextAxisToFit(ImAxis_X1);
ImPlot::SetNextAxisToFit(ImAxis_Y1);
ImPlot::BeginPlot(str); ImPlot::BeginPlot(str);
script_call_sym(argv[1], 0, NULL); script_call_sym(argv[1], 0, NULL);
ImPlot::EndPlot(); ImPlot::EndPlot();
) )
JSC_SCALL(imgui_lineplot, JSC_SCALL(imgui_lineplot,
double data[js_arrlen(argv[1])]; HMM_Vec2 data[js_arrlen(argv[1])];
for (int i = 0; i < js_arrlen(argv[1]); i++) for (int i = 0; i < js_arrlen(argv[1]); i++)
data[i] = js2number(js_getpropidx(argv[1], i)); data[i] = js2vec2(js_getpropidx(argv[1], i));
ImPlot::PlotLine(str, data, js_arrlen(argv[1])); ImPlot::PlotLine(str, &data[0].x, &data[0].y, js_arrlen(argv[1]), 0, 0, sizeof(HMM_Vec2));
)
JSC_SCALL(imgui_scatterplot,
HMM_Vec2 data[js_arrlen(argv[1])];
for (int i = 0; i < js_arrlen(argv[1]); i++)
data[i] = js2vec2(js_getpropidx(argv[1], i));
ImPlot::PlotScatter(str, &data[0].x, &data[0].y, js_arrlen(argv[1]), 0, 0, sizeof(HMM_Vec2));
)
JSC_SCALL(imgui_stairplot,
HMM_Vec2 data[js_arrlen(argv[1])];
for (int i = 0; i < js_arrlen(argv[1]); i++)
data[i] = js2vec2(js_getpropidx(argv[1], i));
ImPlot::PlotStairs(str, &data[0].x, &data[0].y, js_arrlen(argv[1]), 0, 0, sizeof(HMM_Vec2));
)
JSC_SCALL(imgui_barplot,
HMM_Vec2 data[js_arrlen(argv[1])];
for (int i = 0; i < js_arrlen(argv[1]); i++)
data[i] = js2vec2(js_getpropidx(argv[1], i));
ImPlot::PlotBars(str, &data[0].x, &data[0].y, js_arrlen(argv[1]), js2number(argv[2]), 0, 0, sizeof(HMM_Vec2));
)
JSC_SSCALL(imgui_plotaxes,
ImPlot::SetupAxes(str,str2);
)
JSC_CCALL(imgui_axeslimits,
ImPlot::SetupAxesLimits(js2number(argv[0]), js2number(argv[1]), js2number(argv[2]), js2number(argv[3]));
)
JSC_CCALL(imgui_fitaxis,
ImPlot::SetNextAxisToFit((js2number(argv[0]) == 0) ? ImAxis_X1 : ImAxis_Y1);
) )
JSC_SSCALL(imgui_textinput, JSC_SSCALL(imgui_textinput,
@ -600,6 +634,12 @@ static const JSCFunctionListEntry js_imgui_funcs[] = {
MIST_FUNC_DEF(imgui, text, 1), MIST_FUNC_DEF(imgui, text, 1),
MIST_FUNC_DEF(imgui, plot, 1), MIST_FUNC_DEF(imgui, plot, 1),
MIST_FUNC_DEF(imgui, lineplot, 2), MIST_FUNC_DEF(imgui, lineplot, 2),
MIST_FUNC_DEF(imgui, scatterplot, 2),
MIST_FUNC_DEF(imgui, stairplot, 2),
MIST_FUNC_DEF(imgui, barplot, 3),
MIST_FUNC_DEF(imgui, plotaxes, 2),
MIST_FUNC_DEF(imgui, axeslimits, 4),
MIST_FUNC_DEF(imgui, fitaxis, 1),
MIST_FUNC_DEF(imgui, sokol_gfx, 0), MIST_FUNC_DEF(imgui, sokol_gfx, 0),
MIST_FUNC_DEF(imgui, columns, 1), MIST_FUNC_DEF(imgui, columns, 1),
MIST_FUNC_DEF(imgui, nextcolumn, 0), MIST_FUNC_DEF(imgui, nextcolumn, 0),