bench: the felis CPU split in the resource-use tables disagrees with #397's measurement #398
Labels
No labels
priority/P0
priority/P1
priority/P2
release/v0.1.0
status/blocked
status/planned
type/bug
type/design
type/test-gap
type/tracker
No milestone
No project
No assignees
1 participant
Due date
No due date set.
Dependencies
No dependencies set
Reference
natsukium/felis#398
Loading…
Reference in a new issue
No description provided.
Delete branch "%!s()"
Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?
The published resource-use tables (
docs/reference/benchmarks.md, both platforms, felis9d1d842f) 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.pyleg_processeschargesleg.pidas the client.field.pylaunchesfelis_bin; confirm that pid is the process that renders (thefelisCLI execsfelis-clienton Unix, so it should be).usage.pytakes 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.
Linux measurement (kilimanjaro, i5-12400F, NVIDIA RTX via Vulkan, niri, 3440x1440 @ 59.99 Hz, scale 1). felis built from
mainef96bb46(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 …, insidenix develop .#bench):felis.res.json(usage.py,leg_processes);/proc/<pid>/statand/proc/<pid>/task/*/statonce a second for everyfelis-client/felis-daemonnot on the user's socket, plusniri msg --json windowsfor the window state.The pid is right:
leg.pidis the process whosecommisfelis-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
GRID_ROWS=35 GRID_COLS=106), round 19d1d842f), 3 roundsManual runs: my own
felis-daemon serve --socketand client, empty$HOME/$XDG_CONFIG_HOME, 5 s DOOM-fire warm-up, then/proc/<pid>/statutime+stimeread 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
/procread 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:
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-driverwith NVIDIA userland 595.104.02 while the loaded kernel module is 595.99.02 (NVRM: API mismatchin 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 inllvmpipe-*threads during vtebench. The runs above were taken before that time. My later GUI runs pin the old ICD withVK_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; awarn!whenadapter.get_info().device_type == DeviceType::Cpuwould have caught it.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 logrecords "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.9d1d842fsuites.suite_doom_fire+usage.Sampler, felis only, FloatingPin)9d1d842fps -o time, same config9d1d842f9d1d842f9d1d842f9d1d842fa577fee0a577fee0ps -o timereading agree to 0.01 s (2.33 against 2.33-2.34).felisexecsfelis-client(crates/felis-cli/src/main.rs:803-804), and in every run the pid the harness charges as client equals thefelis-clientpid bound to the socket.956d8378) has the sameon_redrawas9d1d842f.Mechanism
A local, uncommitted probe (per-second counts of
renderer.renderoutcomes inon_redraw) shows what the client does when the window cannot present:SurfaceError::Timeout, 0.17 ms each.Timeout.crates/felis-client/src/event_handler.rs:1235logs the timeout and skips the frame. Line 1258 then sendsInputMsg::NextGridFramewhether 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
SurfaceError::Timeout, back off instead of re-arming at once, either untilWindowEvent::Occluded(false)or on a timer at the refresh interval. Unverified: whether an unlocked but fully occluded or minimized window also takes theTimeoutpath. I could not test that tonight.ioreg -n Root -d1,CGSSessionScreenIsLocked/IOConsoleLocked) and display sleep (system_profiler SPDisplaysDataType, "Display Asleep") inenvinfo.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.partsare 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)
parts: client peak 440 MB, daemon 5 MB. The peak is the client's.vmmap -summaryseries 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.phys_footprintsampled viaproc_pid_rusage, 1 s apart).a577fee0stays flat at 16.9 MB in the same state. #396 (per-frame blits dropped on unified-memory GPUs) appears to have removed that accumulation.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).