# ============================================================================ # prof.ludic — per-pass GPU timing (R3D_PROF=1). # # Wall-clock timing of this renderer is useless at pass granularity: run-to-run # variance on a laptop GPU is ±15%, which is larger than most passes. GL_TIME_ELAPSED # queries measure what the GPU actually spent inside each pass, and averaging a few # hundred frames inside ONE run cancels the run-to-run noise entirely. # # Each slot owns a small ring of query objects. A query is read back only after # enough frames have passed that its result is certainly available, so profiling # never introduces the very stall it is trying to measure. # ============================================================================ const PROF_SLOTS: int = 16 const PROF_RING: int = 4 # frames of latency before a result is read @alloc_ok("start-up: the device, its tables, the programs, the passes and the world's first textures are made once, before play") function prof_init(render3d_st: mut Render3dState) -> void { render3d_st.prof_on = r3d_env_has(render3d_st, "R3D_PROF") if not render3d_st.prof_on { return } render3d_st.prof_names = new []pointer render3d_st.prof_ns = new []long render3d_st.prof_hits = new []long render3d_st.prof_ids = words(PROF_SLOTS * PROF_RING) render3d_st.prof_scratch = words(4) gpu_query_new(render3d_st, PROF_SLOTS * PROF_RING, render3d_st.prof_ids) render3d_st.prof_n = 0 render3d_st.prof_frame = 0 render3d_st.prof_active = -1 } # the slot index for `name`, registering it on first sight (order = frame order) @alloc_ok("profiling and statistics, only under R3D_PROF / R3D_DRAWSTATS") function prof_slot(render3d_st: mut Render3dState, name: pointer) -> int { var i = 0 while i < render3d_st.prof_n { if render3d_st.prof_names[i] == name { return i } i += 1 } if render3d_st.prof_n >= PROF_SLOTS { return -1 } push(render3d_st.prof_names, name) push(render3d_st.prof_ns, 0) push(render3d_st.prof_hits, 0) render3d_st.prof_n += 1 return render3d_st.prof_n - 1 } function prof_begin(render3d_st: mut Render3dState, name: pointer) -> void { ds_set_pass(render3d_st, name) if render3d_st.gvk_labels { gvk_label_begin(render3d_st, name) } if not render3d_st.prof_on { return } if render3d_st.prof_active >= 0 { return } # GL_TIME_ELAPSED queries cannot nest let s = prof_slot(render3d_st, name) if s < 0 { return } render3d_st.prof_active = s gpu_query_begin(render3d_st, render3d_st.prof_ids[s * PROF_RING + (render3d_st.prof_frame % PROF_RING)]) } function prof_end(render3d_st: mut Render3dState) -> void { ds_set_pass(render3d_st, render3d_st.ds_outside) if render3d_st.gvk_labels { gvk_label_end(render3d_st) } if not render3d_st.prof_on { return } if render3d_st.prof_active < 0 { return } gpu_query_end(render3d_st) render3d_st.prof_active = -1 } # Collect the queries issued PROF_RING-1 frames ago — long finished, so no stall. function prof_collect(render3d_st: mut Render3dState) -> void { if not render3d_st.prof_on { return } render3d_st.prof_frame += 1 if render3d_st.prof_frame < PROF_RING { return } let slot_frame = (render3d_st.prof_frame + 1) % PROF_RING var s = 0 while s < render3d_st.prof_n { let q = render3d_st.prof_ids[s * PROF_RING + slot_frame] if gpu_query_result(render3d_st, q, render3d_st.prof_scratch) { # the low 32 bits are ample: a pass is far below 4 seconds render3d_st.prof_ns[s] = render3d_st.prof_ns[s] + render3d_st.prof_scratch[0] render3d_st.prof_hits[s] = render3d_st.prof_hits[s] + 1 } s += 1 } } @alloc_ok("profiling and statistics, only under R3D_PROF / R3D_DRAWSTATS") function prof_report(render3d_st: Render3dState) -> void { if not render3d_st.prof_on { return } print("") print("GPU time per pass (mean over the run):") var total = 0 var s = 0 while s < render3d_st.prof_n { if render3d_st.prof_hits[s] > 0 { total = total + render3d_st.prof_ns[s] / render3d_st.prof_hits[s] } s += 1 } s = 0 while s < render3d_st.prof_n { if render3d_st.prof_hits[s] > 0 { let us = render3d_st.prof_ns[s] / render3d_st.prof_hits[s] / 1000 var pct = 0 if total > 0 { pct = (render3d_st.prof_ns[s] / render3d_st.prof_hits[s]) * 100 / total } print(` {Text.pad_right(render3d_st.prof_names[s], 22)} {Text.pad_left(string(us), 7)} us {string(pct)}%`) } s += 1 } print(` {Text.pad_right("TOTAL", 22)} {Text.pad_left(string(total / 1000), 7)} us`) } # ---- streaming work per frame (R3D_PROF=1) ---------------------------------- # Stutter while walking is not visible in an average: the cover for a newly entered # chunk is generated in whichever frame the camera crosses a 32 m cell, so one frame # in fifty does all the work. `Time.delta` here is a fixed 60 Hz timestep and there is # no finer wall clock in the runtime, so measure the WORK instead — instances generated # per frame is exactly what the hitch is made of, and it needs no clock at all. function prof_gen_add(render3d_st: mut Render3dState, n: int) -> void { if not render3d_st.prof_on { return } render3d_st.prof_gen_cur += n } # Per-chunk generation, so a hitch can be pinned on a stream and a band rather than on # "streaming". One chunk is generated atomically, so the worst chunk is the worst frame. # CPU work that only happens on some frames — which is what a hitch is made of. # Where a frame's time went at the coarsest useful split: work this process did, and # time spent waiting for the GPU to finish it. Headless drains the GPU inside swap, so # the two are cleanly separable there. function prof_before_swap(render3d_st: mut Render3dState) -> void { if render3d_st.prof_on { render3d_st.prof_pre_swap = gl_now_us() } } # The single most expensive CPU phase of each frame, and what it was. A hitch is one # phase running long on one frame, so recording the worst one per frame is enough to # name it without keeping a timeline. function prof_mark_start(render3d_st: mut Render3dState) -> void { if render3d_st.prof_on { render3d_st.prof_mark_last = gl_now_us(); render3d_st.prof_mark_best = 0; render3d_st.prof_mark_name = null } } # ... and every phase's share of the average frame, past the first eight frames (loading, first fills) @alloc_ok("profiling and statistics, only under R3D_PROF / R3D_DRAWSTATS") function prof_cpu_mark(render3d_st: mut Render3dState, name: pointer) -> void { if not render3d_st.prof_on { return } let now = gl_now_us() let d = now - render3d_st.prof_mark_last render3d_st.prof_mark_last = now if d > render3d_st.prof_mark_best { render3d_st.prof_mark_best = d; render3d_st.prof_mark_name = name } var k = -1 var i = 0 while i < render3d_st.prof_mk_n { if render3d_st.prof_mk_names[i] == name { k = i }; i += 1 } if k < 0 { if render3d_st.prof_mk_names == null { render3d_st.prof_mk_names = new []pointer; render3d_st.prof_mk_us = new []long } push(render3d_st.prof_mk_names, name); push(render3d_st.prof_mk_us, 0) render3d_st.prof_mk_n += 1 k = render3d_st.prof_mk_n - 1 } if render3d_st.prof_gen != null and len(render3d_st.prof_gen) > 8 { render3d_st.prof_mk_us[k] = render3d_st.prof_mk_us[k] + d } } # the game's own per-frame work, kept apart from the renderer's function prof_game_add(render3d_st: mut Render3dState, us: long) -> void { if render3d_st.prof_on { render3d_st.prof_game_us_cur = render3d_st.prof_game_us_cur + us } } function prof_layer_add(render3d_st: mut Render3dState, us: long, bytes: long) -> void { if not render3d_st.prof_on { return } render3d_st.prof_layer_us_cur = render3d_st.prof_layer_us_cur + us render3d_st.prof_up_cur = render3d_st.prof_up_cur + bytes } function prof_bake_add(render3d_st: mut Render3dState, us: long) -> void { if render3d_st.prof_on { render3d_st.prof_bake_us_cur = render3d_st.prof_bake_us_cur + us } } @alloc_ok("profiling and statistics, only under R3D_PROF / R3D_DRAWSTATS") function prof_chunk(render3d_st: mut Render3dState, kind: int, band: int, count: int, us: long) -> void { if not render3d_st.prof_on { return } if render3d_st.prof_chunk_us == null { render3d_st.prof_chunk_us = new []long; render3d_st.prof_chunk_kind = new []int render3d_st.prof_chunk_band = new []int; render3d_st.prof_chunk_n = new []int } push(render3d_st.prof_chunk_us, us); push(render3d_st.prof_chunk_kind, kind) push(render3d_st.prof_chunk_band, band); push(render3d_st.prof_chunk_n, count) render3d_st.prof_gen_us_cur += us } @alloc_ok("profiling and statistics, only under R3D_PROF / R3D_DRAWSTATS") function prof_chunk_report(render3d_st: Render3dState) -> void { if not render3d_st.prof_on or render3d_st.prof_chunk_us == null { return } print("") print("chunk generation (one chunk is atomic, so the worst chunk is the worst frame):") # totals per (kind, band) var kinds = new []int var bands = new []int var tot = new []long var cnt = new []int var mx = new []long var i = 0 while i < len(render3d_st.prof_chunk_us) { var f = -1 var j = 0 while j < len(kinds) { if kinds[j] == render3d_st.prof_chunk_kind[i] and bands[j] == render3d_st.prof_chunk_band[i] { f = j }; j += 1 } if f < 0 { push(kinds, render3d_st.prof_chunk_kind[i]); push(bands, render3d_st.prof_chunk_band[i]) push(tot, 0); push(cnt, 0); push(mx, 0) f = len(kinds) - 1 } tot[f] = tot[f] + render3d_st.prof_chunk_us[i] cnt[f] = cnt[f] + 1 if render3d_st.prof_chunk_us[i] > mx[f] { mx[f] = render3d_st.prof_chunk_us[i] } i += 1 } var k = 0 while k < len(kinds) { print(` kind {string(kinds[k])} band {string(bands[k])}: {string(cnt[k])} chunks, mean {string(tot[k] / cnt[k])} us, worst {string(mx[k])} us, total {string(tot[k] / 1000)} ms`) k += 1 } # the per-frame distribution of generation time: this is the hitch itself if render3d_st.prof_gen_us == null or len(render3d_st.prof_gen_us) < 16 { return } let sorted = new []long var a = 8 while a < len(render3d_st.prof_gen_us) { push(sorted, render3d_st.prof_gen_us[a]); a += 1 } var x = 1 while x < len(sorted) { let v = sorted[x] var y = x - 1 while y >= 0 and sorted[y] > v { sorted[y + 1] = sorted[y]; y -= 1 } sorted[y + 1] = v x += 1 } let n = len(sorted) var busy = 0 var t: long = 0 var z = 0 while z < n { if sorted[z] > 0 { busy += 1 }; t += sorted[z]; z += 1 } print(` generation per frame (us): p95 {string(sorted[(n * 95) / 100])} p99 {string(sorted[(n * 99) / 100])} worst {string(sorted[n - 1])} frames that generated: {string(busy)} of {string(n)} total {string(t / 1000)} ms`) } @alloc_ok("profiling and statistics, only under R3D_PROF / R3D_DRAWSTATS") function prof_gen_frame(render3d_st: mut Render3dState) -> void { ds_frame(render3d_st) if not render3d_st.prof_on { return } if render3d_st.prof_gen == null { render3d_st.prof_gen = new []int; render3d_st.prof_ft = new []long render3d_st.prof_gen_us = new []long; render3d_st.prof_layer_us = new []long render3d_st.prof_bake_us = new []long; render3d_st.prof_dt = new []long; render3d_st.prof_up = new []long render3d_st.prof_cpu_us = new []long; render3d_st.prof_game_us = new []long render3d_st.prof_mark_us = new []long; render3d_st.prof_mark_who = new []pointer } push(render3d_st.prof_gen, render3d_st.prof_gen_cur) render3d_st.prof_gen_cur = 0 let now = gl_now_us() var dtf: long = 0 if render3d_st.prof_last_us != 0 { push(render3d_st.prof_ft, now - render3d_st.prof_last_us); dtf = now - render3d_st.prof_last_us } render3d_st.prof_last_us = now # everything the frame just ended spent on work it only does sometimes push(render3d_st.prof_dt, dtf) push(render3d_st.prof_gen_us, render3d_st.prof_gen_us_cur) push(render3d_st.prof_layer_us, render3d_st.prof_layer_us_cur) push(render3d_st.prof_bake_us, render3d_st.prof_bake_us_cur) push(render3d_st.prof_up, render3d_st.prof_up_cur) var cpu: long = 0 if render3d_st.prof_pre_swap != 0 and dtf != 0 { cpu = render3d_st.prof_pre_swap - (now - dtf) } push(render3d_st.prof_cpu_us, cpu) push(render3d_st.prof_game_us, render3d_st.prof_game_us_cur) if len(render3d_st.prof_gen) > 9 and dtf != 0 { render3d_st.prof_sum_dt = render3d_st.prof_sum_dt + dtf; render3d_st.prof_sum_cpu = render3d_st.prof_sum_cpu + cpu; render3d_st.prof_sum_game = render3d_st.prof_sum_game + render3d_st.prof_game_us_cur render3d_st.prof_sum_n += 1 } push(render3d_st.prof_mark_us, render3d_st.prof_mark_best) if render3d_st.prof_mark_name == null { push(render3d_st.prof_mark_who, "-") } else { push(render3d_st.prof_mark_who, render3d_st.prof_mark_name) } render3d_st.prof_gen_us_cur = 0; render3d_st.prof_layer_us_cur = 0; render3d_st.prof_bake_us_cur = 0; render3d_st.prof_up_cur = 0; render3d_st.prof_game_us_cur = 0 } # the distribution of REAL frame times: stutter lives in the tail, not the mean @alloc_ok("profiling and statistics, only under R3D_PROF / R3D_DRAWSTATS") function prof_ft_report(render3d_st: Render3dState) -> void { if not render3d_st.prof_on { return } if render3d_st.prof_ft == null or len(render3d_st.prof_ft) < 16 { return } let sorted = new []long var i = 8 while i < len(render3d_st.prof_ft) { push(sorted, render3d_st.prof_ft[i]); i += 1 } var a = 1 while a < len(sorted) { let v = sorted[a] var b = a - 1 while b >= 0 and sorted[b] > v { sorted[b + 1] = sorted[b]; b -= 1 } sorted[b + 1] = v a += 1 } let n = len(sorted) let med = sorted[n / 2] var over = 0 var j = 0 while j < n { if sorted[j] > med * 2 { over += 1 }; j += 1 } print("") print("REAL frame time (us):") print(` median {string(med)} p95 {string(sorted[(n * 95) / 100])} p99 {string(sorted[(n * 99) / 100])} worst {string(sorted[n - 1])}`) # A hitch is not the mean moving: it is the count of frames that took noticeably # longer than the frame before them. 1.3x median is about where it stops being smooth. var o13 = 0 var o15 = 0 var q = 0 while q < n { if sorted[q] * 10 > med * 13 { o13 += 1 } if sorted[q] * 2 > med * 3 { o15 += 1 } q += 1 } # How much time the run spent being slower than itself: the sum of every frame's # excess over 1.2x the median. One number that goes down when hitching goes down, and # that a handful of unlucky frames cannot dominate the way a maximum can. var excess: long = 0 q = 0 while q < n { let lim = (med * 12) / 10 if sorted[q] > lim { excess = excess + (sorted[q] - lim) } q += 1 } print(` fps at median {string(1000000 / med)} frames over 1.3x median: {string(o13)}, over 1.5x: {string(o15)}, over 2x: {string(over)} — of {string(n)}`) print(` stutter: {string(excess / 1000)} ms of frame time beyond 1.2x median over the run`) print(` streaming totals over the run: walk {string(render3d_st.stream_us_walk / 1000)} ms (generate {string(render3d_st.stream_us_gen / 1000)} ms, gather {string(render3d_st.stream_us_gather / 1000)} ms), {string(render3d_st.stream_walks)} stream-walks`) # the average frame, split: what the process did before the swap (the game's share of it apart), # the rest waiting on the GPU and the swap, and the renderer's CPU phases in frame order if render3d_st.prof_sum_n > 0 { let dt = render3d_st.prof_sum_dt / render3d_st.prof_sum_n let cpu = render3d_st.prof_sum_cpu / render3d_st.prof_sum_n let game = render3d_st.prof_sum_game / render3d_st.prof_sum_n print("") print(`MEAN frame {string(dt)} us over {string(render3d_st.prof_sum_n)} frames: CPU before the swap {string(cpu)} us (the game's own {string(game)} us), GPU and swap {string(dt - cpu)} us`) print(" renderer CPU by phase, mean per frame:") var i = 0 while i < render3d_st.prof_mk_n { print(` {Text.pad_right(render3d_st.prof_mk_names[i], 20)} {Text.pad_left(string(render3d_st.prof_mk_us[i] / render3d_st.prof_sum_n), 7)} us`) i += 1 } } } # The slowest frames of the run, with the once-in-a-while CPU work that landed in them. # An average never shows a hitch; this is the list of the frames you actually felt. @alloc_ok("profiling and statistics, only under R3D_PROF / R3D_DRAWSTATS") function prof_hitch_report(render3d_st: Render3dState) -> void { if not render3d_st.prof_on or render3d_st.prof_dt == null or len(render3d_st.prof_dt) < 32 { return } let n = len(render3d_st.prof_dt) # median, for a sense of what "slow" means here let sorted = new []long var i = 8 while i < n { push(sorted, render3d_st.prof_dt[i]); i += 1 } var a = 1 while a < len(sorted) { let v = sorted[a] var b = a - 1 while b >= 0 and sorted[b] > v { sorted[b + 1] = sorted[b]; b -= 1 } sorted[b + 1] = v a += 1 } let med = sorted[len(sorted) / 2] print("") print(`the 20 slowest frames (median {string(med / 1000)}.{string((med / 100) % 10)} ms), and what was in them:`) print(" frame dt cpu gpu-wait cover-gen game uploaded slowest CPU phase") var shown = 0 var cut: long = sorted[len(sorted) - 1] while shown < 20 and cut > med { # the next slowest frame at or below `cut` var best = -1 var bestv: long = -1 var k = 8 while k < n { if render3d_st.prof_dt[k] <= cut and render3d_st.prof_dt[k] > bestv { bestv = render3d_st.prof_dt[k]; best = k } k += 1 } if best < 0 { return } print(` {Text.pad_left(string(best), 6)} {Text.pad_left(string(render3d_st.prof_dt[best]), 6)}us {Text.pad_left(string(render3d_st.prof_cpu_us[best]), 7)}us {Text.pad_left(string(render3d_st.prof_dt[best] - render3d_st.prof_cpu_us[best]), 8)}us {Text.pad_left(string(render3d_st.prof_gen_us[best]), 7)}us {Text.pad_left(string(render3d_st.prof_game_us[best]), 7)}us {Text.pad_left(string(render3d_st.prof_up[best] / 1024), 7)}KB {Text.pad_right(render3d_st.prof_mark_who[best], 18)} {Text.pad_left(string(render3d_st.prof_mark_us[best]), 7)}us`) cut = bestv - 1 shown += 1 } } @alloc_ok("profiling and statistics, only under R3D_PROF / R3D_DRAWSTATS") function prof_gen_report(render3d_st: Render3dState) -> void { if not render3d_st.prof_on { return } if render3d_st.prof_gen == null or len(render3d_st.prof_gen) < 8 { return } let sorted = new []int var i = 8 # skip the first frames: one-off initial fill while i < len(render3d_st.prof_gen) { push(sorted, render3d_st.prof_gen[i]); i += 1 } var a = 1 while a < len(sorted) { let v = sorted[a] var b = a - 1 while b >= 0 and sorted[b] > v { sorted[b + 1] = sorted[b]; b -= 1 } sorted[b + 1] = v a += 1 } let n = len(sorted) var total = 0 var busy = 0 var j = 0 while j < n { total += sorted[j]; if sorted[j] > 0 { busy += 1 }; j += 1 } print("") print("ground cover generated per frame (the source of walking stutter):") print(` frames that generated anything: {string(busy)} of {string(n)}`) print(` median {string(sorted[n / 2])} p95 {string(sorted[(n * 95) / 100])} worst {string(sorted[n - 1])} total {string(total)}`) }