The Clock That Ran at Half Speed: From a Note-Jumping Report to a One-Line Default

Range: 7583fde (v0.0.132) through e341c8f (v0.0.134)

Major Changes

The reported symptom was one line: "the notes and the BGA lose sync with the music and jump."

Three layers could produce that — the music playing wrong, the guest's clock running wrong, or the render lagging. Four tasks separated them in turn, and along the way it emerged that what several tasks had called "the game stalls" was our own instrument. The final fix was already in the tree: no new mechanism was built, only the default of one environment variable was flipped.

flowchart LR
    S["Symptom<br/>notes and BGA<br/>jump against the music"] --> A["Tasks 421-423<br/>music position is <b>exact</b><br/>zero error, zero regression"]
    A --> B["Task 430<br/>guest clock = <b>51%</b> of real time<br/>13.9 s behind over 28.3 s"]
    B --> C["Task 431<br/><b>93.9%</b> of the loss occurs<br/>while blocked in the Glide gate"]
    C --> D["No safe point inside the gate<br/>= <b>undeliverable</b>, not late"]
    D --> E["Task 432<br/>turn the bool into a count<br/>delivery <b>99.98%</b>"]
    style A fill:#1e8449,color:#fff
    style E fill:#1e8449,color:#fff

1. The music was innocent, and the expectation itself was wrong

CD audio position reporting was the first suspect. The game asks MSCDEX which sector is playing and times its notes from the answer, so a shaky answer produces exactly this symptom.

One decision came before the instrument: sample on the poll thread, not in the audio worker, because a starved worker cannot report its own starvation. Every value the position derives from — worker iterations, underruns — rides on the same row.

The result was unambiguous. Over 1,440 consecutive same-generation gameplay samples:

There is a trap in that table. The design and the guide had recorded the expectation as "7 to 8 per 100 ms." GetTickCount resolution makes the real interval 109.5 ms, and CD-DA runs at 75 sectors per second, so the correct expectation is 75 × 0.1095 = 8.21. The observed 8.21 was exactly right, and the wrong bar would have made it read as "slightly fast."

The command trace caught a separate defect. The guest calls stop every 16 ms in one window, and our Stop() recomputed paused from was_playing on every call, so the second Stop cleared the pause the first had established. After making it idempotent, paused holds at 1 and generation drops from 62 to 5.

2. The "stall" was our watchdog, not the game

The biggest result of this investigation was not on the plan.

Several tasks had recorded that "the game stalls right before gameplay." Reading the guest code located the site:

0x0302C588:  call 0x0303F3F4        ; returns [0x0328FA18]
0x0302C58D:  cmp  eax, 100
0x0302C590:  jl   0x0302C588        ; wait for 100 ticks

The counter is incremented by the INT 8 timer ISR:

0x0303F1A3:  call [0x0328FA08]      ; chain to the previous handler
0x0303F1A9:  inc  [0x0328FA18]      ; the counter the game waits on
0x0303F1AF:  inc  [0x0328FA14]

The game was not stalled — it was performing an ordinary 100-tick (~1.4 s) wait. During that wait nothing raises an exception, single-steps, or crosses an AOT boundary, and to our PollThreadUntilExit one-second no-progress watchdog (live_telemetry_snapshot.cpp, quiet_timeout_milliseconds = 1000) that is indistinguishable from a dead run.

REPIU_EXECUTION_TIMEOUT_MS=0 maps to INFINITE and disables it. Same build, A/B:

Two corrections came with it. 0x030F2786, called the stall site across several tasks, is STI (fb c3 = STI; RET) — merely the privileged instruction trapped most often during the wait. And the single-step hotspot census could never have shown this loop, because it holds only single-step boundaries while the loop runs from the AOT cache; the guest position census, sampling every 5 ms independently of exceptions, is what found it.

3. One cumulative line cannot decide anything

The 174-second run's exit summary carried the next candidate.

timer tick delivery due/injected/coalesced/dropped: 41531/39830/1677/24

