From e7cd2f21c4f60c861939d78a922f1cc23843a840 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 6 Nov 2026 10:51:22 -0500 Subject: [PATCH 01/10] Rank recurrent Mac response failure and specify attribution #1178 --- docs/BACKLOG.md | 23 ++++++++++++------- .../reference/mac-command-attribution-1178.md | 9 ++++++++ 2 files changed, 24 insertions(+), 8 deletions(-) create mode 100644 docs/reference/mac-command-attribution-1178.md diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 573df4a6..c63a6dad 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8,17 +8,24 @@ Specifications and acceptance: [resumed reliability work](reference/resumed-reli | Rank | State | Issue | Scope | Active effort estimate | Hosted/external time | |---|---|---|---|---|---| -| 1 | Done | #1146 | Reproduced stale shell decision, fixed and live-verified warm/cold; #1173 merged. Original host/share scenario acceptance remains tracked in the open issue. | About 25 min active, versus 120 allocated | Final CI completed while next items progressed | -| 2 | Now | #1171 | Attribute actual 1080p-to-720p receive changes without lowering quality; distinguish application requests from SDK/provider behavior. | 90 min, range 60–150 | Controlled remote sender/account changes may be unavailable | -| 3 | Done | #1172 | Single multiview placeholder; shell, negative/fixed compiled and hosted checks passed; #1175 merged. | Within 45 min allocation | CI overlapped with next work | -| 4 | Now | #919 | Fence deferred participant-list callbacks across window teardown; prove no stale XAML access. | 45 min, range 30–75 | Compiled lifetime probe and CI | -| 5 | Now | #1177 | Attribute and repair the newly observed Program recording misses beside long ISO-ingress holds; preserve quality and original failed evidence. | 90 min, range 60–150 | Controlled reproduction, native validation and comparable live test | -| 6 | Reserve | #1074 | Qualify Tiles hold/recovery/video-off behavior through the real runtime; fix only demonstrated discrepancies. | 60 min, range 45–90 | Live remote interruption control may limit acceptance | -| 7 | Conditional | #443 / #989 / #1056 | Matched camera/readiness preflight then full output test if prerequisites are met. Preserve NOT JUDGED when they are not. | 60 min, range 45–90 | 30 min measured run plus decode; camera identity/elevation prerequisite | -| Intake | Later | #1178 | Attribute retained Mac show-drill p99 failure on unchanged native source without relaxing the gate. | Reforecast after log review | Hosted source/baseline comparison | +| 1 | Done | #1146 | Stale shell recommendation reproduced, fixed and live-verified warm/cold; #1173 merged. Broader host/share acceptance remains in the open issue. | About 25 min active versus 120 allocated | Hosted checks overlapped next work | +| 2 | Await reproduction | #1171 | Bounded SDK response evidence and live comparisons complete; #1174 merged after all 17 checks. Original downward transition remains unreproduced; later startup ramp is retained separately. | Diagnostic slice complete within allocation | Requires recurrence or controlled sender/account changes for causal closure | +| 3 | Done | #1172 | Single multiview placeholder; 1981 shell tests, negative/fixed compiled captures and all 17 hosted checks passed; #1175 merged. | Within the 45 min allocation | CI completed alongside live geometry work | +| 4 | Done | #919 | #1176 merged after 1991 shell tests, ten failing old-workspace assertions, passing compiled lifecycle checks and all 17 hosted checks. | Within 75 min active upper range including clean-publish recovery | Hosted runner shortage retried with retained evidence; prior Mac performance failure remains #1178 | +| 5 | Now | #1177 | Investigate the newly observed Program recording miss beside 11.6 ms of ISO ingress; preserve loss evidence and quality. [Spec](reference/program-iso-deadline-1177.md). | 90 min, range 60–150 | Controlled causal reproduction, native tests and comparable live recording | +| 6 | Await gate | #1074 | Actual D3D11 picture fixture and 39 Tiles regressions pass; disabling black painting fails the pixel assertion. #1180 merge held on the actual Mac command p99 failure tracked in #1178. | About 15 min active qualification work | No retry-until-green; remote interruption/owner policy acceptance remain separate | +| 7 | Now | #903 | Preserve truthful monitor counters across mute/disable/reenable and observe suppression/priming/starvation without hiding raw failures. | 90 min, range 60–150 | Local endpoint/lifecycle rehearsal after native validation | +| 8 | Conditional | #443 / #989 / #1056 | Matched camera/readiness preflight then full output test if prerequisites are met. Preserve failures and NOT JUDGED dependencies. | 60 min, range 45–90 | 30 min measured run plus decode; camera identity/elevation prerequisite | +| 9 | Now | #1178 | Recurrent Mac command p99 failure blocks #1180. Retain both failures and add bounded command/reader timing evidence before a controlled comparison. [Spec](reference/mac-command-attribution-1178.md). | 45 min initial attribution, then reforecast | Remote Mac job; keep 100 ms gate and all repeat outcomes | Allocation baseline: 20 min baseline/planning, 120 Auto, 90 resolution, 45 empty-state, 45 teardown, 60 Tiles, 60 conditional output work, 40 validation/report/replenishment reserve = 480 min. These are adjustable allocations, not permission to stop after one fixed list. Use blocked conditional time for the next actionable issue. Owner-deferred #513, business/credential acquisition, public-provider posting and speculative feature expansion are not silently resumed. +09:03 reforecast: roughly 6h33 remain. The new recorded output failure #1177 takes the freed #1172 slot under the owner's replenishment instruction. Allocate up to 150 minutes to attribution/fix/validation before reforecast, with #919 hosted work overlapping; reuse remaining capacity for the next unblocked reserve. No full-output pass is claimed from stable input geometry or successful writer startup. + +09:40 reforecast: 5h56 remain. Auto and empty-state fixes are merged; resolution evidence and participant lifetime fixes await final hosted gates. The second #1177 recording comparison is running at eight actual 1080p feeds after a documented 720p startup ramp. Narrowed timing places repeated multi-millisecond stalls inside admission, with negligible arrival transfer and leaf-lock wait. Reserve up to 100 further minutes for causal attribution/repair and native validation, then reforecast; preserve 90 minutes for matched packaging/output evidence and use freed capacity for #1074/#903. Record a diagnostic result as such, not as a repaired output deadline. + +10:15 reforecast: 5h21 remain. #919 merged and frees the #903 slot. #1177 now has live attribution, a failing old-ownership control and passing corrected focused tests; full native checks are running. Target the next 60–90 minutes for an integrated packaged recording comparison and decoded Program/ISO evidence, while #903 source work progresses without overlapping local builds with measurement. #1074 took less active work than allocated because existing production fixtures were reusable; its freed allocation remains available for #903 and fresh intake after the next milestone. No completed batch ends this window. + ## Active four-hour follow-on — November 5 23:48 to November 6 03:48 Eastern diff --git a/docs/reference/mac-command-attribution-1178.md b/docs/reference/mac-command-attribution-1178.md new file mode 100644 index 00000000..a199a23c --- /dev/null +++ b/docs/reference/mac-command-attribution-1178.md @@ -0,0 +1,9 @@ +# Mac command response attribution — #1178 + +Two real show-drill samples exceeded the 100 ms command-response gate: 135.9 ms on a Windows-only workspace PR and 240.4 ms on a Windows-guarded Tiles fixture PR. Neither changed the Mac media implementation. This narrows patch attribution but does not establish runner contention or a product cause. An infrastructure cancellation with zero executed steps is separate from these executed failures. + +The existing aggregate p99 loses the step identity, command types and timing boundary. Preserve bounded per-request evidence: relative monotonic start, caller-observed duration, response-reader timing, command type names, timeout outcome and nearby bounded diagnostic lines. Never serialize command arguments or whole snapshots into this report. Reader timing describes when Python received/parses a response, not native execution time. A reader delay cannot by itself prove OS scheduling contention. + +The existing 100 ms gate and request population remain unchanged. Generate an evidence artifact on success and failure, including early timeout returns. Hosted CI retains it even when the drill fails. Report any evidence truncation. Preserve the historical failed logs; a later green sample is not a repair or causal explanation. + +Validate with a controlled subprocess responding after a deliberate delay, a caller polling delay, and a missing response. The same measured request must still enter the aggregate gate population exactly once; timeouts remain failures. Run one instrumented hosted sample and compare the named slow step with contemporaneous evidence. Reproduce a demonstrated initiating condition before changing product code. If the cause remains unknown, keep the issue and blocked qualification visible rather than increasing the budget or claiming closure. From f98fcb7ea3bb13f26c23235b1acdcb6ca7dd9a7e Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 6 Nov 2026 10:51:22 -0500 Subject: [PATCH 02/10] Retain per-command Mac rehearsal timing without relaxing gates #1178 --- .github/workflows/ci.yml | 11 +++- scripts/mac-show-drill.py | 63 ++++++++++++++++---- scripts/qa/test_mac_show_timing.py | 82 ++++++++++++++++++++++++++ scripts/tests/mac-show-timing.test.mjs | 12 ++++ 4 files changed, 155 insertions(+), 13 deletions(-) create mode 100644 scripts/qa/test_mac_show_timing.py create mode 100644 scripts/tests/mac-show-timing.test.mjs diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 6d9c06e4..fec75f5d 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -82,7 +82,7 @@ jobs: # THE REAL GATE IS LOCAL, same as the loaded step below. Drop the flag the # day CI runs on a machine that can sustain 60 Hz. - name: Show drill - run: python3 scripts/mac-show-drill.py --seconds 25 --advisory-recorded-rate + run: python3 scripts/mac-show-drill.py --seconds 25 --advisory-recorded-rate --evidence artifacts/show-drill/command-timing.json # Production wall under load: synthetic 1080p60 Zoom feeds through the real # ingest path. Gates sustained fps, frame DELIVERY and coreMutex hold — the # class that made the port look slow for weeks. @@ -109,7 +109,14 @@ jobs: # removal the day CI runs on a machine that can source 1.5GB/s. - name: Show drill (8x1080p60 load) — advisory, see comment continue-on-error: true - run: python3 scripts/mac-show-drill.py --load 8 --seconds 25 + run: python3 scripts/mac-show-drill.py --load 8 --seconds 25 --evidence artifacts/show-drill/loaded-command-timing.json + - name: Retain command timing evidence, including failures + if: always() + uses: actions/upload-artifact@v4 + with: + name: mac-show-command-timing + path: artifacts/show-drill/*command-timing.json + if-no-files-found: warn mac-shell-design-lint: runs-on: ubuntu-latest diff --git a/scripts/mac-show-drill.py b/scripts/mac-show-drill.py index 3fa007c8..bc612eee 100644 --- a/scripts/mac-show-drill.py +++ b/scripts/mac-show-drill.py @@ -119,12 +119,17 @@ def _zoom_video_reserve_ms(): class Core: - def __init__(self, path, env=None): + def __init__(self, path, env=None, evidence_path=None): self.proc = subprocess.Popen( [path], stdin=subprocess.PIPE, stdout=subprocess.PIPE, stderr=subprocess.PIPE, text=True, bufsize=1, env={**os.environ, **(env or {})}) self.responses = {} + self.response_times = {} + self.evidence_path = evidence_path + self.started_at = time.monotonic() + self.request_evidence = [] + self.evidence_truncated = 0 self.events = [] self.stderr = [] self.next_id = 1 @@ -134,11 +139,13 @@ def __init__(self, path, env=None): def _read_stdout(self): for line in self.proc.stdout: + received_at = time.monotonic() try: obj = json.loads(line) except json.JSONDecodeError: continue if obj.get("id"): + self.response_times[obj["id"]] = (received_at, time.monotonic()) self.responses[obj["id"]] = obj elif obj.get("type"): self.events.append(obj) @@ -147,29 +154,62 @@ def _read_stderr(self): for line in self.proc.stderr: self.stderr.append(line.rstrip()) - def request(self, body, timeout=6.0): + def request(self, body, timeout=6.0, step=None): rid = f"drill-{self.next_id}" self.next_id += 1 body = dict(body, id=rid) - started = time.time() + started = time.monotonic() + diagnostic_start = len(self.stderr) self.proc.stdin.write(json.dumps(body, separators=(",", ":")) + "\n") self.proc.stdin.flush() deadline = started + timeout # 1ms poll: this now measures OPERATOR RESPONSIVENESS (the round trip a # Take rides), so a 10ms poll would be most of the number being measured. - while time.time() < deadline: + while time.monotonic() < deadline: if rid in self.responses: - self.round_trips.append((body.get("type", "?"), time.time() - started)) + finished = time.monotonic() + self.round_trips.append((body.get("type", "?"), finished - started)) + self._observe_request(rid, body, step, started, finished, diagnostic_start, False) return self.responses[rid] time.sleep(0.001) + self._observe_request(rid, body, step, started, time.monotonic(), diagnostic_start, True) return None - def sync(self, commands, elapsed_ms): + def _observe_request(self, rid, body, step, started, finished, diagnostic_start, timed_out): + if len(self.request_evidence) >= 4096: + self.evidence_truncated += 1 + return + reader = self.response_times.get(rid) + diagnostics = [line for line in self.stderr[diagnostic_start:] + if line.startswith(("[render]", "[lock-guardrail]", "[video-out]"))] + self.request_evidence.append({ + "id": rid, "type": body.get("type", "?"), "step": step, + "commandTypes": [command.get("type", "?") for command in body.get("commands", [])], + "startMs": (started - self.started_at) * 1000, + "durationMs": (finished - started) * 1000, "timedOut": timed_out, + "readerReceivedMs": (reader[0] - started) * 1000 if reader else None, + "readerParseMs": (reader[1] - reader[0]) * 1000 if reader else None, + "callerAfterReaderMs": (finished - reader[1]) * 1000 if reader else None, + "diagnostics": diagnostics[-12:], "diagnosticsOmitted": max(0, len(diagnostics) - 12), + }) + + def sync(self, commands, elapsed_ms, step=None): return self.request({"type": "media-core-sync", "elapsedMs": elapsed_ms, - "commands": commands}) + "commands": commands}, step=step) def kill(self): self.proc.kill() + self.proc.wait(timeout=10) + if self.evidence_path: + os.makedirs(os.path.dirname(os.path.abspath(self.evidence_path)), exist_ok=True) + with open(self.evidence_path, "w", encoding="utf-8") as output: + json.dump({"clock": "monotonic", "commandP99LimitMs": MAX_COMMAND_P99_MS, + "requestsOmitted": self.evidence_truncated, + "requests": self.request_evidence, + "scope": "Caller/reader timing, not native execution attribution; no command arguments"}, output, indent=2) + print(f"Command timing evidence: {self.evidence_path} ({self.evidence_truncated} omitted)") + for request in sorted(self.request_evidence, key=lambda row: row["durationMs"], reverse=True)[:5]: + print("Command timing: " + json.dumps(request, separators=(",", ":"))) def route(route_id, index=0, capture=None): @@ -259,6 +299,7 @@ def main(): parser = argparse.ArgumentParser() parser.add_argument("--seconds", type=float, default=40.0) parser.add_argument("--core", default=DEFAULT_CORE) + parser.add_argument("--evidence", default=os.path.join(REPO, "artifacts", "show-drill", "command-timing.json")) # The recorded-rate gate measures the MACHINE as much as the code, and a # shared CI runner cannot hold 60 Hz: measured on macos-14 across three # commits with identical code paths, the COMPOSITOR itself rendered 48.7, @@ -286,14 +327,14 @@ def main(): return 1 failures = [] - core = Core(args.core, env=load_env(args.load) if args.load else None) + core = Core(args.core, env=load_env(args.load) if args.load else None, evidence_path=args.evidence) time.sleep(1.5) # Production mode intentionally suppresses the frame/timing lines this # performance harness evaluates. Opt in through the same live command as # the Health switch so a green drill still proves the diagnostic path. diagnostics = core.sync( - [{"type": "set-verbose-diagnostics", "enabled": True}], 0) + [{"type": "set-verbose-diagnostics", "enabled": True}], 0, step="enable-diagnostics") if diagnostics is None: print("FAIL enabling verbose diagnostics timed out") core.kill() @@ -301,7 +342,7 @@ def main(): if args.load: joined = core.request({"type": "zoom-join", "payload": { - "meetingNumber": "1234567890", "displayName": "show-drill"}}, timeout=20.0) + "meetingNumber": "1234567890", "displayName": "show-drill"}}, timeout=20.0, step="synthetic-join") if joined is None: print("FAIL zoom-join timed out") core.kill() @@ -313,7 +354,7 @@ def main(): def step(name, commands, elapsed): nonlocal timeouts - response = core.sync(commands, elapsed) + response = core.sync(commands, elapsed, step=name) if response is None: timeouts += 1 failures.append(f"{name}: request TIMED OUT") diff --git a/scripts/qa/test_mac_show_timing.py b/scripts/qa/test_mac_show_timing.py new file mode 100644 index 00000000..c0f81a5e --- /dev/null +++ b/scripts/qa/test_mac_show_timing.py @@ -0,0 +1,82 @@ +import contextlib +import importlib.util +import io +import json +import pathlib +import subprocess +import sys +import tempfile +import time +import unittest +from unittest import mock + +spec = importlib.util.spec_from_file_location("show_drill", pathlib.Path(__file__).parents[1] / "mac-show-drill.py") +drill = importlib.util.module_from_spec(spec) +spec.loader.exec_module(drill) +REAL_POPEN = subprocess.Popen +REAL_SLEEP = time.sleep + +CHILD = """ +import json,sys,time +for line in sys.stdin: + request=json.loads(line) + if request.get('type') == 'no-response': continue + time.sleep(request.get('testDelay', 0)) + print(json.dumps({'id': request['id'], 'ok': True}), flush=True) +""" + + +class CommandTiming(unittest.TestCase): + def setUp(self): + self.temp = tempfile.TemporaryDirectory() + self.path = pathlib.Path(self.temp.name) / "timing.json" + with mock.patch.object(drill.subprocess, "Popen", side_effect=lambda *a, **kw: + REAL_POPEN([sys.executable, "-u", "-c", CHILD], **kw)): + self.core = drill.Core("controlled-child", evidence_path=str(self.path)) + self.core.request({"type": "ping"}) # exclude process startup from delay attribution + + def tearDown(self): + with contextlib.redirect_stdout(io.StringIO()): + self.core.kill() + self.temp.cleanup() + + def test_delayed_response_remains_in_gate_and_keeps_step_identity_without_arguments(self): + result = self.core.request({"type": "media-core-sync", "testDelay": .15, + "commands": [{"type": "take", "secret": "never-report-this"}]}, step="operator-take") + self.assertTrue(result["ok"]) + row = self.core.request_evidence[-1] + self.assertEqual(row["step"], "operator-take") + self.assertEqual(row["commandTypes"], ["take"]) + self.assertGreaterEqual(row["readerReceivedMs"], 140) + syncs = [duration for name, duration in self.core.round_trips if name == "media-core-sync"] + self.assertEqual(len(syncs), 1) + self.assertGreater(syncs[0] * 1000, drill.MAX_COMMAND_P99_MS) + self.assertAlmostEqual(row["durationMs"], syncs[0] * 1000) + self.assertNotIn("never-report-this", json.dumps(row)) + + def test_delayed_caller_does_not_disappear_from_gate(self): + with mock.patch.object(drill.time, "sleep", side_effect=lambda _: REAL_SLEEP(.2)): + self.core.request({"type": "media-core-sync", "testDelay": .02}, step="poll") + row = self.core.request_evidence[-1] + self.assertGreater(row["callerAfterReaderMs"], 100) + self.assertGreater(self.core.round_trips[-1][1] * 1000, drill.MAX_COMMAND_P99_MS) + + def test_timeout_is_retained_and_not_reported_as_answered(self): + before = len(self.core.round_trips) + self.assertIsNone(self.core.request({"type": "no-response"}, timeout=.05, step="timeout")) + row = self.core.request_evidence[-1] + self.assertTrue(row["timedOut"]) + self.assertIsNone(row["readerReceivedMs"]) + self.assertEqual(len(self.core.round_trips), before) + + def test_bounded_evidence_reports_omissions_without_changing_gate_population(self): + self.core.request_evidence = [self.core.request_evidence[0]] * 4096 + before = len(self.core.round_trips) + self.core.request({"type": "media-core-sync"}) + self.assertEqual(len(self.core.request_evidence), 4096) + self.assertEqual(self.core.evidence_truncated, 1) + self.assertEqual(len(self.core.round_trips), before + 1) + + +if __name__ == "__main__": + unittest.main() diff --git a/scripts/tests/mac-show-timing.test.mjs b/scripts/tests/mac-show-timing.test.mjs new file mode 100644 index 00000000..4ea08104 --- /dev/null +++ b/scripts/tests/mac-show-timing.test.mjs @@ -0,0 +1,12 @@ +import { test } from 'node:test'; +import assert from 'node:assert/strict'; +import { spawnSync } from 'node:child_process'; +import { fileURLToPath } from 'node:url'; + +test('show drill retains command delays, polling delays and timeouts without relaxing the gate', () => { + const result = spawnSync(process.env.COREVIDEO_TEST_PYTHON ?? (process.platform === 'win32' ? 'python' : 'python3'), + [fileURLToPath(new URL('../qa/test_mac_show_timing.py', import.meta.url))], + { encoding: 'utf8', timeout: 30000 }); + assert.ifError(result.error); + assert.equal(result.status, 0, result.stdout + result.stderr); +}); From 360415bda0c4ae2a360893c4143358ab27475b7b Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 6 Nov 2026 10:53:55 -0500 Subject: [PATCH 03/10] Track empty-roster ISO extension found in live rehearsal #1183 --- docs/BACKLOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index c63a6dad..f0ed6c9d 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -17,6 +17,7 @@ Specifications and acceptance: [resumed reliability work](reference/resumed-reli | 7 | Now | #903 | Preserve truthful monitor counters across mute/disable/reenable and observe suppression/priming/starvation without hiding raw failures. | 90 min, range 60–150 | Local endpoint/lifecycle rehearsal after native validation | | 8 | Conditional | #443 / #989 / #1056 | Matched camera/readiness preflight then full output test if prerequisites are met. Preserve failures and NOT JUDGED dependencies. | 60 min, range 45–90 | 30 min measured run plus decode; camera identity/elevation prerequisite | | 9 | Now | #1178 | Recurrent Mac command p99 failure blocks #1180. Retain both failures and add bounded command/reader timing evidence before a controlled comparison. [Spec](reference/mac-command-attribution-1178.md). | 45 min initial attribution, then reforecast | Remote Mac job; keep 100 ms gate and all repeat outcomes | +| Intake | Later | #1183 | ISO silence/held pictures resume after observed departures when roster becomes empty. Preserve the live evidence; reproduce the history transition before repairing departure semantics. | Next freed recording slot | Finalized file evidence pending; related #1030 | Allocation baseline: 20 min baseline/planning, 120 Auto, 90 resolution, 45 empty-state, 45 teardown, 60 Tiles, 60 conditional output work, 40 validation/report/replenishment reserve = 480 min. These are adjustable allocations, not permission to stop after one fixed list. Use blocked conditional time for the next actionable issue. Owner-deferred #513, business/credential acquisition, public-provider posting and speculative feature expansion are not silently resumed. From ba5fa8dac35058715d770365b8b62f74ae56d018 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 6 Nov 2026 13:42:33 -0500 Subject: [PATCH 04/10] diagnostics: retain native phases below the command response limit --- docs/BACKLOG.md | 21 +++++++++++------- .../reference/mac-command-attribution-1178.md | 8 +++++++ native/src/rpc/JsonRpcServer.cpp | 18 ++++++++++++++- native/src/rpc/ResponseAssemblyLane.h | 16 +++++++++++++- scripts/mac-show-drill.py | 21 +++++++++++++++--- scripts/qa/test_mac_show_timing.py | 22 +++++++++++++++++++ 6 files changed, 93 insertions(+), 13 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 39845a89..90126d52 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -14,12 +14,19 @@ Specifications and acceptance: [resumed reliability work](reference/resumed-reli | 4 | Done | #919 | #1176 merged after 1991 shell tests, ten failing old-workspace assertions, passing compiled lifecycle checks and all 17 hosted checks. | Within 75 min active upper range including clean-publish recovery | Hosted runner shortage retried with retained evidence; prior Mac performance failure remains #1178 | | 5 | Done slice / qualification pending | #1177 | Ownership repair #1179 merged. Negative control, 2082 native cases, four CTest suites and all 17 hosted checks passed. Anchored Program interval and eight ISO pixel identities passed; live feeds ended halfway through. [Spec](reference/program-iso-deadline-1177.md). | Attribution/repair slice complete | Full-length local workload still required; retain whole-file Program tail repeat and #1183 departure extension | | 6 | Await gate | #1074 | Actual D3D11 picture fixture and 39 Tiles regressions pass; disabling black painting fails the pixel assertion. #1180 merge held on the actual Mac command p99 failure tracked in #1178. | About 15 min active qualification work | No retry-until-green; remote interruption/owner policy acceptance remain separate | -| 7 | Await gate | #903 | Counter repair passed 2090 native cases, four CTest targets, old-code negative controls and the real GoXLR endpoint lifecycle probe. #1181 awaits its exact-head Mac job. | Implementation and local validation complete | Runner-acquisition cancellation retained; no actual test failure waived | +| 7 | Done | #903 | #1181 merged after real endpoint evidence, 2090 native cases and 17 hosted checks. | Within allocation | Original unexplained audible event remains separate | | 8 | Conditional | #443 / #989 / #1056 | Matched camera/readiness preflight then full output test if prerequisites are met. Preserve failures and NOT JUDGED dependencies. | 60 min, range 45–90 | 30 min measured run plus decode; camera identity/elevation prerequisite | -| 9 | Await hosted evidence | #1178 | Recurrent Mac command p99 failure blocks #1180. Bounded command/reader timing is in #1182 for one instrumented hosted sample. [Spec](reference/mac-command-attribution-1178.md). | Initial attribution slice implemented | Keep 100 ms gate and all repeat outcomes; local controlled transport checks follow the recording | -| 10 | Now | #1183 | ISO silence/held pictures resume after observed departures when roster becomes empty. Reproduce the history transition and preserve authoritative departure state. [Spec](reference/iso-roster-departure-1183.md). | 60 min, range 45–90 | Finalized file evidence and controlled departure recording; related #1030 | -| 11 | Now | #882 | Exercise the real Sources page with distinct moving native sources through unassign, replacement, swap, hide/reopen and recovery. [Spec](reference/source-thumbnail-acceptance-882.md). | 60 min, range 45–90 | Compiled GPU probe after the active output measurement; sampled pixels do not prove every transitional frame | -| 12 | Now | #1186 | Remove the observed duplicate final Program picture without truncating audio or weakening the pixel judge. [Spec](reference/program-recording-tail-1186.md). | 60 min, range 45–90 | Real MF file negative control, decoded audio/video endpoints and packaged close-time check | +| 9 | Now | #1178 | Recurrent Mac command p99 failure blocks #1180. Bounded command/reader timing is in #1182 for one instrumented hosted sample. [Spec](reference/mac-command-attribution-1178.md). | Additional native phase attribution: 30 min, range 20–45 | Keep 100 ms gate and all repeat outcomes; local controlled transport checks follow the recording | +| 10 | Done | #1183 | #1184 merged: all eight ISO counters stopped after departure while Program advanced 1200 pictures; files readable. | Within allocation | Overall rehearsal failed separately on #1186/#1188 and dual source epochs | +| 11 | Await gate | #882 | Compiled Sources lifecycle passes, wrong-pixel publication fails, restored fixture passes. PR #1185 merged after all 17 checks. | Within 90 min upper range | Sampled evidence does not prove every transitional frame | +| 12 | Await gate | #1186 | Whole packaged Program file passes: 5475 identities, zero duplicate final picture. [Spec](reference/program-recording-tail-1186.md). | Within allocation | #1187 exact-head hosted checks pending | +| 13 | Await gate | #1188 | Original session survives stream-first stop after departure; nine files finalize in one take. [Spec](reference/recording-source-loss-1188.md). | About 25 min investigation/implementation plus shared packaged validation | #1190 exact-head checks pending | +| 14 | Await gate | #1189 | Old consumer fails; 2095 native cases and all eight packaged ISO identity judgments pass with auto-subscribe enabled. [Spec](reference/iso-reader-owner-1189.md). | About 15 min implementation plus 10 min native suite and shared packaged validation | #1191 exact-head checks pending | +| 15 | Await gate | #941 | Stop scheduled Program delivery at explicit teardown without hiding active-output failures. [Spec](reference/program-shutdown-941.md). | 45 min, range 30–75 | 2099 native cases, actual RPC negative/restored control and isolated close traces pass; #1192 awaits hosted gates | + +12:55 reforecast: 2h41 remain. Local test beta 8c8e15b1qa has been handed to the owner after a 60.1005536-second eight-source Program/ISO/SRT regression and exact-session finalization. All eleven decoded judgments pass; this is not the 30-minute RC gate. The public beta still needs merges, exact main identity and hosted installer qualification. Keep its contents fixed. Use independent capacity for #941 while preserving the owner's local test session; replenish again when that slice finishes. + +12:22 reforecast: 3h14 remain. Monitor and departure repairs merged. Use freed capacity for the observed empty-take failure, finish Sources/final-picture acceptance, and preserve time for corrected integrated checks. The Mac diagnostic sample passed but did not explain the earlier failure; #1074 remains held. Replenish again if these slices finish early. Allocation baseline: 20 min baseline/planning, 120 Auto, 90 resolution, 45 empty-state, 45 teardown, 60 Tiles, 60 conditional output work, 40 validation/report/replenishment reserve = 480 min. These are adjustable allocations, not permission to stop after one fixed list. Use blocked conditional time for the next actionable issue. Owner-deferred #513, business/credential acquisition, public-provider posting and speculative feature expansion are not silently resumed. @@ -30,8 +37,6 @@ Allocation baseline: 20 min baseline/planning, 120 Auto, 90 resolution, 45 empty 10:15 reforecast: 5h21 remain. #919 merged and frees the #903 slot. #1177 now has live attribution, a failing old-ownership control and passing corrected focused tests; full native checks are running. Target the next 60–90 minutes for an integrated packaged recording comparison and decoded Program/ISO evidence, while #903 source work progresses without overlapping local builds with measurement. #1074 took less active work than allocated because existing production fixtures were reusable; its freed allocation remains available for #903 and fresh intake after the next milestone. No completed batch ends this window. -11:37 reforecast: 3h59 remain. The integrated eight-source Program/ISO/local-stream interval runs until approximately noon. #903 has full native and real endpoint evidence; #1183 has full native and failing-old-consumer evidence. Finish file judgments and exact-head gates after measurement, then merge only qualified slices. Use the third active slot for #882's missing compiled Sources identity evidence (up to 90 minutes), leaving at least 90 minutes for results-driven repairs and final integrated checks. Mac attribution remains waiting for a hosted runner; no repeat-until-green or quality downgrade. Replenish again when capacity frees. - ## Active four-hour follow-on — November 5 23:48 to November 6 03:48 Eastern The owner-authorized conditional batch is triggered: the initial bounded work finished before 06:00 with four merged fixes, passing regression/package gates, and two failed output warmups. Output acceptance remains failed; the next batch addresses the observed causes. This section is the sole current queue and supersedes the completed investigation order below. @@ -612,7 +617,7 @@ These can preempt Next on a show night. They do not jump the ranked Now item unt | [#804](https://github.com/iamfatness/CoreVideoPro/issues/804) | #517 measured follow-on: GPU-ready Program packets expired during scheduled shell/multiview export calls (16.6–19.4 ms); retained losses fail release qualification. Owner-promoted repair merged in [#809](https://github.com/iamfatness/CoreVideoPro/pull/809); six matched trials and full native/CI pass. Receiver/display, installed/fleet and lifecycle qualification remain. Remaining #802 work resumes. | | [#811](https://github.com/iamfatness/CoreVideoPro/issues/811) | Physical native MF HD60 S+ reconnect negotiated 1080p60, then failed before new frames with 0x8007001F during #802 qualification. The same failure reproduces with preparation off in both the candidate and installed October 5 beta. Initial capture passed; failures are retained. Attribution remains open. Unranked; does not independently preempt #802. | | [#807](https://github.com/iamfatness/CoreVideoPro/issues/807) | macOS Metal full native CI suite segfaulted on #806 after focused checks passed. Attribution unconfirmed; retain the failed trial, identify the test/stack and verify exact-head CI. Unranked; does not replace approved #802 work. | -| [#782](https://github.com/iamfatness/CoreVideoPro/issues/782) | Windows supervisor disposal queried an already-disposed Process in the crash lock-order CI test. Captured stack and run; attribution and focused fix need owner rank. **2026-10-25 (CI sweep A):** the exception that failed the run is fixed in the sweep-A PR: `DisposeChild` called `Process.HasExited` on a Process that never associated (a failed `Process.Start` leaves it in `_process`; a disposed one behaves the same), which threw out of `Stop`/`DisposeAsync`. That exception was the mask, not the cause: it hid an earlier failure of the lock-order test, presumed to be its 10 s `concurrentSync` wait timing out under thread-pool starvation on the hosted runner (unproven). The test's two workers now run on dedicated threads; three regression tests cover the disposal path. Keep open until a hosted run confirms. | +| [#782](https://github.com/iamfatness/CoreVideoPro/issues/782) | Windows supervisor disposal queried an already-disposed Process in the crash lock-order CI test. Captured stack and run; attribution and focused fix need owner rank. **2026-10-25 (CI sweep A):** the exception that failed the run is fixed in the sweep-A PR: `DisposeChild` called `Process.HasExited` on a Process that never associated (a failed `Process.Start` leaves it in `_process`; a disposed one behaves the same), which threw out of `Stop`/`DisposeAsync`. That exception was the mask, not the cause: it hid an earlier failure of the lock-order test, presumed to be its 10 s `concurrentSync` wait timing out under thread-pool starvation on the hosted runner (unproven). The test's two workers now run on dedicated threads; three regression tests cover the disposal path. 2026-11-06: closed after inspecting all five actual crash-lock/disposal results in the Windows TRX from run 42262314135; every case passed. The presumed masked-timeout cause remains unproven. | | [#784](https://github.com/iamfatness/CoreVideoPro/issues/784) | Screen/window capture flashes after asynchronous WGC lifecycle change: the shell rejects connecting and auto-retries, repeatedly restarting sessions. Fixed in merged #785 and beta `beta-2026-10-04-92e6b1e`: accepted pending requests are preserved and repeated connect is idempotent. Owner visual check was positive; installed capture alongside streaming acceptance remains. | | [#735](https://github.com/iamfatness/CoreVideoPro/issues/735) | Fixed: the CPU-fallback stream path delivered nothing from 2026-09-30 because shared-AAC routing withheld PCM from a sender that was not on the GPU path. Remaining: RTMP was not tested separately from SRT; owner acceptance on a machine without a hardware encoder. | | [#701](https://github.com/iamfatness/CoreVideoPro/issues/701) | Media playout video can stutter or freeze during a live show; identify decoder versus presentation. Had no row until the 2026-10-02 review. | diff --git a/docs/reference/mac-command-attribution-1178.md b/docs/reference/mac-command-attribution-1178.md index a199a23c..d25861b3 100644 --- a/docs/reference/mac-command-attribution-1178.md +++ b/docs/reference/mac-command-attribution-1178.md @@ -7,3 +7,11 @@ The existing aggregate p99 loses the step identity, command types and timing bou The existing 100 ms gate and request population remain unchanged. Generate an evidence artifact on success and failure, including early timeout returns. Hosted CI retains it even when the drill fails. Report any evidence truncation. Preserve the historical failed logs; a later green sample is not a repair or causal explanation. Validate with a controlled subprocess responding after a deliberate delay, a caller polling delay, and a missing response. The same measured request must still enter the aggregate gate population exactly once; timeouts remain failures. Run one instrumented hosted sample and compare the named slow step with contemporaneous evidence. Reproduce a demonstrated initiating condition before changing product code. If the cause remains unknown, keep the issue and blocked qualification visible rather than increasing the budget or claiming closure. + +## Follow-up after the 103 ms sample + +The latest hosted sample failed at enable-diagnostics: 102.969 ms total, with 98.548 ms before reader receipt, 1.997 ms parsing and 2.425 ms caller continuation. This does not attribute native execution versus transport/reader scheduling. Existing native request/writer warnings start at 500/200 ms and the report filtered those categories out, so a 103 ms failure can have no useful native phase evidence. + +Add opt-in verbose measurements for command queue, assembly-capacity wait, core-lock wait, handler and deferred-engine time; response assembly queue/projection/serialization/enqueue; and response-writer queue/flush. Use the existing bounded asynchronous logger, no command arguments or snapshots, and retain the normal warning thresholds and unchanged 100 ms acceptance gate. Keep a bounded 512-line native timing appendix with omission count and stderr-drain status because asynchronous diagnostics can arrive after the response. Receipt timestamps are not native timestamps or exact request correlation. Missing/dropped evidence stays unknown. + +Validate delayed post-response diagnostic delivery, bounded omissions, and unchanged gate population/privacy through the controlled subprocess. Compile and run native RPC regressions after the active recording measurement; use hosted Mac artifacts for causal attribution. A green sample alone still does not close this issue. This diagnostic work remains outside the frozen beta. diff --git a/native/src/rpc/JsonRpcServer.cpp b/native/src/rpc/JsonRpcServer.cpp index 0df9453d..ff0654cd 100644 --- a/native/src/rpc/JsonRpcServer.cpp +++ b/native/src/rpc/JsonRpcServer.cpp @@ -562,8 +562,9 @@ void JsonRpcServer::run(std::istream& input, std::ostream& output) { std::chrono::duration_cast(wStart - enqueuedAt).count(); output << message << '\n'; output.flush(); + const auto flushedAt = std::chrono::steady_clock::now(); const auto flushMs = std::chrono::duration_cast( - std::chrono::steady_clock::now() - wStart) + flushedAt - wStart) .count(); // A response that sat >500ms before it could be written, or any single // write that blocked >200ms in flush(), means the stdout pipe is the @@ -573,6 +574,12 @@ void JsonRpcServer::run(std::istream& input, std::ostream& output) { isResponse ? "RESPONSE" : "frame", static_cast(sojournMs), static_cast(flushMs), message.size(), hiDepth, loDepth); } + if (isResponse) { + ::corevideo::core::nativeVerboseLogf("[writer-timing] sojourn_us=%lld flush_us=%lld bytes=%zu\n", + static_cast(std::chrono::duration_cast(wStart - enqueuedAt).count()), + static_cast(std::chrono::duration_cast(flushedAt - wStart).count()), + message.size()); + } lock.lock(); } if (writerStopping.load() && outHi.empty() && outResources.empty() && outLo.empty()) { @@ -1231,6 +1238,7 @@ void JsonRpcServer::run(std::istream& input, std::ostream& output) { std::optional lockFreeResponse; std::optional deferredSpine; bool handledWithoutCore = false; + long long capacityWaitUs = 0, coreWaitUs = 0; if ((reqType == "zoom-leave" || reqType == "zoom-cancel") && (!request->get("protocolVersion") || contracts::validateProtocolVersion(*request->get("protocolVersion")))) { std::lock_guard lock(joinMx); @@ -1273,8 +1281,13 @@ void JsonRpcServer::run(std::istream& input, std::ostream& output) { response = std::move(*lockFreeResponse); } else { // Backpressure is admitted before acquiring the render lock. + const auto capacityStarted = std::chrono::steady_clock::now(); assembly.waitForCapacity(); + const auto capacityFinished = std::chrono::steady_clock::now(); auto lock = lockCommandCore(); + const auto coreAcquired = std::chrono::steady_clock::now(); + capacityWaitUs = std::chrono::duration_cast(capacityFinished - capacityStarted).count(); + coreWaitUs = std::chrono::duration_cast(coreAcquired - capacityFinished).count(); // #1048: an over-budget command hold names its command type in the // [lock-hold-attribution] line (production; [command-lock] is verbose only). const CommandHoldDetail commandDetail(reqType); @@ -1318,6 +1331,9 @@ void JsonRpcServer::run(std::istream& input, std::ostream& output) { const auto engineHalfMs = engineHalfUs / 1000; const auto heldMs = std::chrono::duration_cast(h1 - h0).count(); const auto heldUs = std::chrono::duration_cast(h1 - h0).count(); + ::corevideo::core::nativeVerboseLogf("[request-timing] type=%.80s queue_us=%lld capacity_us=%lld core_wait_us=%lld handle_us=%lld engine_us=%lld deferred=%u\n", + reqType.c_str(), static_cast(std::chrono::duration_cast(dequeuedAt - enqueuedAt).count()), + capacityWaitUs, coreWaitUs, static_cast(heldUs), engineHalfUs, capture ? 1u : 0u); if (heldUs > core::LockHoldGuardrail::kCommandHandleBudgetUs) { ::corevideo::core::nativeVerboseLogf("[command-lock] type=%.80s held_us=%lld engine_half_us=%lld capture_deferred=%u\n", reqType.c_str(), static_cast(heldUs), engineHalfUs, capture ? 1u : 0u); diff --git a/native/src/rpc/ResponseAssemblyLane.h b/native/src/rpc/ResponseAssemblyLane.h index 34819368..2583effc 100644 --- a/native/src/rpc/ResponseAssemblyLane.h +++ b/native/src/rpc/ResponseAssemblyLane.h @@ -1,5 +1,7 @@ #pragma once #include "core/CoreStateCapture.h" +#include "core/BoundedAsyncLog.h" +#include #include #include @@ -15,6 +17,7 @@ class ResponseAssemblyLane { std::unique_ptr capture; core::SnapshotProjection kind = core::SnapshotProjection::Session; std::string field; + std::chrono::steady_clock::time_point submittedAt; }; ResponseAssemblyLane(Assemble assemble, Deliver deliver) : assemble_(std::move(assemble)), deliver_(std::move(deliver)), worker_([this] { run(); }) {} @@ -25,6 +28,7 @@ class ResponseAssemblyLane { } // Single producer, after waitForCapacity and after releasing coreMutex. void submit(Job job) { + job.submittedAt = std::chrono::steady_clock::now(); { std::lock_guard lock(mutex_); pending_ = std::make_unique(std::move(job)); } ready_.notify_all(); } @@ -45,10 +49,20 @@ class ResponseAssemblyLane { } ready_.notify_all(); try { + const auto started = std::chrono::steady_clock::now(); auto projected = assemble_ ? assemble_(*job->capture, job->kind) : job->capture->assemble(job->kind); auto object = job->response.asObject(); object.insert_or_assign(job->field, std::move(projected)); - deliver_(Json(std::move(object)).stringify()); + const auto projectedAt = std::chrono::steady_clock::now(); + auto serialized = Json(std::move(object)).stringify(); + const auto serializedAt = std::chrono::steady_clock::now(); + deliver_(std::move(serialized)); + const auto deliveredAt = std::chrono::steady_clock::now(); + const auto us = [](auto elapsed) { return static_cast( + std::chrono::duration_cast(elapsed).count()); }; + core::nativeVerboseLogf("[response-timing] assembly_queue_us=%lld project_us=%lld serialize_us=%lld enqueue_us=%lld\n", + us(started - job->submittedAt), us(projectedAt - started), + us(serializedAt - projectedAt), us(deliveredAt - serializedAt)); } catch (const std::exception& e) { deliver_(Json(Json::Object{{"id", *job->response.get("id")}, {"ok", false}, {"error", Json::Object{{"code", "response-assembly-failed"}, {"message", e.what()}}}}).stringify()); diff --git a/scripts/mac-show-drill.py b/scripts/mac-show-drill.py index bc612eee..a1894944 100644 --- a/scripts/mac-show-drill.py +++ b/scripts/mac-show-drill.py @@ -116,6 +116,8 @@ def _zoom_video_reserve_ms(): MIN_LOAD_FPS = 59.5 MAX_LOAD_RENDER_MS = 10.0 MAX_DROPPED_FRAMES = 0 +NATIVE_TIMING_PREFIXES = ("[request-timing]", "[response-timing]", "[writer-timing]", + "[req]", "[cmd]", "[response]", "[writer]", "[command-lock]") class Core: @@ -132,10 +134,13 @@ def __init__(self, path, env=None, evidence_path=None): self.evidence_truncated = 0 self.events = [] self.stderr = [] + self.native_timing = [] + self.native_timing_omitted = 0 self.next_id = 1 self.round_trips = [] # (type, seconds) per answered request threading.Thread(target=self._read_stdout, daemon=True).start() - threading.Thread(target=self._read_stderr, daemon=True).start() + self.stderr_reader = threading.Thread(target=self._read_stderr, daemon=True) + self.stderr_reader.start() def _read_stdout(self): for line in self.proc.stdout: @@ -153,6 +158,12 @@ def _read_stdout(self): def _read_stderr(self): for line in self.proc.stderr: self.stderr.append(line.rstrip()) + if line.startswith(NATIVE_TIMING_PREFIXES): + if len(self.native_timing) < 512: + self.native_timing.append({"observedMs": (time.monotonic() - self.started_at) * 1000, + "line": line.rstrip()}) + else: + self.native_timing_omitted += 1 def request(self, body, timeout=6.0, step=None): rid = f"drill-{self.next_id}" @@ -181,7 +192,7 @@ def _observe_request(self, rid, body, step, started, finished, diagnostic_start, return reader = self.response_times.get(rid) diagnostics = [line for line in self.stderr[diagnostic_start:] - if line.startswith(("[render]", "[lock-guardrail]", "[video-out]"))] + if line.startswith(("[render]", "[lock-guardrail]", "[video-out]") + NATIVE_TIMING_PREFIXES)] self.request_evidence.append({ "id": rid, "type": body.get("type", "?"), "step": step, "commandTypes": [command.get("type", "?") for command in body.get("commands", [])], @@ -200,13 +211,17 @@ def sync(self, commands, elapsed_ms, step=None): def kill(self): self.proc.kill() self.proc.wait(timeout=10) + self.stderr_reader.join(timeout=1) if self.evidence_path: os.makedirs(os.path.dirname(os.path.abspath(self.evidence_path)), exist_ok=True) with open(self.evidence_path, "w", encoding="utf-8") as output: json.dump({"clock": "monotonic", "commandP99LimitMs": MAX_COMMAND_P99_MS, "requestsOmitted": self.evidence_truncated, "requests": self.request_evidence, - "scope": "Caller/reader timing, not native execution attribution; no command arguments"}, output, indent=2) + "nativeTiming": self.native_timing, + "nativeTimingOmitted": self.native_timing_omitted, + "stderrDrained": not self.stderr_reader.is_alive(), + "scope": "Caller/reader timing plus opt-in native phase durations; observedMs is stderr receipt time, not a native timestamp or request correlation; no command arguments"}, output, indent=2) print(f"Command timing evidence: {self.evidence_path} ({self.evidence_truncated} omitted)") for request in sorted(self.request_evidence, key=lambda row: row["durationMs"], reverse=True)[:5]: print("Command timing: " + json.dumps(request, separators=(",", ":"))) diff --git a/scripts/qa/test_mac_show_timing.py b/scripts/qa/test_mac_show_timing.py index c0f81a5e..2eff3d5d 100644 --- a/scripts/qa/test_mac_show_timing.py +++ b/scripts/qa/test_mac_show_timing.py @@ -23,6 +23,10 @@ if request.get('type') == 'no-response': continue time.sleep(request.get('testDelay', 0)) print(json.dumps({'id': request['id'], 'ok': True}), flush=True) + if request.get('nativeTimingCount'): + time.sleep(.02) # diagnostic logger can arrive after the response reader + for index in range(request['nativeTimingCount']): + print('[writer-timing] sojourn_us=7 flush_us=11 bytes=32', file=sys.stderr, flush=True) """ @@ -77,6 +81,24 @@ def test_bounded_evidence_reports_omissions_without_changing_gate_population(sel self.assertEqual(self.core.evidence_truncated, 1) self.assertEqual(len(self.core.round_trips), before + 1) + def test_late_native_phases_are_retained_with_bounded_omissions(self): + before = len(self.core.round_trips) + self.core.request({"type": "media-core-sync", "nativeTimingCount": 600, + "secret": "never-report-native-arguments"}) + deadline = time.monotonic() + 3 + while len(self.core.native_timing) + self.core.native_timing_omitted < 600 and time.monotonic() < deadline: + REAL_SLEEP(.001) + with contextlib.redirect_stdout(io.StringIO()): + self.core.kill() + evidence = json.loads(self.path.read_text()) + self.assertTrue(evidence["stderrDrained"]) + self.assertEqual(len(evidence["nativeTiming"]), 512) + self.assertEqual(evidence["nativeTimingOmitted"], 88) + self.assertTrue(all(row["observedMs"] >= 0 and "flush_us=11" in row["line"] + for row in evidence["nativeTiming"])) + self.assertNotIn("never-report-native-arguments", json.dumps(evidence)) + self.assertEqual(len(self.core.round_trips), before + 1) + if __name__ == "__main__": unittest.main() From fa448a79f1e7be993be5790acaeed73b70b82075 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 6 Nov 2026 13:48:34 -0500 Subject: [PATCH 05/10] test(diagnostics): include command timing regressions in CI script gate --- package.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/package.json b/package.json index ff7c1b09..6ca80924 100644 --- a/package.json +++ b/package.json @@ -46,7 +46,7 @@ "validate:tiles": "node scripts/validate-tiles.mjs", "qualify:redesign": "node scripts/qa/redesign-workload-verdict.mjs", "test:qa-harness": "node --test scripts/tests/av-content-analysis.test.mjs scripts/tests/av-content-decode.test.mjs scripts/tests/frame-performance.test.mjs scripts/tests/program-buffer-smoke.test.mjs", - "test:scripts": "node --test scripts/tests/camera-installation.test.mjs scripts/tests/release-evidence.test.mjs scripts/tests/av-content-analysis.test.mjs scripts/tests/av-content-decode.test.mjs scripts/tests/ffprobe-frame-pts.test.mjs scripts/tests/frame-performance.test.mjs scripts/tests/program-buffer-smoke.test.mjs scripts/validate-show-engine-judge.test.mjs scripts/qa/production-qualification.test.mjs scripts/qa/runtime-snapshot-qualification.test.mjs scripts/qa/take-verdict-judge.test.mjs scripts/qa/vcam-delivery-evidence.test.mjs scripts/qa/camera-pixel-receiver.test.mjs scripts/qa/publication-qa-evidence.test.mjs scripts/qa/redesign-workload-verdict.test.mjs scripts/tests/iso-pixel-evidence.test.mjs scripts/qa/iso-record-rules.test.mjs", + "test:scripts": "node --test scripts/tests/mac-show-timing.test.mjs scripts/tests/camera-installation.test.mjs scripts/tests/release-evidence.test.mjs scripts/tests/av-content-analysis.test.mjs scripts/tests/av-content-decode.test.mjs scripts/tests/ffprobe-frame-pts.test.mjs scripts/tests/frame-performance.test.mjs scripts/tests/program-buffer-smoke.test.mjs scripts/validate-show-engine-judge.test.mjs scripts/qa/production-qualification.test.mjs scripts/qa/runtime-snapshot-qualification.test.mjs scripts/qa/take-verdict-judge.test.mjs scripts/qa/vcam-delivery-evidence.test.mjs scripts/qa/camera-pixel-receiver.test.mjs scripts/qa/publication-qa-evidence.test.mjs scripts/qa/redesign-workload-verdict.test.mjs scripts/tests/iso-pixel-evidence.test.mjs scripts/qa/iso-record-rules.test.mjs", "test:production-qualification": "node --test scripts/qa/production-qualification.test.mjs scripts/qa/runtime-snapshot-qualification.test.mjs", "test:release-evidence": "node --test scripts/tests/release-evidence.test.mjs", "test:show-engine-drill-judge": "node --test scripts/validate-show-engine-judge.test.mjs", From 95f1aaba2caab16546d1087a94e114fb2471fff7 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 6 Nov 2026 13:50:20 -0500 Subject: [PATCH 06/10] diagnostics: retain allowlisted native log loss counters with timing --- scripts/mac-show-drill.py | 5 +++++ scripts/qa/test_mac_show_timing.py | 9 ++++++++- 2 files changed, 13 insertions(+), 1 deletion(-) diff --git a/scripts/mac-show-drill.py b/scripts/mac-show-drill.py index a1894944..113ede0a 100644 --- a/scripts/mac-show-drill.py +++ b/scripts/mac-show-drill.py @@ -193,6 +193,10 @@ def _observe_request(self, rid, body, step, started, finished, diagnostic_start, reader = self.response_times.get(rid) diagnostics = [line for line in self.stderr[diagnostic_start:] if line.startswith(("[render]", "[lock-guardrail]", "[video-out]") + NATIVE_TIMING_PREFIXES)] + snapshot = self.responses.get(rid, {}).get("snapshot", {}) + native_log = snapshot.get("nativeDiagnostics") if isinstance(snapshot, dict) else None + log_keys = ("logDropped", "logTruncated", "logSinkFailures", "logQueued") + native_log = {key: native_log.get(key) for key in log_keys} if isinstance(native_log, dict) else None self.request_evidence.append({ "id": rid, "type": body.get("type", "?"), "step": step, "commandTypes": [command.get("type", "?") for command in body.get("commands", [])], @@ -202,6 +206,7 @@ def _observe_request(self, rid, body, step, started, finished, diagnostic_start, "readerParseMs": (reader[1] - reader[0]) * 1000 if reader else None, "callerAfterReaderMs": (finished - reader[1]) * 1000 if reader else None, "diagnostics": diagnostics[-12:], "diagnosticsOmitted": max(0, len(diagnostics) - 12), + "nativeLog": native_log, }) def sync(self, commands, elapsed_ms, step=None): diff --git a/scripts/qa/test_mac_show_timing.py b/scripts/qa/test_mac_show_timing.py index 2eff3d5d..765c82be 100644 --- a/scripts/qa/test_mac_show_timing.py +++ b/scripts/qa/test_mac_show_timing.py @@ -22,7 +22,11 @@ request=json.loads(line) if request.get('type') == 'no-response': continue time.sleep(request.get('testDelay', 0)) - print(json.dumps({'id': request['id'], 'ok': True}), flush=True) + response = {'id': request['id'], 'ok': True} + if request.get('nativeTimingCount'): + response['snapshot'] = {'nativeDiagnostics': dict(logDropped=3, logTruncated=1, + logSinkFailures=0, logQueued=2, secret='never-copy-native-snapshot')} + print(json.dumps(response), flush=True) if request.get('nativeTimingCount'): time.sleep(.02) # diagnostic logger can arrive after the response reader for index in range(request['nativeTimingCount']): @@ -97,6 +101,9 @@ def test_late_native_phases_are_retained_with_bounded_omissions(self): self.assertTrue(all(row["observedMs"] >= 0 and "flush_us=11" in row["line"] for row in evidence["nativeTiming"])) self.assertNotIn("never-report-native-arguments", json.dumps(evidence)) + self.assertNotIn("never-copy-native-snapshot", json.dumps(evidence)) + self.assertEqual(evidence["requests"][-1]["nativeLog"], + dict(logDropped=3, logTruncated=1, logSinkFailures=0, logQueued=2)) self.assertEqual(len(self.core.round_trips), before + 1) From a587b2d31cab332220469c1ade48abc48ae2fce7 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 6 Nov 2026 14:06:54 -0500 Subject: [PATCH 07/10] test(diagnostics): handle timestamp precision and retire owned readers --- docs/BACKLOG.md | 2 ++ scripts/mac-show-drill.py | 12 +++++++++++- scripts/qa/test_mac_show_timing.py | 5 ++++- 3 files changed, 17 insertions(+), 2 deletions(-) diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 90126d52..340172ad 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -28,6 +28,8 @@ Specifications and acceptance: [resumed reliability work](reference/resumed-reli 12:22 reforecast: 3h14 remain. Monitor and departure repairs merged. Use freed capacity for the observed empty-take failure, finish Sources/final-picture acceptance, and preserve time for corrected integrated checks. The Mac diagnostic sample passed but did not explain the earlier failure; #1074 remains held. Replenish again if these slices finish early. +13:55 reforecast: 1h41 remain in the window. #1186 and #1189 repairs are merged after exact-head gates; #1188 is validating their integration. The immutable 30-minute Program/eight ISO/SRT comparison ends about 14:04, then finalize, restore settings and decode every output. Reserve 60–90 minutes for clean public-beta building, final main checks and installer qualification, overlapping independent hosted work. #941 passed 2099 native cases and isolated close traces; its Mac job had a zero-step runner-acquisition cancellation, retained and retried. #1178 adds native phase evidence with unchanged latency limits; its controlled timing tests now pass in hosted CI, while native/hosted causal evidence remains pending. No builds or probes overlap collection; no camera/real-SDK/receiver-latency qualification is inferred. Replenish validation work as capacity frees, keeping the testing beta frozen. + Allocation baseline: 20 min baseline/planning, 120 Auto, 90 resolution, 45 empty-state, 45 teardown, 60 Tiles, 60 conditional output work, 40 validation/report/replenishment reserve = 480 min. These are adjustable allocations, not permission to stop after one fixed list. Use blocked conditional time for the next actionable issue. Owner-deferred #513, business/credential acquisition, public-provider posting and speculative feature expansion are not silently resumed. 09:03 reforecast: roughly 6h33 remain. The new recorded output failure #1177 takes the freed #1172 slot under the owner's replenishment instruction. Allocate up to 150 minutes to attribution/fix/validation before reforecast, with #919 hosted work overlapping; reuse remaining capacity for the next unblocked reserve. No full-output pass is claimed from stable input geometry or successful writer startup. diff --git a/scripts/mac-show-drill.py b/scripts/mac-show-drill.py index 113ede0a..8b325578 100644 --- a/scripts/mac-show-drill.py +++ b/scripts/mac-show-drill.py @@ -138,7 +138,8 @@ def __init__(self, path, env=None, evidence_path=None): self.native_timing_omitted = 0 self.next_id = 1 self.round_trips = [] # (type, seconds) per answered request - threading.Thread(target=self._read_stdout, daemon=True).start() + self.stdout_reader = threading.Thread(target=self._read_stdout, daemon=True) + self.stdout_reader.start() self.stderr_reader = threading.Thread(target=self._read_stderr, daemon=True) self.stderr_reader.start() @@ -216,7 +217,15 @@ def sync(self, commands, elapsed_ms, step=None): def kill(self): self.proc.kill() self.proc.wait(timeout=10) + self.stdout_reader.join(timeout=1) self.stderr_reader.join(timeout=1) + self.proc.stdin.close() + # Do not close a pipe underneath a still-running reader or wait forever + # on its stream lock. Preserve an incomplete-drain result instead. + if not self.stdout_reader.is_alive(): + self.proc.stdout.close() + if not self.stderr_reader.is_alive(): + self.proc.stderr.close() if self.evidence_path: os.makedirs(os.path.dirname(os.path.abspath(self.evidence_path)), exist_ok=True) with open(self.evidence_path, "w", encoding="utf-8") as output: @@ -226,6 +235,7 @@ def kill(self): "nativeTiming": self.native_timing, "nativeTimingOmitted": self.native_timing_omitted, "stderrDrained": not self.stderr_reader.is_alive(), + "stdoutDrained": not self.stdout_reader.is_alive(), "scope": "Caller/reader timing plus opt-in native phase durations; observedMs is stderr receipt time, not a native timestamp or request correlation; no command arguments"}, output, indent=2) print(f"Command timing evidence: {self.evidence_path} ({self.evidence_truncated} omitted)") for request in sorted(self.request_evidence, key=lambda row: row["durationMs"], reverse=True)[:5]: diff --git a/scripts/qa/test_mac_show_timing.py b/scripts/qa/test_mac_show_timing.py index 765c82be..7111a03e 100644 --- a/scripts/qa/test_mac_show_timing.py +++ b/scripts/qa/test_mac_show_timing.py @@ -55,7 +55,10 @@ def test_delayed_response_remains_in_gate_and_keeps_step_identity_without_argume row = self.core.request_evidence[-1] self.assertEqual(row["step"], "operator-take") self.assertEqual(row["commandTypes"], ["take"]) - self.assertGreaterEqual(row["readerReceivedMs"], 140) + # Subtracting float monotonic timestamps can represent 140 ms as + # 139.999999897 ms. Round only nanosecond-scale representation noise; + # the independent 100 ms production gate below remains unchanged. + self.assertGreaterEqual(round(row["readerReceivedMs"], 6), 140) syncs = [duration for name, duration in self.core.round_trips if name == "media-core-sync"] self.assertEqual(len(syncs), 1) self.assertGreater(syncs[0] * 1000, drill.MAX_COMMAND_P99_MS) From 5489c21269dec5ca7bacc4a2685cfcceb1c40ff4 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 6 Nov 2026 14:50:26 -0500 Subject: [PATCH 08/10] test: wait for background decoder picture readiness (#867) --- native/tests/MediaCoreCommandTest.cpp | 43 +++++++++++++++++++++++++-- 1 file changed, 40 insertions(+), 3 deletions(-) diff --git a/native/tests/MediaCoreCommandTest.cpp b/native/tests/MediaCoreCommandTest.cpp index 76945a32..ee097975 100644 --- a/native/tests/MediaCoreCommandTest.cpp +++ b/native/tests/MediaCoreCommandTest.cpp @@ -27,6 +27,7 @@ #include #include +#include #include #include #include @@ -9643,6 +9644,40 @@ TEST(MediaCoreCommand, AGenuinelyUnroutedClipIsStillReleasedAfterTheGrace) { // `media:` row, so the refusal comes from the LAST tier - and it must carry a // real reason naming the loop, never silently do nothing. // --------------------------------------------------------------------------- +TEST(MediaCoreCommand, BackgroundTransportCanBeLiveBeforeDecoderConstruction) { + auto modules = corevideo::modules::createStubModules(); + CountingDecoder::resetAll(); + std::mutex factoryMutex; + std::condition_variable factoryReady; + bool releaseFactory = false; + modules.mediaDecoderFactory = [&]() -> std::unique_ptr { + std::unique_lock lock(factoryMutex); + // A failed assertion must not leave teardown waiting on an unbounded gate. + if (!factoryReady.wait_for(lock, std::chrono::seconds(3), [&] { return releaseFactory; })) return {}; + lock.unlock(); + return std::make_unique(); + }; + corevideo::core::MediaCore core(std::move(modules)); + core.enableAudioOutputWorker(); + (void)core.applyCommands(corevideo::rpc::Json::Array{ + slice3bBackgroundScene("scene-a", "load-scene-graph")}); + ASSERT_TRUE(slice3bPumpUntil(core, [&] { + return slice3bTransportState(core, "background:bg") == "live"; + })); + // #867: the old readiness predicate is true while construction is held. + EXPECT_EQ(CountingDecoder::created.load(), 0) + << "logical Live is not decoder readiness; created=" << CountingDecoder::created.load(); + { + std::lock_guard lock(factoryMutex); + releaseFactory = true; + } + factoryReady.notify_all(); + ASSERT_TRUE(slice3bPumpUntil(core, [&] { + return CountingDecoder::lastFrameIdFor("background:bg") > 0; + })) << "the released background decoder never produced its first picture"; + EXPECT_EQ(CountingDecoder::created.load(), 1); +} + TEST(MediaCoreCommand, ATransportOnABackgroundOnlyAssetIsRefusedAndNamesTheLoop) { auto modules = corevideo::modules::createStubModules(); CountingDecoder::resetAll(); @@ -9653,8 +9688,9 @@ TEST(MediaCoreCommand, ATransportOnABackgroundOnlyAssetIsRefusedAndNamesTheLoop) (void)core.applyCommands(corevideo::rpc::Json::Array{ slice3bBackgroundScene("scene-a", "load-scene-graph")}); ASSERT_TRUE(slice3bPumpUntil(core, [&] { - return slice3bTransportState(core, "background:bg") == "live"; - })) << "the loop background never went live"; + return slice3bTransportState(core, "background:bg") == "live" && + CountingDecoder::lastFrameIdFor("background:bg") > 0; + })) << "the live loop background never produced its first picture; created=" << CountingDecoder::created.load(); ASSERT_EQ(slice3bMediaSource(core.sessionState(), "media:bg"), nullptr) << "this asset must exist ONLY as background:bg for the test to exercise the last tier"; @@ -9680,7 +9716,8 @@ TEST(MediaCoreCommand, ATransportOnABackgroundOnlyAssetIsRefusedAndNamesTheLoop) // #867: this counter is process-global. If it ever reads 2 again, say WHICH source // restarted (loop restart vs a decoder opened outside this core) instead of a bare 2 vs 1. EXPECT_EQ(CountingDecoder::created.load(), 1) - << "background:bg decoder restarts=" << CountingDecoder::restartsFor("background:bg") + << "background:bg decoders created=" << CountingDecoder::created.load() + << " restarts=" << CountingDecoder::restartsFor("background:bg") << " first-frame-id-after-restart=" << CountingDecoder::firstFrameIdAfterRestartFor("background:bg") << " last-frame-id=" << CountingDecoder::lastFrameIdFor("background:bg"); } From cea2b30dccdb43cbe8cab7c500a69abcb6c2d50d Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 6 Nov 2026 15:02:40 -0500 Subject: [PATCH 09/10] docs: align diagnostic qualification with decoder readiness dependency --- docs/BACKLOG.md | 6 ++++-- docs/reference/background-decoder-readiness-867.md | 9 +++++++++ 2 files changed, 13 insertions(+), 2 deletions(-) create mode 100644 docs/reference/background-decoder-readiness-867.md diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index 24166b4c..098f1014 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -22,7 +22,9 @@ Specifications and acceptance: [resumed reliability work](reference/resumed-reli | 12 | Done | #1186 | #1187 merged; whole packaged Program file passes 110536 identities with zero duplicate final picture in the 30-minute rehearsal. [Spec](reference/program-recording-tail-1186.md). | Within allocation | All 17 exact-head hosted checks passed; issue closed with retained negative and final-file evidence | | 13 | Done | #1188 | #1190 merged; original session survives stream-first stop after departure; nine files finalize in one take in short and 30-minute runs. [Spec](reference/recording-source-loss-1188.md). | About 25 min investigation/implementation plus shared packaged validation | All 17 exact-head checks passed; issue closed with exact-session evidence | | 14 | Done | #1189 | #1191 merged; old consumer fails, 2095 native cases pass, and all eight ISO identity judgments pass across 1800.86 seconds with auto-subscribe enabled. [Spec](reference/iso-reader-owner-1189.md). | About 15 min implementation plus 10 min native suite and shared packaged validation | All 17 exact-head checks passed; issue closed with single-epoch arrival/file evidence | -| 15 | Ready after beta | #941 | Stop scheduled Program delivery at explicit teardown without hiding active-output failures. [Spec](reference/program-shutdown-941.md). | 45 min, range 30–75 | 2099 native cases, actual RPC negative/restored control, isolated close traces and all 17 hosted checks pass; excluded from frozen beta | +| 15 | Await #867 | #941 | Stop scheduled Program delivery at explicit teardown without hiding active-output failures. [Spec](reference/program-shutdown-941.md). | 45 min, range 30–75 | Prior head passed all 17 checks; integration hit the existing background-decoder readiness assertion on Metal. Preserve the failure and qualify the repair; excluded from frozen beta | +| 16 | Now | #867 | Prove the background transport can be logically Live before its asynchronous decoder is constructed; wait for actual first-picture readiness before the existing strict single-decoder assertion. [Spec](reference/background-decoder-readiness-867.md). | 20 min, range 15–35 | Controlled delayed-worker proof, old-precondition negative control, focused native tests and exact-head hosted gates; keep beta files frozen | +| Unranked | Intake | #1194 | Two-frame internal Program startup records one Unavailable slot at sequence 2 before the measurement baseline; the whole-trace failure is retained. | Not allocated | No causal old-code comparison; distinct from #941 shutdown and outside the frozen beta | 12:55 reforecast: 2h41 remain. Local test beta 8c8e15b1qa has been handed to the owner after a 60.1005536-second eight-source Program/ISO/SRT regression and exact-session finalization. All eleven decoded judgments pass; this is not the 30-minute RC gate. The public beta still needs merges, exact main identity and hosted installer qualification. Keep its contents fixed. Use independent capacity for #941 while preserving the owner's local test session; replenish again when that slice finishes. @@ -814,7 +816,7 @@ Owner closes each issue. Outcome per issue: fixed, no-repro (with hardening), ma | Issue | Outcome | Evidence | |---|---|---| | [#850](https://github.com/iamfatness/CoreVideoPro/issues/850) | mac-unverified, hardened | macOS-only failure; test now judges healthy phases against a 60 s window and shortens it to 60 ms only for the decay phase. 25/25 Windows runs before and after. | -| [#867](https://github.com/iamfatness/CoreVideoPro/issues/867) | no-repro, diagnostics added | 25/25 before; failing line was the process-global decoder-created count. Failure message now names restarts and frame ids. | +| [#867](https://github.com/iamfatness/CoreVideoPro/issues/867) | Active window, readiness repair | November 6 Metal recurrence retained. #1193 adds controlled delayed-construction evidence, actual-picture readiness and the observed count; historical trials still omit the count. | | [#877](https://github.com/iamfatness/CoreVideoPro/issues/877) | fixed | utf-8 pinned in monitor_evidence.Core; new test fails before, passes after. | | [#878](https://github.com/iamfatness/CoreVideoPro/issues/878) | no-repro (fixed on main by #875) | WgcScreenCapture UTF-8 title test passes. | | [#881](https://github.com/iamfatness/CoreVideoPro/issues/881) | fixed | Reproduced with a held reader (the concurrent-reader test is a stress guard); store now serialises, retries, replaces atomically and never persists a fabricated Enabled=false. | diff --git a/docs/reference/background-decoder-readiness-867.md b/docs/reference/background-decoder-readiness-867.md new file mode 100644 index 00000000..b8621fe1 --- /dev/null +++ b/docs/reference/background-decoder-readiness-867.md @@ -0,0 +1,9 @@ +# Background decoder readiness in the transport regression — #867 + +The background-only transport refusal regression waits for logical `live` state, then asserts one decoder was created. `MediaTransports` publishes that state before its asynchronous worker constructs the decoder. The retained November 6 Metal failure on #1192 repeats this assertion at line 9682, reporting no background pictures or restarts but omitting the actual created count. Earlier failures remain retained; their missing count prevents attributing each one to the same initiating condition. + +Use the real MediaCore/MediaTransports consumer with an injected factory whose construction is held behind a bounded test gate. Demonstrate that the source is logically Live while the constructor count is still zero, then release the worker and observe an actual first picture. This establishes the missing readiness guarantee without changing production scheduling or weakening the strict one-decoder assertion. + +The existing refusal test must wait for both Live and a real background picture before exercising pause/play. Preserve refusal reasons, unchanged transport state, unknown-asset diagnostics and the final exact constructor count. Include the observed count in failure output. A missing decoder must still fail its bounded readiness wait; duplicate construction must still fail the exact-count assertion. + +Implementation sequence: retain the hosted failure; add the controlled readiness regression and repair the existing wait; compile the actual native test executable; run a control that applies the old one-decoder expectation while construction is held, restore and run both focused cases plus the related MediaCore command regressions; submit for hosted Windows/Metal/stub checks. No arbitrary increase to performance limits, no retry-until-green and no production adapter change. Keep this test repair outside the frozen Windows beta; #941 remains held until its integrated checks pass. From a52f5e5ad97972758a4201321a64bc360e5bb6e1 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 6 Nov 2026 15:17:15 -0500 Subject: [PATCH 10/10] diagnostics: retain early render phase evidence for #1178 --- .../reference/mac-command-attribution-1178.md | 8 +++++++ scripts/mac-show-drill.py | 3 ++- scripts/qa/test_mac_show_timing.py | 24 +++++++++++++++++++ 3 files changed, 34 insertions(+), 1 deletion(-) diff --git a/docs/reference/mac-command-attribution-1178.md b/docs/reference/mac-command-attribution-1178.md index d25861b3..d6cbbd41 100644 --- a/docs/reference/mac-command-attribution-1178.md +++ b/docs/reference/mac-command-attribution-1178.md @@ -15,3 +15,11 @@ The latest hosted sample failed at enable-diagnostics: 102.969 ms total, with 98 Add opt-in verbose measurements for command queue, assembly-capacity wait, core-lock wait, handler and deferred-engine time; response assembly queue/projection/serialization/enqueue; and response-writer queue/flush. Use the existing bounded asynchronous logger, no command arguments or snapshots, and retain the normal warning thresholds and unchanged 100 ms acceptance gate. Keep a bounded 512-line native timing appendix with omission count and stderr-drain status because asynchronous diagnostics can arrive after the response. Receipt timestamps are not native timestamps or exact request correlation. Missing/dropped evidence stays unknown. Validate delayed post-response diagnostic delivery, bounded omissions, and unchanged gate population/privacy through the controlled subprocess. Compile and run native RPC regressions after the active recording measurement; use hosted Mac artifacts for causal attribution. A green sample alone still does not close this issue. This diagnostic work remains outside the frozen beta. + +## Core-lock wait demonstrated in the 199 ms sample + +At `cea2b30d`, run 42284929309 failed with a 199.222 ms enable-diagnostics request. Its sole adjacent request-phase record reports 186.117 ms waiting for the core lock, compared with 2.147 ms handling, 3.586 ms projection and 2.377 ms serialization. The reader/caller contribution is 3.649 ms. A contemporaneous render STALL reports 289 ms rendering. Requests are serialized by this drill, so the first request and first native request record give strong boundary attribution; receipt adjacency alone still cannot identify the exact render tick or GPU operation. + +The request starts 1.552 seconds into the process. The later guardrail aggregate reports a 1.417-second worst render hold, but the report did not retain render/lock attribution emitted before the first request. Add those existing fixed-format prefixes to the same bounded appendix, including `lock-hold-attribution`. Preserve all startup requests in the unchanged 100 ms population; do not sleep away the failure or reset counters. A controlled child emitting render phases before its first response must fail with the old filter and pass with the new one. The existing 512-line bound, omissions, asynchronous drain and privacy restrictions remain in force. + +The next hosted sample must retain early rendering phases so an initiating operation can be reproduced before changing the renderer. Native logger loss (two records later in this failed run) remains explicit. The existing record-rate and render-over-budget failures also remain failures. This change repairs missing evidence, not command latency; keep the issue and dependent Tiles qualification open. diff --git a/scripts/mac-show-drill.py b/scripts/mac-show-drill.py index 8b325578..a9eef65c 100644 --- a/scripts/mac-show-drill.py +++ b/scripts/mac-show-drill.py @@ -117,7 +117,8 @@ def _zoom_video_reserve_ms(): MAX_LOAD_RENDER_MS = 10.0 MAX_DROPPED_FRAMES = 0 NATIVE_TIMING_PREFIXES = ("[request-timing]", "[response-timing]", "[writer-timing]", - "[req]", "[cmd]", "[response]", "[writer]", "[command-lock]") + "[req]", "[cmd]", "[response]", "[writer]", "[command-lock]", + "[render]", "[lock-guardrail]", "[lock-hold-attribution]") class Core: diff --git a/scripts/qa/test_mac_show_timing.py b/scripts/qa/test_mac_show_timing.py index 7111a03e..7a7cc998 100644 --- a/scripts/qa/test_mac_show_timing.py +++ b/scripts/qa/test_mac_show_timing.py @@ -18,6 +18,8 @@ CHILD = """ import json,sys,time +print('[lock-hold-attribution] site=render.display-tick held_us=186117 phases_us=[program=185000] startup=1', file=sys.stderr, flush=True) +print('[render] STALL lockWait=0ms render=289ms startup=1', file=sys.stderr, flush=True) for line in sys.stdin: request=json.loads(line) if request.get('type') == 'no-response': continue @@ -42,6 +44,10 @@ def setUp(self): REAL_POPEN([sys.executable, "-u", "-c", CHILD], **kw)): self.core = drill.Core("controlled-child", evidence_path=str(self.path)) self.core.request({"type": "ping"}) # exclude process startup from delay attribution + deadline = time.monotonic() + 3 + while len(self.core.stderr) < 2 and time.monotonic() < deadline: + REAL_SLEEP(.001) + self.assertGreaterEqual(len(self.core.stderr), 2) def tearDown(self): with contextlib.redirect_stdout(io.StringIO()): @@ -89,6 +95,9 @@ def test_bounded_evidence_reports_omissions_without_changing_gate_population(sel self.assertEqual(len(self.core.round_trips), before + 1) def test_late_native_phases_are_retained_with_bounded_omissions(self): + # This test isolates the appendix cap from startup lines, which have + # their own real-reader regression below. + self.core.native_timing.clear() before = len(self.core.round_trips) self.core.request({"type": "media-core-sync", "nativeTimingCount": 600, "secret": "never-report-native-arguments"}) @@ -109,6 +118,21 @@ def test_late_native_phases_are_retained_with_bounded_omissions(self): dict(logDropped=3, logTruncated=1, logSinkFailures=0, logQueued=2)) self.assertEqual(len(self.core.round_trips), before + 1) + def test_render_attribution_before_first_request_is_retained(self): + deadline = time.monotonic() + 3 + while not any('startup=1' in line and line.startswith('[render]') + for line in self.core.stderr) and time.monotonic() < deadline: + REAL_SLEEP(.001) + with contextlib.redirect_stdout(io.StringIO()): + self.core.kill() + evidence = json.loads(self.path.read_text()) + startup = [entry['line'] for entry in evidence['nativeTiming'] if 'startup=1' in entry['line']] + self.assertEqual(len(startup), 2) + self.assertTrue(any('phases_us=[program=185000]' in line for line in startup)) + self.assertTrue(any('render=289ms' in line for line in startup)) + self.assertEqual(evidence['nativeTimingOmitted'], 0) + self.assertTrue(evidence['stderrDrained']) + if __name__ == "__main__": unittest.main()