re: the frozen wait-object capture, and screen_id was never a freeze test
Caught the freeze by waiting for the event (frozen.py + in_flight) instead of sleeping a guessed interval; freeze_waitobj.sh splits into boot/watch so the wait is not capped by one Bash call. Verified hard: a frame minutes later is byte-identical to the capture. Healthy vs frozen, same run: 20 -> 24 wait frames, XEvent 19 -> 23, XSemaphore 8 -> 7. The signature is per-thread -- 17 of 24 threads sit on the exact object they were on, four previously-running threads park, and T74/T75 move off a semaphore onto an event. So the freeze is not a whole-emulator stall. Also corrects the previous entry's test: screen_id reads 'flight' during a freeze by design, which is why frozen.py exists. Re-testing the saved frames says that run was genuinely healthy, but it was right by luck. heavy_read.py added to test whether the instrument provokes the freeze: I/O is free (371 MB in 0.1s, page cache), the cost is Python-level CPU. One data point -- 670s clean, then frozen 54s after the inducer started -- recorded as n=1, not as causation.
This commit is contained in:
Sylpheed RE agent
@@ -1,4 +1,29 @@
|
||||
=== healthy: 23 wait frames ===
|
||||
=== healthy: 20 wait frames ===
|
||||
T106 Wait n=1 xe::kernel::XEvent
|
||||
T104 Wait n=1 xe::kernel::XEvent
|
||||
T97 Wait n=1 xe::kernel::XEvent
|
||||
T96 Wait n=1 xe::kernel::XEvent
|
||||
T80 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
T79 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
T78 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
T77 Wait n=1 xe::kernel::XEvent
|
||||
T76 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XTimer
|
||||
T75 Wait n=1 xe::kernel::XSemaphore
|
||||
T74 Wait n=1 xe::kernel::XSemaphore
|
||||
T71 Wait n=1 xe::kernel::XEvent
|
||||
T66 Wait n=1 xe::kernel::XEvent
|
||||
T65 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
T64 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
T63 Wait n=1 xe::kernel::XSemaphore
|
||||
T62 Wait n=1 xe::kernel::XEvent
|
||||
T61 Wait n=1 xe::kernel::XEvent
|
||||
T50 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XEvent
|
||||
T36 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XEvent
|
||||
--- objects waited on:
|
||||
xe::kernel::XEvent 19
|
||||
xe::kernel::XSemaphore 8
|
||||
xe::kernel::XTimer 1
|
||||
=== frozen: 24 wait frames ===
|
||||
T106 Wait n=1 xe::kernel::XEvent
|
||||
T105 Wait n=1 xe::kernel::XEvent
|
||||
T104 Wait n=1 xe::kernel::XEvent
|
||||
@@ -9,11 +34,12 @@
|
||||
T78 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
T77 Wait n=1 xe::kernel::XEvent
|
||||
T76 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XTimer
|
||||
T75 Wait n=1 xe::kernel::XSemaphore
|
||||
T74 Wait n=1 xe::kernel::XSemaphore
|
||||
T75 Wait n=1 xe::kernel::XEvent
|
||||
T74 Wait n=1 xe::kernel::XEvent
|
||||
T71 Wait n=1 xe::kernel::XEvent
|
||||
T69 Wait n=1 xe::kernel::XSemaphore
|
||||
T68 Wait n=1 xe::kernel::XEvent
|
||||
T67 Wait n=1 xe::kernel::XEvent
|
||||
T66 Wait n=1 xe::kernel::XEvent
|
||||
T65 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
T64 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
@@ -23,35 +49,36 @@
|
||||
T50 Wait n=1 xe::kernel::XEvent
|
||||
T36 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XEvent
|
||||
--- objects waited on:
|
||||
xe::kernel::XEvent 20
|
||||
xe::kernel::XSemaphore 9
|
||||
xe::kernel::XTimer 1
|
||||
=== frozen: 20 wait frames ===
|
||||
T106 Wait n=1 xe::kernel::XEvent
|
||||
T104 Wait n=1 xe::kernel::XEvent
|
||||
T97 Wait n=1 xe::kernel::XEvent
|
||||
T96 Wait n=1 xe::kernel::XEvent
|
||||
T80 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
T79 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
T78 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
T77 Wait n=1 xe::kernel::XEvent
|
||||
T76 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XTimer
|
||||
T75 Wait n=1 xe::kernel::XSemaphore
|
||||
T74 Wait n=1 xe::kernel::XSemaphore
|
||||
T71 Wait n=1 xe::kernel::XEvent
|
||||
T66 Wait n=1 xe::kernel::XEvent
|
||||
T65 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
T64 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XSemaphore
|
||||
T63 Wait n=1 xe::kernel::XSemaphore
|
||||
T62 Wait n=1 xe::kernel::XEvent
|
||||
T61 Wait n=1 xe::kernel::XEvent
|
||||
T50 Wait n=1 xe::kernel::XEvent
|
||||
T36 WaitMultiple n=2 xe::kernel::XEvent, xe::kernel::XEvent
|
||||
--- objects waited on:
|
||||
xe::kernel::XEvent 18
|
||||
xe::kernel::XSemaphore 8
|
||||
xe::kernel::XEvent 23
|
||||
xe::kernel::XSemaphore 7
|
||||
xe::kernel::XTimer 1
|
||||
=== healthy -> frozen ===
|
||||
xe::kernel::XEvent 20 -> 18 CHANGED
|
||||
xe::kernel::XSemaphore 9 -> 8 CHANGED
|
||||
xe::kernel::XEvent 19 -> 23 CHANGED
|
||||
xe::kernel::XSemaphore 8 -> 7 CHANGED
|
||||
xe::kernel::XTimer 1 -> 1
|
||||
=== per-thread healthy -> frozen ===
|
||||
thread healthy frozen
|
||||
T106 Wait(XEvent) Wait(XEvent)
|
||||
T105 -- Wait(XEvent) <-- CHANGED
|
||||
T104 Wait(XEvent) Wait(XEvent)
|
||||
T97 Wait(XEvent) Wait(XEvent)
|
||||
T96 Wait(XEvent) Wait(XEvent)
|
||||
T80 WaitMultiple(XEvent,XSemaphore) WaitMultiple(XEvent,XSemaphore)
|
||||
T79 WaitMultiple(XEvent,XSemaphore) WaitMultiple(XEvent,XSemaphore)
|
||||
T78 WaitMultiple(XEvent,XSemaphore) WaitMultiple(XEvent,XSemaphore)
|
||||
T77 Wait(XEvent) Wait(XEvent)
|
||||
T76 WaitMultiple(XEvent,XTimer) WaitMultiple(XEvent,XTimer)
|
||||
T75 Wait(XSemaphore) Wait(XEvent) <-- CHANGED
|
||||
T74 Wait(XSemaphore) Wait(XEvent) <-- CHANGED
|
||||
T71 Wait(XEvent) Wait(XEvent)
|
||||
T69 -- Wait(XSemaphore) <-- CHANGED
|
||||
T68 -- Wait(XEvent) <-- CHANGED
|
||||
T67 -- Wait(XEvent) <-- CHANGED
|
||||
T66 Wait(XEvent) Wait(XEvent)
|
||||
T65 WaitMultiple(XEvent,XSemaphore) WaitMultiple(XEvent,XSemaphore)
|
||||
T64 WaitMultiple(XEvent,XSemaphore) WaitMultiple(XEvent,XSemaphore)
|
||||
T63 Wait(XSemaphore) Wait(XSemaphore)
|
||||
T62 Wait(XEvent) Wait(XEvent)
|
||||
T61 Wait(XEvent) Wait(XEvent)
|
||||
T50 WaitMultiple(XEvent,XEvent) Wait(XEvent) <-- CHANGED
|
||||
T36 WaitMultiple(XEvent,XEvent) WaitMultiple(XEvent,XEvent)
|
||||
|
||||
@@ -968,3 +968,77 @@ and does not reproduce under gdb, not that it is wrong.
|
||||
**Next:** get a freeze under gdb at all — either drive the mission to the end
|
||||
condition that produces it instead of waiting on a clock, or measure guest time
|
||||
under gdb so the wait can be set in the units the freeze actually follows.
|
||||
|
||||
## ✅ 2026-08-25 — THE FROZEN CAPTURE, and `screen_id` was the wrong test all along
|
||||
|
||||
### First, a correction to the entry above
|
||||
|
||||
The previous entry ruled out a freeze because `screen_id` read `flight`. **That
|
||||
is not a freeze test**, and `frozen.py`'s own docstring says why: a Stage 02 run
|
||||
froze with `screen_id` still saying `flight`, the emulator still burning 212 %
|
||||
CPU, and 724 s of identical state. The right test is two **byte-identical**
|
||||
frames while the flight HUD is up.
|
||||
|
||||
Re-running that test on the saved frames says the conclusion was right anyway —
|
||||
`fz-late1/2/3` and `fz-healthy/frozen` all come back `animating`,
|
||||
`max_pixel_delta=254`. So the previous run really was healthy throughout. But it
|
||||
was right by luck, and the "~270 s black-screen" it was planned around is not a
|
||||
thing: the freeze does not black the screen and does not keep a clock. Measured
|
||||
onsets in `BACKLOG.md` are **27/45/83/183/255 s**.
|
||||
|
||||
### The capture
|
||||
|
||||
`freeze_waitobj.sh` now splits into `boot` and `watch`, and `watch` waits for the
|
||||
**event** (`frozen.py` + `in_flight`) instead of sleeping a guessed interval.
|
||||
That got the capture on the first attempt. It is a hard stop, not a hitch: the
|
||||
frame taken minutes after the capture is still `max_pixel_delta=0` against it.
|
||||
|
||||
Both captures, same run, same mission (`data/waitobj-s02.txt`):
|
||||
|
||||
| waited on | healthy | frozen |
|
||||
|---|---|---|
|
||||
| `XEvent` | 19 | **23** |
|
||||
| `XSemaphore` | 8 | **7** |
|
||||
| `XTimer` | 1 | 1 |
|
||||
| wait frames | 20 | **24** |
|
||||
|
||||
**The signature is in which threads moved, not in the totals:**
|
||||
|
||||
| thread | healthy | frozen |
|
||||
|---|---|---|
|
||||
| T105, T67, T68 | *not waiting* | `Wait(XEvent)` |
|
||||
| T69 | *not waiting* | `Wait(XSemaphore)` |
|
||||
| T74, T75 | `Wait(XSemaphore)` | `Wait(XEvent)` |
|
||||
| T50 | `WaitMultiple(XEvent,XEvent)` | `Wait(XEvent)` |
|
||||
|
||||
Every other thread — 17 of them — is on exactly the object it was on before. So
|
||||
the freeze is **not** the whole emulator stalling: the established waiters are
|
||||
untouched, and what changes is that **four threads that were running are now
|
||||
parked**, and **two threads move off a semaphore onto an event**. T74/T75 are the
|
||||
pair to chase — they are the only ones that changed *what kind* of thing they
|
||||
wait for.
|
||||
|
||||
⚠️ "Not waiting" means not in a wait frame **at that instant**; those threads
|
||||
existed and were running, they were not created by the freeze.
|
||||
|
||||
## 🟡 One data point that our own instrument provokes it — not proof
|
||||
|
||||
Worth stating because it changes what the freeze *is*. This run flew **~670 s
|
||||
clean** with only the pilot attached. A heavy-CPU inducer (`heavy_read.py cpu`,
|
||||
full-region Python word scan of guest memory) was then started at 08:59:54, and
|
||||
the freeze landed at **09:00:48 — 54 s later**, inside the 27–255 s band the old
|
||||
heavy-probe runs froze in.
|
||||
|
||||
That is consistent with the tally already in `BACKLOG.md` (heavy probe froze at
|
||||
27/45/83/183/255 s; cheap probe with the rescan removed was clean past 200 s on 3
|
||||
of 4 runs), and it is still **n=1 and not causal**. The obvious confounder is
|
||||
simply elapsed mission time.
|
||||
|
||||
**Refuted along the way:** the I/O was never the cost. A full uncapped walk of
|
||||
every allocated extent moves **371 MB in 0.1 s** — all page cache — so "32 MB
|
||||
reads" was the wrong description of what the old probes spent. The cost is CPU:
|
||||
unpacking and comparing every word in Python takes **~4.2 s per pass**.
|
||||
|
||||
**The experiment that would settle it:** alternate inducer-on and inducer-off
|
||||
windows within one run, several runs, and compare freeze rate per unit of
|
||||
*mission* time. Cheap now that `watch` is event-driven.
|
||||
|
||||
Reference in New Issue
Block a user