fabi/Sylpheed
1
0
Fork 0
Code Issues 9 Pull Requests Actions Packages Projects Releases Wiki Activity

docs: logging the wait target is blocked by the flag's own cost

Browse Source 
KeWaitForSingleObject is kHighFrequency, so it is silent unless
--log_high_frequency_kernel_calls=true - which confirms the corpus's earlier
"kHighFrequency waits are simply unlogged" note. With the flag the calls do
appear (1944 lines in 40 s), but the emulator slows so far that after SEVENTEEN
minutes the screen was still black and skip_intro had not seen even the intro
movie, with 175 MB of log written. A 2400 s boot budget did not help; the boot
was not going to finish.

Recorded with the numbers so nobody pays them twice, along with the two cheaper
routes: a targeted Canary log line that fires only after a wait has timed out N
times on the same thread (self-selecting, free on a healthy run, one small patch
plus a build that is already configured), or digging the PPCContext out of a
stack frame under gdb - possible but fragile, since the Release binary has symtab
only and no DWARF.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01PMRJjbxLqZtsb5Vb7KunPE
This commit is contained in:
Sylpheed RE agent
2026-08-24 01:49:05 +00:00
parent 99d94146b4
commit 80dc6352b6
1 changed files with 35 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files

35
docs/re/mission-freeze-resume-spin.md
View File

@@ -301,3 +301,38 @@ through short timed waits.
the handle is an argument to `KeWaitForSingleObject`, one `info args`-equivalent
away now that a debugger can be attached at will — and find who was supposed to
signal it.
## 🔴 2026-08-24 — reading the wait target from the log does not work: the flag is too expensive
The obvious next move — find *which* object those two threads wait on by logging
`KeWaitForSingleObject` — is **blocked by its own cost**, and the numbers are
worth recording so nobody pays them twice.
`KeWaitForSingleObject` is declared `kHighFrequency`
(`xboxkrnl_threading.cc`, `DECLARE_XBOXKRNL_EXPORT3(..., kHighFrequency)`), and
`shim_utils.h` suppresses those unless `--log_high_frequency_kernel_calls=true`.
That flag exists, so it was tried:
| | without the flag | with it |
|---|---|---|
| `KeWaitForSingleObject` lines | **0** (the corpus's "kHighFrequency waits are simply unlogged" note, confirmed) | 1 944 in the first 40 s |
| log growth | ~1 MB / 25 s | **157 MB in 10 minutes**, 175 MB in 17 |
| boot progress | title in ~3 min | **17 minutes and the screen was still BLACK** — not even the intro movie, 0 `movie` probes from `skip_intro` |
So the flag does not merely add volume, it slows the emulator past usability:
the first attempt was scored `BOOT FAILED` purely because `skip_intro`'s fixed
600 s budget expired. That is now a knob (`SKIP_INTRO_TIMEOUT`), and
`EXTRA_FLAGS` passes one-off cvars — but a 2 400 s budget did not help either,
because the boot was not going to finish.
**What to do instead, in order of cost:**
1. **A targeted log line in Canary.** Log the object pointer only when a wait has
already timed out N times on the same thread — the freeze's signature is a
wait that expires and re-enters, so a counter makes it self-selecting and
costs nothing on a healthy run. One small patch plus a `build-canary`, and the
build is already configured.
2. **gdb, reading the shim argument.** A debugger can be attached at will now, but
the Release binary has **no DWARF** (`No debugging symbols found` — symtab
only), so `info args` is unavailable and the `PPCContext*` would have to be
dug out of a stack frame by hand. Fragile, but free.