Journal reader per-object 1000ms budget trips on first read on hosted windows-2025 despite ~4ms I/O #851

Activity

1. coneilen commented on Oct 16, 2026

   

   coneilen

   on Oct 16, 2026

   CollaboratorAuthor

   More actions

   A third occurrence on #850's single diagnostic rerun (head dea7de2a) confirms this is deterministic-enough on hosted windows-2025 to block capture-core PRs.

   Run	Job	Failing case	Sequence	openMs	copyMs	totalMs
   #850 diagnostic	117223178057	lease-bound admission lane-d	3	0.323	0.129	1273.276
   #850 diagnostic	117223178057	real capture command with genuine zero arguments	1	1.061	2.599	1374.675

   The suite was 82 executed, 79 passed, 3 failed. The third failure is the dependent report gate. Receipt-block passed this time, so its earlier first-attempt failure remains unattributed.

   The sequence=3 failure refutes the "first invocation only" part of the hypothesis. The roughly 1.2 to 1.4 s that open and copy don't account for happens before the first Open, also on a later read.

   Candidates:

   • work between New-CapJournalTransaction and the first Open in callers (for example Get-CapJournalNames directory enumeration);
   • script-block or AMSI cost per invocation.

   Fix direction: start the per-object I/O budget at the first Open attempt, keep the absolute lease deadline as the hard bound, and report pre-open elapsed time in the failure message, failure path only.
2. coneilen commented on Oct 16, 2026

   

   coneilen

   on Oct 16, 2026

   CollaboratorAuthor

   More actions

   Tracking relationship (operator-directed): #846, #849 and #851 form the capture-core flake set. This is an administrative grouping of distinct intermittent failures, not a claim that their root causes are identical or proven harmless flakes. #846 tracks actor exit/kernel/both-EOF evidence; #849 tracks unavailable Process Handle/Id during Snapshot attestation; #851 tracks journal per-object budget ownership/pre-open timing. Preserve each failed attempt and its exact signature independently; a passing diagnostic is not a source fix or causal explanation. Current execution order is #851 first, parked #850 mechanical rebase/requalification after that merge, then #849, then the separately leased live B attempt. No retry, gate weakening or live execution is granted by this comment.