1,677 coalesced deliveries means several owed ticks were merged into one. Guest time running slow and then catching up in bursts is exactly what "jumping" looks like.

But that line cannot decide the question. 1,677 / 41,531 = 4.04% is the average over 174 seconds and says nothing about whether the loss sits in boot, in attract, or in gameplay. Worse, re-aggregating the existing trace showed the guest's main loop pinned to real time at 7,200 polls / 119.968 s = 60.0160 Hz (0.03% error). Uniform 4% loss would put it at 57.6 Hz, so the cumulative figure and the loop frequency contradict each other.

Task 430 therefore put tick loss on a time axis: timer_ticks_due and timer_ticks_injected deltas on the CD position census sample, plus a derived tick_lag_ms column. Behaviour is unchanged — two atomic reads of counters already maintained.

A smoke run meant only to prove the instrument works delivered half the answer immediately.

Delivery swings between 25% and 98.6%, and the run-long average of 43.1% describes none of it — which is precisely why judging this axis from a single exit line was unsafe.

One design choice was confirmed by measurement too. tick_lag_ms does not hard-code 240 Hz, and the smoke's first second shows one to two ticks_due per sample — about 18.2 Hz, the DOS default BIOS rate before the guest reprograms the PIT divisor. A hard-coded 240 would have overstated boot-phase lag thirteenfold.

The verdict came from a user run — 47 seconds of pumpit1, 427 samples, in which the symptom was actually visible. Over the main track:

The music ran 28.3 seconds while the guest clock ran 14.5.

The time series also exposed structure no average could show: in the same run the preview tracks deliver at about 100% with tick_lag_ms actually falling (9,006 → 8,793), while the main track sits at 51%. The cumulative 51.7% describes neither.

I record that my expectation was wrong here. Before the measurement I wrote that the steady 60.016 Hz loop made me expect this candidate rejected — but that 60 Hz came from a different run (pumpit3, 95.9% delivery). Binding figures from two runs into one conclusion is the error. Fixing the readings before measuring is what let the data decide regardless of the guess.

4. From counting to attributing

Knowing that ticks vanish does not say where to fix. It does not separate injections being refused from injections never being reached.

Task 431 attributed rather than counted: it records whether the guest thread was inside the Glide gate at the moment each tick came due.

sequenceDiagram
    participant P as poll thread
    participant G as guest thread
    participant H as host thread (GL)
    G->>H: InvokeOnHostThread(grDrawTriangle …)
    activate H
    G-->>G: host_command_cv_.wait() — no guest code runs
    P->>P: PIT 240 Hz — tick due
    Note over P: none of the 967 in-cache<br/>INT3 safe points is reachable
    P->>P: tick due (second, third …)
    Note over P: merged into one bool<br/>→ coalesced
    H-->>G: completion
    deactivate H
    G->>G: safe point reached — exactly one injected

The verdict, from a user run (pumpit1, 33 s, 297 samples), over the main track:

The deciding quantity is deferred = 0. No injection was ever held back by IF=0 or a non-guest EIP. The ticks were not refused — InjectPendingInterrupts was simply never reached. Inside the gate not one line of guest code executes, so no safe point can be stepped on, while ticks keep coming due at 240 Hz. Those ticks were undeliverable, not late.

Both cross-checks hold. safe_point_traps / injected is 2,765 to 2,781, a ratio of 0.99, confirming that the opportunity really is the safe point; and main-track traps run at 121.4 per second rather than near 240, consistent with opportunities genuinely being scarce.

Verification also caught a defect in my own instrument. The first smoke had in_gate > (due − injected) in 47 of 404 rows. Not a counter bug — the denominator I chose was wrong. Per interval, due − injected is not that interval's coalesced count, because an injection here can consume a tick armed in the previous interval, so the subtraction understates it. Carrying ticks_coalesced as its own column and dividing by that brought violations to zero.

