diff --git a/docs/Disaggregated/notes/perf-p15/PLAN-P15.md b/docs/Disaggregated/notes/perf-p15/PLAN-P15.md index a9b0a4b0..07d01b59 100644 --- a/docs/Disaggregated/notes/perf-p15/PLAN-P15.md +++ b/docs/Disaggregated/notes/perf-p15/PLAN-P15.md @@ -35,18 +35,46 @@ This is the plan, plus the measurements it rests on (section 2). Nothing here is epochs (a client one and a server one); - per-VAO and per-program slices that persist across frames. It does not build a pair-keyed packet table. +4. **Swap interval 0 does not unlimit the frame rate today, and interval ≥1 vsyncs correctly.** + - MC 1.21.5 in FCL runs with vsync off (interval 0) and maxFps 260, which is MC's "unlimited". + - At interval 1, every build locks to 165.0 fps. + - At interval 0, every build is still partly display-coupled: the GL thread blocks ~2 ms/frame + in `queueBuffer`. That includes dev and the MobileGlues plugin. + - The cause is on the platform side. The app's own buffer-queue binder thread holds the queue + mutex across a SurfaceFlinger call, and SurfaceFlinger in turn waits synchronously on the + composer HAL. + - Stage P moves the present off the GL thread to a present worker, so interval 0 is CPU-bound + and interval ≥1 is still paced to the display (section 2.4). -Stage order: 0 (parity audit + wire non-draw fast path), 0b (an FCL 1.21.5 trace fixture), 1 -(client draw-delta prototype), 2 (per-VAO / per-program slices), 3 (applier + backend -draw-delta), 4 (split arms, verify, default-on). +Stage order: +- 0: parity audit + wire non-draw fast path; +- 0b: an FCL 1.21.5 trace fixture; +- P: swap-interval-correct presentation. It is independent of 1-4 and can run in parallel after 0; +- 1: client draw-delta prototype; +- 2: per-VAO / per-program slices; +- 3: applier + backend draw-delta; +- 4: split arms, verify, default-on. + +Decisions taken with the user (2026-10-08): +- Presenting-thread CPU ms/frame is the primary FCL metric, with fps beside it. +- Swap interval must be honoured properly. This is stage P. +- minSdk / native TLS is the user's own change; P15 does not touch it. +- The probe tools are committed under `tools/device_bench/disagg/`. +- No Espryt deferred-clear port: its clear and blit costs match dev's. ## 1. Measurement rules for P15 - **FCL:** - The primary metric is the presenting-thread CPU in ms/frame, which MobileGL's fps log already prints. Report fps beside it, never alone. - - Above ~165 fps, frame time ≈ CPU + ~2.4 ms of display-coupled wait (section 2.1). So fps - ratios understate CPU ratios and are not linear in CPU saved. + - Until stage P lands, at interval 0 and above ~165 fps, frame time ≈ CPU + ~2.4 ms of + display-coupled wait (section 2.1). So fps ratios understate CPU ratios and are not linear in + CPU saved. + - Record the swap interval of every FCL reading (MC's `enableVsync` in + `/sdcard/FCL/.minecraft/versions/1.21.5/options.txt`; the default bench is `false`). Back the + file up before editing and restore it md5-checked. + - At interval ≥1 the per-frame CPU of every build rises by 0.3-0.7 ms (section 2.4), because the + thread idles between frames. Compare CPU only within one interval setting. - Take readings only from in-world steady windows. The probe waits for MC's `Time elapsed:` line and then four fps-log windows of more than 150 frames each. - **Trace (rd12, openra, and the FCL 1.21.5 fixture from stage 0b):** @@ -72,15 +100,14 @@ draw-delta), 4 (split arms, verify, default-on). ## 2. Measurements behind the plan (2026-10-07) -Tools are in the session scratchpad `p15/`, to be landed under `tools/device_bench/disagg/` -(open question 4): +Tools are in `tools/device_bench/disagg/` (README section "P15 FCL probes"): - `fcl_probe.sh`: waits for in-world frames, then runs 4 s of ftrace (sched, kgsl cmdbatch, atrace gfx) and 6 s of `simpleperf --trace-offcpu -p`; - `offwait.py`: off-CPU time by open atrace slice and waker; - `sfalign.py`: SurfaceFlinger transaction phase; -- `fclsplit.py` / `incl.py` / `drvcaller.py`: layer split, inclusive functions, and driver time - by caller; -- `P15Count.inl` (measurement-only patch): per-draw pair and gap statistics. +- `fcl_split.py` / `fcl_incl.py` / `fcl_drvcaller.py` / `fcl_stacks.py`: layer split, inclusive + functions, driver time by caller, and stacks; +- `fcl_count.sh` + `p15count.patch` (measurement-only): per-draw pair and gap statistics. ### 2.1 Item 1: where FCL's wait is @@ -108,9 +135,12 @@ FCL MC 1.21.5, in world, view distance 2, monolith. The figures for the presenti - **Other checks:** - GPU busy is ~14 % (union of kgsl `adreno_cmdbatch_retired`). - The swapchain is MAILBOX with 6 images, so present mode and image count are not the cause. -- **Consequence:** this is not a MobileGL defect and not a feat regression. Making the present - asynchronous would raise every build's FCL fps above 165, but only by producing frames SF drops. - It is not proposed as a perf item; open question 2 covers it. +- **SurfaceFlinger's side:** its binder thread sleeps inside `setTransactionState` until it is + woken by `binder:1555_x`, a thread of `vendor.qti.hardware.display.composer-service`. That + thread is busy with its `HWCDisplay::CommitOrPrepare` cycle. So the composer HAL's display + cycle sets the phase. +- **Consequence:** this is not a MobileGL defect and not a feat regression. The fix for interval 0 + is stage P (section 2.4). ### 2.2 FCL CPU by function (render thread, on-CPU ms/frame, inclusive) @@ -180,6 +210,52 @@ What sits between draws: - **openra:** every draw changes blend, texture, attrib pointers and sub-data. No per-draw shortcut applies, and none is needed: openra is not where the gap is. +### 2.4 Swap interval: what is requested, what each backend does, what happens + +**What MC requests:** +- The bench world runs with `enableVsync:false` and `maxFps:260` (MC's "unlimited"). So the app + asks for interval 0 through FCL's GLFW → `eglSwapInterval`. +- That interval 0 reaches Espryt's host EGL is shown by behaviour: the host default of 1 would cap + at 165 fps, but Espryt runs at 194-225. +- For Magma, `enableVsync:true` logs `Picked present mode: VK_PRESENT_MODE_FIFO_KHR` and locks to + 165 fps, so the interval is plumbed. + +**How each backend honours it today:** +- **Espryt:** + - `EGLImpl::SwapInterval` → `BackendObject::SetEGLSwapInterval` → `DirectGLES::SetSwapInterval` + → host `eglSwapInterval`. On Android that is `ANativeWindow` `setSwapInterval`; 0 is the + async queue mode. + - The interval is re-applied when the window surface is recreated. +- **Magma:** + - `DirectVulkan::SetSwapInterval` → `VulkanRenderer::SetSwapInterval`. + - A changed interval recreates the swapchain between frames. + - `ChooseSwapchainPresentMode`: 0 → IMMEDIATE, then MAILBOX, then FIFO; ≥1 → FIFO; negative → + FIFO_RELAXED, then FIFO; no request → MAILBOX first. + - Android offers no IMMEDIATE here, so interval 0 is MAILBOX with 6 images. + - Magma creates one queue. `m_presentQueue` is the same queue as `m_graphicsQueue` when the + families match. + +**Measured, FCL, monolith, same session, mean of 4 fps-log windows** (presenting-thread CPU in +ms/frame): + +| build | interval 1: fps | interval 1: CPU | interval 0: fps | interval 0: CPU | interval 0: GL-thread sleep | interval 0: runnable | +|---|---|---|---|---|---|---| +| dev Magma | 164.9 | 2.43 | 235.5 | 1.76 | 2.02 | 0.35 | +| feat Magma | 163.2 | 2.92 | 172.8 | 3.12 | 2.02 | 0.44 | +| dev Espryt | 164.9 | 2.37 | 216.5 | 2.14 | 1.94 | 0.36 | +| feat Espryt | 163.4 | 2.72 | 194.3 | 2.73 | 1.87 | 0.41 | +| MobileGlues plugin (control) | 164.9 | ~1.9 | 248.4 | ~1.7 | 1.98 | 0.34 | + +- The MobileGlues CPU figures come from schedstat (the plugin has no fps log). +- **Interval 1 is correct everywhere:** FIFO, or host interval 1. The waits sit in + `dequeueBuffer` / `AcquireNextImageKHR` and in the render thread's own `setTransactionState`. +- **Interval 0 is wrong everywhere,** including dev and the control. The GL thread still spends + ~2 ms/frame in `queueBuffer` → `BLASTBufferQueue::onFrameAvailable`, waiting for the mutex that + the app's binder thread holds across `setTransactionState`, and that call is phase-locked to the + composer HAL (section 2.1). +- **The async queue mode does not help.** It changes what happens to the buffers, not who holds the + mutex. + ## 3. Stages ### Stage 0: parity audit, then the wire non-draw fast path (Magma first) @@ -274,6 +350,81 @@ Espryt's deleted mechanisms. Port only those that show in profiles. not, the fixture does not represent FCL. - **Order:** best done before stage 0.2 lands, so stage 0 can be A/B'd on a trace as well as on FCL. +### Stage P: swap-interval-correct presentation (both backends) + +**Goal:** +- With interval 0, presentation never paces the app: FCL fps becomes 1 / presenting-thread CPU. +- With interval ≥1 the app is still paced to the display: 165 fps ±1 % on this device, with no + extra latency beyond one queued frame. + +**Design: a present worker that owns the blocking present.** +- The GL thread finishes a frame and hands it to the worker through a bounded queue (depth 1 at + interval ≥1, depth 2 at 0). It returns at once. +- The worker performs the present call that may block. +- At interval ≥1, backpressure comes from the full queue: the GL thread waits for the worker, + which waits for the display. At interval 0 the queue never fills, because the worker's blocked + windows (≤3.4 ms, about once per refresh) are absorbed by the swapchain's spare images. +- The worker exists only for window surfaces. Pbuffer and offscreen surfaces keep the inline path. + +**Magma:** +- The GL thread keeps `vkAcquireNextImageKHR` and the submit, which signals the image's + render-done semaphore. +- The worker calls `vkQueuePresentKHR`. +- Queue access must be externally synchronised, and the WSI's `queueBuffer` runs inside + `vkQueuePresentKHR`. So the worker needs **its own VkQueue**: a second queue of the graphics + family, or a present-capable family. + - Check the Adreno queue count first. + - If only one queue exists, the fallback is a queue mutex released before the WSI blocks. That + is not possible from outside the loader, so a single-queue device keeps the inline present + and logs it once. +- Swapchain recreation (resize, interval change, `OUT_OF_DATE`) drains the worker first. +- The frame-in-flight fences already gate the reuse of images. + +**Espryt:** `eglSwapBuffers` is bound to the context's thread, so the prototype compares two routes: +- **(a) Own the native window.** + - Dequeue `ANativeWindowBuffer`s on the GL thread (or worker) and wrap each as an EGLImage + (`EGL_NATIVE_BUFFER_ANDROID`, cached by buffer identity: generation + id, never a pointer). + - Render the default framebuffer into it. + - The worker queues it with an `EGL_ANDROID_native_fence_sync` fd. + - This route also needs buffer count, transform / pre-rotation, damage, buffer age and + `setSwapInterval` on the window itself. + - No extra blit. The anland shared-image route already does part of this. +- **(b) A present thread with a shared context.** + - The default framebuffer becomes an offscreen FBO. + - The present thread waits on a fence, blits to its window surface and calls `eglSwapBuffers`. + - Costs one full-screen blit per frame (800×1280; small on Adreno 750), a second context, and + redirecting default-framebuffer reads. +- Prototype (a) first. + +**Split arms:** +- The server presents on the apply thread (inproc) or in the server process (spawn/tcp). The + worker sits there. +- The present credit is returned when the frame is handed to the worker, not when `queueBuffer` + returns. + +**Tests:** +- interval 0 → fps bounded by CPU, and the GL thread never sleeps in `queueBuffer` + (`offwait.py` shows no `queueBuffer` sleep on the GL thread); +- interval 1 → 165 fps ±1 %, and so is interval 2 → 82.5; +- interval changes at runtime (MC's vsync toggle); +- surface resize / rotation; eglMakeCurrent away and back with frames queued; +- teardown and device loss with a frame in the worker; +- the anland desktop (a split-arm present on the same device); +- negative control: a knob that makes the worker present inline must bring the ~2 ms + `queueBuffer` sleep back. +- Kill switch: `MOBILEGL_PRESENT_WORKER=0`. + +**Expected at FCL interval 0** (presenting-thread CPU is unchanged; fps approaches 1/CPU): + +| build | today | after stage P | after stage 0 as well | +|---|---|---|---| +| dev Magma | ~236 | ~450-550 | | +| feat Magma | ~173 | ~300-330 | ~450 | +| feat Espryt | ~194 | ~350 | | + +At interval ≥1 nothing changes. Confidence: medium. It depends on the second queue (Magma) and on +route (a) working (Espryt). + ### Stage 1: client draw-delta prototype (Espryt monolith) This is the client half of the old sketch, re-keyed on what section 2.3 shows. @@ -388,8 +539,7 @@ This is the client half of the old sketch, re-keyed on what section 2.3 shows. - a (VAO, program) pair table: 0 % hit on rd12, and FCL's hits are covered by the draw delta; - record batching (measured and dropped in P14); - protocol changes; -- asynchronous present (open question 2); -- native TLS (open question 3); +- native TLS / minSdk (the user's own change); - openra, whose gaps change state on every draw. ### 4.2 Per-layer state for one draw on the fast path @@ -526,18 +676,14 @@ What the totals mean: - **Gains below estimate:** the stage 1 prototype is the go/no-go for stages 2-3. - **FCL fixture fidelity:** stage 0b's P15Count check. -## 7. Open questions for the user +## 7. Questions resolved with the user (2026-10-08) -1. **The FCL metric.** Do you agree to make presenting-thread CPU ms/frame the primary FCL metric? - fps above refresh rate is display-coupled (section 2.1). -2. **Asynchronous present.** Presenting from a separate thread would cut the ~2 ms/frame BBQ wait - from the render thread on every build, dev included. It would raise FCL fps above refresh, but - the extra frames are ones SF drops; at or below refresh nothing changes. Leave it out (my - recommendation), or plan it as a separate item? -3. **Native TLS** (minSdk 29, +1.7 % Espryt): still your call from P14. -4. **The P15 measurement tools.** May I commit `fcl_probe.sh`, `offwait.py`, `sfalign.py`, - `fclsplit.py`, `drvcaller.py` and `incl.py` under `tools/device_bench/disagg/` with the plan? - They are tooling, not product code. This assignment was docs-only, so they are not in this - commit. -5. **Magma deferred clears, Espryt side:** the wire arm's Espryt clears cost the same as dev's, so - no port is planned there. Confirm. +1. FCL metric: presenting-thread CPU ms/frame is primary, with fps beside it. +2. Swap interval: interval 0 must unlimit the frame rate, and interval ≥1 must vsync. This is + stage P. +3. minSdk 29 / native TLS: the user decides and changes it. P15 does not touch it. +4. The probe tools are committed under `tools/device_bench/disagg/`. +5. No Espryt deferred-clear port: Espryt's clear and blit costs match dev's. + +Still open (for stage P): does Adreno 750 expose a second graphics-family queue for the Magma +present worker? Which Espryt route, (a) or (b)? diff --git a/tools/device_bench/disagg/README.md b/tools/device_bench/disagg/README.md index 06e8b2ef..0f15c1d0 100644 --- a/tools/device_bench/disagg/README.md +++ b/tools/device_bench/disagg/README.md @@ -106,3 +106,31 @@ exits on EOF and RSTs the connection, and `pkill` must be anchored Attaches the device `/system/bin/strace` to the server's session child as the app uid via `run-as` (shell-uid ptrace is blocked). + +## P15 FCL probes: fcl_probe.sh, fcl_count.sh and their reducers + +`fcl_probe.sh [simpleperf=1]` swaps a library into +FCL (rooted device), launches it, waits for steady in-world frames (MC's `Time elapsed:` line, +then four fps-log windows of more than 150 frames each, relaunching on the known start-up death), +then records: +- 4 s of ftrace: sched, kgsl cmdbatch/waittimestamp, and atrace gfx for the app; +- schedstat and `gpu_clock_stats` bracketing that window; +- with the last argument at 1, 6 s of `simpleperf --trace-offcpu -p `. + +The caller restores FCL with `fcl_p14.sh restore`. `fcl_count.sh` does the same launch for a +`p15count.patch` build (per-draw (VAO, program) pair and between-draw entry statistics, armed by +`debug.mobilegl.p15count=1` or `MOBILEGL_P15_COUNT=1`, window `MOBILEGL_P15_COUNT_WINDOW`). + +Reducers, all reading a probe directory: +- `snapdiff.py`: per-thread CPU and runqueue wait; +- `offwait.py `: sleep and runnable time per frame, keyed by the + atrace slices open at switch-out and the waker, plus GPU busy; +- `sfalign.py`: SurfaceFlinger `setTransactionState` duration and phase against `flushTransactions`; +- `slices.py`: atrace slice totals per thread; +- `fcl_split.py`: layer split, on- vs off-CPU; +- `fcl_incl.py`: inclusive libMobileGL functions; +- `fcl_drvcaller.py`: driver time by entry and MobileGL caller; +- `fcl_stacks.py`: top stacks. + +The simpleperf reducers need `SIMPLEPERF_DIR` and a `binary_cache` from `binary_cache_builder.py`. +Findings: `docs/Disaggregated/notes/perf-p15/PLAN-P15.md` section 2. diff --git a/tools/device_bench/disagg/fcl_count.sh b/tools/device_bench/disagg/fcl_count.sh new file mode 100755 index 00000000..e17909b4 --- /dev/null +++ b/tools/device_bench/disagg/fcl_count.sh @@ -0,0 +1,40 @@ +#!/usr/bin/env bash +# fcl_count.sh +# One FCL launch with a P15Count build (p15count.patch): waits for steady in-world frames, runs +# 25 s with debug.mobilegl.p15count=1, and extracts the P15CNT lines to /count.txt. +# Caller restores FCL (fcl_p14.sh restore). +set -u +export MSYS_NO_PATHCONV=1 MSYS2_ARG_CONV_EXCL='*' +name="$1" lib="$2" backend="$3" transport="$4" out="$5" sp="${6:-1}" +SER=HA27Q3LQ FCL=com.tungsten.fcl.mgdebug.debug +CFG=/data/data/$FCL/files/config.json +mkdir -p "$out" +su_sh() { adb -s $SER shell "su -c '$1'"; } +dir=$(su_sh "dirname /data/app/*/$FCL-*/lib/arm64/libMobileGL.so" | tr -d '\r' | head -1) +id=5e273ee2-baca-4c81-8e48-b63feefb9ba8; [ "$backend" = DirectVulkan ] && id=2be0dc10-1eef-4ce2-b512-b266dd33fd9e +adb -s $SER push "$(cygpath -w "$lib")" /data/local/tmp/p15-fcl-lib.so >/dev/null +su_sh "am force-stop $FCL; cat /data/local/tmp/p15-fcl-lib.so > $dir/libMobileGL.so; rm -f /data/local/tmp/p15-fcl-lib.so; md5sum $dir/libMobileGL.so" > "$out/libmd5.txt" +su_sh "sh /data/local/tmp/p14-fcl-set.sh $id $CFG; setprop debug.mobilegl.fps_log 1; setprop debug.mobilegl.transport $transport; setprop debug.mobilegl.p15count 1" +ok=0 +for attempt in 1 2 3 4; do + su_sh "am force-stop $FCL"; sleep 2 + adb -s $SER logcat -c + su_sh "input keyevent KEYCODE_WAKEUP; monkey -p $FCL -c android.intent.category.LAUNCHER 1" >/dev/null 2>&1 + t=0 + while [ $t -lt 200 ]; do + sleep 3; t=$((t+3)) + if [ $t -gt 12 ] && [ -z "$(adb -s $SER shell pidof $FCL | tr -dc '0-9')" ]; then echo "attempt $attempt: died at $t s" >> "$out/wait.txt"; break; fi + adb -s $SER logcat -d > "$out/logcat_wait.txt" 2>/dev/null + n=$(awk '/Time elapsed:/{f=1} f && /MobileGL fps:/{ if (match($0,/over [0-9]+ frames/)) { s=substr($0,RSTART+5,RLENGTH-12); if (s+0>150) c++ } } END{print c+0}' "$out/logcat_wait.txt") + if [ "$n" -ge 4 ]; then ok=1; break; fi + done + [ $ok = 1 ] && break +done +echo "waited=$t ok=$ok attempt=$attempt" >> "$out/wait.txt" +[ $ok = 1 ] || { su_sh "am force-stop $FCL"; echo "NO STEADY FRAMES"; exit 3; } +sleep 25 +adb -s $SER logcat -d > "$out/logcat.txt" +su_sh "am force-stop $FCL; resetprop --delete debug.mobilegl.p15count" +grep -a "P15CNT" "$out/logcat.txt" | sed 's/.*P15CNT/P15CNT/' > "$out/count.txt" +grep -a "MobileGL fps:" "$out/logcat.txt" | tail -3 | sed 's/.*MobileGL fps: //' +tail -12 "$out/count.txt" diff --git a/tools/device_bench/disagg/fcl_drvcaller.py b/tools/device_bench/disagg/fcl_drvcaller.py new file mode 100644 index 00000000..2503e12e --- /dev/null +++ b/tools/device_bench/disagg/fcl_drvcaller.py @@ -0,0 +1,37 @@ +# fcl_drvcaller.py : driver-layer on-CPU time keyed by (driver entry, MobileGL caller) +import os, sys +from collections import Counter +sys.path.insert(0, os.environ.get("SIMPLEPERF_DIR", "")) +sys.path.insert(0, os.path.dirname(os.path.abspath(__file__))) +from simpleperf_report_lib import ReportLib +from layers import layer_of +d, tid, frames = sys.argv[1], int(sys.argv[2]), float(sys.argv[3]) +l = ReportLib(); l.SetRecordFile(os.path.join(d, "perf.data")); l.SetSymfs(os.path.join(d, "binary_cache")) +c = Counter(); entry = Counter(); leafc = Counter() +sh = lambda n: n.replace("(anonymous namespace)", "{anon}").split("(")[0][-60:] +while True: + s = l.GetNextSample() + if s is None: break + if s.tid != tid: continue + leaf = l.GetSymbolOfCurrentSample(); cc = l.GetCallChainOfCurrentSample() + fr = [(leaf.symbol_name, leaf.dso_name)] + [(cc.entries[i].symbol.symbol_name, cc.entries[i].symbol.dso_name) for i in range(cc.nr)] + if any(n in ("__schedule", "schedule") or n.startswith("__switch_to") for n, _ in fr[:10]): continue + lay = None + for n, dso in fr: + lay = layer_of(n, dso) + if lay: break + if lay != "driver": continue + # outermost driver frame and the first MobileGL frame above it + last_drv = None; caller = "?" + for i, (n, dso) in enumerate(fr): + if layer_of(n, dso) == "driver": last_drv = i + if last_drv is not None: + e = sh(fr[last_drv][0]) + " [" + os.path.basename(fr[last_drv][1]) + "]" + for n, dso in fr[last_drv + 1:]: + if "libMobileGL" in dso: caller = sh(n); break + if "libgui" in dso or "libvulkan" in dso: caller = sh(n) + " [" + os.path.basename(dso) + "]"; break + c[(e, caller)] += s.period; entry[e] += s.period + leafc[sh(fr[0][0]) + " [" + os.path.basename(fr[0][1]) + "]"] += s.period +print("driver entry (ms/frame):"); [print(f" {v/1e6/frames:7.3f} {k}") for k, v in entry.most_common(15)] +print("entry x caller:"); [print(f" {v/1e6/frames:7.3f} {k[0]} <- {k[1]}") for k, v in c.most_common(20)] +print("leaf:"); [print(f" {v/1e6/frames:7.3f} {k}") for k, v in leafc.most_common(12)] diff --git a/tools/device_bench/disagg/fcl_incl.py b/tools/device_bench/disagg/fcl_incl.py new file mode 100644 index 00000000..904a7da7 --- /dev/null +++ b/tools/device_bench/disagg/fcl_incl.py @@ -0,0 +1,28 @@ +# fcl_incl.py [N]: inclusive on-CPU ms/frame of libMobileGL functions +import os, sys +from collections import Counter +sys.path.insert(0, os.environ.get("SIMPLEPERF_DIR", "")) +from simpleperf_report_lib import ReportLib +d, tid, frames = sys.argv[1], (int(sys.argv[2]) if sys.argv[2].isdigit() else sys.argv[2]), float(sys.argv[3]); N = int(sys.argv[4]) if len(sys.argv) > 4 else 60 +l = ReportLib(); l.SetRecordFile(os.path.join(d, "perf.data")); l.SetSymfs(os.path.join(d, "binary_cache")) +incl = Counter(); selfc = Counter(); tot = 0 +sh = lambda n: n.replace("(anonymous namespace)", "{anon}").replace("MobileGL::", "").split("(")[0][-75:] +while True: + s = l.GetNextSample() + if s is None: break + if (s.tid != tid) if isinstance(tid, int) else (tid not in s.thread_comm): continue + leaf = l.GetSymbolOfCurrentSample(); cc = l.GetCallChainOfCurrentSample() + fr = [(leaf.symbol_name, leaf.dso_name)] + [(cc.entries[i].symbol.symbol_name, cc.entries[i].symbol.dso_name) for i in range(cc.nr)] + if any(n in ("__schedule", "schedule") or n.startswith("__switch_to") for n, _ in fr[:10]): continue + tot += s.period + seen = set() + for n, dso in fr: + if "libMobileGL" in dso: + k = sh(n) + if k not in seen: incl[k] += s.period; seen.add(k) + for n, dso in fr: + if "libMobileGL" in dso: selfc[sh(n)] += s.period; break +print(f"on-CPU {tot/1e6/frames:.3f} ms/frame") +for k, v in incl.most_common(N): print(f" {v/1e6/frames:7.3f} {k}") +print("self (first MobileGL frame):") +for k, v in selfc.most_common(25): print(f" {v/1e6/frames:7.3f} {k}") diff --git a/tools/device_bench/disagg/fcl_probe.sh b/tools/device_bench/disagg/fcl_probe.sh new file mode 100755 index 00000000..b2cb79f6 --- /dev/null +++ b/tools/device_bench/disagg/fcl_probe.sh @@ -0,0 +1,59 @@ +#!/usr/bin/env bash +# fcl_probe.sh [simpleperf=1] +# One FCL launch: wait for steady in-world frames (fps log), then +# A) 4 s ftrace (sched + kgsl cmdbatch/waittimestamp + atrace gfx for the app), schedstat and gpu_clock_stats bracketing it +# B) 6 s simpleperf --trace-offcpu on the game pid (optional) +# Caller restores FCL (fcl_p14.sh restore). +set -u +export MSYS_NO_PATHCONV=1 MSYS2_ARG_CONV_EXCL='*' +name="$1" lib="$2" backend="$3" transport="$4" out="$5" sp="${6:-1}" +SER=HA27Q3LQ FCL=com.tungsten.fcl.mgdebug.debug +CFG=/data/data/$FCL/files/config.json +mkdir -p "$out" +su_sh() { adb -s $SER shell "su -c '$1'"; } +dir=$(su_sh "dirname /data/app/*/$FCL-*/lib/arm64/libMobileGL.so" | tr -d '\r' | head -1) +id=5e273ee2-baca-4c81-8e48-b63feefb9ba8; [ "$backend" = DirectVulkan ] && id=2be0dc10-1eef-4ce2-b512-b266dd33fd9e +adb -s $SER push "$(cygpath -w "$lib")" /data/local/tmp/p15-fcl-lib.so >/dev/null +su_sh "am force-stop $FCL; cat /data/local/tmp/p15-fcl-lib.so > $dir/libMobileGL.so; rm -f /data/local/tmp/p15-fcl-lib.so; md5sum $dir/libMobileGL.so" > "$out/libmd5.txt" +su_sh "sh /data/local/tmp/p14-fcl-set.sh $id $CFG; setprop debug.mobilegl.fps_log 1; setprop debug.mobilegl.transport $transport" +ok=0 +for attempt in 1 2 3 4; do + su_sh "am force-stop $FCL"; sleep 2 + adb -s $SER logcat -c + su_sh "input keyevent KEYCODE_WAKEUP; monkey -p $FCL -c android.intent.category.LAUNCHER 1" >/dev/null 2>&1 + t=0 + while [ $t -lt 200 ]; do + sleep 3; t=$((t+3)) + if [ $t -gt 12 ] && [ -z "$(adb -s $SER shell pidof $FCL | tr -dc '0-9')" ]; then echo "attempt $attempt: died at $t s" >> "$out/wait.txt"; break; fi + adb -s $SER logcat -d > "$out/logcat_wait.txt" 2>/dev/null + n=$(awk '/Time elapsed:/{f=1} f && /MobileGL fps:/{ if (match($0,/over [0-9]+ frames/)) { s=substr($0,RSTART+5,RLENGTH-12); if (s+0>150) c++ } } END{print c+0}' "$out/logcat_wait.txt") + if [ "$n" -ge 4 ]; then ok=1; break; fi + done + [ $ok = 1 ] && break +done +echo "waited=$t ok=$ok attempt=$attempt" >> "$out/wait.txt" +[ $ok = 1 ] || { su_sh "am force-stop $FCL"; echo "NO STEADY FRAMES"; exit 3; } +pid=$(adb -s $SER shell pidof $FCL | tr -d '\r' | awk '{print $NF}') +echo "pid=$pid" >> "$out/wait.txt" +snap() { adb -s $SER shell "su -c 'cat /proc/uptime; cat /sys/class/kgsl/kgsl-3d0/gpu_clock_stats; for t in /proc/$pid/task/*; do echo T \${t##*/} \$(cut -d\" \" -f1-3 \$t/schedstat) \$(cat \$t/comm); done'" > "$1"; } +# A: ftrace +EV=/sys/kernel/tracing/events +su_sh "atrace --async_start -c -b 65536 -a $FCL gfx view sched freq >/dev/null 2>&1; for e in adreno_cmdbatch_submitted adreno_cmdbatch_retired kgsl_waittimestamp_entry kgsl_waittimestamp_exit adreno_syncobj_submitted adreno_syncobj_retired adreno_drawctxt_wait_start adreno_drawctxt_wait_done kgsl_timeline_wait; do echo 1 > $EV/kgsl/\$e/enable; done; echo 1 > $EV/sched/sched_waking/enable" +snap "$out/snapA0.txt" +sleep 4 +snap "$out/snapA1.txt" +su_sh "atrace --async_stop -o /data/local/tmp/p15.atrace >/dev/null 2>&1; for e in adreno_cmdbatch_submitted adreno_cmdbatch_retired kgsl_waittimestamp_entry kgsl_waittimestamp_exit adreno_syncobj_submitted adreno_syncobj_retired adreno_drawctxt_wait_start adreno_drawctxt_wait_done kgsl_timeline_wait; do echo 0 > $EV/kgsl/\$e/enable; done; chmod 644 /data/local/tmp/p15.atrace" +adb -s $SER pull /data/local/tmp/p15.atrace "$(cygpath -w "$out/trace.txt")" >/dev/null +# B: simpleperf +if [ "$sp" = 1 ]; then + snap "$out/snapB0.txt" + su_sh "rm -f /data/local/tmp/p15perf.data; simpleperf record -p $pid -e cpu-clock --trace-offcpu --call-graph fp -f 4000 --duration 6 -o /data/local/tmp/p15perf.data" > "$out/record.log" 2>&1 + snap "$out/snapB1.txt" + su_sh "chmod 644 /data/local/tmp/p15perf.data" + adb -s $SER pull /data/local/tmp/p15perf.data "$(cygpath -w "$out/perf.data")" >/dev/null +fi +adb -s $SER logcat -d > "$out/logcat.txt" +su_sh "am force-stop $FCL" +grep -a "MobileGL fps:" "$out/logcat.txt" | tail -8 | sed 's/.*MobileGL fps: //' > "$out/fps.txt" +echo "$name $backend $transport :: $(tail -4 "$out/fps.txt" | tr '\n' '|')" +tail -1 "$out/record.log" 2>/dev/null diff --git a/tools/device_bench/disagg/fcl_split.py b/tools/device_bench/disagg/fcl_split.py new file mode 100644 index 00000000..4f7c1432 --- /dev/null +++ b/tools/device_bench/disagg/fcl_split.py @@ -0,0 +1,45 @@ +# fcl_split.py [depth] [--detail=layer] +# Period-weighted on/off-CPU split of one thread of an FCL simpleperf --trace-offcpu profile. +# On-CPU goes to a layer (driver / backend / applier / client half / jvm+game / other), off-CPU is +# grouped by its first user frames. +import os, sys +from collections import Counter +sys.path.insert(0, os.environ.get("SIMPLEPERF_DIR", "")) +sys.path.insert(0, os.path.dirname(os.path.abspath(__file__))) +from simpleperf_report_lib import ReportLib +from layers import layer_of +args = [a for a in sys.argv[1:] if not a.startswith("--")] +d, tid, mspf = args[0], int(args[1]), float(args[2]); depth = int(args[3]) if len(args) > 3 else 6 +detail = next((a.split("=", 1)[1] for a in sys.argv[1:] if a.startswith("--detail=")), None) +l = ReportLib(); l.SetRecordFile(os.path.join(d, "perf.data")); l.SetSymfs(os.path.join(d, "binary_cache")) +on = Counter(); off = Counter(); det = Counter(); t0 = t1 = None; ON = OFF = 0 +sh = lambda n: n.replace("(anonymous namespace)", "{anon}").split("(")[0][-60:] +def lay(fr): + for n, dso in fr: + x = layer_of(n, dso) + if x == "harness": x = None + if x: return x + if any("libjvm" in dso or "jit" in dso.lower() or dso.endswith(".jar") or "dalvik" in dso or "[anon" in dso for _, dso in fr): return "jvm+game" + return "other" +while True: + s = l.GetNextSample() + if s is None: break + if s.tid != tid: continue + t0 = s.time if t0 is None else t0; t1 = s.time + leaf = l.GetSymbolOfCurrentSample(); cc = l.GetCallChainOfCurrentSample() + fr = [(leaf.symbol_name, leaf.dso_name)] + [(cc.entries[i].symbol.symbol_name, cc.entries[i].symbol.dso_name) for i in range(cc.nr)] + if any(n in ("__schedule", "schedule") or n.startswith("__switch_to") for n, _ in fr[:10]): + OFF += s.period + user = [sh(n) for n, dso in fr if "kallsyms" not in dso and not dso.startswith("[")][:depth] + off[" <- ".join(user)] += s.period + else: + ON += s.period; L = lay(fr); on[L] += s.period + if detail and L == detail: + # first frame of that layer + for n, dso in fr: + if layer_of(n, dso) == detail: det[sh(n)] += s.period; break +frames = (t1 - t0) / 1e6 / mspf +print(f"tid {tid}: {frames:.0f} frames ({(t1-t0)/1e9:.2f}s at {mspf} ms/frame); on-CPU {ON/1e6/frames:.3f} ms/frame, off-CPU {OFF/1e6/frames:.3f}") +for k, v in on.most_common(): print(f" on {v/1e6/frames:7.3f} {k}") +for k, v in off.most_common(16): print(f" off {v/1e6/frames:7.3f} {k[:230]}") +for k, v in det.most_common(30): print(f" det {v/1e6/frames:7.3f} {k}") diff --git a/tools/device_bench/disagg/fcl_stacks.py b/tools/device_bench/disagg/fcl_stacks.py new file mode 100644 index 00000000..e067bd66 --- /dev/null +++ b/tools/device_bench/disagg/fcl_stacks.py @@ -0,0 +1,26 @@ +# fcl_stacks.py [depth] [filter-substring]: on-CPU inclusive function time (ms/frame) and top stacks +import os, sys +from collections import Counter +sys.path.insert(0, os.environ.get("SIMPLEPERF_DIR", "")) +from simpleperf_report_lib import ReportLib +d, tid, frames = sys.argv[1], int(sys.argv[2]), float(sys.argv[3]); depth = int(sys.argv[4]) if len(sys.argv) > 4 else 8 +flt = sys.argv[5] if len(sys.argv) > 5 else None +l = ReportLib(); l.SetRecordFile(os.path.join(d, "perf.data")); l.SetSymfs(os.path.join(d, "binary_cache")) +incl = Counter(); st = Counter(); offst = Counter() +sh = lambda n: n.replace("(anonymous namespace)", "{anon}").split("(")[0][-55:] +while True: + s = l.GetNextSample() + if s is None: break + if s.tid != tid: continue + leaf = l.GetSymbolOfCurrentSample(); cc = l.GetCallChainOfCurrentSample() + fr = [(leaf.symbol_name, leaf.dso_name)] + [(cc.entries[i].symbol.symbol_name, cc.entries[i].symbol.dso_name) for i in range(cc.nr)] + names = [sh(n) for n, _ in fr] + if flt and not any(flt in n for n in names): continue + if any(n in ("__schedule", "schedule") or n.startswith("__switch_to") for n, _ in fr[:10]): + u = [sh(n) for n, dso in fr if "kallsyms" not in dso and not dso.startswith("[")][:depth] + offst[" <- ".join(u)] += s.period; continue + for n in set(names): incl[n] += s.period + st[" <- ".join(names[:depth])] += s.period +print("inclusive on-CPU:"); [print(f" {v/1e6/frames:7.3f} {k}") for k, v in incl.most_common(40)] +print("top on stacks:"); [print(f" {v/1e6/frames:7.3f} {k[:300]}") for k, v in st.most_common(12)] +print("top off stacks:"); [print(f" {v/1e6/frames:7.3f} {k[:300]}") for k, v in offst.most_common(8)] diff --git a/tools/device_bench/disagg/offwait.py b/tools/device_bench/disagg/offwait.py new file mode 100644 index 00000000..bec18ebf --- /dev/null +++ b/tools/device_bench/disagg/offwait.py @@ -0,0 +1,73 @@ +# offwait.py [present_marker] +# Off-CPU accounting for one thread from an atrace/ftrace text dump: +# - sleep (S/D) and runnable (preempted) time per frame +# - sleep time keyed by the atrace slice stack open at the switch-out and the waker's comm +# - GPU busy from adreno_cmdbatch_retired (start/retire are GPU ticks: 19.2 MHz) +import re, sys +from collections import Counter, defaultdict +path, tid = sys.argv[1], sys.argv[2] +present = sys.argv[3] if len(sys.argv) > 3 else "QueuePresentKHR|eglSwapBuffers" +pres_re = re.compile(present) +line_re = re.compile(r'^\s*(.+?)-(\d+)\s+\(\s*([\d-]+)\)\s+\[(\d+)\]\s+\S+\s+([\d.]+):\s+(\w+):\s*(.*)$') +stack = [] +state = None; t_state = None # 'run' | 'sleep' | 'runq' +sleep_by = Counter(); runq_total = 0.0; sleep_total = 0.0; run_total = 0.0 +pending_sleep = None # (t0, stackkey, prev_state) +last_waker = None +presents = [] +gpu = [] # (start_tick, retire_tick, ctx) +t_first = t_last = None +slice_time = Counter(); slice_open = [] +for line in open(path, errors="replace"): + m = line_re.match(line) + if not m: continue + comm, pid, tgid, cpu, ts, ev, rest = m.groups(); ts = float(ts) + if t_first is None: t_first = ts + t_last = ts + if ev == "tracing_mark_write" and pid == tid: + if rest.startswith("B|"): + name = rest.split("|", 2)[2] + stack.append((name, ts)) + if pres_re.search(name): presents.append(ts) + elif rest.startswith("E|"): + if stack: + name, t0 = stack.pop(); slice_time[name[:60]] += ts - t0 + elif ev == "sched_waking": + mm = re.search(r'pid=(\d+)', rest) + if mm and mm.group(1) == tid: last_waker = f"{comm}" + elif ev == "sched_switch": + mp = re.search(r'prev_pid=(\d+) prev_prio=\d+ prev_state=(\S+) ==> next_comm=.* next_pid=(\d+)', rest) + if not mp: continue + ppid, pst, npid = mp.groups() + if ppid == tid: + key = " > ".join(n[:40] for n, _ in stack[-3:]) or "(no slice)" + pending_sleep = (ts, key, pst) + last_waker = None + if npid == tid and pending_sleep: + t0, key, pst = pending_sleep + d = ts - t0 + if pst.startswith("R"): runq_total += d; sleep_by[("RUNNABLE(preempted)", key, "-")] += d + else: sleep_total += d; sleep_by[("sleep " + pst, key, last_waker or "?")] += d + pending_sleep = None + elif ev == "adreno_cmdbatch_retired": + ms = re.search(r'ctx=(\d+).*start=(\d+) retire=(\d+)', rest) + if ms: gpu.append((int(ms.group(2)), int(ms.group(3)), int(ms.group(1)))) +win = t_last - t_first +# only steady presents +nfr = max(1, len(presents) - 1); span = presents[-1] - presents[0] if len(presents) > 1 else win +print(f"window {win:.3f}s, presents {len(presents)} -> {len(presents)/win:.1f} fps, frame {1e3*span/nfr:.3f} ms") +print(f"per frame: sleep {1e3*sleep_total/nfr:.3f} ms, runnable(preempted) {1e3*runq_total/nfr:.3f} ms") +print("top off-CPU (ms/frame): state | open slices at switch-out | waker") +for (st, key, wk), d in sleep_by.most_common(18): + print(f" {1e3*d/nfr:6.3f} {st:<22} | {key[:110]:<110} | {wk}") +print("top slices on thread (ms/frame, wall incl. children):") +for k, v in slice_time.most_common(14): print(f" {1e3*v/nfr:6.3f} {k}") +if gpu: + gpu.sort(); busy = 0; cs, ce = gpu[0][0], gpu[0][1] + for s, e, c in gpu[1:]: + if s > ce: busy += ce - cs; cs, ce = s, e + else: ce = max(ce, e) + busy += ce - cs + spanticks = gpu[-1][1] - gpu[0][0] + ctxs = Counter(c for _, _, c in gpu) + print(f"GPU: {len(gpu)} cmdbatches, busy {100*busy/spanticks:.1f}% of {spanticks/19.2e6:.2f}s, {1e3*busy/19.2e6/nfr:.3f} ms/frame; ctxs {ctxs.most_common(5)}") diff --git a/tools/device_bench/disagg/p15count.patch b/tools/device_bench/disagg/p15count.patch new file mode 100644 index 00000000..c50e767c --- /dev/null +++ b/tools/device_bench/disagg/p15count.patch @@ -0,0 +1,239 @@ +diff --git a/MobileGL/MG_Impl/EGLImpl/EGLImpl.cpp b/MobileGL/MG_Impl/EGLImpl/EGLImpl.cpp +index 45375ee4..4ab2cf50 100644 +--- a/MobileGL/MG_Impl/EGLImpl/EGLImpl.cpp ++++ b/MobileGL/MG_Impl/EGLImpl/EGLImpl.cpp +@@ -57,6 +57,7 @@ + #include + #endif + ++void P15CountFrame(); + namespace MobileGL::MG_Impl::EGLImpl { + namespace { + // MOBILEGL_FPS_LOG=1 (on Android also the property debug.mobilegl.fps_log=1): one INFO line +@@ -77,6 +78,7 @@ namespace MobileGL::MG_Impl::EGLImpl { + } + + void NoteSwapForFrameRateLog() { ++ ::P15CountFrame(); + if (!FrameRateLogEnabled()) return; + using Clock = std::chrono::steady_clock; + static Clock::time_point windowStart = Clock::now(); +diff --git a/MobileGL/MG_Impl/GLImpl/Exporting/Definitions.cpp b/MobileGL/MG_Impl/GLImpl/Exporting/Definitions.cpp +index cc00326f..dfb56a3b 100644 +--- a/MobileGL/MG_Impl/GLImpl/Exporting/Definitions.cpp ++++ b/MobileGL/MG_Impl/GLImpl/Exporting/Definitions.cpp +@@ -23,6 +23,7 @@ + #include "../Debug/GL_Debug.h" + #include + #include ++#include "P15Count.inl" + + #define DECLARE_GL_FUNCTION_STUB_HEAD(type, name, ...) MOBILEGL_GL_API type gl##name(__VA_ARGS__) { + +@@ -53,12 +54,14 @@ + } + #else + #define DECLARE_GL_FUNCTION_END(type, name, ...) \ ++ { static const int mglP15 = ::p15count::Reg(#name); ::p15count::Hit(mglP15); } \ + MGLOG_D("Implementing function: %s(...)", __FUNCTION__); \ + const MobileGL::MG_Impl::EGLImpl::GLStreamScope mglStreamScope; \ + return MobileGL::MG_Impl::GLImpl::name(__VA_ARGS__); \ + } + + #define DECLARE_GL_FUNCTION_END_NO_RETURN(type, name, ...) \ ++ { static const int mglP15 = ::p15count::Reg(#name); ::p15count::Hit(mglP15); } \ + MGLOG_D("Implementing function: %s(...)", __FUNCTION__); \ + const MobileGL::MG_Impl::EGLImpl::GLStreamScope mglStreamScope; \ + MobileGL::MG_Impl::GLImpl::name(__VA_ARGS__); \ +diff --git a/MobileGL/MG_Impl/GLImpl/Exporting/P15Count.inl b/MobileGL/MG_Impl/GLImpl/Exporting/P15Count.inl +new file mode 100644 +index 00000000..1cb26c9a +--- /dev/null ++++ b/MobileGL/MG_Impl/GLImpl/Exporting/P15Count.inl +@@ -0,0 +1,186 @@ ++// P15 MEASUREMENT ONLY (apply to a scratch tree, never merge into product code): per-draw (VAO, program) pair statistics and the GL entries ++// called between draws, to size the draw-packet cache. Armed by debug.mobilegl.p15count=1 or ++// MOBILEGL_P15_COUNT=1. One log line per 600 presented frames. ++#include ++#include ++#include ++#include ++#include ++#include ++#if defined(__ANDROID__) ++#include ++#endif ++namespace p15count { ++ using MobileGL::Uint64; using MobileGL::Uint32; using MobileGL::SizeT; ++ // categories: 0 free (draw, BindVertexArray, float uniform, UseProgram), 1 int uniform / block binding, ++ // 2 texture/sampler/image bind, 3 buffer bind/data/vertex setup, 4 texture data/params, ++ // 5 render state, 6 framebuffer/clear/blit, 7 other ++ constexpr int kCats = 8; ++ struct Fn { const char* name; int cat; bool draw; bool strictFree; }; ++ inline std::vector& Fns() { static std::vector v; return v; } ++ inline bool On() { ++ static const bool on = [] { ++ const char* e = std::getenv("MOBILEGL_P15_COUNT"); ++ if (e && e[0] == '1') return true; ++#if defined(__ANDROID__) ++ char p[PROP_VALUE_MAX] = {}; ++ if (__system_property_get("debug.mobilegl.p15count", p) > 0 && p[0] == '1') return true; ++#endif ++ return false; ++ }(); ++ return on; ++ } ++ inline bool Pre(const char* n, const char* p) { return std::strncmp(n, p, std::strlen(p)) == 0; } ++ inline bool IsFloatUniform(const char* n) { ++ if (Pre(n, "Program")) n += 7; ++ if (!Pre(n, "Uniform")) return false; ++ n += 7; ++ if (Pre(n, "BlockBinding")) return false; ++ const SizeT l = std::strlen(n); ++ if (l == 0) return false; ++ // ...f / ...fv ++ return n[l - 1] == 'f' || (l >= 2 && n[l - 2] == 'f' && n[l - 1] == 'v'); ++ } ++ inline int Classify(const char* n, bool* draw, bool* strictFree) { ++ *draw = (Pre(n, "Draw") || Pre(n, "MultiDraw")) && !Pre(n, "DrawBuffer"); ++ const bool fu = IsFloatUniform(n); ++ *strictFree = *draw || std::strcmp(n, "BindVertexArray") == 0 || fu; ++ if (*strictFree || std::strcmp(n, "UseProgram") == 0) return 0; ++ if (Pre(n, "Uniform") || Pre(n, "ProgramUniform")) return 1; ++ static const char* tex[] = {"BindTexture", "ActiveTexture", "BindSampler", "BindTextureUnit", "BindImageTexture"}; ++ for (auto* t : tex) if (Pre(n, t)) return 2; ++ static const char* buf[] = {"BindBuffer", "BufferSubData", "BufferData", "NamedBuffer", "MapBuffer", "MapNamedBuffer", ++ "UnmapBuffer", "UnmapNamedBuffer", "FlushMapped", "VertexAttrib", "EnableVertexAttrib", ++ "DisableVertexAttrib", "BindVertexBuffer", "VertexBindingDivisor", "VertexArray", ++ "EnableVertexArrayAttrib", "DisableVertexArrayAttrib", "CopyBufferSubData", "ClearBuffer"}; ++ for (auto* t : buf) if (Pre(n, t)) return 3; ++ static const char* td[] = {"TexImage", "TexSubImage", "TexParameter", "TextureParameter", "TexStorage", "TextureStorage", ++ "TextureSubImage", "GenerateMipmap", "GenerateTextureMipmap", "CopyTex", "CompressedTex", "PixelStore"}; ++ for (auto* t : td) if (Pre(n, t)) return 4; ++ static const char* rs[] = {"Enable", "Disable", "Blend", "Depth", "ColorMask", "CullFace", "FrontFace", "Polygon", "Scissor", ++ "Viewport", "Stencil", "LineWidth", "PointSize", "SampleCoverage", "LogicOp", "ClipControl", ++ "PrimitiveRestart", "ProvokingVertex", "PatchParameter", "MinSampleShading", "SampleMask"}; ++ for (auto* t : rs) if (Pre(n, t)) return 5; ++ static const char* fb[] = {"BindFramebuffer", "Framebuffer", "NamedFramebuffer", "DrawBuffer", "ReadBuffer", "Clear", "Blit", ++ "ReadPixels", "BindRenderbuffer", "Renderbuffer", "InvalidateFramebuffer", "InvalidateSubFramebuffer"}; ++ for (auto* t : fb) if (Pre(n, t)) return 6; ++ return 7; ++ } ++ struct PairState { Uint64 lastFrame = ~0ull; Uint64 epoch[kCats] = {}; Uint64 strictEpoch = 0; Uint64 lastDraw = 0; }; ++ struct St { ++ Uint64 frame = 0, frames = 0, draws = 0, calls = 0; ++ Uint64 epoch[kCats] = {}; // epoch[k] bumps on any call with category > k (k = allowed max category) ++ Uint64 strictEpoch = 0; // bumps on anything outside {draw, BindVertexArray, float uniform} ++ Uint64 gapMask = 0; // categories since the previous draw ++ bool gapStrictDirty = false; ++ std::vector gapFns; std::vector gapStamp; Uint64 gapGen = 1; ++ std::vector fnGapDraws; // draws whose gap included fn ++ std::vector fnCalls; ++ std::unordered_map pairs; // key: vao lifetime * 2^24 ^ program lifetime ++ std::unordered_map pairsThisFrame; ++ Uint64 prevPair = ~0ull; ++ Uint64 sameAsPrev = 0, seenThisFrame = 0, seenPrevFrame = 0, newEver = 0, distinctFrameSum = 0; ++ Uint64 hit[kCats] = {}, strictHit = 0, prevDrawClean[kCats] = {}, prevDrawStrictClean = 0; ++ Uint64 maskHist[256] = {}; ++ Uint64 vaoZero = 0, progZero = 0; ++ }; ++ inline St& S() { static St s; return s; } ++ inline int Reg(const char* name) { ++ bool d, sf; const int c = Classify(name, &d, &sf); ++ Fns().push_back({name, c, d, sf}); ++ auto& s = S(); s.gapStamp.push_back(0); s.fnGapDraws.push_back(0); s.fnCalls.push_back(0); ++ return static_cast(Fns().size() - 1); ++ } ++ inline void Hit(int idx) { ++ if (!On()) return; ++ auto& s = S(); const Fn& f = Fns()[idx]; ++ ++s.calls; ++s.fnCalls[idx]; ++ if (!f.draw) { ++ for (int k = 0; k < f.cat; ++k) ++s.epoch[k]; ++ if (!f.strictFree) { ++s.strictEpoch; s.gapStrictDirty = true; } ++ s.gapMask |= 1ull << f.cat; ++ if (f.cat != 0 && s.gapStamp[idx] != s.gapGen) { s.gapStamp[idx] = s.gapGen; s.gapFns.push_back(idx); } ++ return; ++ } ++ // a draw: read the bound VAO and program before it runs ++ auto* ctx = MobileGL::MG_State::pGLContext.get(); ++ if (!ctx) return; ++ const auto& vao = ctx->GetBoundVertexArray(); ++ const auto& prog = ctx->GetCurrentProgram(); ++ const Uint64 v = vao ? vao->GetLifetimeId() : 0, p = prog ? prog->GetLifetimeId() : 0; ++ if (!v) ++s.vaoZero; ++ if (!p) ++s.progZero; ++ const Uint64 key = (v << 24) ^ p; ++ ++s.draws; ++ if (key == s.prevPair) ++s.sameAsPrev; ++ s.prevPair = key; ++ auto [fit, fnew] = s.pairsThisFrame.emplace(key, 1); ++ if (!fnew) { ++s.seenThisFrame; ++fit->second; } ++ auto [it, isNew] = s.pairs.try_emplace(key); ++ PairState& ps = it->second; ++ if (isNew) ++s.newEver; ++ else { ++ if (ps.lastFrame + 1 == s.frame || ps.lastFrame == s.frame) ++s.seenPrevFrame; ++ for (int k = 0; k < kCats; ++k) if (ps.epoch[k] == s.epoch[k]) ++s.hit[k]; ++ if (ps.strictEpoch == s.strictEpoch) ++s.strictHit; ++ } ++ for (int k = 0; k < kCats; ++k) ps.epoch[k] = s.epoch[k]; ++ ps.strictEpoch = s.strictEpoch; ps.lastFrame = s.frame; ++ // gap since previous draw ++ int maxCat = 0; for (int k = 0; k < kCats; ++k) if (s.gapMask >> k & 1) maxCat = k; ++ for (int k = 0; k < kCats; ++k) if (maxCat <= k) ++s.prevDrawClean[k]; ++ if (!s.gapStrictDirty) ++s.prevDrawStrictClean; ++ ++s.maskHist[s.gapMask & 255]; ++ for (Uint32 i : s.gapFns) ++s.fnGapDraws[i]; ++ s.gapFns.clear(); ++s.gapGen; s.gapMask = 0; s.gapStrictDirty = false; ++ } ++ inline void Frame() { ++ if (!On()) return; ++ auto& s = S(); ++ s.distinctFrameSum += s.pairsThisFrame.size(); ++ s.pairsThisFrame.clear(); ++ ++s.frame; ++s.frames; ++ static const Uint64 kWin = [] { const char* w = std::getenv("MOBILEGL_P15_COUNT_WINDOW"); return w ? std::strtoull(w, nullptr, 10) : 600ull; }(); ++ if (s.frames < kWin) return; ++ const double F = double(s.frames), D = s.draws ? double(s.draws) : 1.0; ++ MGLOG_I("P15CNT frames=%.0f draws/frame=%.1f glcalls/frame=%.1f distinctPairs/frame=%.1f pairsEver=%zu newPairs/frame=%.2f " ++ "sameAsPrev=%.1f%% seenThisFrame=%.1f%% seenPrevOrThisFrame=%.1f%% vao0=%.1f%% prog0=%.1f%%", ++ F, D / F, double(s.calls) / F, double(s.distinctFrameSum) / F, s.pairs.size(), double(s.newEver) / F, ++ 100.0 * s.sameAsPrev / D, 100.0 * s.seenThisFrame / D, 100.0 * s.seenPrevFrame / D, 100.0 * s.vaoZero / D, ++ 100.0 * s.progZero / D); ++ MGLOG_I("P15CNT strict(draw+BindVAO+floatUniform): pairEpochHit=%.1f%% prevDrawGapClean=%.1f%%", 100.0 * s.strictHit / D, ++ 100.0 * s.prevDrawStrictClean / D); ++ for (int k = 0; k < kCats; ++k) ++ MGLOG_I("P15CNT allow<=cat%d: pairEpochHit=%.1f%% prevDrawGapClean=%.1f%%", k, 100.0 * s.hit[k] / D, ++ 100.0 * s.prevDrawClean[k] / D); ++ // top gap masks ++ std::vector> mh; ++ for (int m = 0; m < 256; ++m) if (s.maskHist[m]) mh.push_back({s.maskHist[m], m}); ++ std::sort(mh.rbegin(), mh.rend()); ++ char line[1200]; int o = 0; ++ for (SizeT i = 0; i < mh.size() && i < 14 && o < 1100; ++i) o += std::snprintf(line + o, sizeof line - o, " %02x:%.1f%%", mh[i].second, 100.0 * mh[i].first / D); ++ MGLOG_I("P15CNT gapMasks(bit=cat):%s", line); ++ std::vector> fg; ++ for (SizeT i = 0; i < s.fnGapDraws.size(); ++i) if (s.fnGapDraws[i]) fg.push_back({s.fnGapDraws[i], int(i)}); ++ std::sort(fg.rbegin(), fg.rend()); ++ o = 0; ++ for (SizeT i = 0; i < fg.size() && i < 24 && o < 1100; ++i) ++ o += std::snprintf(line + o, sizeof line - o, " %s(c%d):%.1f%%", Fns()[fg[i].second].name, Fns()[fg[i].second].cat, 100.0 * fg[i].first / D); ++ MGLOG_I("P15CNT gapFns(%% of draws):%s", line); ++ std::vector> fc; ++ for (SizeT i = 0; i < s.fnCalls.size(); ++i) if (s.fnCalls[i]) fc.push_back({s.fnCalls[i], int(i)}); ++ std::sort(fc.rbegin(), fc.rend()); ++ o = 0; ++ for (SizeT i = 0; i < fc.size() && i < 30 && o < 1100; ++i) ++ o += std::snprintf(line + o, sizeof line - o, " %s:%.1f", Fns()[fc[i].second].name, double(fc[i].first) / F); ++ MGLOG_I("P15CNT calls/frame:%s", line); ++ // reset window counters (keep pair table and epochs) ++ s.frames = s.draws = s.calls = 0; s.sameAsPrev = s.seenThisFrame = s.seenPrevFrame = s.newEver = s.distinctFrameSum = 0; ++ s.strictHit = s.prevDrawStrictClean = s.vaoZero = s.progZero = 0; ++ for (int k = 0; k < kCats; ++k) s.hit[k] = s.prevDrawClean[k] = 0; ++ for (auto& m : s.maskHist) m = 0; ++ for (auto& x : s.fnGapDraws) x = 0; ++ for (auto& x : s.fnCalls) x = 0; ++ } ++} ++extern "C++" void P15CountFrame() { p15count::Frame(); } diff --git a/tools/device_bench/disagg/sfalign.py b/tools/device_bench/disagg/sfalign.py new file mode 100644 index 00000000..28f62875 --- /dev/null +++ b/tools/device_bench/disagg/sfalign.py @@ -0,0 +1,26 @@ +# sfalign.py : does SF's setTransactionState return right after SF main-thread flushTransactions? +import re, sys, bisect +from collections import defaultdict +line_re = re.compile(r'^\s*(.+?)-(\d+)\s+\(\s*([\d-]+)\)\s+\[(\d+)\]\s+\S+\s+([\d.]+):\s+tracing_mark_write:\s*(.*)$') +st = defaultdict(list); ends = []; flush = []; begins = [] +for line in open(sys.argv[1], errors="replace"): + m = line_re.match(line) + if not m: continue + comm, pid, tgid, cpu, ts, rest = m.groups(); ts = float(ts) + if tgid.strip() != "1645": continue + if rest.startswith("B|"): + n = rest.split("|", 2)[2]; st[pid].append((n, ts)) + if n.startswith("TransactionHandler:flushTransactions"): flush.append(ts) + elif rest.startswith("E|") and st[pid]: + n, s = st[pid].pop() + if n == "setTransactionState": ends.append(ts); begins.append(s) +flush.sort(); d = []; w = [] +for b, e in zip(begins, ends): + i = bisect.bisect_right(flush, e) - 1 + if i >= 0: d.append(1e3 * (e - flush[i])) + j = bisect.bisect_right(flush, b) + w.append(1e3 * (e - b)) +d.sort(); w.sort() +q = lambda a, p: a[int(p * (len(a) - 1))] +print(f"setTransactionState n={len(d)} duration ms p10/50/90 {q(w,.1):.2f}/{q(w,.5):.2f}/{q(w,.9):.2f}") +print(f"end - last flushTransactions ms p10/50/90 {q(d,.1):.3f}/{q(d,.5):.3f}/{q(d,.9):.3f}; flush period {1e3*(flush[-1]-flush[0])/(len(flush)-1):.2f} ms") diff --git a/tools/device_bench/disagg/slices.py b/tools/device_bench/disagg/slices.py new file mode 100644 index 00000000..e438c5e7 --- /dev/null +++ b/tools/device_bench/disagg/slices.py @@ -0,0 +1,16 @@ +# slices.py : atrace slice wall time per slice name for threads whose comm-pid matches +import re, sys +from collections import Counter, defaultdict +line_re = re.compile(r'^\s*(.+?)-(\d+)\s+\(\s*([\d-]+)\)\s+\[(\d+)\]\s+\S+\s+([\d.]+):\s+tracing_mark_write:\s*(.*)$') +rx = re.compile(sys.argv[2]); stacks = defaultdict(list); tot = Counter(); cnt = Counter(); t0 = t1 = None +for line in open(sys.argv[1], errors="replace"): + m = line_re.match(line) + if not m: continue + comm, pid, tgid, cpu, ts, rest = m.groups(); ts = float(ts) + t0 = ts if t0 is None else t0; t1 = ts + if not rx.search(comm + "-" + pid): continue + if rest.startswith("B|"): + stacks[pid].append((rest.split("|", 2)[2][:70], ts)) + elif rest.startswith("E|") and stacks[pid]: + n, s = stacks[pid].pop(); tot[n] += ts - s; cnt[n] += 1 +for k, v in tot.most_common(25): print(f"{1e3*v:9.1f} ms n={cnt[k]:6d} avg {1e6*v/cnt[k]:8.1f} us {k}") diff --git a/tools/device_bench/disagg/snapdiff.py b/tools/device_bench/disagg/snapdiff.py new file mode 100644 index 00000000..5dee54c9 --- /dev/null +++ b/tools/device_bench/disagg/snapdiff.py @@ -0,0 +1,16 @@ +import sys +def rd(p): + L=open(p).read().split('\n'); up=float(L[0].split()[0]); gpu=sum(int(x) for x in L[1].split()) + T={} + for l in L[2:]: + f=l.split() + if len(f)>=5 and f[0]=='T': T[f[1]]=(int(f[2]),int(f[3]),int(f[4]),' '.join(f[5:])) + return up,gpu,T +a=rd(sys.argv[1]); b=rd(sys.argv[2]); wall=b[0]-a[0] +print(f"wall {wall:.2f}s gpu_clock_stats delta {(b[1]-a[1])/1e6:.3f} (units?) per wall-s {(b[1]-a[1])/wall/1e6:.3f}") +rows=[] +for k,v in b[2].items(): + if k in a[2]: + u=a[2][k]; rows.append(((v[0]-u[0])/1e6,(v[1]-u[1])/1e6,v[2]-u[2],v[3],k)) +rows.sort(reverse=True) +for r in rows[:12]: print(f"{r[3]:<22} tid {r[4]:>6} cpu {r[0]:8.1f} ms ({100*r[0]/1e3/wall:5.1f}%) runq-wait {r[1]:7.1f} ms switches {r[2]}")