3. coneilen commented on Oct 16, 2026

   

   coneilen

   on Oct 16, 2026

   CollaboratorAuthor

   More actions

   #852's new failure-only artifact upload worked on its first real failure, and its preOpenMs data localizes the cost.

   Windows-2025 job 117246916321 failed on real argument vector preserves an empty string and Unicode. The artifact file argument-vector/output/diagnostics/journal-read-observations.jsonl shows one Read-CapJournalSnapshot transaction:

   Decision	totalElapsedMs	Notes
   ReadVerified (seq 1)	98.4	preOpenMs 44.9, openMs 0.33, copyMs 2.45
   AcceptedLiveSequenceOnly (seq 1)	895.3
   DeadlineExhausted	1979.8

   Open and copy are about 3 ms, and pre-open is about 45 ms. Moving the clock to the first Open attempt (#852's change) therefore doesn't address the cost. The roughly 1.9 s goes elsewhere, in the gaps after each success-path Write-CapJournalObservation call:

   • ReadVerified → AcceptedLiveSequenceOnly (about 800 ms) covers the ReadVerified observation write plus Get-CapJournalNames.
   • AcceptedLiveSequenceOnly → DeadlineExhausted (about 1084 ms) covers only the AcceptedLiveSequenceOnly observation write before the next Assert-CapJournalTime.

   Write-CapJournalObservation opens in Append mode and calls Flush($true), which is FlushFileBuffers, a synchronous disk flush. On hosted runners that apparently costs up to about 1 s per call.

   Correction to the earlier record: the "flushed write inside the budget" mechanism from #845 was right. #845 removed only one of the three success-path flushed observation writes, CopyCompleted. ReadVerified and AcceptedLiveSequenceOnly still flush inside the window.

   Next fix: success-path observation writes must not perform a synchronous disk flush inside the transaction budget. An OS-buffered Flush() keeps the records durable across process termination, including kill-on-close. Leave the budget value unchanged.
4. coneilen

   added a commit that references this issue on Oct 17, 2026

   Keep journal retry observations buffered until terminal failure (#852)

   ...

   77ec221
5. coneilen commented on Oct 17, 2026

   

   coneilen

   on Oct 17, 2026

   CollaboratorAuthor

   More actions

   Confirmation evidence: PR #852 was squash-merged as 77ec22136a99f55e7d0be00ce37979525753a57f at 2026-10-17T01:58:48Z, from exact reviewed R3 head bd6bb43a3850f418a5d9219799d1fbb50944cac8 and canonical body SHA-256 5173FC06EE6CABB374D6975140F92FBF8AB591EB48040B2556C0CE898539805F.

   Both required hardening jobs passed on the FIRST attempt, without any diagnostic rerun:

   • Windows-2022 job 117272004103: actual UiCaptureDriver 72 executed / 72 passed / 0 failed, plus ValidationRunner.Tests.ps1: PASS.
   • Windows-2025 job 117272004091: actual 72/72/0, plus ValidationRunner.Tests.ps1: PASS.

   Each retained whole job log contains exactly one JournalUnavailable string: the evidenced PASSing intentionally blocked observer-sink fixture diagnostic. No real/unclassified reader timeout or failing actor-cleanup case appeared in either run. Raw job-log SHA-256: Windows-2022 ADD17ABED3531ABAFE6B122914C6BF5D3BF91F4C5A0D5EB88967B0E8B1F12E35; Windows-2025 B0EFCD95F83ED05952B2533D163E490D25B94AA567A29F6152E4DC6CD3949FC9.

   All nine required contexts and all nonrequired checks were accepted. Ready was requested at 01:55:46.4898393Z; a NEW Ready-event DCO run 38992894522, created at 01:55:50Z, passed before merge. The earlier synchronize DCO was not reused as Ready evidence. Final head/body/main/one-commit/five-file/review/CLEAN guards passed; a private compare-response metadata binding was corrected before Ready, without source changes, check bypass or CI rerun.

   Persistence was independently checked: merge parent is 95a12681d6d3a6bbc3e1c64992489dd4d04f2863; whole tree d057d02a23ed68052a26be61b7530aa747e3a7f8 equals the reviewed tree; all eight qualified raw Git blobs and SHA-256 values match on the merged commit. The local R3 contained run separately passed 75/75 with retained lifecycle/journal proofs. Its disclosed concurrent D: deletion remains in the evidence; that local pass was accepted without a replacement or any claim of zero I/O impact.

   This confirms the terminal-only durability policy on this hosted head, not a universal historical-cause or flakiness claim. Earlier failures remain preserved, including the R2 real reader timeout masked behind #846-shaped actor cleanup; see the recovered-primary record. Whole-observation timing is not isolated FlushFileBuffers timing. No GUI, visual parity, accessibility or macOS safety claim follows.

   Leaving #851 OPEN for additional hosted Windows-2025 confirmation, including rebased #850. Closure will be proposed only after the further required runs are green. Next is the separate pre-existing production observer-mask issue, then mechanical #850 rebase, then #849; no live B admission is implied.
6. coneilen commented on Oct 17, 2026

   

   coneilen

   on Oct 17, 2026

   CollaboratorAuthor

   More actions

   Closing as completed. Both hardening jobs passed on the first attempt across two independent heads since the fix, and both fixes are merged:

   • Keep journal retry observations buffered until terminal failure #852 (merged 77ec2213), head bd6bb43a: windows-2022 and windows-2025 both passed 72/72 on the first attempt.
   • Retain bounded selector-refusal evidence without observing successful waits #850 (rebased, merged 206a7dbc), head 5a37cd6e: windows-2022 and windows-2025 both passed 85/85 on the first attempt.

   On both heads, every JournalUnavailable line in the logs was the expected line from the passing observer-sink fixture; there was no real timeout.

   Root cause, as confirmed by the artifacts uploaded on failure: journal observation writes called Flush($true) (FlushFileBuffers) inside the 1000 ms per-object budget. That covered success-path writes and the retryable OpenFailed writes, and each forced write could take hundreds of milliseconds to about 1 s on hosted runners. #852 starts the budget at the first Open, and only terminal observations now flush durably. The budget value and retry semantics are unchanged.

   Related issues that remain open:

   • Windows-2025 journal actor cleanup intermittently lacks exit and EOF proof #846: the hypothesis that actor-cleanup failures masked the reader's JournalUnavailable is unproven.
   • Preserve primary journal errors when failure-observation writes fail #853: a failure-observation write error can still mask the primary error.
7. coneilen

   closed this as completedon Oct 17, 2026