Lesson: ship a derived ratio's numerator and denominator under the same definition. Ship one and let the reader subtract for the other, and nobody ever checks whether that subtraction is valid.

5. The fix was already in the code

Knowing the loss was concentrated in the gate window, I prepared to build a new mechanism that drains owed ticks at the gate boundary. I got as far as establishing that the direct-dispatch thunk never returns guest ESP through its frame — meaning the hottest path in the emulator would have to be reworked.

Only then did I try flipping one environment variable.

REPIU_TIMER_TICK_BACKLOG is a bounded backlog Task 366 had already built and left as an opt-in. It does exactly one thing: it turns the bool that carried delivery into a count.

    if (!backlog_enabled)
    {
        // Stage one accounting for the shipping behaviour: arming delivery
        // publishes a single boolean, so one owed tick becomes the pending
        // injection and the rest are gone.
        const std::uint32_t retained = already_pending ? 0U : 1U;
        counters->coalesced_total.fetch_add(due - retained, …);
        …
        return;
    }

    // Stage two: keep the owed ticks, bounded.
    const std::uint32_t room = kWin32TimerTickBacklogCapacity > backlog
        ? kWin32TimerTickBacklogCapacity - backlog : 0U;
    const std::uint32_t accepted = std::min(due, room);

On the injection side, a still-owed tick keeps delivery armed, so the backlog drains one interrupt per safe point rather than bursting into the guest stack.

The user played gameplay with REPIU_TIMER_TICK_BACKLOG=1 and confirmed the symptom is gone. From the same run's main track, 64.53 seconds over 591 samples:

traps/s = 240.2 is the key figure — exactly one per owed tick, with no excess trapping.

So why did Task 366 leave this as an opt-in? It measured −16.4% frames with the same switch and wrote "do not enable this expecting speed." But 366 also named the mechanism itself: what is expensive is not the injection but the safe point being held armed continuously — which happens only when the backlog pins at its cap.

In between, Tasks 414 (port reads per tick 200 → 2), 415, 417 (zero generation failures) and 419 (+27.7% frames) raised execution speed, so the backlog empties between gate calls. 366's conclusion stays as the record of its moment, with a scope note at the head of both its documents. REPIU_TIMER_TICK_BACKLOG=0 remains as the regression control.

The cost of the new default reads −1.6% frames (2,042 against 2,076), consistent with an earlier −1.2% and indistinguishable from run-to-run variation. The supported claim is not "zero cost" but "not −16.4%." A paired frame measurement over the main track is left unmeasured — every A/B here was in the attract phase, and the gate-heavy window is where the cost would show.

Other commits in this range

Two independent items sit in the same range.

• 78366f8 (v0.0.133) — the execution backends were reduced to legacy and dynamic. aot and aot-dynamic were already failing to build the pumpit3 image at the time of removal, and the old names are rejected without aliases.
• 2038829 · 3b5073c — the OpenWatcom sample baseline moved from v0.0.59 to v0.0.133, and the pass criterion gained a completion requirement.

piu_1st execution log — current position and blockers

Before the fix, from the user run where the symptom was visible (pumpit1, 33 s):

timer tick delivery due/injected/coalesced/dropped/deferred: 7523/4024/3475/24/0
timer tick in-gate    due/coalesced/coalesced-share:          4872/3213/92%
AOT timer safe-point  trap/injected/deferred:                 4010/3988/22

The three lines only mean something together. deferred = 0 says nothing was refused; 3,213 of 3,475 coalesced ticks (92%) happened inside the gate; and 4,010 safe-point traps over 33 seconds is 121 per second, half of 240 Hz.

After the fix the same instrument reports coalesced = 0, 99.98% delivery, and max_backlog = 12.

Current position: with the watchdog disabled via REPIU_EXECUTION_TIMEOUT_MS=0, piu_1st runs 174 seconds and 8,023 frames into gameplay, and the note/BGA jumping axis is closed.

Two current blockers:

