john/prosperon
1
0
Fork 0
Code Issues Pull requests Actions Releases Activity

unify frame, report, cache in profiler

Browse source
This commit is contained in:
John Alanbrook 2024-10-02 09:55:32 -05:00
parent ca6c21ebb8
commit fa824aec3a
9 changed files with 221 additions and 201 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

3
scripts/actor.js
View file

@ -62,10 +62,8 @@ actor.__stats = function () {
};
actor.hotreload = function () {
profile.cache("hotreload", "check");
for (var i in script_times) {
if (io.mod(i) > script_times[i]) {
say(`HOT RELAODING ${i}`);
script_times[i] = io.mod(i);
var script = Resources.replstrs(i);
script = `(function() {
@ -86,7 +84,6 @@ actor.hotreload = function () {
}
}
}
profile.endcache();
};
actor.spawn = function (script, config) {

7
scripts/components.js
View file

@ -268,14 +268,21 @@ Object.mixin(os.make_seg2d(), {
*/
var animcache = {};
var SpriteAnim = {};
SpriteAnim.hotreload = function(path) {
delete animcache[path];
}
SpriteAnim.make = function (path) {
var anim;
if (animcache[path]) return animcache[path];
profile.report(`animation_${path}`);
if (io.exists(path.set_ext(".ase"))) anim = SpriteAnim.aseprite(path.set_ext(".ase"));
else if (io.exists(path.set_ext(".json"))) anim = SpriteAnim.aseprite(path.set_ext(".json"));
else if (path.ext() === "ase") anim = SpriteAnim.aseprite(path);
else if (path.ext() === "gif") anim = SpriteAnim.gif(path);
else anim = undefined;
profile.endreport(`animation_${path}`);
animcache[path] = anim;
return animcache[path];
};

26
scripts/engine.js
View file

@ -144,6 +144,8 @@ Resources.is_image = function (path) {
return Resources.images.some(x => x === ext);
};
var res_cache = {};
function find_ext(file, ext, root = "") {
if (!file) return;
@ -171,6 +173,12 @@ function find_ext(file, ext, root = "") {
var hashhit = 0;
var hashmiss = 0;
globalThis.hashifier = {};
hashifier.stats = function()
{
}
Object.defineProperty(Function.prototype, "hashify", {
value: function () {
var hash = new Map();
@ -279,21 +287,24 @@ var use_cache = {};
globalThis.use = function use(file) {
file = Resources.find_script(file);
profile.cache("USE", file);
if (use_cache[file]) {
profile.report(`use_${file}`);
var ret = use_cache[file]();
profile.endcache(" [cached]");
profile.endreport(`use_${file}`);
return ret;
}
profile.report(`compile_${file}`);
var script = Resources.replstrs(file);
script = `(function() { var self = this; ${script}; })`;
var fn = os.eval(file, script);
use_cache[file] = fn;
profile.endreport(`compile_${file}`);
profile.report(`use_${file}`);
var ret = fn();
profile.endcache();
profile.endreport(`use_${file}`);
return ret;
};
@ -309,7 +320,6 @@ function stripped_use(file, script) {
script = `(function() { var self = this; ${script}; })`;
var fn = os.eval(file, script);
var ret = fn();
profile.endcache();
return ret;
}
@ -343,10 +353,10 @@ if (!profile.enabled) use = stripped_use;
Object.assign(globalThis, use("scripts/prosperon.js"));
app.interval(_ => {
profile.frame("hotreload");
profile.report("hotreload");
actor.hotreload();
render.hotreload();
game.tex_hotreload();
repl.hotreload();
profile.endframe();
profile.endreport("hotreload");
}, 1);

4
scripts/entity.js
View file

@ -127,6 +127,7 @@ var entity = {
},
spawn(text, config, callback) {
profile.report(`make_${text}`);
var ent = class_use(text, config, entity, function (ent) {
ent.transform = os.make_transform();
ent.guid = prosperon.guid();
@ -168,7 +169,6 @@ var entity = {
}
else if (Array.isArray(text))
for (var path of text) use(path,ent);
profile.cache("ENTITY TIME", ent.ur.name);
*/
ent.reparent(this);
@ -223,7 +223,7 @@ var entity = {
ent.ur.fresh.objects = {};
for (var i in ent.objects) ent.ur.fresh.objects[i] = ent.objects[i].instance_obj();
profile.endcache();
profile.endreport(`make_${text}`);
return ent;
},

281
scripts/profile.js
View file

@ -1,12 +1,9 @@
/*
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
cpu frames - gets stack frames randomly for a few seconds
report - can see specific events that happened. Includes inclusive vs noninclusive times.
snapshot - See the amount of something every amount of time
memory - can see how much memory is allocated and from where
*/
@ -50,6 +47,27 @@ profile.ms = function (t) {
var callgraph = {};
profile.rawstacks = {};
function add_callgraph_from_stack(err, time)
{
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);
var lines = stack.map(x => x[1]).filter(x => x);
lines = lines.map(x => x.slice(1, x.length - 1));
add_callgraph(fns[0], lines[0], time, true);
for (var i = 1; i < fns.length; i++) add_callgraph(fns[i], lines[i], time, false);
}
function add_callgraph(fn, line, time, alone) {
var cc = callgraph[line];
if (!cc) {
@ -82,12 +100,41 @@ profile.cpu_start = undefined;
profile.clear_cpu = function () {
callgraph = {};
profile.cpu_instr = undefined;
profile.gather_stop();
profile.cpu_start = undefined;
};
profile.start_cpu_gather = function (gathertime = 5) {
profile.clear_cpu();
// gather cpu frames for 'time' seconds
function cpu_record_frame()
{
}
// These values are set to get the most amount of frames without causing a stack overflow
var hittar = 450;
var hitpct = 0.2;
profile.start_cpu_gather_fn = function()
{
if (profile.cpu_start) return;
profile.clear_cpu();
profile.cpu_start = profile.now();
var st = profile.cpu_start;
profile.gather(Math.variate(hittar,hitpct), function() {
var time = profile.now() - st;
var err = new Error();
add_callgraph_from_stack(err, time);
st = profile.now();
profile.gather_rate(Math.variate(hittar,hitpct));
});
}
profile.start_cpu_gather = function (gathertime = 5) {
if (profile.cpu_start) return;
profile.clear_cpu();
// gather cpu frames for 'gathertime' seconds
profile.cpu_start = profile.now();
var st = profile.cpu_start;
@ -95,59 +142,51 @@ profile.start_cpu_gather = function (gathertime = 5) {
var time = profile.now() - st;
var err = new Error();
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);
var lines = stack.map(x => x[1]).filter(x => x);
lines = lines.map(x => x.slice(1, x.length - 1));
add_callgraph(fns[0], lines[0], time, true);
for (var i = 1; i < fns.length; i++) add_callgraph(fns[i], lines[i], time, false);
add_callgraph_from_stack(err, time);
st = profile.now();
if (profile.secs(st - profile.cpu_start) < gathertime) profile.gather_rate(Math.variate(hittar, hitpct));
else {
profile.gather_stop();
profile.cpu_start = undefined;
var e = Object.values(callgraph);
e = e.filter(x => x.line);
for (var x of e) {
var ffs = x.line.split(":");
x.timestr = profile.best_t(x.time);
x.timeper = x.time / x.hits;
x.timeperstr = profile.best_t(x.timeper);
x.pct = (profile.secs(x.time) / gathertime) * 100;
x.alone.timestr = profile.best_t(x.alone.time);
x.alone.timeper = x.alone.time / x.alone.hits;
x.alone.timeperstr = profile.best_t(x.alone.timeper);
x.alone.pct = (profile.secs(x.alone.time) / gathertime) * 100;
x.fncall = get_line(ffs[0], ffs[1]);
x.log = x.line + " " + x.fn + " " + x.fncall;
x.incl = {
time: x.time,
timestr: x.timestr,
timeper: x.timeper,
timeperstr: x.timeperstr,
hits: x.hits,
pct: x.pct,
};
}
profile.cpu_instr = e;
}
if (profile.secs(st - profile.cpu_start) < gathertime)
profile.gather_rate(Math.variate(hittar, hitpct));
else
profile.stop_cpu_measure();
});
};
profile.stop_cpu_measure = function()
{
if (!profile.cpu_start) return;
profile.gather_stop();
var gathertime = profile.now()-profile.cpu_start;
console.info(`gathered for ${profile.best_t(gathertime)}`);
profile.cpu_start = undefined;
var e = Object.values(callgraph);
e = e.filter(x => x.line);
for (var x of e) {
var ffs = x.line.split(":");
x.timestr = profile.best_t(x.time);
x.timeper = x.time / x.hits;
x.timeperstr = profile.best_t(x.timeper);
x.pct = x.time/gathertime * 100;
x.alone.timestr = profile.best_t(x.alone.time);
x.alone.timeper = x.alone.time / x.alone.hits;
x.alone.timeperstr = profile.best_t(x.alone.timeper);
x.alone.pct = x.alone.time / gathertime * 100;
x.fncall = get_line(ffs[0], ffs[1]);
x.log = x.line + " " + x.fn + " " + x.fncall;
x.incl = {
time: x.time,
timestr: x.timestr,
timeper: x.timeper,
timeperstr: x.timeperstr,
hits: x.hits,
pct: x.pct,
};
}
profile.cpu_instr = e;
}
function push_time(arr, ob, max) {
arr.push({
time: profile.now(),
@ -258,94 +297,25 @@ profile.endframe = function profile_endframe() {
profile_cframe = profile_frame_ts.pop();
};
/*
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
*/
var cache_reporting = false;
var report_cache = {};
var cachest = 0;
var cachegroup;
var cachetitle;
profile.cache_reporting = function () {
return cache_reporting;
};
profile.cache_toggle = function () {
cache_reporting = !cache_reporting;
};
profile.cache_dump = function () {
report_cache = {};
};
profile.cache = function profile_cache(group, title) {
if (!cache_reporting) return;
cachest = profile.now();
cachegroup = group;
cachetitle = title;
};
profile.endcache = function profile_endcache(tag = "") {
return;
addreport(cachegroup, cachetitle + tag, cachest);
};
function addreport(group, line, start) {
return;
if (typeof group !== "string") group = "UNGROUPED";
report_cache[group] ??= {};
var cache = report_cache[group];
cache[line] ??= [];
var t = profile.now();
cache[line].push(t - start);
return t;
}
function printreport(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;
}
profile.data = {};
profile.curframe = 0;
profile.snapshot = {};
var classes = ["gameobject", "transform", "dsp_node", "texture", "font", "warp_gravity", "warp_damp", "sg_buffer", "datastream", "cpShape", "cpConstraint", "timer", "skin"];
var get_snapshot = function()
{
var snap = profile.snapshot;
for (var monitor of monitors) {
var stat = monitor.fn();
monitor.hook?.(stat);
snap[monitor.path] = stat;
}
snap.actors = actor.__stats();
snap.memory = os.mem();
snap.memory.textures = game.texture.total_size();
snap.memory.texture_vram = game.texture.total_vram();
snap.rusage = os.rusage();
snap.rusage.ru_maxrss *= 1024; // delivered in KB; convert here to B
snap.mallinfo = os.mallinfo();
snap.particles = stat_emitters();
snap.obj ??= {};
@ -357,6 +327,21 @@ var get_snapshot = function()
}
}
var monitors = [];
profile.add_custom_monitor = function(path, fn, hook)
{
monitors.push({
path:path,
fn:fn,
hook:hook
});
}
profile.add_custom_monitor('rusage', os.rusage, stat => stat.ru_maxrss *= 1024);
profile.add_custom_monitor('mallinfo', os.mallinfo);
profile.add_custom_monitor('memory', os.mem);
var fps = [];
var frame_lead = 1;
var fps_t = 0;
@ -368,7 +353,33 @@ profile.report_frame = function (t) {
fps_t = profile.now();
get_snapshot();
}
};
}
profile.reports = {};
profile.report = function(path)
{
profile.reports[path] ??= {
report: path,
time: 0,
hits: 0,
avg: 0
};
if (profile.reports[path].st) return;
profile.reports[path].st = profile.now();
}
profile.endreport = function(path)
{
var rep = profile.reports[path];
if (!rep || !rep.st) return;
rep.hits++;
rep.time += profile.now()-rep.st;
delete rep.st;
rep.avg = rep.time/rep.hits;
profile.report_cache = Object.values(profile.reports);
}
function prof_add_stats(obj, stat) {
for (var i in stat) {

5
scripts/prosperon.js
View file

@ -182,6 +182,7 @@ game.tex_hotreload = function () {
if (io.mod(path) > game.texture.time_cache[path]) {
var tex = game.texture.cache[path];
game.texture.time_cache[path] = io.mod(path);
SpriteAnim.hotreload(path);
os.texture_swap(path, game.texture.cache[path]);
for (var sprite of Object.values(allsprites)) {
if (sprite.texture == tex) {
@ -331,10 +332,10 @@ var Register = {
var guid = prosperon.guid();
var dofn = function (...args) {
profile.cache(name, oname);
profile.report(`call_${name}_${oname}`);
var st = profile.now();
fn(...args);
profile.endcache();
profile.endreport(`call_${name}_${oname}`);
};
var left = 0;

76
scripts/render.js
View file

@ -299,8 +299,6 @@ function make_shader(shader) {
}
var writejson = `.prosperon/${file.name()}.shader.json`;
profile.cache("shader", file);
breakme: if (io.exists(writejson)) {
var data = json.decode(io.slurp(writejson));
var filemod = io.mod(writejson);
@ -310,8 +308,7 @@ function make_shader(shader) {
break breakme;
}
}
profile.endcache(" [cached]");
var shaderobj = json.decode(io.slurp(writejson));
var obj = shaderobj[os.sys()];
obj.pipe = render.pipeline(obj);
@ -319,6 +316,8 @@ function make_shader(shader) {
shader_times[file] = io.mod(file);
return obj;
}
profile.report(`shader_${file}`);
var compiled = create_shader_obj(file);
io.slurpwrite(writejson, json.encode(compiled));
@ -327,6 +326,8 @@ function make_shader(shader) {
shader_cache[file] = obj;
shader_times[file] = io.mod(file);
profile.endreport(`shader_${file}`);
return obj;
}
@ -524,7 +525,7 @@ render.draw_gizmos = true;
render.buckets = [];
render.sprites = function render_sprites() {
profile.frame("drawing");
profile.report("drawing");
render.use_shader(spritessboshader);
var buckets = component.sprite_buckets();
for (var l in buckets) {
@ -538,7 +539,7 @@ render.sprites = function render_sprites() {
render.draw(shape.quad, sprite_ssbo, sparray.length);
}
}
profile.endframe();
profile.endreport("drawing");
};
render.circle = function render_circle(pos, radius, color, inner_radius = 1) {
@ -843,9 +844,9 @@ render.rectangle.doc = "Draw a rectangle, with its corners at lowerleft and uppe
render.draw = function render_draw(mesh, ssbo, inst = 1, e_start = 0) {
sg_bind(mesh, ssbo);
profile.frame("gpu");
profile.report("gpu_draw");
render.spdraw(e_start, cur.bind.count, inst);
profile.endframe();
profile.endreport("gpu_draw");
};
// Returns an array in the form of [left, bottom, right, top] in pixels of the camera to render to
@ -1030,22 +1031,22 @@ var imgui_fn = function () {
};
prosperon.render = function () {
profile.frame("world");
profile.report("world");
render.set_camera(prosperon.camera);
profile.frame("sprites");
profile.report("sprites");
if (render.draw_sprites) render.sprites();
if (render.draw_particles) draw_emitters();
profile.endframe();
profile.frame("draws");
profile.endreport("sprites");
profile.report("draws");
prosperon.draw();
// sgl.draw();
profile.endframe();
profile.endreport("draws");
profile.endreport("world");
prosperon.hudcam.size = prosperon.camera.size;
prosperon.hudcam.transform.pos = [prosperon.hudcam.size.x / 2, prosperon.hudcam.size.y / 2, -100];
render.set_camera(prosperon.hudcam);
profile.endframe();
profile.frame("hud");
profile.report("hud");
if (render.draw_hud) prosperon.hud();
render.flush_text();
@ -1055,22 +1056,20 @@ prosperon.render = function () {
render.end_pass();
profile.endframe();
profile.endframe();
profile.endframe();
profile.endreport("hud");
/* draw the image of the game world first */
render.glue_pass();
profile.frame("frame");
profile.frame("render");
profile.frame("post process");
profile.report("frame");
profile.report("render");
profile.report("post process");
render.viewport(...prosperon.camera.view());
render.use_shader(render.postshader);
render.use_mat({ diffuse: prosperon.screencolor });
render.draw(shape.quad);
profile.endframe();
profile.endreport("post process");
profile.frame("app");
profile.report("app");
// Flush & render
prosperon.appcam.transform.pos = [window.size.x / 2, window.size.y / 2, -100];
@ -1089,13 +1088,13 @@ prosperon.render = function () {
check_flush();
profile.endframe();
profile.endreport("app");
profile.frame("imgui");
profile.report("imgui");
if (debug.show) imgui_fn();
profile.endframe();
profile.endreport("imgui");
render.end_pass();
@ -1106,7 +1105,7 @@ prosperon.render = function () {
};
prosperon.process = function process() {
profile.frame("frame");
profile.report("frame");
var dt = profile.secs(profile.now()) - frame_t;
frame_t = profile.secs(profile.now());
@ -1118,20 +1117,20 @@ prosperon.process = function process() {
var cycles = os.check_cycles();
if (cycles) say(cycles);
profile.frame("app update");
profile.report("app update");
prosperon.appupdate(dt);
profile.endframe();
profile.endreport("app update");
profile.frame("input");
profile.report("input");
input.procdown();
profile.endframe();
profile.endreport("input");
if (sim.mode === "play" || sim.mode === "step") {
profile.frame("update");
profile.report("update");
prosperon.update(dt * game.timescale);
update_emitters(dt * game.timescale);
os.update_timers(dt * game.timescale);
profile.endframe();
profile.endreport("update");
if (sim.mode === "step") sim.pause();
}
@ -1139,7 +1138,7 @@ prosperon.process = function process() {
sst = profile.now();
if (sim.mode === "play" || sim.mode === "step") {
profile.frame("physics");
profile.report("physics");
physlag += dt;
while (physlag > physics.delta) {
@ -1147,17 +1146,18 @@ prosperon.process = function process() {
prosperon.phys2d_step(physics.delta * game.timescale);
prosperon.physupdate(physics.delta * game.timescale);
}
profile.endframe();
profile.endreport("physics");
profile.pushdata(profile.data.cpu.physics, profile.now() - sst);
sst = profile.now();
}
profile.frame("render");
profile.report("render");
prosperon.window_render(window.size);
prosperon.render();
profile.endreport("render");
profile.pushdata(profile.data.cpu.render, profile.now() - sst);
profile.endframe();
profile.endframe();
profile.endreport('frame');
profile.capture_data();
};

4
scripts/tween.js
View file

@ -115,7 +115,7 @@ Ease.elastic.c5 = (2 * Math.PI) / 4.5;
var tween = function (from, to, time, fn, endfn) {
var start = profile.secs(profile.now());
var update = function (dt) {
profile.frame("tween");
profile.report("tween");
var elapsed = profile.secs(profile.now()) - start;
fn(from.lerp(to, elapsed / time));
if (elapsed >= time) {
@ -124,7 +124,7 @@ var tween = function (from, to, time, fn, endfn) {
stop();
endfn?.();
}
profile.endframe();
profile.endreport("tween");
};
var stop = Register.update.register(update);
return stop;

16
source/engine/texture.c
View file

@ -23,19 +23,13 @@ struct rect ST_UNIT = {0.f, 0.f, 1.f, 1.f};
static inline void write_pixel(unsigned char *data, int idx, rgba color)
{
data[idx] = color.r;
data[idx+1] = color.g;
data[idx+2] = color.b;
data[idx+3] = color.a;
memcpy(data+idx, &color, sizeof(color));
}
static inline rgba get_pixel(unsigned char *data, int idx)
{
rgba color;
color.r = data[idx];
color.g = data[idx+1];
color.b = data[idx+2];
color.a = data[idx+3];
memcpy(&color, data+idx, sizeof(color));
return color;
}
@ -328,16 +322,16 @@ void texture_save(texture *tex, const char *file)
// sw the width of the destination to take in pixels
// sh the height of the destination to take in pixels
int texture_blit(texture *dst, texture *src, rect dstrect, rect srcrect, int tile) {
// if (!src || !dst || !src->data || !dst->data) return 0;
if (!src || !dst || !src->data || !dst->data) return 0;
float scaleX = srcrect.w / dstrect.w;
float scaleY = srcrect.h / dstrect.h;
/* if (srcrect.x < 0 || srcrect.y < 0 || srcrect.x + srcrect.w > src->width ||
if (srcrect.x < 0 || srcrect.y < 0 || srcrect.x + srcrect.w > src->width ||
dstrect.x < 0 || dstrect.y < 0 || dstrect.x + dstrect.w > dst->width ||
srcrect.y + srcrect.h > src->height || dstrect.y + dstrect.h > dst->height) {
return false; // Rectangles exceed texture bounds
}*/
}
for (int dstY = 0; dstY < dstrect.h; ++dstY) {
for (int dstX = 0; dstX < dstrect.w; ++dstX) {