add profiling

docs/engine_tour/profiling.md

@@ -0,0 +1,9 @@
+# Profiling
+
+There are a handful of profiling methods available to you.
+
+## Frame by frame profile
+
+## Cpu instrumentation
+
+## Game stats

scripts/actor.js

@@ -12,6 +12,7 @@ actor.spawn = function(script, config, callback){
   padawan.timers = [];
   padawan.master = this;
   Object.hide(padawan, "master", "timers", "padawans");
+  padawan.toString = function() { return script; }  
   check_registers(padawan);
   this.padawans.push(padawan);
   return padawan;

scripts/base.js

@@ -1033,6 +1033,19 @@ value: function(b) {
   return c;
 }});
 
+/*Object.defineProperty(Array.prototype, 'concat', {
+  value: function(b) {
+    var result = [];
+    for (var i = 0; i < this.length; i++)
+      result.push(this[i]);
+      
+    for (var i = 0; i < b.length; i++)
+      result.push(b[i]);
+      
+    return result;
+  }
+});*/
+
 Object.defineProperty(Array.prototype, 'normalized', {
   value: function() {
     var c = this.slice();
@@ -1377,6 +1390,7 @@ Math.rad2turn = function(x) { return x/Math.TAU; };
 Math.turn2deg = function(x) { return x*360; };
 Math.deg2turn = function(x) { return x/360; };
 Math.randomint = function(max) { return Math.clamp(Math.floor(Math.random() * max), 0, max-1); };
+Math.variate = function(n, pct) { return n + (Math.random_range(-pct,pct)*n); }
 
 /* BOUNDINGBOXES */
 var bbox = {};

scripts/debug.js

@@ -64,80 +64,6 @@ var Gizmos = {
   },
 };
 
-profile.cpu = function(fn, times = 1, q = "unnamed") {
-  var start = profile.now();
-  for (var i = 0; i < times; i++)
-    fn();
-    
-  var elapsed = profile.now() - start;
-  var avgt = profile.best_t(elapsed/times);
-  var totalt = profile.best_t(elapsed);
-
-  say(`profile [${q}]: ${profile.best_t(avgt)} average [${profile.best_t(totalt)} for ${times} loops]`);
-}
-
-profile.ms = function(t) { return t/1000000; }
-profile.secs = function(t) { return t/1000000000; }
-
-
-var callgraph = {};
-var st = profile.now();
-
-function add_callgraph(line, time) {
-  callgraph[line] ??= 0;
-  callgraph[line] += time;
-}
-
-profile.gather(500, function() {
-  var time = profile.now()-st;
-  
-  var err = new Error();
-  var stack = err.stack.split("\n");
-  stack = stack.slice(1);
-  stack = stack.map(x => x.slice(7).split(' '));
-  var lines = stack.map(x => x[1]).filter(x => x);
-  lines = lines.map(x => x.slice(1,x.length-1));
-  
-  lines.forEach(x => add_callgraph(x,time));
-  st = profile.now();
-  
-  profile.gather_rate(400+Math.random()*200);
-});
-
-var filecache = {};
-function get_line(file, line) {
-  var text = filecache[file];
-  if (!text) {
-    var f = io.slurp(file);
-    if (!f) {
-      filecache[file] = "undefined";
-      return filecache[file];
-    }
-    filecache[file] = io.slurp(file).split('\n');
-    text = filecache[file];
-  }
-  
-  if (typeof text === 'string') return text;
-  text = text[Number(line)-1];
-  if (!text) return "NULL";
-  return text.trim();
-}
-
-prosperon.quit_hook = function()
-{
-  var e = Object.entries(callgraph);
-  e = e.sort((a,b) => {
-    if (a[1] > b[1]) return -1;
-    return 1;
-  });
-
-  e.forEach(x => {
-    var ffs = x[0].split(':');
-    var time = profile.best_t(x[1]);
-    say(x[0] + '::' + time + ':: ' + get_line(ffs[0], ffs[1]));
-  });
-}
-
 /* These controls are available during editing, and during play of debug builds */
 debug.inputs = {};
 debug.inputs.f1 = function () { debug.draw_phys =  !debug.draw_phys; };

scripts/engine.js

@@ -110,37 +110,7 @@ Resources.find_script = function (file) {
   return find_ext(file, Resources.scripts);
 };
 
-profile.best_t = function (t) {
-  var qq = "ns";
-  if (t > 1000) {
-    t /= 1000;
-    qq = "us";
-    if (t > 1000) {
-      t /= 1000;
-      qq = "ms";
-    }
-  }
-  return `${t.toPrecision(4)} ${qq}`;
-};
-
-profile.report = function (start, msg = "[undefined report]") {
-  console.info(`${msg} in ${profile.best_t(profile.now() - start)}`);
-};
-
-profile.addreport = function (cache, line, start) {
-  cache ??= profcache;
-  cache[line] ??= [];
-  cache[line].push(profile.now() - start);
-  return profile.now();
-};
-
-profile.printreport = function (cache, name) {
-  var report = name + "\n";
-  for (var i in cache)
-    report += `${i}    ${profile.best_t(cache[i].reduce((a, b) => a + b) / cache[i].length)}\n`;
-
-  return report;
-};
+var t_units = ["ns", "us", "ms", "s", "m", "h"];
 
 console.transcript = "";
 console.say = function (msg) {
@@ -218,17 +188,17 @@ console.doc = {
 
 globalThis.global = globalThis;
 
-var profcache = {};
+var use_prof = "USE";
+
+profile.addreport = function(){};
 
 function use(file, env = {}, script) {
   file = Resources.find_script(file);
   var st = profile.now();
 
-  profcache[file] ??= [];
-
   if (use.cache[file]) {
     var ret = use.cache[file].call(env);
-    profile.addreport(profcache, file, st);
+    profile.addreport(use_prof, file, st);
     return;
   }
   script ??= Resources.replstrs(file);
@@ -236,16 +206,21 @@ function use(file, env = {}, script) {
   var fn = os.eval(file, script);
   use.cache[file] = fn;
   var ret = fn.call(env);
-  profile.addreport(profcache, file, st);
+  profile.addreport(use_prof, file, st);
   return ret;
 }
 
 use.cache = {};
 
 global.check_registers = function (obj) {
-  for (var reg in Register.registries)
-    if (typeof obj[reg] === 'function')
-      obj.timers.push(Register.registries[reg].register(obj[reg].bind(obj)));
+  for (var reg in Register.registries) {
+    if (typeof obj[reg] === 'function') {
+      var fn = obj[reg].bind(obj);
+      var name = obj.ur ? obj.ur.name : obj.toString();
+      obj.timers.push(Register.registries[reg].register(fn, name));
+    }
+  }
+      
   for (var k in obj) {
     if (!k.startswith("on_")) continue;
     var signal = k.fromfirst("on_");
@@ -255,6 +230,7 @@ global.check_registers = function (obj) {
 
 Object.assign(global, use("scripts/base"));
 global.obscure("global");
+global.mixin("scripts/profile");
 global.mixin("scripts/render");
 global.mixin("scripts/debug");
 
@@ -452,6 +428,7 @@ var screencolor;
 
 prosperon.render = function()
 {
+  profile.frame("world");
   render.set_camera(camera);
   render.sprites();
   prosperon.draw();
@@ -459,11 +436,17 @@ prosperon.render = function()
   hudcam.transform.pos = [hudcam.size.x/2, hudcam.size.y/2, -100];
   render.set_camera(hudcam);
 
+  profile.endframe();
+  profile.frame("hud");
+
   prosperon.hud();
   render.flush_text();
 
   render.end_pass();
 
+  profile.endframe();
+
+  profile.frame("post process");
   /* draw the image of the game world first */
   render.glue_pass();
   render.viewport(...camera.view());
@@ -471,6 +454,10 @@ prosperon.render = function()
   render.use_mat({diffuse:screencolor});
   render.draw(shape.quad);
 
+  profile.endframe();
+
+  profile.frame("app");
+
   // Flush & render
   appcam.transform.pos = [window.size.x/2, window.size.y/2, -100];
   appcam.size = window.size.slice();
@@ -488,49 +475,65 @@ prosperon.render = function()
   render.flush_text();
   mum.style = mum.base;
 
+  profile.endframe();
+
+  profile.frame("imgui");
+
   render.imgui_new(window.size.x, window.size.y, 0.01);
-//  if (gfx_gui) render.gfx_gui();
+  prosperon.imgui();
   render.imgui_end();
 
+  profile.endframe();
+
   render.end_pass();
   render.commit();
 }
 
 function process() {
-  var startframe = profile.now();
+  profile.frame("frame");
   var dt = profile.secs(profile.now()) - frame_t;
   frame_t = profile.secs(profile.now());
 
+  profile.frame("app update");
   prosperon.appupdate(dt);
+  profile.endframe();
+
+  profile.frame("input");
   input.procdown();
+  profile.endframe();
 
   if (sim.mode === "play" || sim.mode === "step") {
+    profile.frame("update");  
     prosperon.update(dt * game.timescale);
+    profile.endframe();
     if (sim.mode === "step") sim.pause();
 
+    profile.frame("physics");
     physlag += dt;
 
     while (physlag > physics.delta) {
       physlag -= physics.delta;
-      var st = profile.now();
       prosperon.phys2d_step(physics.delta * game.timescale);
       prosperon.physupdate(physics.delta * game.timescale);
-      profile.addreport(profcache, "physics step", st);
     }
+    profile.endframe();
   }
-  var st = profile.now();
+
+  profile.frame("window render");
   prosperon.window_render(window.size);
-  profile.addreport(null, "window render", st);
+  profile.endframe();
+  profile.frame("render");
   prosperon.render();
-  profile.addreport(profcache, "render frame", st);
-  frames.push(profile.secs(profile.now() - startframe));
-  if (frames.length > 20) frames.shift();
+  profile.endframe();
+
+  profile.endframe();
 }
 
 globalThis.fps = function () {
-  var sum = 0;
-  for (var i = 0; i < frames.length; i++) sum += frames[i];
-  return frames.length / sum;
+  return 0;
+//  var sum = 0;
+//  for (var i = 0; i < frames.length; i++) sum += frames[i];
+//  return frames.length / sum;
 };
 
 game.timescale = 1;
@@ -649,9 +652,16 @@ prosperon.touchrelease = function (touches) {};
 prosperon.touchmove = function (touches) {};
 prosperon.clipboardpaste = function (str) {};
 prosperon.quit = function () {
-  say(profile.printreport(profcache, "USE REPORT"));
-  say(profile.printreport(entityreport, "ENTITY REPORT"));
-  if (prosperon.quit_hook) prosperon.quit_hook();
+  say("===START CACHE REPORTS===\n");
+  for (var i in profile.report_cache) {
+    say(profile.printreport(profile.report_cache[i],i));
+  }
+
+  say("===FRAME AVERAGES===\n");
+  say(profile.print_frame_avg());
+  say("\n");
+
+  profile.print_cpu_instr();
 
   console.info("QUITTING");
   for (var i in debug.log.time)
@@ -718,17 +728,25 @@ var Register = {
     var n = {};
     var fns = [];
 
-    n.register = function (fn, obj) {
+    n.register = function (fn, oname) {
       if (typeof fn !== "function") return;
-      if (typeof obj === "object") fn = fn.bind(obj);
-      fns.push(fn);
+
+      var dofn = function(...args) {
+        var st = profile.now();
+        fn(...args);
+	profile.addreport(name, oname, st);
+      }
+      
+      fns.push(dofn);
       return function () {
-        fns.remove(fn);
+        fns.remove(dofn);
       };
     };
+    
     prosperon[name] = function (...args) {
-      fns.forEach((x) => x(...args));
+      fns.forEach(x => x(...args));
     };
+    
     prosperon[name].fns = fns;
     n.clear = function () {
       fns = [];
@@ -750,6 +768,7 @@ Register.add_cb("draw_dbg", true);
 Register.add_cb("gui_dbg", true);
 Register.add_cb("hud_dbg", true);
 Register.add_cb("draw", true);
+Register.add_cb("imgui", true);
 
 var Event = {
   events: {},

scripts/entity.js

@@ -230,7 +230,7 @@ var entity = {
     for (var i in ent.objects)
       ent.ur.fresh.objects[i] = ent.objects[i].instance_obj();
 
-    profile.addreport(entityreport, ent.ur.name, st);
+    profile.addreport("ENTITY TIME", ent.ur.name, st);
     
     return ent;
   },
@@ -677,7 +677,10 @@ var getur = function(text, data)
       name: "empty"
     };
   }
-  var urstr = text + "+" + data;
+  var urstr = text;
+  if (data)
+    urstr += "+" + data;
+
   if (!ur[urstr]) {
     ur[urstr] = {
       name: urstr,

scripts/profile.js

@@ -0,0 +1,178 @@
+profile.cpu = function(fn, times = 1, q = "unnamed") {
+  var start = profile.now();
+  for (var i = 0; i < times; i++)
+    fn();
+    
+  var elapsed = profile.now() - start;
+  var avgt = profile.best_t(elapsed/times);
+  var totalt = profile.best_t(elapsed);
+
+  say(`profile [${q}]: ${profile.best_t(avgt)} average [${profile.best_t(totalt)} for ${times} loops]`);
+}
+
+profile.ms = function(t) { return t/1000000; }
+profile.secs = function(t) { return t/1000000000; }
+
+var callgraph = {};
+var st = profile.now();
+
+function add_callgraph(fn, line, time) {
+  var cc = callgraph[line];
+  if (!cc) {
+    var cc = {};
+    callgraph[line] = cc;
+    cc.time = 0;
+    cc.hits = 0;
+    cc.fn = fn;
+    cc.line = line;
+  }
+  cc.time += time;
+  cc.hits++;
+}
+
+var hittar = 500;
+var hitpct = 0.2;
+var start_gather = profile.now();
+profile.gather(hittar, function() {
+  var time = profile.now()-st;
+  
+  var err = new Error();
+  var stack = err.stack.split("\n");
+
+  stack = stack.slice(1);
+  stack = stack.map(x => x.slice(7).split(' '));
+
+  var fns = stack.map(x => x[0]).filter(x=>x);
+  var lines = stack.map(x => x[1]).filter(x => x);
+  lines = lines.map(x => x.slice(1,x.length-1));
+
+  for (var i = 0; i < fns.length; i++)
+    add_callgraph(fns[i], lines[i], time);
+
+  st = profile.now();
+  
+  profile.gather_rate(Math.variate(hittar,hitpct));
+});
+
+var filecache = {};
+function get_line(file, line) {
+  var text = filecache[file];
+  if (!text) {
+    var f = io.slurp(file);
+    if (!f) {
+      filecache[file] = "undefined";
+      return filecache[file];
+    }
+    filecache[file] = io.slurp(file).split('\n');
+    text = filecache[file];
+  }
+  
+  if (typeof text === 'string') return text;
+  text = text[Number(line)-1];
+  if (!text) return "NULL";
+  return text.trim();
+}
+
+profile.print_cpu_instr = function()
+{
+  say("===CPU INSTRUMENTATION===\n");
+  var gather_time = profile.now()-start_gather;
+  var e = Object.values(callgraph);
+  e = e.sort((a,b) => {
+    if (a.time > b.time) return -1;
+    return 1;
+  });
+
+  e.forEach(x => {
+    var ffs = x.line.split(':');
+    var time = profile.best_t(x.time);
+    var pct = x.time/gather_time*100;
+    say(`${x.line}::${x.fn}:: ${time} (${pct.toPrecision(3)}%) (${x.hits} hits) --> ${get_line(ffs[0], ffs[1])}`);
+  });
+}
+
+profile.best_t = function (t) {
+  var qq = 0;
+  while (t > 1000 && qq < t_units.length-1) {
+    t /= 1000;
+    qq++;
+  }
+  return `${t.toPrecision(4)} ${t_units[qq]}`;
+};
+
+profile.report = function (start, msg = "[undefined report]") { console.info(`${msg} in ${profile.best_t(profile.now() - start)}`); };
+
+var profile_frames = {};
+var profile_frame_ts = [];
+var profile_cframe = profile_frames;
+var profile_frame = 0;
+profile.frame = function(title)
+{
+  profile_frame_ts.push(profile_cframe);
+  profile_cframe[title] ??= {};
+  profile_cframe = profile_cframe[title];
+  profile_cframe._times ??= [];
+  profile_cframe._times[profile_frame] = profile.now();
+}
+
+profile.endframe = function()
+{
+  if (profile_cframe === profile_frames) return;
+  profile_cframe._times[profile_frame] = profile.now() - profile_cframe._times[profile_frame];
+  profile_cframe = profile_frame_ts.pop();
+  if (profile_cframe === profile_frames) profile_frame++;
+}
+
+var print_frame = function(frame, indent, title)
+{
+  var avg = frame._times.reduce((sum, e) => sum += e)/frame._times.length;
+  say(indent + `${title} ::::: ${profile.best_t(avg)}`);
+  
+  for (var i in frame) {
+    if (i === '_times') continue;
+    print_frame(frame[i], indent + "  ", i);
+  }
+}
+
+profile.print_frame_avg = function()
+{
+  var indent = "";
+  for (var i in profile_frames)
+    print_frame(profile_frames[i], "", 'frame');
+}
+
+profile.report_cache = {};
+
+profile.addreport = function (group, line, start) {
+  if (typeof group !== 'string') group = 'UNGROUPED';
+  profile.report_cache[group] ??= {};
+  var cache = profile.report_cache[group];
+  cache[line] ??= [];
+  var t = profile.now();
+  cache[line].push(t - start);
+  return t;
+};
+
+profile.printreport = function (cache, name) {
+  var report = `==${name}==` + "\n";
+
+  var reports = [];
+  for (var i in cache) {
+    var time = cache[i].reduce((a,b)=>a+b);
+    reports.push({
+      time:time,
+      name:i,
+      hits:cache[i].length,
+      avg:time/cache[i].length
+    });
+  }
+  reports = reports.sort((a,b) => {
+    if (a.avg<b.avg) return 1;
+    return -1;
+  });
+  
+  for (var rep of reports)
+    report += `${rep.name}    ${profile.best_t(rep.avg)} (${rep.hits} hits) (total ${profile.best_t(rep.time)})\n`;
+
+  return report;
+};

source/engine/gui.cpp

@@ -3,6 +3,7 @@
 #include "render.h"
 #include "sokol/sokol_app.h"
 #include "imgui.h"
+#include "implot.h"
 #define SOKOL_IMPL
 #include "sokol/util/sokol_imgui.h"
 #include "sokol/util/sokol_gfx_imgui.h"
@@ -12,11 +13,11 @@ static sgimgui_t sgimgui;
 #include "jsffi.h"
 
 JSC_CCALL(imgui_begin,
-char *title = js2strdup(argv[0]);
-bool active = true;
-ImGui::Begin(title, &active, ImGuiWindowFlags_MenuBar);
-free(title);
-return boolean2js(active);
+  char *title = js2strdup(argv[0]);
+  bool active = true;
+  ImGui::Begin(title, &active, ImGuiWindowFlags_MenuBar);
+  free(title);
+  return boolean2js(active);
 )
 
 JSC_CCALL(imgui_end, ImGui::End())
@@ -37,6 +38,22 @@ JSC_CCALL(imgui_menuitem,
   free(hotkey);
 )
 
+JSC_SCALL(imgui_startplot,
+  ImPlot::SetNextAxisToFit(ImAxis_X1);
+  ImPlot::SetNextAxisToFit(ImAxis_Y1);  
+  ImPlot::BeginPlot(str);
+)
+
+JSC_CCALL(imgui_endplot, ImPlot::EndPlot() )
+
+JSC_SCALL(imgui_lineplot,
+  double data[js_arrlen(argv[1])];
+  for (int i = 0; i < js_arrlen(argv[1]); i++)
+    data[i] = js2number(js_getpropidx(argv[1], i));
+
+  ImPlot::PlotLine(str, data, js_arrlen(argv[1]));
+)
+
 JSC_CCALL(imgui_beginmenubar, ImGui::BeginMenuBar())
 JSC_CCALL(imgui_endmenubar, ImGui::EndMenuBar())
 
@@ -55,6 +72,9 @@ static const JSCFunctionListEntry js_imgui_funcs[] = {
   MIST_FUNC_DEF(imgui, beginmenubar, 0),
   MIST_FUNC_DEF(imgui, endmenubar, 0),
   MIST_FUNC_DEF(imgui, textinput, 2),
+  MIST_FUNC_DEF(imgui, startplot,1),
+  MIST_FUNC_DEF(imgui,endplot,0),
+  MIST_FUNC_DEF(imgui,lineplot,2)
 };
 
 static int started = 0;
@@ -67,6 +87,8 @@ JSValue gui_init(JSContext *js)
   sgimgui_desc_t desc = {0};
   sgimgui_init(&sgimgui, &desc);
 
+  ImPlot::CreateContext();
+
   JSValue imgui = JS_NewObject(js);
   JS_SetPropertyFunctionList(js, imgui, js_imgui_funcs, countof(js_imgui_funcs));
   started = 1;