1. The no-progress watchdog is still unfixed. It kills healthy runs after one second, which distorts every frame-based measurement. Progress needs to include HLE activity (MSCDEX, DOS services), or a tick wait needs to count as progress. Until then, measurements go through REPIU_EXECUTION_TIMEOUT_MS=0 with the harness bounding the run.
2. The 3D model renders corrupted. Immediately after this range, 6ab688a (v0.0.135) traced it to Glide vertex depth: the decoder never read ooz, so every vertex left with z = 0. That is the next post.

Sample test results

The scripts/test_openwatcom_samples.ps1 baseline moved from v0.0.59 to v0.0.133. The comparison immediately before the update showed zero regressions and six new passes, so the update was safe.

The six new passes are b_keybrd.c, chainint.c, getdate.c, gettime.c, getvect.c and setvect.c — the interrupt, date and time family. They come not from this timer work but from 74 versions of accumulated INT 21h and INT 8 work in between.

xychart-beta
    title "OpenWatcom Sample Cumulative Results"
    x-axis ["0.0.1", "0.0.5", "0.0.9", "0.0.15", "0.0.34", "0.0.59", "0.0.133"]
    y-axis "Samples" 0 --> 850
    line "Total" [819, 819, 819, 819, 819, 819, 819]
    line "Build Passed" [788, 793, 793, 793, 793, 793, 793]
    line "Run Passed" [419, 473, 473, 522, 523, 529, 535]
    line "Build Skipped" [0, 26, 26, 26, 26, 26, 26]

One caveat belongs with that number. The 535 was measured under the old criterion, because 3b5073c added a completion requirement afterwards.

# Before — a timeout also counted as a pass
$runPassed = $run.ExitCode -eq 0 -and
             $run.Output -match "Win32 minimal execution exception caught: false"

# After
$runPassed = $run.ExitCode -eq 0 -and
             $run.Output -match "Win32 minimal execution exception caught: false" -and
             $run.Output -match "Win32 minimal execution returned: true" -and
             $run.Output -notmatch "minimal execution attempt timed out"

When the guest hangs and the loader's default 1,000 ms timeout expires, no exception is caught and the process exits 0. The old expression looked at exactly those two things, so a timeout counted as a pass — four of eight verification samples were false positives. The first run under the tightened criterion may report regressions, and those are measurement corrections, not code regressions.

Commits

Lessons

Try the thing that costs one environment variable first. I finished designing a new drain mechanism, and established that the hottest path would have to be reworked, before running the backlog A/B. The order was exactly backwards.

Inverting cause and effect deletes the solution. I asserted that "the backlog cannot fix this, because there are only 120 injection opportunities per second." Those 120 were not an independent ceiling — they were a consequence of the boolean. Preserving the count made them 240.

Doubt an old measurement's scope. Taking Task 366's −16.4% at face value would have kept this axis shut. Re-testing was possible only because 366 recorded the mechanism behind the cost and not just the verdict. Had it written the conclusion alone, there would have been nothing to re-test.

A cumulative line is not evidence for a verdict. Within one run, delivery swung between 25% and 98.6%, and preview versus main track split 100% against 51%. No average explains that structure.

Fix the readings before measuring. My expectation (rejection) was wrong again, and the pre-registered bar handed the verdict to the data.

Doubt "it stalled." What several tasks had recorded as a game stall was our own instrument's one-second timeout.

Technology Stack Used

The 8254 PIT channel 0 and INT 8

Time in a DOS game comes from channel 0 of the Intel 8253/8254 Programmable Interval Timer. The input clock is about 1.193 MHz (our implementation uses kInputClockHz = 1193280), and channel 0's 16-bit divisor sets the IRQ 0 period. IRQ 0 arrives as real-mode INT 08h.

The value PIU.EXE actually writes is visible in the log:

[repiu-pit] channel=0 divisor=4972 frequency=240.000000Hz generation=2

