From 1961738ca7e7c21852243c6d1fe20d59919e8d17 Mon Sep 17 00:00:00 2001 From: "Darwin D. Wu" Date: Tue, 22 Sep 2026 09:23:13 -0700 Subject: [PATCH] docs(time-model): draft the upstream QEMU report for the replay-flush patch Add `poc/time-model/qemu-nosleep-replay-upstream.adoc`, the submission-ready report for the patch this repository carries: the subject and body a contributor would send, the problem, the mechanism and the exact ordering, the reproduction on stock and patched QEMU 11.1.0, the argument that the flush can move without disturbing checkpoint ordering, the counter-arguments to expect, the regression test proposed for QEMU's functional record/replay suite, and what this project's probe already covers that the upstream test should not duplicate. The reproduction was re-measured for the report: stock QEMU drops the input and writes no `EVENT_ASYNC_CHAR_READ` to the recording, the patched build delivers it in record and replay, and the `sleep=on` control is unchanged. Index the report from `docs/time-model.adoc` beside the patch and the evidence. --- docs/time-model.adoc | 4 + .../qemu-nosleep-replay-upstream.adoc | 465 ++++++++++++++++++ 2 files changed, 469 insertions(+) create mode 100644 poc/time-model/qemu-nosleep-replay-upstream.adoc diff --git a/docs/time-model.adoc b/docs/time-model.adoc index 2d3a55e..56f7506 100644 --- a/docs/time-model.adoc +++ b/docs/time-model.adoc @@ -52,6 +52,10 @@ measurements. Current progress lives in the implementation checklist, not here. | link:../poc/time-model/qemu-nosleep-replay-flush.patch[`qemu-nosleep-replay-flush.patch`] with link:../poc/time-model/qemu-nosleep-replay-spike.nix[`qemu-nosleep-replay-spike.nix`] | The minimal QEMU change that flushes queued replay events with `sleep=off`, and the scratch expression that builds the pinned QEMU with it; neither is wired into the repository's build, and the measurements are in the evidence document +| Upstream report +| link:../poc/time-model/qemu-nosleep-replay-upstream.adoc[`qemu-nosleep-replay-upstream.adoc`] +| The submission-ready report for the patch: the problem, the mechanism, the reproduction on a stock and a patched QEMU, why the flush can move without disturbing checkpoint ordering, the counter-arguments to expect, and the regression test proposed for QEMU's own functional suite; it is a draft for the owner to submit, not a submission + | Probe source | link:../poc/time-model/probe.c[`poc/time-model/probe.c`] | The five guest measurements — sleep, spin, race, sleep_loop, and the checksum control — and what each one does and does not establish diff --git a/poc/time-model/qemu-nosleep-replay-upstream.adoc b/poc/time-model/qemu-nosleep-replay-upstream.adoc new file mode 100644 index 0000000..e0e86ba --- /dev/null +++ b/poc/time-model/qemu-nosleep-replay-upstream.adoc @@ -0,0 +1,465 @@ += Upstream QEMU report: flush replay async events with sleep=off + +This document is the upstream submission for +link:qemu-nosleep-replay-flush.patch[`qemu-nosleep-replay-flush.patch`], the +change this repository carries for its pinned emulator: it moves +`replay_async_events()` ahead of the `icount_sleep` check in +`icount_account_warp_timer()`, so that `-icount sleep=off` stops skipping the +replay asynchronous event queue. + +It is a draft for the project owner to send, and nothing here has been +submitted: the `Signed-off-by` trailer is the submitter's to add, and the +proposed regression test is a proposal rather than something this repository +can run, because it lives in QEMU's own test suite. The measurements it cites +are recorded in link:../../rfd/0004/EVIDENCE.adoc[RFD 4 evidence], and the runs +in the reproduction section were re-measured for this document against the +pinned QEMU 11.1.0 with and without the patch. + +The ordering the report describes is still present on upstream `master` at +commit `67166d97a3269285aa68c489f85c9ccdf78495e1` (`accel/tcg/icount-common.c`, +`icount_account_warp_timer()`), and no commit there moves the flush, so the +patch applies to `master` and not only to the pinned 11.1.0. + +== Submission + +QEMU takes patches on the `qemu-devel@nongnu.org` mailing list as +`git format-patch` output with a `Signed-off-by` trailer, which +`docs/devel/submitting-a-patch.rst` describes. The subject and body below are +what a contributor would send; the diff is the patch this repository carries, +and it applies to the pinned QEMU 11.1.0 and to upstream `master`. + +=== Subject + +[source] +---- +[PATCH] icount: flush replay async events with sleep=off +---- + +=== Body + +[source] +---- +With -icount sleep=off, icount_account_warp_timer() returns before +replay_async_events(), so the replay asynchronous event queue is never +flushed. Live character input is delivered through that queue: with +record/replay enabled, qemu_chr_be_write() queues the bytes as a +REPLAY_ASYNC_EVENT_CHAR_READ instead of calling the device's chr_read +handler, and only replay_async_events() runs a queued event. A guest that +waits for serial input therefore never receives it under sleep=off, in +record mode and in replay mode alike, although QEMU documents sleep=off as +giving "deterministic execution times from the guest point of view" and +record/replay as recording and replaying serial port input. In record mode +the queued bytes are not written to the log either, because +replay_save_events() is the same flush, so the recording is silently +missing the input rather than delivering it late. + +Move the flush before the sleep check. The running-state check stays +first, so a stopped VM still does not process events, and the checkpoint +and the clock warp stay behind the sleep check, so the sleep=on path is +unchanged and the sleep=off path simply stops skipping the flush. The call +stays on the round-robin CPU thread with the replay mutex held, which is +what replay_async_events() asserts and what gives the queued events their +instruction position in the log. + +The flush has been behind this early return since 60618e2d7769 ("replay: +rewrite async event handling", 2022) added the call to this function; the +sleep=off early return itself goes back to e76d1798faa6 ("icount: decouple +warp calls", 2016). + +Signed-off-by: +---- + +=== Patch + +The exact patch text is +link:qemu-nosleep-replay-flush.patch[`poc/time-model/qemu-nosleep-replay-flush.patch`]; +the diff it carries is: + +[source,diff] +---- +--- a/accel/tcg/icount-common.c ++++ b/accel/tcg/icount-common.c +@@ -392,10 +392,6 @@ + + void icount_account_warp_timer(void) + { +- if (!icount_sleep) { +- return; +- } +- + /* + * Nothing to do if the VM is stopped: QEMU_CLOCK_VIRTUAL timers + * do not fire, so computing the deadline does not make sense. +@@ -404,8 +400,18 @@ + return; + } + ++ /* ++ * Flush queued replay events before the sleep check. External input is ++ * queued as a replay asynchronous event and delivered by this flush, so ++ * returning first would leave a guest that waits for host input without ++ * it in both record and replay mode. ++ */ + replay_async_events(); + ++ if (!icount_sleep) { ++ return; ++ } ++ + /* warp clock deterministically in record/replay mode */ + if (!replay_checkpoint(CHECKPOINT_CLOCK_WARP_ACCOUNT)) { + return; +---- + +The file's commit message is a provenance note written for this repository: it +calls the change a spike retained for Phase 0's record-mode blocker and says +the repository's build did not apply it. That note is not the submission text, +and the body above replaces it. + +== Problem + +`-icount sleep=off` is documented in `qemu-options.hx` (rendered into +`docs/system/invocation.rst` and the man page) as the setting under which + +* the virtual time "will jump to the next timer deadline instantly whenever + the virtual cpu goes to sleep mode and will not advance if no timer is + enabled. This behavior gives deterministic execution times from the guest + point of view"; + +and it is only incompatible with `shift=auto` and `align=on`, so a user who +wants it pins a scale and has a supported configuration. + +Record/replay is documented in `docs/system/replay.rst` as recording and +replaying exactly the input a deterministic execution cannot derive: + +* "Performs deterministic replay of all operations with keyboard and mouse + input devices, serial ports, and network." +* "The following non-deterministic data from peripheral devices is saved into + the log: mouse and keyboard input, network packets, audio controller input, + serial port input, and hardware clocks". +* "Serial ports input is recorded and replay automatically." + +The two documented behaviours do not compose. With `sleep=off` and +record/replay enabled, a guest receives no live input at all, in record mode +and in replay mode alike. The failure is not latency: the bytes are queued as +an asynchronous replay event and the queue is never drained, so in record mode +they are neither delivered to the device nor written to the log, and in replay +mode the recorded events are never injected. A guest that waits for a control +command never receives it; a guest that polls never sees the bytes; the run +hangs or times out, which presents as a broken guest rather than as a missing +flush. + +== Mechanism + +The exact function and ordering, as they are in the pinned QEMU 11.1.0 and on +`master` (`accel/tcg/icount-common.c`): + +[source,c] +---- +void icount_account_warp_timer(void) +{ + if (!icount_sleep) { + return; + } + + /* + * Nothing to do if the VM is stopped: QEMU_CLOCK_VIRTUAL timers + * do not fire, so computing the deadline does not make sense. + */ + if (!runstate_is_running()) { + return; + } + + replay_async_events(); + + /* warp clock deterministically in record/replay mode */ + if (!replay_checkpoint(CHECKPOINT_CLOCK_WARP_ACCOUNT)) { + return; + } + + timer_del(timers_state.icount_warp_timer); + icount_warp_rt(); +} +---- + +The function is called from the round-robin TCG CPU thread, +`rr_cpu_thread_fn()` in `accel/tcg/tcg-accel-ops-rr.c`, between +`replay_mutex_lock()` and `replay_mutex_unlock()`, once per loop iteration +whenever `icount_enabled()`. It is not the warp timer's callback - that is +`icount_timer_cb()` - so `sleep=off` does not stop the function from being +called; the early return is the only thing that skips its body. + +`replay_async_events()` (`replay/replay.c`) is the only site that drains the +queue. It calls `replay_save_instructions()` and then `replay_save_events()` in +record mode or `replay_read_events()` in replay mode, and it asserts that the +replay mutex is held. `docs/devel/replay.rst` documents the contract directly: +"EVENT_ASYNC. This is a group of events. When such an event is generated, it is +stored in the queue and processed in `icount_account_warp_timer()`", and the +declaration in `include/system/replay.h` describes the function as processing +"the async events added to the queue (while recording)" or reading "the events +from the file (while replaying)". + +Character input enters that queue in `qemu_chr_be_write()` (`chardev/char.c`): +when the chardev is replay-enabled, record mode calls `replay_chr_be_write()` +(`replay/replay-char.c`), which allocates a `CharEvent` and calls +`replay_add_event(REPLAY_ASYNC_EVENT_CHAR_READ, ...)` instead of calling the +device's receive handler. The event's runner calls `qemu_chr_be_write_impl()`, +which is what invokes the handler the device registered - `serial_receive1()` +for a 16550 UART, `pl011_receive()` for a PL011. `docs/devel/replay.rst` +describes the event as "Character (e.g., serial port) device input initiated by +the sender", and in replay mode host writes are dropped entirely, because +`qemu_chr_be_write()` returns for `REPLAY_MODE_PLAY`. + +Under `sleep=off`, therefore, `replay_async_events()` is never called: the +queue is never drained in record mode, and the log's asynchronous events are +never read in replay mode. The stub in `stubs/icount.c` is a non-TCG +placeholder and not a second processing site. + +== Minimal reproduction + +=== Measured with this project's host-input probe + +The probe boots `poc/time-model/input-probe.c` as the guest init, waits for the +guest's `READY`, stops the guest through QEMU's monitor, writes one line while +the guest cannot be polling, resumes it, and reports whether the line arrived. +The acknowledged stop and resume are what make a non-delivery claim causal +rather than timing-dependent; the measurement is recorded in +link:../../rfd/0004/EVIDENCE.adoc[RFD 4 evidence]. The checked-in commands are: + +[source,shell] +---- +QEMU_SYSTEM_X86_64= .agents/dev ./scripts/time-model-input-probe.sh --expect not-delivered +QEMU_SYSTEM_X86_64= .agents/dev ./scripts/time-model-input-probe.sh --expect delivered +QEMU_SYSTEM_X86_64= .agents/dev ./scripts/time-model-input-probe.sh --expect delivered shift=4 +---- + +Both binaries are the pinned QEMU 11.1.0 and report the same version string; +they differ only by this patch, and the stock and patched digests are recorded +in the evidence. Re-measured for this document: + +[cols="2,2,2",options="header"] +|=== +| Configuration | Stock QEMU | Patched QEMU + +| `shift=4,sleep=off`, `rr=record` +| `input=not-delivered`: the guest reported `READY`, the host wrote the line + after an acknowledged stop, and the guest then polled 25,450 times over 84 s + without receiving it +| `input=delivered`, immediately after `READY` + +| `shift=4` (`sleep=on`), `rr=record` +| `input=delivered` +| `input=delivered`, unchanged +|=== + +=== Minimal QEMU-only form + +The essential guest is the probe's guest: an init that prints `READY`, polls +its console with a 100 ms timeout rather than blocking, and prints +`GOT: iterations=N` when a line arrives. The full source is 75 lines +(`poc/time-model/input-probe.c`) and can be attached to a submission; the +recipe below is what a maintainer can run without this repository's harness. +One line is written to the guest's console once `READY` appears, and the +observation is whether `GOT:hello-from-host` is printed within the window: + +[source,shell] +---- +qemu-system-x86_64 -machine pc-i440fx-9.2,accel=tcg -cpu qemu64 -smp 1 -m 256M \ + -nodefaults -no-user-config -display none -monitor none -serial stdio -no-reboot \ + -net none -rtc base=2000-01-01T00:00:00,clock=vm \ + -kernel bzImage -initrd initramfs.cpio.gz \ + -append 'console=ttyS0 quiet loglevel=0 panic=-1 nokaslr random.trust_cpu=off init=/init' \ + -icount shift=4,sleep=off,rr=record,rrfile=replay.bin +---- + +The same command with `sleep=on` (that is, `shift=4`) and with `rr=replay` on a +recording made by the patched build gives the control and replay rows. The +runs below were measured for this document on the pinned kernel and the same +guest, with a 40 s window after the line was written: + +[cols="2,2,2",options="header"] +|=== +| Configuration | Stock QEMU | Patched QEMU + +| `shift=4,sleep=off`, `rr=record` +| no `GOT`: the guest polled 1,469 times in the window + (`WAITING iterations=14690`) and never received the line; the recording + contains no `EVENT_ASYNC_CHAR_READ` at all, so the input was dropped rather + than delayed +| `GOT:hello-from-host iterations=13`, and the recording contains the + `EVENT_ASYNC_CHAR_READ` events + +| `shift=4` (`sleep=on`), `rr=record` +| `GOT` as expected +| `GOT`, unchanged + +| `shift=4,sleep=off`, `rr=replay` of the patched recording +| no `GOT`: the guest prints `READY` and one poll report, then virtual time + stops advancing and the guest hangs, because the event pending in the log is + never injected +| `GOT:hello-from-host iterations=13`, the same iteration as the recording, with + no live input at all +|=== + +The log check is QEMU's own `scripts/replay-dump.py`: the stock recording of +the first row has no `EVENT_ASYNC_CHAR_READ`, and the patched recording has it. +That is the part a reviewer may find most useful, because it shows the defect +is data loss in record mode and a hang in replay mode rather than a delay. + +== Why the flush can move without disturbing checkpoint ordering + +* With `sleep=on` the sequence inside `icount_account_warp_timer()` is + unchanged: the running-state check, the flush, + `CHECKPOINT_CLOCK_WARP_ACCOUNT`, `timer_del()`, and `icount_warp_rt()` happen + in the same order, because the sleep check does not fire. +* With `sleep=off` no checkpoint is taken before the change and none is taken + after it: `replay_checkpoint(CHECKPOINT_CLOCK_WARP_ACCOUNT)` is still behind + the sleep check, so the no-sleep path still skips the clock warp exactly as + it did. There is no ordering between the flush and that checkpoint to + disturb, because that path never reaches the checkpoint. +* The flush keeps the context that gives it its meaning: the same thread (the + round-robin CPU thread), still inside `replay_mutex_lock()` and + `replay_mutex_unlock()`, so `replay_async_events()`'s + `g_assert(replay_mutex_locked())` still holds, and still preceded by + `replay_save_instructions()`, so an event keeps its instruction position in + the log instead of acquiring a host-dependent one. +* The running-state check stays first, so a stopped VM still returns before the + flush, and input submitted while the guest is stopped is queued and delivered + on resume. That is the ordering this project's probe relies on to make its + measurement causal, and it is unchanged. +* Measured: under the patched emulator the pinned model reproduces every + reference value exactly, and the product's record-and-two-replays run has + normalized events, assertions, and semantic outcome digest byte-identical to + the same run under the model in use + (link:../../rfd/0004/EVIDENCE.adoc[RFD 4 evidence]). The patch does not + perturb what a recording contains beyond adding the input it was dropping. + +== Counter-arguments to expect + +* *The change should come with a record/replay test covering input under + `sleep=off`.* This is the expected one, and it is fair: the fix is one early + return, and the behaviour it restores is a documented input path. The next + section proposes the test. This project's measurements are the basis for it, + but they are not a substitute, because they live here and they measure the + absence of delivery as a project-specific negative. +* *Why not deliver the bytes where they are queued, in the chardev write + path?* Because the queue exists to place the event at a deterministic + instruction position: `replay_async_events()` calls + `replay_save_instructions()` before it saves the events, and a chardev write + arrives on the I/O thread at an arbitrary host point. Delivering it + immediately would give input a host-dependent position in the log and in the + guest, which is what record/replay exists to remove, and it would contradict + `docs/devel/replay.rst`, which says queued events are processed in + `icount_account_warp_timer()`. +* *Is the function called often enough under `sleep=off` for this to work?* + Yes: it is called from the round-robin CPU thread's loop whenever icount is + enabled, unconditionally on `icount_sleep`, and the early return is the only + thing that skips the flush. The patched runs above deliver the line on the + guest's next poll after it is written. +* *Does this change `sleep=on`?* No. The order of the running-state check, the + flush, and the checkpoint is identical when the sleep check does not fire, + and the `sleep=on` control runs deliver input before and after the patch. +* *Should the flush move ahead of the running-state check instead, so input is + processed while the guest is stopped?* That would process events while + `QEMU_CLOCK_VIRTUAL` timers do not fire, which the function's own comment + says makes the deadline computation meaningless, and it is unnecessary: + queued events survive a stop and are delivered on resume, which is how the + probe orders its write against the guest's polling. + +== Proposed upstream regression test + +The test belongs in QEMU's functional record/replay suite, which already boots a +guest and asserts a console pattern in both record and replay: + +* *Directory and harness.* `tests/functional/x86_64/test_replay.py`, class + `X86Replay`, which derives from `ReplayKernelBase` in + `tests/functional/replay_kernel.py` (itself a `LinuxKernelTest`) and uses + `self.get_vm()`, `vm.set_console()`, and + `wait_for_console_pattern()`. It needs one small extension in + `ReplayKernelBase`: `run_vm()` builds the `-icount` string as + `shift=,rr=,rrfile=`, and the new test needs `sleep=off` + appended, which no existing test does. Registration needs no new entry: the + architecture's `meson.build` already lists `replay` in its thorough suite, + which registers `func-x86_64-replay`. +* *What it boots.* The assets the file already uses, the TuxBoot Buildroot + x86_64 `bzImage` and `rootfs.ext4.zst` from + `https://storage.tuxboot.com/buildroot/20241119/x86_64/`. They are + interactive: `tests/functional/x86_64/test_tuxrun.py` boots the same pair and + drives it with `tuxtest login:`, `root`, and shell commands, so the test + needs no new asset and no new guest. +* *What it asserts.* The recording run starts with + `-icount shift=4,sleep=off,rr=record,rrfile=`, waits for the login + prompt, sends `root` over the console, waits for the shell prompt, and sends a + command whose output is a fixed string (`echo rr-input-ok`), asserting that + the string appears. The replay run starts with + `-icount shift=4,sleep=off,rr=replay,rrfile=`, sends no live input at + all, and asserts the same string appears from the log and that QEMU exits + successfully; the base harness already runs `scripts/replay-dump.py` over the + log. Before the fix the recording run reaches the login prompt but the login + it sends never arrives, so the test fails waiting for the shell prompt; after + it, both directions pass. Both directions matter because the flush site is + shared: a recording that silently omits the input and a replay that never + injects it are the same defect, and the replay half is the one a user meets + when replaying an existing recording. +* *Cheaper alternative, not measured here.* If a test that downloads a guest + image is not wanted, the asset-free shape is a bare-metal TCG test combining + the existing input and record/replay wrappers under `tests/tcg/scripts/`: a + guest that reads its semihosting console, recorded with + `-icount shift=5,sleep=off` and input fed to the recording run only, then + replayed with no input, comparing the two outputs as `record_replay.sh` + already does. Semihosting console input reaches the guest through the same + queued character event, so it would exercise the same path, but that has not + been measured here and it needs a new wrapper that feeds input to the + recording run alone. + +=== What this project's probe already covers that the test should not duplicate + +`scripts/time-model-input-probe.sh` with `poc/time-model/input-probe.c` is a +measurement instrument, not a regression test, and the upstream test should not +inherit its machinery: + +* It establishes a *negative* result - input was not delivered - where the + failure mode is a guest that hangs. That needs the acknowledged stop and + resume on QEMU's monitor, the drain before the write, the stall bound, the + requirement that the emulator's output ended in one piece, and the + classification of inconclusive versus not-delivered, so that "nothing + arrived" cannot be confused with "the experiment did not run". An upstream + test asserts the positive behaviour - the guest's response to console input + appears - and fails by timeout or by a missing prompt, so it needs none of + that. +* It compares several models (`shift=auto`, `shift=4`, and `shift=4,sleep=off`) + to separate the model from the mechanism. That comparison is this project's + question about which model to pin, not a QEMU regression, and upstream should + test one supported configuration. +* It asserts the known non-delivery as a continuous-integration expectation + (`--expect not-delivered`), which is a guard for this project's pin: the job + fails if a QEMU change starts delivering input, which is the signal that the + pin may be unblocked. That expectation is the opposite of what upstream + wants, and this project inverts it when the pin moves to a QEMU that carries + the fix. +* Its guest tests (`poc/time-model/input-probe-test.c` with + `scripts/time-model-input-probe-test.sh`) cover properties of this project's + probe guest - no poll limit, late delivery reported as received, no give-up + report - which are properties of the instrument rather than of QEMU. +* The replay direction is not covered by the probe's continuous integration at + all: it follows from the single flush site in the source and was measured for + this document. The upstream test should cover it, because a regression there + is invisible to a record-only test. + +== References + +* link:qemu-nosleep-replay-flush.patch[`poc/time-model/qemu-nosleep-replay-flush.patch`] +* link:../../rfd/0004/EVIDENCE.adoc[RFD 4 evidence] +* link:input-probe.c[`poc/time-model/input-probe.c`] and + link:../../scripts/time-model-input-probe.sh[`scripts/time-model-input-probe.sh`] +* Upstream sources cited: `accel/tcg/icount-common.c`, + `accel/tcg/tcg-accel-ops-rr.c`, `replay/replay.c`, `replay/replay-char.c`, + `replay/replay-events.c`, `chardev/char.c`, `include/system/replay.h`, + `qemu-options.hx`, `docs/system/replay.rst`, `docs/devel/replay.rst`, and + `docs/devel/submitting-a-patch.rst`. +* Upstream tests cited: `tests/functional/replay_kernel.py`, + `tests/functional/x86_64/test_replay.py`, + `tests/functional/x86_64/test_tuxrun.py`, and + `tests/tcg/scripts/record_replay.sh`. +* Commits cited: `60618e2d7769` ("replay: rewrite async event handling", 2022) + and `e76d1798faa6` ("icount: decouple warp calls", 2016).