bench: the felis CPU split in the resource-use tables disagrees with #397's measurement #398

Closed
opened 2026-09-25 01:34:54 +09:00 by natsukium · 3 comments
Owner

The published resource-use tables (docs/reference/benchmarks.md, both platforms, felis 9d1d842f) say "The daemon accounts for 95% or more of felis's time in every workload." #397 measured 10 s of DOOM-fire on an M4 Max with the same default config and found the client at 7.9-8.1 s of CPU against the daemon's 17.8-17.9 s, about 30% client.

Both cannot hold for the same workload. Which one is right decides where CPU work pays off: if the harness is right, #397's win does not reach the published table; if #397 is right, the harness undercounts the client.

Candidates to check:

  • tools/bench/suites.py leg_processes charges leg.pid as the client. field.py launches felis_bin; confirm that pid is the process that renders (the felis CLI execs felis-client on Unix, so it should be).
  • The harness's window state during the pass: floating, focused, occluded, or on another workspace changes whether the client paints at all.
  • usage.py takes readings every 0.25 s and subtracts the first from the last; a client whose accounting read fails would drop the whole leg, not return zero, so a silent undercount would need another cause.

Done when one measurement method is shown to be wrong and fixed, and the resource-use prose states a split that both methods reproduce.

The published resource-use tables (`docs/reference/benchmarks.md`, both platforms, felis `9d1d842f`) say "The daemon accounts for 95% or more of felis's time in every workload." #397 measured 10 s of DOOM-fire on an M4 Max with the same default config and found the client at 7.9-8.1 s of CPU against the daemon's 17.8-17.9 s, about 30% client. Both cannot hold for the same workload. Which one is right decides where CPU work pays off: if the harness is right, #397's win does not reach the published table; if #397 is right, the harness undercounts the client. Candidates to check: - `tools/bench/suites.py` `leg_processes` charges `leg.pid` as the client. `field.py` launches `felis_bin`; confirm that pid is the process that renders (the `felis` CLI execs `felis-client` on Unix, so it should be). - The harness's window state during the pass: floating, focused, occluded, or on another workspace changes whether the client paints at all. - `usage.py` takes readings every 0.25 s and subtracts the first from the last; a client whose accounting read fails would drop the whole leg, not return zero, so a silent undercount would need another cause. Done when one measurement method is shown to be wrong and fixed, and the resource-use prose states a split that both methods reproduce.
Author
Owner

Linux measurement (kilimanjaro, i5-12400F, NVIDIA RTX via Vulkan, niri, 3440x1440 @ 59.99 Hz, scale 1). felis built from main ef96bb46 (release, line tables). Load average (1 min) is given with every figure; the host was also running CI.

Both methods agree on Linux

