From d62a1ca0dbb33e55303bc9fa010c4cdd62ddf810 Mon Sep 17 00:00:00 2001 From: John Alanbrook Date: Mon, 23 Sep 2024 18:17:46 -0500 Subject: [PATCH] add profiling code --- scripts/engine.js | 2 +- scripts/profile.js | 52 ++++++++++++++++++++++---------- scripts/render.js | 70 ++++++++++++++++++++++++++++++++++--------- source/engine/gui.cpp | 54 ++++++++++++++++++++++++++++----- 4 files changed, 141 insertions(+), 37 deletions(-) diff --git a/scripts/engine.js b/scripts/engine.js index 76a894a..11a8c20 100644 --- a/scripts/engine.js +++ b/scripts/engine.js @@ -297,6 +297,7 @@ globalThis.use = function use(file) { var fn = os.eval(file, script); use_cache[file] = fn; var ret = fn(); + profile.endcache(); return ret; @@ -350,7 +351,6 @@ if (!profile.enabled) Object.assign(globalThis, use("scripts/prosperon.js")); - app.interval(_ => { profile.frame("hotreload"); actor.hotreload(); diff --git a/scripts/profile.js b/scripts/profile.js index f84cb5d..fa8fcf3 100644 --- a/scripts/profile.js +++ b/scripts/profile.js @@ -1,6 +1,13 @@ /* 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"]; @@ -41,6 +48,7 @@ profile.cpu = function profile_cpu(fn, times = 1, q = "unnamed") { profile.ms = function(t) { return profile.secs(t)*1000; } var callgraph = {}; +profile.rawstacks = {}; profile.cpu_cg = callgraph; 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 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 { - if (cpu_start) return; - cpu_start = profile.now(); - var st = cpu_start; + if (profile.cpu_start) return; + profile.cpu_start = profile.now(); + var st = profile.cpu_start; profile.gather(hittar, function() { var time = profile.now()-st; var err = new Error(); - var stack = err.stack.split("\n"); - - stack = stack.slice(1); + 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.map(x => x.slice(7).split(' ')); 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); 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)); else { profile.gather_stop(); - cpu_start = undefined; + profile.cpu_start = undefined; var e = Object.values(callgraph); e = e.sort((a,b) => { 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) { 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; - 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; @@ -118,12 +140,12 @@ function push_time(arr, ob, max) } profile.cpu_frames = []; +profile.last_cpu_frame = undefined; profile.cpu_frame = function() { - if (gathering_cpu) return; - 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(); }); } @@ -221,6 +243,7 @@ var profile_stack = []; profile.frame = function profile_frame(title) { + if (profile.cpu_start) return; if (!frame_avg) return; if (!profile_cframe) { @@ -265,7 +288,6 @@ profile.print_frame_avg = function() say("\n"); } - /* 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 diff --git a/scripts/render.js b/scripts/render.js index 8e978c8..69c53ef 100644 --- a/scripts/render.js +++ b/scripts/render.js @@ -632,6 +632,7 @@ function flush() 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) { if (!nextflush) @@ -675,6 +676,11 @@ function flush_poly() poly_idx = 0; } +function flush_image() +{ + +} + render.line = function render_line(points, color = Color.white, thickness = 1) { for (var i = 0; i < points.length-1; i++) { var a = points[i]; @@ -780,27 +786,63 @@ render.text = function(str, pos, size = 1, color = Color.white, wrap = -1, ancho 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') { tex = game.texture(tex); scale.x ??= tex.width; scale.y ??= tex.height; } 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 = {}; bb.b = pos.y; bb.l = pos.x; diff --git a/source/engine/gui.cpp b/source/engine/gui.cpp index e6a3b00..58d0ce0 100644 --- a/source/engine/gui.cpp +++ b/source/engine/gui.cpp @@ -64,19 +64,53 @@ JSC_CCALL(imgui_menuitem, ) JSC_SCALL(imgui_plot, - ImPlot::SetNextAxisToFit(ImAxis_X1); - ImPlot::SetNextAxisToFit(ImAxis_Y1); ImPlot::BeginPlot(str); script_call_sym(argv[1], 0, NULL); ImPlot::EndPlot(); ) 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++) - 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, @@ -598,8 +632,14 @@ static const JSCFunctionListEntry js_imgui_funcs[] = { MIST_FUNC_DEF(imgui, button, 2), MIST_FUNC_DEF(imgui, checkbox, 2), MIST_FUNC_DEF(imgui, text, 1), - MIST_FUNC_DEF(imgui, plot,1), - MIST_FUNC_DEF(imgui, lineplot,2), + MIST_FUNC_DEF(imgui, plot, 1), + 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, columns, 1), MIST_FUNC_DEF(imgui, nextcolumn, 0),