diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 6d9c06e47..fec75f5dc 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/docs/BACKLOG.md b/docs/BACKLOG.md index 45d86d4b7..098f10146 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -12,19 +12,28 @@ Specifications and acceptance: [resumed reliability work](reference/resumed-reli | 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 | 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 | +| 5 | Done slice / qualification pending | #1177 | Ownership repair #1179 merged. Negative control, 2082 native cases, four CTest suites and all 17 hosted checks passed. The corrected 1800.86-second synthetic Program/eight ISO/SRT identity comparison passes after #1186/#1188/#1189. [Spec](reference/program-iso-deadline-1177.md). | Attribution/repair slice complete | Real SDK, registered camera and bounded end-to-end latency remain unverified; earlier failures retained | | 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 | 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 | +| 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 | Done slice / qualification pending | #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 | Preserve final Program picture once while retaining audio tail. [Spec](reference/program-recording-tail-1186.md). | 60 min, range 45–90 | Decoded negative controls fail; full suite and packaged check pending | -| 13 | Await gate | #1188 | Preserve the recording take when sources depart and streaming stops. [Spec](reference/recording-source-loss-1188.md). | 60 min, range 45–90 | Short packaged causal sequence and finalized file checks | -| 14 | Await gate | #1189 | Bind each ISO reader to its actual camera UUID; reproduce duplicate reads through auto/share aliases. [Spec](reference/iso-reader-owner-1189.md). | 45 min, range 30–75 | Native causal regression and corrected local trace/file workload | +| 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 | 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. 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. + +14:23 reforecast: approximately 73 minutes remain. All three recording repairs are merged and closed with the complete 1800.86-second synthetic comparison; all eleven decoded judgments pass. Public beta source is frozen at 74495ade, with a clean self-contained shell publish/runtime probe passed and the production native suite running. Reserve the next 35–55 minutes for packaging, exact-main CI and hosted install/probe/uninstall of immutable draft assets. The public beta is not yet published. Keep #941/#1178 out; reconcile their branches locally while release gates run, then replenish follow-up validation without changing the frozen release. Superseded CI runs are retained and cancelled to free runner capacity; no failing performance result is discarded or retried until green. + 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. @@ -614,7 +623,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. | @@ -807,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 000000000..b8621fe15 --- /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. diff --git a/docs/reference/mac-command-attribution-1178.md b/docs/reference/mac-command-attribution-1178.md new file mode 100644 index 000000000..d6cbbd41a --- /dev/null +++ b/docs/reference/mac-command-attribution-1178.md @@ -0,0 +1,25 @@ +# 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. + +## 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. + +## 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/native/src/rpc/JsonRpcServer.cpp b/native/src/rpc/JsonRpcServer.cpp index 0df9453da..ff0654cd6 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 34819368c..2583effc2 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/native/tests/MediaCoreCommandTest.cpp b/native/tests/MediaCoreCommandTest.cpp index 76945a32f..ee097975f 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"); } diff --git a/package.json b/package.json index ff7c1b093..6ca809241 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", diff --git a/scripts/mac-show-drill.py b/scripts/mac-show-drill.py index 3fa007c8a..a9eef65c7 100644 --- a/scripts/mac-show-drill.py +++ b/scripts/mac-show-drill.py @@ -116,29 +116,43 @@ 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]", + "[render]", "[lock-guardrail]", "[lock-hold-attribution]") 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.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.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() 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) @@ -146,30 +160,87 @@ 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): + 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]") + 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", [])], + "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), + "nativeLog": native_log, + }) + + 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) + 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: + json.dump({"clock": "monotonic", "commandP99LimitMs": MAX_COMMAND_P99_MS, + "requestsOmitted": self.evidence_truncated, + "requests": self.request_evidence, + "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]: + print("Command timing: " + json.dumps(request, separators=(",", ":"))) def route(route_id, index=0, capture=None): @@ -259,6 +330,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 +358,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 +373,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 +385,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 000000000..7a7cc9988 --- /dev/null +++ b/scripts/qa/test_mac_show_timing.py @@ -0,0 +1,138 @@ +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 +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 + time.sleep(request.get('testDelay', 0)) + 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']): + print('[writer-timing] sojourn_us=7 flush_us=11 bytes=32', file=sys.stderr, 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 + 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()): + 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"]) + # 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) + 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) + + 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"}) + 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.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) + + 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() diff --git a/scripts/tests/mac-show-timing.test.mjs b/scripts/tests/mac-show-timing.test.mjs new file mode 100644 index 000000000..4ea08104b --- /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); +});