Repository navigation
Concurrent native hook capture times out acquiring shared spool admission #3188
Description
Activity
Measured follow-up confirms a preparation omission, although the original CI timeout was not reproduced locally. Existing tracing captured all four native hook children: first commit took 49.0 ms including 6.19 ms data sync and 42.6 ms directory sync; sibling commit-lock admission waited 43.6, 59.0, and 55.4 ms. Writer admission was only 0.002–5.35 ms.
publish_daemon_bindingsopens then drops each capture spool before exposing its binding. This prepares creation but leaves the exact records file without a committed extent/directory durability barrier. Consequently the first live callback pays that cold barrier under the shared commit lock. Ordinarycommit()intentionally does nothing when the handle appended no frames, so calling it unchanged would not prepare this boundary.Planned narrow fix: explicit daemon preparation consumes the opened spool, releases its writer lease, and invokes existing
commit_recordsfor its exact observed identity and extent before binding publication. Preserve current identity checks, group commit, reset behavior, and all budgets. Add direct preparation and daemon-publication behavior coverage, rerun concurrent real captures, and compare existing spans. No claim yet that this alone explains the original CI failure.Candidate verification: all 54 spool tests pass, including a new regression that verifies the exact empty records identity has committed extent 0, no pending record, first real sequence 1, one data-only barrier for first capture, and reset invalidation. The real daemon binding publication regression passes and proves repeat preparation needs zero additional barriers.
The same 12-client storage journey passed after the fix with all four hook child traces captured. Capture times were 3.44/2.25/2.90/2.45 ms (baseline 52.3–62 ms). Commit-lock waits were 0.770/0.809/1.11/1.33 microseconds (baseline sibling waits 43.6–59 ms); data syncs were 0.599–2.28 ms. No callback emitted a
hooks.spool.fsync.commit_directoryspan, confirming the directory barrier moved to daemon preparation. Timing comparisons are separate runs and include normal scheduling/storage variance; the removed callback directory barrier is the direct behavioral evidence.No deadline/retry changes. Temporary test instrumentation removed. The original CI timeout was not locally reproduced; the measured cold preparation omission is fixed in the candidate. Bazel logs:
bazel-testlogs/crates/tracedecay-hooks/unit_test/test.log,bazel-testlogs/crates/tracedecay-agent-hosts/unit_test/test.log, andbazel-testlogs/crates/tracedecay/storage_suite/test.log.Follow-up review #3200 (comment) identifies a possible remaining cold preparation gap: fresh
opencaches a checkpoint with no records-file revision;preparethen creates the empty records file without updating that checkpoint. The first callback can consequently rescan/rewrite the checkpoint under the writer lease.Validating with a behavioral regression that the first open after preparation reuses its checkpoint and retains zero pending records/sequence 1. If confirmed, update through the existing checkpoint authority while the preparation writer lease is held; no timing-budget changes.
Confirmed the follow-up checkpoint gap with RED/GREEN evidence: adding
!report.checkpoint_rewrittenon the first open after preparation failed against the prior candidate. The fix refreshes the checkpoint through canonicalwrite_checkpointonly when preparation creates a previously absent records file, while still holding the writer lease; release-before-commit ordering is unchanged. Existing records files do not get rewritten.GREEN: all 54 spool tests pass, including exact empty extent/reset/sequence and first-open checkpoint reuse; daemon publication regression passes with checkpoint-reuse and no-extra-barrier assertions. Both affected Bazel Clippy targets pass. No deadline/retry changes or additional instrumentation.
Master CI run37746919534 Linux storage_suite fails multi_connection_test::twelve_mcp_cli_and_hook_clients_share_one_daemon_profile_store_owner: three concurrent native captures return AdmissionTimedOut at ownership.rs160. Both spool writer and commit locks map to this error; commit includes file and directory fsync. CI has no span evidence identifying which lock held the admission.
Reproduce with existing tracing spans and fix measured work or incorrect fixture synchronization; preserve all12 client checks, ownership guarantees, and existing budgets.
https://github.com/ScriptedAlchemy/tracedecay/actions/runs/37746919534
A corrected focused Bazel run captured actual span-close timing from all four hook child processes, with the real test passing in 2.96 seconds:
This identifies durable commit admission, particularly directory sync, as the expensive measured phase; the original 100 ms admission failure did not reproduce. Temporary instrumentation was removed. No timeout or retry was changed. Further analysis is checking whether unnecessary directory sync or serialized work remains in the canonical commit path.
Commit 59fdad2 prepares the capture records file and its durable directory entry before daemon binding publication. It captures the exact identity/extent while holding the writer lease, releases that lease, then uses the existing canonical commit authority. Empty preparation creates no event or sequence; reset invalidates the old synced extent.
Verification:
The phase removal is direct evidence; absolute before/after timings also reflect scheduling and storage variability. The original CI admission timeout has not been independently reproduced. No deadline or retry increase was made.
Native Linux verification is now complete at commit 5ac8f07, whose source includes the preparation before binding publication:
multi_connection_test::twelve_mcp_cli_and_hook_clients_share_one_daemon_profile_store_owner. Verified from the archived bazel-test-logs-Linux artifact. The overall Linux job failed on a separate cancellation fixture; this storage suite passed.The measured unnecessary commit phase is removed and the original native Linux regression passes with all twelve clients and the existing budgets preserved. The original transient 100 ms failure was not independently reproduced.