ludic/packages/ludic.render3d/prof.ludic

# ============================================================================
# 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


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)
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 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 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
  }
}

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)
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 } }

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
}

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`)
}

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
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.
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
  }
}

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)}`)
}