Shortly after boot the game lowers the divisor to reach 240 Hz, and its own INT 08h handler chains to the previous handler before incrementing its counters — the inc [0x0328FA18] seen in section 2. "Guest time" in this project is therefore literally how many times we injected INT 8.

Our implementation has PitChannel0 observe writes to ports 0x40/0x43 and publish an atomic generation + divisor snapshot, while PitIrqSchedule::Poll derives due ticks from elapsed time at the ratio 1,193,280 / divisor. The BDA BIOS tick count at 0x0000:0x046C is updated separately at the default divisor of 65,536, whatever the guest programs, because code reading that address expects 18.2 Hz.

flowchart LR
    A["guest: out 0x43/0x40<br/>divisor write"] --> B["PitChannel0<br/>publishes snapshot (generation)"]
    B --> C["PitIrqSchedule::Poll<br/>elapsed ns → due ticks"]
    C --> D["RecordTimerTicksDue<br/>accumulate into the backlog"]
    D --> E["at a safe point<br/>InjectPendingInterrupts"]
    E --> F["build a frame on the guest stack<br/>jump to the INT 08h vector"]

PitIrqSchedule carrying the divisor generation matters. Without re-epoching the moment the guest changes the period, time that elapsed at 18.2 Hz would be reinterpreted at 240 Hz and thousands of ticks would come due at once.

Interrupt injection safe points

Executing the original code while injecting interrupts means you cannot inject anywhere. Building a frame on the guest stack mid-instruction, or inside one of our HLE boundaries, corrupts state. Injection therefore happens only where all three conditions hold:

1. EIP is guest code or inside the AOT cache
2. EFLAGS.IF is set — the guest is accepting interrupts
3. the INT 8 vector is installed

On the dynamic translation backend those points are the 967 INT3 safe points planted in the cache. While armed, the guest stepping on one raises an exception to us, and we build the frame and jump to the vector there. Cases blocked by conditions 1 and 2 are counted as deferred, which is a delay and not a loss — the pending state survives and lands at the next opportunity.

This is why deferred = 0 was decisive: zero refusals leaves exactly one remaining explanation — the opportunity never came.

The Glide gate and thread rendezvous

The OpenGL context is owned by the host thread, so a Glide call made by the guest is handed to that thread through InvokeOnHostThread while the guest thread waits on host_command_cv_. No guest code runs inside that window. Safe points are things guest code steps on, so the longer the gate, the structurally fewer the injection opportunities.

Task 418 had already measured that gate at 54-55% of guest-run time, and Task 431's due_in_gate/due of 56.5% lines up with it. Two independent instruments drawing the same picture was this attribution's cross-check.

CD-DA position and MSCDEX

CD audio plays 75 sectors (frames) per second by specification, and position is reported as an LBA. A rhythm game times its notes from that value, so the accuracy of the position our HLE returns is the accuracy of the game's judgement.

We take real playback progress from the host audio backend, convert it to an LBA, and answer MSCDEX IOCTL 12 (position query) with it. Section 1's delta_lba check asks whether that conversion drifts along the time axis. The expectation 75 frames/s × 0.1095 s = 8.21 comes straight from the specification.

Measurement methodology — pre-registered readings

The procedure used repeatedly across this range:

1. Write the readings into the design before measuring (for example, injected/due ≤ 96% confirms the candidate).
2. Write the expectation afterwards. The expectation takes no part in the verdict.
3. Make every instrument an environment-variable opt-in that does not change behaviour.
4. Apply the verdict only to a run where the symptom was visible.

That procedure paid off in Task 430, where my expectation was wrong. Had the bar been written after the guess, 51% could have been read as "fine, the loop is still 60 Hz."

The instruments used here:

References

• Intel 8254 Programmable Interval Timer datasheet
• OSDev Wiki — Programmable Interval Timer
• Ralf Brown's Interrupt List — INT 08h / INT 1Ah
• MSCDEX / CD-ROM device driver specification
• Microsoft Learn — GetTickCount resolution
• 3Dfx Glide 2.4 Programming Guide