Two independent readings of the same harness pass (crossterm.py run doom-fire --terminals foot --felis-bin …, inside nix develop .#bench):

  • the harness's felis.res.json (usage.py, leg_processes);
  • a separate poller reading /proc/<pid>/stat and /proc/<pid>/task/*/stat once a second for every felis-client/felis-daemon not on the user's socket, plus niri msg --json windows for the window state.
pass (load) grid harness client / daemon /proc poller client / daemon
DOOM-fire 20 s (4.4 → 6.2) 188x82 3.64 / 24.19 s 3.62 / 23.95 s
vtebench, all rows (2.6 → 4.9) 106x35 4.95 / 124.04 s 4.92 / 123.87 s

The pid is right: leg.pid is the process whose comm is felis-client (the CLI execs it in place), and the daemon is the one bound to the leg's socket. For the whole pass the window was floating, focused, and on the visible workspace (niri reported the same state at every one of the 20 and 109 polls), so the harness is not measuring an occluded client.

What sets the split: grid size and whether the window is shown

run load grid client daemon client share
harness DOOM-fire, published pin (GRID_ROWS=35 GRID_COLS=106), round 1 3.2 106x35 1.52 s 25.28 s 5.7%
same, round 2 5.1 106x35 1.56 s 25.63 s 5.7%
published run (9d1d842f), 3 rounds 3.6 106x35 1.09-1.11 s 30.4-30.7 s 3.5%
harness DOOM-fire, no grid pin 4.4 188x82 3.64 s 24.19 s 13.1%
manual, default config, tiled, focused 4.7 188x93 3.23 s 28.34 s 10.2%
same, repeat 3.9 188x93 3.23 s 28.11 s 10.3%
manual, focus moved to another window (still visible) 8.0 188x93 3.39 s 27.94 s 10.8%
manual, window moved to another workspace 6.5 188x93 0.08 s 25.76 s 0.3%

Manual runs: my own felis-daemon serve --socket and client, empty $HOME/$XDG_CONFIG_HOME, 5 s DOOM-fire warm-up, then /proc/<pid>/stat utime+stime read at the wrapper's start and end markers of a 20 s DOOM-fire pass.

At the display rate (59.99 Hz, about 1200 frames in 20 s) the client's main thread costs about 1.3 ms per frame at 3,710 cells and 2.7-2.9 ms per frame at 15-17k cells. The daemon's cost does not grow with the grid the same way, so the client's share roughly doubles between the published pin and a default-sized window. Off-screen the client stops painting and its share drops to zero.

Conclusion

On Linux neither method is wrong. The harness reads the right pids with the right counters, and a direct /proc read over the same window gives the same seconds. "The daemon accounts for 95% or more of felis's time in every workload" is true only for the harness's pinned 106x35 grid on a 60 Hz output. With a default-sized window, felis's client uses 10-13% on this machine. #397's 30% on the M4 Max comes from its default window (Retina, and probably 120 Hz); the harness pins neither of those, so the macOS lane has to check that part.

Proposed fix:

  1. Change the resource-use prose on both platforms so it states the split at the pinned grid (Linux DOOM-fire: client 3.5-5.7%, vtebench 3.8-5.4%) and says that the client's share grows with window area and refresh rate, instead of "95% or more in every workload".
  2. Harness: record the output refresh rate and the window's visible/focused state in meta.json / <name>.res.json. That makes a pass where the window was hidden, and so did not paint, visible in the data.

Host condition that affects every later GUI figure

At 02:03:50 JST a system switch replaced /run/opengl-driver with NVIDIA userland 595.104.02 while the loaded kernel module is 595.99.02 (NVRM: API mismatch in the kernel log for every new Vulkan client). Since then the NVIDIA ICD reports no physical devices, and wgpu silently picks lavapipe (llvmpipe). A felis client then burns about 12 cores in llvmpipe-* threads during vtebench. The runs above were taken before that time. My later GUI runs pin the old ICD with VK_DRIVER_FILES=/nix/store/qavh820laayfcch9wah7dpqnl1l5g1kr-graphics-drivers/share/vulkan/icd.d/nvidia_icd.json (the driver niri itself has loaded). Any GUI benchmark on this host needs a reboot or that pin until then. felis gave no warning that it was running on a CPU adapter; a warn! when adapter.get_info().device_type == DeviceType::Cpu would have caught it.

Linux measurement (kilimanjaro, i5-12400F, NVIDIA RTX via Vulkan, niri, 3440x1440 @ 59.99 Hz, scale 1). felis built from `main` ef96bb46 (release, line tables). Load average (1 min) is given with every figure; the host was also running CI. ## Both methods agree on Linux Two independent readings of the same harness pass (`crossterm.py run doom-fire --terminals foot --felis-bin …`, inside `nix develop .#bench`): - the harness's `felis.res.json` (`usage.py`, `leg_processes`); - a separate poller reading `/proc/<pid>/stat` and `/proc/<pid>/task/*/stat` once a second for every `felis-client`/`felis-daemon` not on the user's socket, plus `niri msg --json windows` for the window state. | pass (load) | grid | harness client / daemon | /proc poller client / daemon | |---|---|---|---| | DOOM-fire 20 s (4.4 → 6.2) | 188x82 | 3.64 / 24.19 s | 3.62 / 23.95 s | | vtebench, all rows (2.6 → 4.9) | 106x35 | 4.95 / 124.04 s | 4.92 / 123.87 s | The pid is right: `leg.pid` is the process whose `comm` is `felis-client` (the CLI execs it in place), and the daemon is the one bound to the leg's socket. For the whole pass the window was floating, focused, and on the visible workspace (niri reported the same state at every one of the 20 and 109 polls), so the harness is not measuring an occluded client. ## What sets the split: grid size and whether the window is shown | run | load | grid | client | daemon | client share | |---|---|---|---|---|---| | harness DOOM-fire, published pin (`GRID_ROWS=35 GRID_COLS=106`), round 1 | 3.2 | 106x35 | 1.52 s | 25.28 s | 5.7% | | same, round 2 | 5.1 | 106x35 | 1.56 s | 25.63 s | 5.7% | | published run (9d1d842f), 3 rounds | 3.6 | 106x35 | 1.09-1.11 s | 30.4-30.7 s | 3.5% | | harness DOOM-fire, no grid pin | 4.4 | 188x82 | 3.64 s | 24.19 s | 13.1% | | manual, default config, tiled, focused | 4.7 | 188x93 | 3.23 s | 28.34 s | 10.2% | | same, repeat | 3.9 | 188x93 | 3.23 s | 28.11 s | 10.3% | | manual, focus moved to another window (still visible) | 8.0 | 188x93 | 3.39 s | 27.94 s | 10.8% | | manual, window moved to another workspace | 6.5 | 188x93 | 0.08 s | 25.76 s | 0.3% | Manual runs: my own `felis-daemon serve --socket` and client, empty `$HOME`/`$XDG_CONFIG_HOME`, 5 s DOOM-fire warm-up, then `/proc/<pid>/stat` `utime+stime` read at the wrapper's start and end markers of a 20 s DOOM-fire pass. At the display rate (59.99 Hz, about 1200 frames in 20 s) the client's main thread costs about 1.3 ms per frame at 3,710 cells and 2.7-2.9 ms per frame at 15-17k cells. The daemon's cost does not grow with the grid the same way, so the client's share roughly doubles between the published pin and a default-sized window. Off-screen the client stops painting and its share drops to zero. ## Conclusion On Linux neither method is wrong. The harness reads the right pids with the right counters, and a direct `/proc` read over the same window gives the same seconds. "The daemon accounts for 95% or more of felis's time in every workload" is true only for the harness's pinned 106x35 grid on a 60 Hz output. With a default-sized window, felis's client uses 10-13% on this machine. #397's 30% on the M4 Max comes from its default window (Retina, and probably 120 Hz); the harness pins neither of those, so the macOS lane has to check that part. Proposed fix: 1. Change the resource-use prose on both platforms so it states the split at the pinned grid (Linux DOOM-fire: client 3.5-5.7%, vtebench 3.8-5.4%) and says that the client's share grows with window area and refresh rate, instead of "95% or more in every workload". 2. Harness: record the output refresh rate and the window's visible/focused state in `meta.json` / `<name>.res.json`. That makes a pass where the window was hidden, and so did not paint, visible in the data. ## Host condition that affects every later GUI figure At 02:03:50 JST a system switch replaced `/run/opengl-driver` with NVIDIA userland 595.104.02 while the loaded kernel module is 595.99.02 (`NVRM: API mismatch` in the kernel log for every new Vulkan client). Since then the NVIDIA ICD reports no physical devices, and wgpu silently picks lavapipe (llvmpipe). A felis client then burns about 12 cores in `llvmpipe-*` threads during vtebench. The runs above were taken before that time. My later GUI runs pin the old ICD with `VK_DRIVER_FILES=/nix/store/qavh820laayfcch9wah7dpqnl1l5g1kr-graphics-drivers/share/vulkan/icd.d/nvidia_icd.json` (the driver niri itself has loaded). Any GUI benchmark on this host needs a reboot or that pin until then. felis gave no warning that it was running on a CPU adapter; a `warn!` when `adapter.get_info().device_type == DeviceType::Cpu` would have caught it.
Author
Owner

macOS (M4 Max, LG 3440x1440 at 60 Hz): the harness is right, and #397 measured a window that could not present

Verdict

The harness charges the right process and its sampler agrees with a manual reading. The two figures differ because of window state. #397's runs (about 01:06-01:36 on Sep 25) fell inside a period when the display was off: pmset -g log records "Display is turned off" at 00:46:27 and "turned on" at 01:56:04. A window that cannot present puts the client into a pull loop that vsync no longer paces. The published run was taken with the display on (on 19:02, off 21:03; DOOM-fire legs finished at 19:38, 20:11 and 20:42). Its split, with the client at 2-5% of felis's CPU, is what a presenting window costs. The "95% or more" sentence holds for that state.

Figures

DOOM-fire, CPU seconds per 10 s of measured pass, 35x106 grid (Menlo 14, features = []) unless noted. All of tonight's runs were taken with the screen locked (CGSSessionScreenIsLocked=Yes; I cannot unlock it), so none of them presents a frame.

Run Binary Display client daemon fps load avg (1 min)
published harness, 3 rounds (20 s, halved) 9d1d842f on, unlocked 0.43-0.45 16.2-16.3 2,751-2,761 2.36 before, 3.16 after (round 1)
harness code path (suites.suite_doom_fire + usage.Sampler, felis only, FloatingPin) 9d1d842f asleep 2.33 16.91 2,732 1.79 → 1.68
manual ps -o time, same config 9d1d842f asleep 2.33-2.34 16.78-16.94 2,716-2,754 2.66-3.03
manual, the user's config (Moralerspace + 7 features, 33x120) 9d1d842f asleep 3.55-4.57 16.0-17.2 2,448-2,486 2.6-3.0
manual 9d1d842f awake, locked 7.31 17.94 2,463 1.58-1.87
manual, the user's config 9d1d842f awake, locked 7.31 17.80 2,287 1.80-2.21
manual + frame probe main a577fee0 awake, locked 6.88 17.85 2,160 4.60
manual + frame probe main a577fee0 asleep 1.41-1.87 16.4-16.7 2,523-2,784 2.7-4.1
  • In the same state, the harness's sampler and a manual ps -o time reading agree to 0.01 s (2.33 against 2.33-2.34).
  • The launch pid is the renderer: felis execs felis-client (crates/felis-cli/src/main.rs:803-804), and in every run the pid the harness charges as client equals the felis-client pid bound to the socket.
  • The daemon costs about the same in every state (16-18 s per 10 s). Only the client moves, by a factor of up to 16.
  • #397's 7.9-8.0 s client figure falls within the non-presenting range measured here. Its build (base 956d8378) has the same on_redraw as 9d1d842f.

Mechanism

A local, uncommitted probe (per-second counts of renderer.render outcomes in on_redraw) shows what the client does when the window cannot present:

  • Display awake, screen locked: 2,035-2,125 render attempts/s, 0 painted, every one SurfaceError::Timeout, 0.17 ms each.
  • Display asleep: 501-549 attempts/s, 0 painted, all Timeout.

crates/felis-client/src/event_handler.rs:1235 logs the timeout and skips the frame. Line 1258 then sends InputMsg::NextGridFrame whether or not anything was painted. The comment at 1255 assumes that this happens "once per painted frame, which winit drives at vsync". With no blocking present, nothing paces the pull, so the client pulls and decodes grid frames as fast as the acquire fails. The client CPU in #397 measures that loop, not painting. A profile taken in this state (such as #397's glyph-hash share) describes the loop, too.

This is a client bug in its own right. A felis window left under continuous output on a locked Mac or behind a sleeping display burns 0.14-0.73 of a core without drawing anything.

Proposed fix

  1. Client: release the pull only after a frame was presented. On SurfaceError::Timeout, back off instead of re-arming at once, either until WindowEvent::Occluded(false) or on a timer at the refresh interval. Unverified: whether an unlocked but fully occluded or minimized window also takes the Timeout path. I could not test that tonight.
  2. Bench: record the session lock (ioreg -n Root -d1, CGSSessionScreenIsLocked / IOConsoleLocked) and display sleep (system_profiler SPDisplaysDataType, "Display Asleep") in envinfo.leg_env, and refuse or flag a leg taken in either state. Without that, an overnight rerun would publish the non-presenting split with no warning.
  3. Prose: the published macOS split stands. The client shares from the published parts are doom-fire 2.6%, vtebench 2.0%, cat 2.5%, kittenbench 0.6% and termbench 4.7%. #397's saving is real for the non-presenting loop. For a presenting window, 14% of the client's 0.44 s per 10 s is about 0.06 s.

Aside: macOS peak footprint (tracker "not filed" item)

  • Published doom-fire parts: client peak 440 MB, daemon 5 MB. The peak is the client's.
  • An earlier vmmap -summary series on this Mac (display on, Sep 24 23:28, a local release build at that time) put the client at 424.8 MB, of which 387.2 MB was "owned unmapped (graphics)", 0 IOSurface, and only a few MB of malloc. So the peak is Metal/IOAccelerator memory charged to the process, not heap.
  • With the display asleep, 9d1d842f's IOAccelerator region grows about 500 MB/s while every acquire times out. It reached 5.8 GB after 10 s of DOOM-fire, and none of it was released once the flood stopped (phys_footprint sampled via proc_pid_rusage, 1 s apart).
  • main a577fee0 stays flat at 16.9 MB in the same state. #396 (per-frame blits dropped on unified-memory GPUs) appears to have removed that accumulation.
  • Whether the presenting peak also falls on main needs an unlocked rerun of the memory/usage suites.
## macOS (M4 Max, LG 3440x1440 at 60 Hz): the harness is right, and #397 measured a window that could not present ### Verdict The harness charges the right process and its sampler agrees with a manual reading. The two figures differ because of window state. #397's runs (about 01:06-01:36 on Sep 25) fell inside a period when the display was off: `pmset -g log` records "Display is turned off" at 00:46:27 and "turned on" at 01:56:04. A window that cannot present puts the client into a pull loop that vsync no longer paces. The published run was taken with the display on (on 19:02, off 21:03; DOOM-fire legs finished at 19:38, 20:11 and 20:42). Its split, with the client at 2-5% of felis's CPU, is what a presenting window costs. The "95% or more" sentence holds for that state. ### Figures DOOM-fire, CPU seconds per 10 s of measured pass, 35x106 grid (Menlo 14, `features = []`) unless noted. All of tonight's runs were taken with the screen locked (`CGSSessionScreenIsLocked=Yes`; I cannot unlock it), so none of them presents a frame. | Run | Binary | Display | client | daemon | fps | load avg (1 min) | |---|---|---|---|---|---|---| | published harness, 3 rounds (20 s, halved) | 9d1d842f | on, unlocked | 0.43-0.45 | 16.2-16.3 | 2,751-2,761 | 2.36 before, 3.16 after (round 1) | | harness code path (`suites.suite_doom_fire` + `usage.Sampler`, felis only, FloatingPin) | 9d1d842f | asleep | 2.33 | 16.91 | 2,732 | 1.79 → 1.68 | | manual `ps -o time`, same config | 9d1d842f | asleep | 2.33-2.34 | 16.78-16.94 | 2,716-2,754 | 2.66-3.03 | | manual, the user's config (Moralerspace + 7 features, 33x120) | 9d1d842f | asleep | 3.55-4.57 | 16.0-17.2 | 2,448-2,486 | 2.6-3.0 | | manual | 9d1d842f | awake, locked | 7.31 | 17.94 | 2,463 | 1.58-1.87 | | manual, the user's config | 9d1d842f | awake, locked | 7.31 | 17.80 | 2,287 | 1.80-2.21 | | manual + frame probe | main a577fee0 | awake, locked | 6.88 | 17.85 | 2,160 | 4.60 | | manual + frame probe | main a577fee0 | asleep | 1.41-1.87 | 16.4-16.7 | 2,523-2,784 | 2.7-4.1 | - In the same state, the harness's sampler and a manual `ps -o time` reading agree to 0.01 s (2.33 against 2.33-2.34). - The launch pid is the renderer: `felis` execs `felis-client` (`crates/felis-cli/src/main.rs:803-804`), and in every run the pid the harness charges as client equals the `felis-client` pid bound to the socket. - The daemon costs about the same in every state (16-18 s per 10 s). Only the client moves, by a factor of up to 16. - #397's 7.9-8.0 s client figure falls within the non-presenting range measured here. Its build (base 956d8378) has the same `on_redraw` as 9d1d842f. ### Mechanism A local, uncommitted probe (per-second counts of `renderer.render` outcomes in `on_redraw`) shows what the client does when the window cannot present: - Display awake, screen locked: 2,035-2,125 render attempts/s, **0 painted**, every one `SurfaceError::Timeout`, 0.17 ms each. - Display asleep: 501-549 attempts/s, 0 painted, all `Timeout`. `crates/felis-client/src/event_handler.rs:1235` logs the timeout and skips the frame. Line 1258 then sends `InputMsg::NextGridFrame` whether or not anything was painted. The comment at 1255 assumes that this happens "once per painted frame, which winit drives at vsync". With no blocking present, nothing paces the pull, so the client pulls and decodes grid frames as fast as the acquire fails. The client CPU in #397 measures that loop, not painting. A profile taken in this state (such as #397's glyph-hash share) describes the loop, too. This is a client bug in its own right. A felis window left under continuous output on a locked Mac or behind a sleeping display burns 0.14-0.73 of a core without drawing anything. ### Proposed fix 1. Client: release the pull only after a frame was presented. On `SurfaceError::Timeout`, back off instead of re-arming at once, either until `WindowEvent::Occluded(false)` or on a timer at the refresh interval. Unverified: whether an unlocked but fully occluded or minimized window also takes the `Timeout` path. I could not test that tonight. 2. Bench: record the session lock (`ioreg -n Root -d1`, `CGSSessionScreenIsLocked` / `IOConsoleLocked`) and display sleep (`system_profiler SPDisplaysDataType`, "Display Asleep") in `envinfo.leg_env`, and refuse or flag a leg taken in either state. Without that, an overnight rerun would publish the non-presenting split with no warning. 3. Prose: the published macOS split stands. The client shares from the published `parts` are doom-fire 2.6%, vtebench 2.0%, cat 2.5%, kittenbench 0.6% and termbench 4.7%. #397's saving is real for the non-presenting loop. For a presenting window, 14% of the client's 0.44 s per 10 s is about 0.06 s. ### Aside: macOS peak footprint (tracker "not filed" item) - Published doom-fire `parts`: client peak 440 MB, daemon 5 MB. The peak is the client's. - An earlier `vmmap -summary` series on this Mac (display on, Sep 24 23:28, a local release build at that time) put the client at 424.8 MB, of which 387.2 MB was "owned unmapped (graphics)", 0 IOSurface, and only a few MB of malloc. So the peak is Metal/IOAccelerator memory charged to the process, not heap. - With the display asleep, 9d1d842f's IOAccelerator region grows about 500 MB/s while every acquire times out. It reached 5.8 GB after 10 s of DOOM-fire, and none of it was released once the flood stopped (`phys_footprint` sampled via `proc_pid_rusage`, 1 s apart). - main a577fee0 stays flat at 16.9 MB in the same state. #396 (per-frame blits dropped on unified-memory GPUs) appears to have removed that accumulation. - Whether the presenting peak also falls on main needs an unlocked rerun of the memory/usage suites.
Author
Owner

The harness's split is right and the published prose stands (client 0.6-4.7% per workload on macOS); #397 ran with the display off, where the client spins on failed acquires. Details in the comment above. Follow-ups: #407 (client pulls unpaced when it cannot present), #408 (bench records display state).

The harness's split is right and the published prose stands (client 0.6-4.7% per workload on macOS); #397 ran with the display off, where the client spins on failed acquires. Details in the comment above. Follow-ups: #407 (client pulls unpaced when it cannot present), #408 (bench records display state).
Commenting is not possible because the repository is archived.
No description provided.