From 7961f0cbdbb93d95d70fa3859d1833c29c6e7f98 Mon Sep 17 00:00:00 2001 From: Aleksandr Shabelnikov Date: Sun, 19 Jul 2026 11:27:05 +0200 Subject: [PATCH 1/6] Accept FCP response delivered before local write completion AR Request drains before AR Response, so a target's FCP response block write can arrive before our own command-write acknowledgement has been dispatched. The response itself proves the target received and processed the command; dropping it made the Duet 48 kHz prepublish sequence time out and deferred the audio nub entirely. Accept a validated response for the active write attempt and treat the later local write callback as a harmless stale event. Documented in AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md (committed with the stabilization change). Co-Authored-By: Claude Fable 5 --- ASFWDriver/Protocols/AVC/FCPTransport.cpp | 25 ++++++++++++++++++++--- tests/protocols/FCPTransportTests.cpp | 9 ++++---- 2 files changed, 27 insertions(+), 7 deletions(-) diff --git a/ASFWDriver/Protocols/AVC/FCPTransport.cpp b/ASFWDriver/Protocols/AVC/FCPTransport.cpp index 74caea2d..6857f397 100644 --- a/ASFWDriver/Protocols/AVC/FCPTransport.cpp +++ b/ASFWDriver/Protocols/AVC/FCPTransport.cpp @@ -360,14 +360,24 @@ void FCPTransport::OnFCPResponse(uint16_t srcNodeID, return; } - if (!pending_->successfulWriteAttempt.has_value()) { + // AR Request and AR Response are separate DMA contexts. RxPath drains the + // request context first, so a target's FCP block write can be delivered + // before our earlier command-write acknowledgement is dispatched from AR + // Response. That ordering is normal on the wire: the FCP response itself + // is definitive proof that the target received and processed this command. + // Do not drop it merely because the local write-completion callback is + // still queued. + const bool responsePrecedesWriteCompletion = !pending_->successfulWriteAttempt.has_value(); + if (responsePrecedesWriteCompletion && !pending_->activeWriteAttempt.has_value()) { IOLockUnlock(lock_); ASFW_LOG_V3(FCP, - "FCPTransport: Ignoring response before write completion"); + "FCPTransport: Ignoring response without an active write attempt"); return; } - const FCPWriteAttempt successfulAttempt = *pending_->successfulWriteAttempt; + const FCPWriteAttempt successfulAttempt = responsePrecedesWriteCompletion + ? *pending_->activeWriteAttempt + : *pending_->successfulWriteAttempt; const uint16_t expectedNodeID = successfulAttempt.targetNodeID; const bool exactMatch = srcNodeID == expectedNodeID; const bool nodeNumberMatch = (srcNodeID & 0x3F) == (expectedNodeID & 0x3F); @@ -403,6 +413,15 @@ void FCPTransport::OnFCPResponse(uint16_t srcNodeID, return; } + if (responsePrecedesWriteCompletion) { + // Preserve the delivery proof for diagnostics and make a later async + // write completion a harmless stale callback after CompleteCommand(). + pending_->successfulWriteAttempt = successfulAttempt; + ASFW_LOG_V2(FCP, + "FCPTransport: Accepting FCP response before local write completion attempt=%llu", + successfulAttempt.id); + } + FCPFrame response; response.length = std::min(payload.size(), response.data.size()); std::copy_n(payload.begin(), response.length, response.data.begin()); diff --git a/tests/protocols/FCPTransportTests.cpp b/tests/protocols/FCPTransportTests.cpp index fa01dcee..322e84e5 100644 --- a/tests/protocols/FCPTransportTests.cpp +++ b/tests/protocols/FCPTransportTests.cpp @@ -65,7 +65,7 @@ class FCPTransportTests : public ::testing::Test { FCPTransportConfig config_{}; }; -TEST_F(FCPTransportTests, IgnoresResponseUntilCommandWriteCompletes) { +TEST_F(FCPTransportTests, AcceptsResponseBeforeCommandWriteCompletion) { int completionCount = 0; FCPStatus completionStatus = FCPStatus::kTransportError; const auto command = MakeUnitInfoCommand(); @@ -80,11 +80,12 @@ TEST_F(FCPTransportTests, IgnoresResponseUntilCommandWriteCompletes) { ASSERT_EQ(bus_.PendingWriteCount(), 1U); transport_->OnFCPResponse(2, 1, response); - EXPECT_EQ(completionCount, 0); + EXPECT_EQ(completionCount, 1); + EXPECT_EQ(completionStatus, FCPStatus::kOk); + // AR Request is drained before AR Response. Once the target's FCP write + // proves delivery, the queued local write acknowledgement is stale. ASSERT_TRUE(bus_.CompleteNextWrite(AsyncStatus::kSuccess)); - transport_->OnFCPResponse(2, 1, response); - EXPECT_EQ(completionCount, 1); EXPECT_EQ(completionStatus, FCPStatus::kOk); } From 81aab179c535da3393ecf1528c954c44662177b5 Mon Sep 17 00:00:00 2001 From: Aleksandr Shabelnikov Date: Sun, 19 Jul 2026 11:27:20 +0200 Subject: [PATCH 2/6] Stabilize TX streaming against IT ring lap loss The IT descriptor ring is free-running and completion accounting measured hardware progress modulo the 48-packet ring, so any refill gap over 6 ms silently discarded whole laps: the wire re-transmitted stale packets at full rate while completionCursor dilated against bus time, dragging the TX producer and the RX replay reader into a permanent all-zero-payload state (2026-07-19 Duet incident: interrupt path died mid-session, the watchdog carried the stream, and 71% of wire packets were stale re-sends). - Recover true progress from the OUTPUT_LAST completion timestamps (ComputeLostLapPackets, one packet per cycle), including the pointer-unmoved whole-lap stall, and reconcile completionCursor, softwareFillAbsIdx_, and completion stamps forward. New lapLossEvents/lapLossPacketsTotal counters and an IT LAP LOSS record. - Fault the transmit context after 16 consecutive IRQ-silent watchdog kicks and log the first watchdog engagement; watchdog-carried streaming re-sends stale ring laps between kicks and is never a valid steady state. - Classify TX replay read failures: re-anchor the reader in place on overwritten history (no frame-cursor realign; skipped entries only shift NODATA placement, legal under IEC 61883-6 blocking), hold the reader on ahead-of-producer, and reserve reader reset plus frame-cursor realignment for genuine RX-domain transitions. Documented in AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md as TX-LAPLOSS-001 (fixed, hardware-validated on a live Duet run) and TX-IRQ-001 (open: why the interrupt path died). Scheme file is xcodegen regeneration. Co-Authored-By: Claude Fable 5 --- .../xcschemes/ASFWDriver.xcscheme | 22 +-- .../Audio/DriverKit/ASFWAudioDriverZts.cpp | 89 ++++++--- .../Isoch/Transmit/IsochTransmitContext.cpp | 22 +++ .../Isoch/Transmit/IsochTransmitContext.hpp | 8 + ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp | 78 +++++++- ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp | 49 +++++ AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md | 132 +++++++++++++ tests/audio/IsochTxDmaRingTests.cpp | 173 ++++++++++++++++++ tests/audio/RxDrivenTimingTests.cpp | 51 ++++++ 9 files changed, 581 insertions(+), 43 deletions(-) diff --git a/ASFW.xcodeproj/xcshareddata/xcschemes/ASFWDriver.xcscheme b/ASFW.xcodeproj/xcshareddata/xcschemes/ASFWDriver.xcscheme index 0d79cf89..09c8b9be 100644 --- a/ASFW.xcodeproj/xcshareddata/xcschemes/ASFWDriver.xcscheme +++ b/ASFW.xcodeproj/xcshareddata/xcschemes/ASFWDriver.xcscheme @@ -1,11 +1,10 @@ + version = "1.3"> + buildImplicitDependencies = "YES"> @@ -27,21 +26,18 @@ buildConfiguration = "Debug" selectedDebuggerIdentifier = "Xcode.DebuggerFoundation.Debugger.LLDB" selectedLauncherIdentifier = "Xcode.DebuggerFoundation.Launcher.LLDB" - shouldUseLaunchSchemeArgsEnv = "YES" - onlyGenerateCoverageForSpecifiedTargets = "NO"> + shouldUseLaunchSchemeArgsEnv = "YES"> - - - - - - diff --git a/ASFWDriver/Audio/DriverKit/ASFWAudioDriverZts.cpp b/ASFWDriver/Audio/DriverKit/ASFWAudioDriverZts.cpp index 4177e2fa..e017b9c7 100644 --- a/ASFWDriver/Audio/DriverKit/ASFWAudioDriverZts.cpp +++ b/ASFWDriver/Audio/DriverKit/ASFWAudioDriverZts.cpp @@ -228,11 +228,9 @@ uint32_t PrepareTransmitSlots(ASFWAudioDriver_IVars& ivars, // can momentarily outrun the producer. Killing TX here would leave the // stream permanently silent -- the timing-loss recovery is health-gated // when the device clock is fine (see DiceAudioBackend), and even ungated - // a coordinator restart cannot re-prime TX. Instead, re-sync the reader - // to RX's current epoch and ship a NO-DATA (silence) packet for this - // slot; DATA replay resumes as soon as RX republishes kReadDelay - // entries. Persistent unavailability degrades to silence, which is the - // correct "nothing to send yet" state, not a stream death. + // a coordinator restart cannot re-prime TX. Persistent unavailability + // degrades to silence, which is the correct "nothing to send yet" + // state, not a stream death. if (!ivars.runtime.txReplayReader.IsActive()) { (void)ivars.runtime.txReplayReader.Begin( directControl->rxSequenceReplay); @@ -240,9 +238,40 @@ uint32_t PrepareTransmitSlots(ASFWAudioDriver_IVars& ivars, ASFW::Audio::Runtime::RxSequenceEntry replay{}; ASFW::Audio::Runtime::RxSequenceReplayReadDiagnostic replayDiagnostic{}; - if (ivars.runtime.txReplayReader.TryRead( - directControl->rxSequenceReplay, replay, - &replayDiagnostic)) { + bool replayReadable = ivars.runtime.txReplayReader.TryRead( + directControl->rxSequenceReplay, replay, + &replayDiagnostic); + // A reader that fell out of the bounded 512-entry RX history is + // repositionable, not faulted: Begin() re-anchors kReadDelay + // behind the live producer and the skipped entries only shift + // NODATA placement, which IEC 61883-6 blocking permits (DBC + // continuity is packetizer-owned; the SYT offset drifts sub-tick + // across the skipped span). Frame-cursor alignment must NOT + // re-arm for this: re-projecting abandons the established + // host-frame mapping and orphans every host frame behind the new + // cursor (the all-zero-payload Duet zombie of 2026-07-19). + if (!replayReadable && + replayDiagnostic.failure == + ASFW::Audio::Runtime::RxSequenceReplayReadFailure:: + kHistoryOverwritten) { + if (ivars.runtime.txReplayReader.Begin( + directControl->rxSequenceReplay)) { + replayReadable = ivars.runtime.txReplayReader.TryRead( + directControl->rxSequenceReplay, replay, + &replayDiagnostic); + } + ASFW_LOG_RING_ONLY_RL( + DirectAudio, + "tx-replay-reclamp", + 1000u, + ::ASFW::Logging::LogLevel::Warning, + "[TxReplay] reclamped pkt=%llu cur=%llu prod=%llu ok=%u", + nextPacketToPrepare, + replayDiagnostic.readerCursor, + replayDiagnostic.producerCursor, + replayReadable ? 1u : 0u); + } + if (replayReadable) { directControl->txReplayEntries.fetch_add( 1, std::memory_order_relaxed); timing.replayDataBlocks = replay.dataBlocks; @@ -273,26 +302,36 @@ uint32_t PrepareTransmitSlots(ASFWAudioDriver_IVars& ivars, replayDiagnostic.slotSequence, replayDiagnostic.slotEpoch, replayDiagnostic.replayEstablished ? 1u : 0u); - // Reader stale (epoch moved) or ahead of the producer: count it, - // drop the reader so the next packet re-Begins on the live epoch, - // and fall through with the NO-DATA disposition set above. Also - // re-arm the frame-cursor alignment: while stalled we emit NO-DATA - // packets, which do NOT advance the content-frame cursor, so it - // freezes at its pre-stall frame while CoreAudio keeps writing. If - // the stall outlasts one playback ring the cursor is stranded on - // overwritten (silent) frames forever. Re-arming makes the first - // DATA packet after replay recovers re-project the cursor to the - // live frame, closing the gap. Only reached on a genuine replay - // stall (churn), never during normal cadence NO-DATA. directControl->txReplayUnderflows.fetch_add( 1, std::memory_order_relaxed); - ivars.runtime.txReplayReader.Reset(); - ivars.runtime.txStreamEngine.ReArmFrameCursorAlignment(); - if (ivars.runtime.txSecondaryActive) { - ivars.runtime.txStreamEngineSecondary - .ReArmFrameCursorAlignment(); - } timing.replayDataBlocks = 0; + if (replayDiagnostic.failure == + ASFW::Audio::Runtime::RxSequenceReplayReadFailure:: + kAheadOfProducer) { + // RX simply has not published this entry yet (a deep + // preparation burst outran real-time RX). Hold the reader + // where it is and ship one NODATA packet; the same cursor + // reads successfully once RX catches up. Resetting the + // reader or re-arming alignment here turns a transient, + // self-resolving condition into a frame-cursor jump that + // abandons host frames. + } else { + // Epoch change, establishment loss, or a seqlock miss: the + // RX timing domain itself moved. Drop the reader so the + // next packet re-Begins on the live epoch and re-arm the + // frame-cursor alignment: while stalled we emit NO-DATA + // packets, which do NOT advance the content-frame cursor, + // so it freezes at its pre-stall frame while CoreAudio + // keeps writing. Re-arming makes the first DATA packet + // after replay recovers re-project the cursor to the live + // frame, closing the gap. + ivars.runtime.txReplayReader.Reset(); + ivars.runtime.txStreamEngine.ReArmFrameCursorAlignment(); + if (ivars.runtime.txSecondaryActive) { + ivars.runtime.txStreamEngineSecondary + .ReArmFrameCursorAlignment(); + } + } } if (replay.dataBlocks != 0) { diff --git a/ASFWDriver/Isoch/Transmit/IsochTransmitContext.cpp b/ASFWDriver/Isoch/Transmit/IsochTransmitContext.cpp index 81bbd72d..57fb8c44 100644 --- a/ASFWDriver/Isoch/Transmit/IsochTransmitContext.cpp +++ b/ASFWDriver/Isoch/Transmit/IsochTransmitContext.cpp @@ -274,6 +274,7 @@ kern_return_t IsochTransmitContext::Start() noexcept { interruptCount_.store(0, std::memory_order_relaxed); lastInterruptCountSeen_ = 0; irqStallTicks_ = 0; + irqSilentKickStreak_ = 0; refillInProgress_.clear(std::memory_order_release); latencyBucket0_.store(0, std::memory_order_relaxed); @@ -500,6 +501,26 @@ void IsochTransmitContext::Poll() noexcept { if (irqStallTicks_ >= 5) { irqStallTicks_ = 0; irqWatchdogKicks_.fetch_add(1, std::memory_order_relaxed); + ++irqSilentKickStreak_; + if (irqSilentKickStreak_ == 1) { + ASFW_LOG(Isoch, + "IT: refill watchdog engaged (no IT interrupts " + "observed; kicks=%llu)", + irqWatchdogKicks_.load(std::memory_order_relaxed)); + } + if (irqSilentKickStreak_ >= kIrqSilentKickFatalThreshold) { + // Watchdog-carried streaming re-transmits stale descriptor + // laps between kicks (observed Duet zombie, 2026-07-19: the + // interrupt path died mid-session and the watchdog fed the + // wire for 35 minutes of corrupt audio). Sustained interrupt + // silence is a transport fault, not jitter. + ASFW_LOG(Isoch, + "IT FATAL: interrupt path silent across %u " + "consecutive watchdog kicks; stopping context", + irqSilentKickStreak_); + StopImmediatelyForTxFault(); + return; + } if (!refillInProgress_.test_and_set(std::memory_order_acq_rel)) { // Stop() may have acquired the gate after the first state // check. Re-check while holding it before touching the slab. @@ -512,6 +533,7 @@ void IsochTransmitContext::Poll() noexcept { } else { lastInterruptCountSeen_ = currentInterrupts; irqStallTicks_ = 0; + irqSilentKickStreak_ = 0; } } diff --git a/ASFWDriver/Isoch/Transmit/IsochTransmitContext.hpp b/ASFWDriver/Isoch/Transmit/IsochTransmitContext.hpp index 9a68d0da..cc0378e0 100644 --- a/ASFWDriver/Isoch/Transmit/IsochTransmitContext.hpp +++ b/ASFWDriver/Isoch/Transmit/IsochTransmitContext.hpp @@ -126,6 +126,14 @@ class IsochTransmitContext final { uint64_t lastInterruptCountSeen_{0}; uint32_t irqStallTicks_{0}; + // Consecutive watchdog kicks with zero interrupts observed. The watchdog + // bridges interrupt-delivery jitter only: its cadence is far coarser than + // the 48-packet descriptor ring, so a stream carried by the watchdog + // re-transmits stale ring laps between kicks. A sustained silent streak + // is a dead interrupt path and the context must stop honestly. + static constexpr uint32_t kIrqSilentKickFatalThreshold = 16; + uint32_t irqSilentKickStreak_{0}; + // Refill Latency Histogram (buckets: <50us, 50-200us, 200-500us, >500us) std::atomic latencyBucket0_{0}; std::atomic latencyBucket1_{0}; diff --git a/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp b/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp index ed7f846a..22208146 100644 --- a/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp +++ b/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp @@ -38,6 +38,8 @@ void IsochTxDmaRing::ResetForStart() noexcept { nextTransmitCycle_ = 0; cycleTrackingValid_ = false; lastHwTimestamp_ = 0; + lastLapTimestamp_ = 0; + lapTimestampValid_ = false; counters_.lastDmaGapPackets.store(Layout::kNumPackets, std::memory_order_relaxed); counters_.minDmaGapPackets.store(Layout::kNumPackets, std::memory_order_relaxed); @@ -120,6 +122,41 @@ void IsochTxDmaRing::ResyncCycleTracking(Driver::HardwareInterface& hw, nextTransmitCycle_ = (hwCycle + aheadCount) % 8000; } +uint32_t IsochTxDmaRing::DetectLostLapPackets( + const uint32_t hwPacketIndex, const uint32_t deltaConsumed) noexcept { + if (!cycleTrackingValid_) { + return 0; + } + // Read the completion timestamp of the most recently executed packet. + // This must run even when the modulo delta is zero: a stall of exactly + // whole ring laps leaves the command pointer where it was while the + // timestamp has moved by kNumPackets * laps cycles. + const uint32_t lastProcessedPkt = + (hwPacketIndex + Layout::kNumPackets - 1) % Layout::kNumPackets; + auto* completionDesc = slab_.GetDescriptorPtr( + lastProcessedPkt * Layout::kBlocksPerPacket + + Layout::kCompletionBlock); + if (dmaMemory_) { + dmaMemory_->FetchFromDevice( + reinterpret_cast(completionDesc), + sizeof(*completionDesc)); + } + if (completionDesc->statusWord == 0) { + return 0; + } + const uint16_t rawTimestamp = + static_cast(completionDesc->statusWord & 0xFFFF); + const bool hadPrevious = lapTimestampValid_; + const uint16_t previousTimestamp = lastLapTimestamp_; + lastLapTimestamp_ = rawTimestamp; + lapTimestampValid_ = true; + if (!hadPrevious) { + return 0; + } + return ComputeLostLapPackets(previousTimestamp, rawTimestamp, + deltaConsumed); +} + void IsochTxDmaRing::CommitRefill(const uint32_t toFill) noexcept { softwareFillAbsIdx_ += toFill; ringPacketsAhead_ += toFill; @@ -404,6 +441,37 @@ IsochTxDmaRing::RefillOutcome IsochTxDmaRing::Refill( UpdateGapCounters(gap); ResyncCycleTracking(hw, hwPacketIndex, deltaConsumed, out); + // The free-running ring only exposes progress modulo kNumPackets through + // the command pointer. Recover whole ring laps the hardware executed + // between refills from the completion timestamps and reconcile every + // absolute cursor forward, or the producer/completion clock dilates + // against the bus while the wire re-transmits stale slots indefinitely + // (observed Duet zombie, 2026-07-19: 71% of wire packets were stale + // re-sends with the audio side dragged out of its replay window). + const uint32_t lostPackets = + DetectLostLapPackets(hwPacketIndex, deltaConsumed); + if (lostPackets != 0) { + counters_.lapLossEvents.fetch_add(1, std::memory_order_relaxed); + counters_.lapLossPacketsTotal.fetch_add(lostPackets, + std::memory_order_relaxed); + // The stale re-transmissions already left the wire (a DBC seam per + // lap); descriptors still queued keep at most one more stale lap. + // Reconciliation restores true bus-time pacing from this refill on. + ASFW_LOG( + Isoch, + "IT LAP LOSS: ring lapped %u packets between refills " + "delta=%u completion=%llu committed=%llu fill=%llu", + lostPackets, + deltaConsumed, + controlBlock->completionCursor.load(std::memory_order_relaxed), + controlBlock->committedEnd.load(std::memory_order_acquire), + softwareFillAbsIdx_); + if (softwareFillAbsIdx_ != 0) { + softwareFillAbsIdx_ += lostPackets; + } + ringPacketsAhead_ = 0; + } + // Publish a neutral completion-delta high-water. Content consumers decide // whether their own frame/lead policy can tolerate the observed cadence. { @@ -427,8 +495,12 @@ IsochTxDmaRing::RefillOutcome IsochTxDmaRing::Refill( } } - // Fetch and publish completed stamps - const uint64_t completedAbsIdx = controlBlock->completionCursor.load(std::memory_order_relaxed); + // Fetch and publish completed stamps. Lost laps shift the absolute index + // base: the descriptors read below were last executed in the newest lap, + // so their stamps belong to the reconciled indices, not the stale window. + const uint64_t completedAbsIdx = + controlBlock->completionCursor.load(std::memory_order_relaxed) + + lostPackets; for (uint32_t i = 0; i < deltaConsumed; ++i) { const uint64_t currentAbsIdx = completedAbsIdx + i; const uint32_t completedPktSlot = static_cast(currentAbsIdx % Layout::kNumPackets); @@ -451,7 +523,7 @@ IsochTxDmaRing::RefillOutcome IsochTxDmaRing::Refill( controlBlock->PushCompletionStamp(currentAbsIdx, completionCycleTimer); } - if (deltaConsumed > 0) { + if (deltaConsumed > 0 || lostPackets > 0) { controlBlock->completionCursor.store(completedAbsIdx + deltaConsumed, std::memory_order_release); const uint64_t requested = diff --git a/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp b/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp index 5da49a17..0761bce5 100644 --- a/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp +++ b/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp @@ -49,6 +49,13 @@ class IsochTxDmaRing final { // own the policy that decides whether this is an unsafe cadence. std::atomic maxDeltaConsumed{0}; + // Full descriptor-ring laps the free-running hardware executed between + // two refills. Every lost lap is kNumPackets stale packets re-sent on + // the wire; the completion cursor is reconciled forward so producer + // pacing stays on true bus time instead of dilating. + std::atomic lapLossEvents{0}; + std::atomic lapLossPacketsTotal{0}; + // DMA ring gap monitoring std::atomic lastDmaGapPackets{Layout::kNumPackets}; std::atomic minDmaGapPackets{Layout::kNumPackets}; @@ -137,6 +144,41 @@ class IsochTxDmaRing final { [[nodiscard]] const Counters& RTCounters() const noexcept { return counters_; } [[nodiscard]] uint32_t LastHwTimestamp() const noexcept { return lastHwTimestamp_; } + // The IT descriptor ring is circular and free-running: hardware keeps + // executing it whether or not software refilled, so per-refill progress + // measured from the command pointer is only known modulo kNumPackets. + // The OUTPUT_LAST completion timestamps (3-bit seconds + 13-bit cycle, + // OHCI §9.4.2) recover true progress: the context transmits exactly one + // packet per cycle, so cycles elapsed between the last-processed packets + // of two refills equals packets truly consumed. Any surplus over the + // modulo delta is whole ring laps of stale re-transmission. Rounding to + // whole laps absorbs single-cycle jitter (missed cycle / cycle-master + // correction). Valid for refill gaps below the 8-second timestamp wrap; + // the transmit context faults out long before that horizon. + [[nodiscard]] static constexpr uint32_t ComputeLostLapPackets( + uint16_t previousTimestamp, + uint16_t currentTimestamp, + uint32_t deltaConsumed) noexcept { + constexpr uint32_t kCyclesPerSecond = 8000u; + constexpr uint32_t kTimestampDomainCycles = 8u * kCyclesPerSecond; + const uint32_t previousOrdinal = + ((previousTimestamp >> 13) & 0x7u) * kCyclesPerSecond + + ((previousTimestamp & 0x1FFFu) % kCyclesPerSecond); + const uint32_t currentOrdinal = + ((currentTimestamp >> 13) & 0x7u) * kCyclesPerSecond + + ((currentTimestamp & 0x1FFFu) % kCyclesPerSecond); + const uint32_t elapsedCycles = + (currentOrdinal + kTimestampDomainCycles - previousOrdinal) % + kTimestampDomainCycles; + if (elapsedCycles <= deltaConsumed) { + return 0; + } + const uint32_t surplus = elapsedCycles - deltaConsumed; + const uint32_t lostLaps = + (surplus + Layout::kNumPackets / 2) / Layout::kNumPackets; + return lostLaps * Layout::kNumPackets; + } + // Expose slab for audio injection. [[nodiscard]] IsochTxDescriptorSlab& Slab() noexcept { return slab_; } [[nodiscard]] const IsochTxDescriptorSlab& Slab() const noexcept { return slab_; } @@ -149,6 +191,8 @@ class IsochTxDmaRing final { uint32_t deltaConsumed, RefillOutcome& out) noexcept; void CommitRefill(uint32_t toFill) noexcept; + [[nodiscard]] uint32_t DetectLostLapPackets(uint32_t hwPacketIndex, + uint32_t deltaConsumed) noexcept; [[nodiscard]] bool DecodeHardwarePacketIndex(Driver::HardwareInterface& hw, uint8_t contextIndex, uint32_t& outPacketIndex, @@ -168,6 +212,11 @@ class IsochTxDmaRing final { bool cycleTrackingValid_{false}; uint32_t lastHwTimestamp_{0}; + // Previous refill's last-processed completion timestamp; anchors the + // true-cycle lap-loss detection across refills. + uint16_t lastLapTimestamp_{0}; + bool lapTimestampValid_{false}; + Counters counters_{}; }; diff --git a/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md b/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md index ae92407c..594678d8 100644 --- a/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md +++ b/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md @@ -243,6 +243,8 @@ Linux and FFADO, without copying their mechanisms. | `AVC-RECOVERY-002` | **Confirmed critical defect** | FW-64 treats every *established* replay reset as an eventual destructive `RecoverStreaming()`. A reset can mean a malformed RX packet, one cycle gap, rejected cadence, or rejected clock anchor—not necessarily a device outage. The coordinator stops/restarts transport while CoreAudio remains running with its old TX producer state. | Disable AV/C automatic transport restart until recovery atomically quiesces/resets/re-primes the audio producer and transport under one recovery epoch. Report the fault and request an audio-side xrun/controlled restart instead. | | `AVC-PROPERTY-001` | **Fixed; requires hardware confirmation** | `AudioNubPublisher` sets stream mode on the nub, but `ASFWAudioDevice::PopulateNubProperties()` did not publish `ASFWStreamMode`; the driver parser consequently defaulted to non-blocking. The model default is also non-blocking ([`ASFWAudioDevice.hpp:52-60`](ASFWDriver/Audio/Model/ASFWAudioDevice.hpp#L52-L60)); parsing only changes it if the property exists ([`AudioDriverConfig.cpp:67-84`](ASFWDriver/Audio/DriverKit/Config/AudioDriverConfig.cpp#L67-L84)). The matching dictionary now publishes the selected mode. | On the next Duet/BeBoB start, confirm the AudioDriver reports `Stream mode from nub: blocking`; the property path is shared by all published audio nubs. | | `AVC-TX-EXPOSURE-001` | **Confirmed audio-path defect; root scheduling cause open** | The payload writer skips CoreAudio frames which arrive beyond `Timeline().ExposedFrameEnd()` (`framesWithoutPacket`); `TxAlign` later repositions the producer cursor to close the deficit. This can produce audible corruption while DMA/CMP and the TX descriptor lead remain healthy, then self-heal without a stream restart ([`AmdtpPayloadWriter.cpp:90-126`](ASFWDriver/Audio/Wire/AMDTP/AmdtpPayloadWriter.cpp#L90-L126), [`ASFWAudioDriverZts.cpp:360-389`](ASFWDriver/Audio/DriverKit/ASFWAudioDriverZts.cpp#L360-L389)). | Retain pending host frames until slots exist and maintain a data-bearing packet horizon beyond the maximum IO callback plus measured scheduling jitter; never discard a running stream's host frames because their packet is not yet exposed. | +| `TX-LAPLOSS-001` | **Confirmed; fixed 2026-07-19, requires hardware confirmation** | IT completion accounting measured hardware progress modulo the 48-packet free-running ring; refill gaps > 6 ms silently discarded whole laps, dilating producer time and re-transmitting stale packets (the 2026-07-19 all-zero Duet zombie). | Validate the lap-loss reconciliation and `IT LAP LOSS` telemetry on hardware; see "2026-07-19 zombie stream" below. | +| `TX-IRQ-001` | **Open** | The IT interrupt path went permanently silent ~10 minutes into the 2026-07-19 session; the refill watchdog carried the stream. Cause unknown (mask write, storm mitigation, dispatch loss). | Reproduce with the new watchdog-engagement log; correlate with `IsoXmitIntMask` writes. The 16-kick fatal now bounds the damage. | | `AVC-SYNC-001` | **Not proven** | Treating raw RX/TX SYT inequality as a fault would be wrong for the captured duplex stream. | Add the normalized, per-direction trace below before adjusting delays or cadence. | | `AVC-HEALTH-001` | **Instrumented; root cause open** | The original RX timing loss occurred without a bus reset in the observed driver ring; successful restart was then masked by `AVC-RECOVERY-001`. | Reproduce with the first-fault record below; it distinguishes a local RX validation failure from a real no-RX/CMP outage. | @@ -592,6 +594,97 @@ The required contract is non-negotiable: 4. On recovery, reset/re-prime W/E/C/R under one epoch before transport runs; do not use `TxAlign` to silently abandon the old interval. +## 2026-07-19 zombie stream: transport lap loss confirmed as the driver + +The 44-minute Duet run of 2026-07-19 (FireBug capture `!duet-fubar.txt` plus +the full MCP driver ring) finally attributed the "transport-alive, +audio-all-zero" state to a transport accounting defect underneath everything +in this document. The wire showed both channels at one packet per cycle with +0 silent cycles and channel 0 carrying 72-byte DATA packets whose SYT tracked +channel 1 exactly — with every PCM sample zero. + +Measured from the retained ring (17.3-minute window, zero dropped records): + +| Quantity | Expected | Measured | +| --- | ---: | ---: | +| RX replay entries published | 8,000/s | 7,995/s (healthy) | +| TX completion cursor advance | 8,000/s | ~575/s | +| TX packets prepared | 8,000/s | ~575/s | +| `[TxAlign]` realignments | 1 per stream | every prepare batch (~28,000 total) | +| `[TxReplay] fail=overwritten` | none | ~13/s at `d=-547..-920`, `ep=4/4` | +| PayloadWriter frames written | ~all | ~0 (`outside` ≈ all visited) | + +At stop, the context reported `6,228,647 pkts IRQs=810214` against ~21.4 M +wire packets: the IT interrupt path ran at its healthy ~1,333/s for roughly +the first ten minutes, then went permanently silent; the `Poll()` watchdog +(~68 ms cadence) carried the stream for the remaining half hour. + +The causal chain, each link now confirmed in code: + +1. The IT descriptor ring is circular and free-running; hardware never stops. + `ComputeDeltaConsumed()` measured progress from the command pointer, which + is only defined **modulo the 48-packet ring**. Any refill gap longer than + 6 ms silently discards whole laps: the wire re-transmits the stale 48 + slots (a DBC seam per lap, invisible in SYT because 48 ≡ 0 mod 16 cycles) + while `completionCursor` under-advances with no fault raised. Under the + watchdog cadence this lost ~10 laps per kick — 71% of the session's wire + packets were stale re-sends. +2. The producer paces itself from `completionCursor`, so producer time + dilated to ~7% of bus time. The replay reader consumed ~575 entries/s + against RX's 8,000/s and fell out of its 512-entry window every few tens + of milliseconds (`fail=overwritten` with `ep` unchanged — no RX reset). +3. Every replay miss reset the reader **and re-armed frame-cursor + alignment**; the next DATA read re-projected the cursor ahead of the host + write frontier, so the payload writer classified essentially every host + frame `outside` and the pre-zeroed DATA payloads shipped as silence. The + loop is self-sustaining: transport looks healthy, audio is permanently + dead. + +### Implemented fixes (2026-07-19) + +1. **True-cycle completion accounting** (`IsochTxDmaRing`): + `ComputeLostLapPackets()` recovers true progress from the OUTPUT_LAST + completion timestamps (the context transmits exactly one packet per + cycle), detects whole lost laps — including the pointer-unmoved + exactly-one-lap stall — and reconciles `completionCursor`, + `softwareFillAbsIdx_`, and the completion stamps forward. New counters + `lapLossEvents`/`lapLossPacketsTotal` plus an `IT LAP LOSS` ring record + make every event attributable. The stale packets already on the wire are + acknowledged as a bounded glitch, not silently converted into permanent + time dilation. +2. **Sustained interrupt-silence fault** (`IsochTransmitContext::Poll()`): + the watchdog now logs its first engagement and, after 16 consecutive + IRQ-silent kicks (~1 s), stops the context via the existing TX-fault path. + Watchdog-carried streaming re-transmits stale laps between kicks and is + never a valid steady state. +3. **Failure-class replay handling** (`PrepareTransmitSlots()`): + `overwritten` re-anchors the reader via `Begin()` and retries in place + (`[TxReplay] reclamped`, no alignment re-arm — skipped entries only shift + NODATA placement, which IEC 61883-6 blocking permits); `ahead` holds the + reader and ships one NODATA; only a genuine RX-domain transition (epoch + change, establishment loss, seqlock miss) resets the reader and re-arms + alignment. This removes the realign churn that orphaned host frames. + +Host-side regression coverage: `IsochTxLapLossMath.*`, +`IsochTxDmaRingTest.RefillReconcilesLostLapForward`, +`IsochTxDmaRingTest.RefillDetectsWholeLapStallWithUnmovedPointer`, +`RxDrivenTimingTests.ReaderReBeginReanchorsAfterHistoryOverwritten`. + +### Still open after these fixes + +- `TX-IRQ-001` — **why the IT interrupt path died ~10 minutes in.** The ring + had already wrapped past the transition. The new first-engagement log and + lap-loss counters will timestamp the next occurrence; correlate against + `IsoXmitIntMask` writes (the stop/fault paths mask IT interrupts). +- The FW-64 items (`AUDIO-RECOVERY-ROUTING-001` callback overwrite, + `AVC-RECOVERY-002` unsafe background restart) are unchanged by this work + and remain confirmed defects; they were not required to produce this + incident. +- The pending-frame model of `AVC-TX-EXPOSURE-001` (retain host frames until + slots exist) remains the durable repair for exposure lag; with the + transport clock no longer dilating it is defense in depth rather than the + first-order fault. + ## Minimal anomaly-only telemetry for the next hardware run Keep the MCP ring as the primary evidence path; no Console logging is needed @@ -619,3 +712,42 @@ clock failure; a DBC/cycle discontinuity, invalid valid-SYT cadence, or a timeout without a fresh valid RX anchor is. The implemented first-fault record identifies the present reset path; add the remaining normalized RX/TX phase and recovery-epoch records only after that result identifies the layer at fault. + +## Duet discovery: FCP clock prepublish must not hide a usable device + +### Evidence + +During the 2026-07-19 no-nub incident, discovery read Duet's live rate as +44.1 kHz, then started the optional fixed-48-kHz prepublish sequence. The +discovery watchdog completed it after 1,200 ms, while FCP's first response +deadline is 2,000 ms. The failure path then deferred the nub entirely, so no +AudioDriverKit device could reach Audio MIDI Setup. + +The FireBug trace shows that Duet uses the standard, expected choreography: +an 8-byte `STATUS` or `CONTROL` Unit Plug Signal Format command (opcodes +`0x19` input then `0x18` output) is answered by an 8-byte FCP block write to +the initiator's `0xfffff0000d00` response register. This matches the command +form used by ASFW and Linux OXFW's input-before-output ordering +(`references/linux-upstream/sound/firewire/oxfw/oxfw-stream.c:41-54`). The +device does not reject the standard format sequence. + +### Root cause and implemented fix + +ASFW drains AR Request before AR Response. The FCP payload is a block write in +AR Request; the write acknowledgement for our preceding command is in AR +Response. `FCPTransport::OnFCPResponse()` previously rejected a valid FCP +payload until the latter callback had set `successfulWriteAttempt`. The exact +Duet wire order therefore became: + +```text +Duet FCP response arrives in AR Request → dropped as "before write completion" +our write acknowledgement arrives in AR Response → start a 2 s FCP timer +no second FCP payload exists → timeout, no verified 48 kHz, no nub +``` + +The FCP response itself proves that the target received and processed the +command. The transport now accepts a validated response for its active +node/generation/write-attempt even if the local write-completion callback has +not run yet. A later write callback is safely stale after the FCP command has +completed. The Duet remains fixed to 48 kHz: no fallback rate is advertised or +published. diff --git a/tests/audio/IsochTxDmaRingTests.cpp b/tests/audio/IsochTxDmaRingTests.cpp index 251aeecb..33b0e7a8 100644 --- a/tests/audio/IsochTxDmaRingTests.cpp +++ b/tests/audio/IsochTxDmaRingTests.cpp @@ -1116,3 +1116,176 @@ TEST(IsochTxQueueControlTests, ProducerAndConsumerResetsHaveDisjointOwnership) { EXPECT_EQ(queue.statusWord.load(std::memory_order_acquire), IsochTxQueueStatus::kRunning); } + +// --- Lap-loss detection: the IT descriptor ring is free-running, so the +// command pointer exposes progress only modulo Layout::kNumPackets. The +// completion timestamps recover true progress; a surplus is whole ring laps +// of stale re-transmission that must reconcile every absolute cursor. + +TEST(IsochTxLapLossMath, ExactLapSurplusYieldsWholeLap) { + const uint16_t prev = static_cast((3u << 13) | 3007u); + const uint16_t cur = static_cast((3u << 13) | 3063u); + EXPECT_EQ(IsochTxDmaRing::ComputeLostLapPackets(prev, cur, 8), + Layout::kNumPackets); +} + +TEST(IsochTxLapLossMath, SecondsFieldWrapIsUnambiguous) { + const uint16_t prev = static_cast((7u << 13) | 7990u); + const uint16_t cur = static_cast((0u << 13) | 50u); + // 60 cycles elapsed across the 8-second wrap, 12 accounted by the + // command-pointer delta: one lost lap. + EXPECT_EQ(IsochTxDmaRing::ComputeLostLapPackets(prev, cur, 12), + Layout::kNumPackets); +} + +TEST(IsochTxLapLossMath, SmallSurplusIsTimestampJitterNotALap) { + const uint16_t prev = static_cast((3u << 13) | 3000u); + const uint16_t cur = static_cast((3u << 13) | 3011u); + EXPECT_EQ(IsochTxDmaRing::ComputeLostLapPackets(prev, cur, 8), 0u); +} + +TEST(IsochTxLapLossMath, NoProgressNoLoss) { + const uint16_t ts = static_cast((2u << 13) | 100u); + EXPECT_EQ(IsochTxDmaRing::ComputeLostLapPackets(ts, ts, 0), 0u); +} + +TEST(IsochTxLapLossMath, MultipleLapsAccumulate) { + const uint16_t prev = static_cast((1u << 13) | 1000u); + const uint16_t cur = static_cast( + (1u << 13) | (1000u + 8u + 2u * Layout::kNumPackets)); + EXPECT_EQ(IsochTxDmaRing::ComputeLostLapPackets(prev, cur, 8), + 2u * Layout::kNumPackets); +} + +TEST_F(IsochTxDmaRingTest, RefillReconcilesLostLapForward) { + auto metadataRing = MakeMetadataRing(); + (void)ring_.Prime( + payloadDmaMap_, kSharedPayloadSlots, kSharedPayloadStride, + metadataRing.data(), Layout::kNumPackets); + ring_.ResetForStart(); + ring_.SeedCycleTracking(hardware_); + + IsochTxQueueControl controlBlock{}; + controlBlock.numSlots = kSharedPayloadSlots; + controlBlock.slotStrideBytes = kSharedPayloadStride; + controlBlock.maxPacketBytes = kSharedPayloadStride; + + hardware_.SetTestRegister( + static_cast(DMAContextHelpers::IsoXmitContextControl(0)), + 0); + + // Refill 1: hardware consumed packets 0..7, completing at cycles + // 3000..3007. This anchors the lap-loss timestamp baseline. + for (uint32_t i = 0; i < 8; ++i) { + auto* desc = ring_.Slab().GetDescriptorPtr( + i * Layout::kBlocksPerPacket + Layout::kCompletionBlock); + desc->statusWord = + (0x8000u << 16) | ((3u << 13) | (3000u + i)); + } + hardware_.SetTestRegister( + static_cast(DMAContextHelpers::IsoXmitCommandPtr(0)), + ring_.Slab().GetDescriptorIOVA(8 * Layout::kBlocksPerPacket) | + Layout::kBlocksPerPacket); + auto first = ring_.Refill( + hardware_, 0, metadataRing.data(), &controlBlock, + kSharedPayloadSlots, sharedPayload_.data(), payloadDmaMap_); + ASSERT_TRUE(first.ok); + ASSERT_EQ(controlBlock.completionCursor.load(), 8u); + + // Refill 2: the command pointer moved 8 positions (mod-48 delta = 8), + // but the completion timestamps show 56 elapsed cycles: the hardware + // lapped the whole ring once, re-transmitting 48 stale packets. + for (uint32_t i = 8; i < 16; ++i) { + auto* desc = ring_.Slab().GetDescriptorPtr( + i * Layout::kBlocksPerPacket + Layout::kCompletionBlock); + desc->statusWord = + (0x8000u << 16) | ((3u << 13) | (3048u + i)); + } + hardware_.SetTestRegister( + static_cast(DMAContextHelpers::IsoXmitCommandPtr(0)), + ring_.Slab().GetDescriptorIOVA(16 * Layout::kBlocksPerPacket) | + Layout::kBlocksPerPacket); + auto second = ring_.Refill( + hardware_, 0, metadataRing.data(), &controlBlock, + kSharedPayloadSlots, sharedPayload_.data(), payloadDmaMap_); + ASSERT_TRUE(second.ok); + + // Completion reconciled: 8 consumed + 48 lost + 8 consumed = 64. + EXPECT_EQ(controlBlock.completionCursor.load(), 64u); + EXPECT_EQ(ring_.RTCounters().lapLossEvents.load(), 1u); + EXPECT_EQ(ring_.RTCounters().lapLossPacketsTotal.load(), + Layout::kNumPackets); + + // Stamps carry the reconciled absolute indices (56..63), so downstream + // packet-to-cycle anchoring stays on true bus time. + for (uint32_t i = 0; i < 8; ++i) { + uint64_t pktIdx = 0; + uint32_t ts = 0; + ASSERT_TRUE(controlBlock.ReadCompletionStamp(8 + i, pktIdx, ts)); + EXPECT_EQ(pktIdx, 56u + i); + } + + // The refill mapped the reconciled absolute window (slots 56..63), not + // the stale pre-lap window (slots 8..15). + for (uint32_t i = 0; i < 8; ++i) { + auto* desc2 = ring_.Slab().GetDescriptorPtr( + (8 + i) * Layout::kBlocksPerPacket + Layout::kFirstPayloadBlock); + EXPECT_EQ(desc2->dataAddress, + kSharedPayloadIOVA + (56u + i) * kSharedPayloadStride); + } +} + +TEST_F(IsochTxDmaRingTest, RefillDetectsWholeLapStallWithUnmovedPointer) { + auto metadataRing = MakeMetadataRing(); + (void)ring_.Prime( + payloadDmaMap_, kSharedPayloadSlots, kSharedPayloadStride, + metadataRing.data(), Layout::kNumPackets); + ring_.ResetForStart(); + ring_.SeedCycleTracking(hardware_); + + IsochTxQueueControl controlBlock{}; + controlBlock.numSlots = kSharedPayloadSlots; + controlBlock.slotStrideBytes = kSharedPayloadStride; + controlBlock.maxPacketBytes = kSharedPayloadStride; + + hardware_.SetTestRegister( + static_cast(DMAContextHelpers::IsoXmitContextControl(0)), + 0); + + for (uint32_t i = 0; i < 8; ++i) { + auto* desc = ring_.Slab().GetDescriptorPtr( + i * Layout::kBlocksPerPacket + Layout::kCompletionBlock); + desc->statusWord = + (0x8000u << 16) | ((3u << 13) | (3000u + i)); + } + hardware_.SetTestRegister( + static_cast(DMAContextHelpers::IsoXmitCommandPtr(0)), + ring_.Slab().GetDescriptorIOVA(8 * Layout::kBlocksPerPacket) | + Layout::kBlocksPerPacket); + auto first = ring_.Refill( + hardware_, 0, metadataRing.data(), &controlBlock, + kSharedPayloadSlots, sharedPayload_.data(), payloadDmaMap_); + ASSERT_TRUE(first.ok); + ASSERT_EQ(controlBlock.completionCursor.load(), 8u); + + // The command pointer has not moved (mod-48 delta = 0), but packet 7's + // completion timestamp advanced exactly one ring lap: the stall was an + // invisible whole-lap re-transmission. + { + auto* desc = ring_.Slab().GetDescriptorPtr( + 7 * Layout::kBlocksPerPacket + Layout::kCompletionBlock); + desc->statusWord = + (0x8000u << 16) | + ((3u << 13) | (3007u + Layout::kNumPackets)); + } + auto second = ring_.Refill( + hardware_, 0, metadataRing.data(), &controlBlock, + kSharedPayloadSlots, sharedPayload_.data(), payloadDmaMap_); + ASSERT_TRUE(second.ok); + + EXPECT_EQ(controlBlock.completionCursor.load(), + 8u + Layout::kNumPackets); + EXPECT_EQ(ring_.RTCounters().lapLossEvents.load(), 1u); + EXPECT_EQ(ring_.RTCounters().lapLossPacketsTotal.load(), + Layout::kNumPackets); +} diff --git a/tests/audio/RxDrivenTimingTests.cpp b/tests/audio/RxDrivenTimingTests.cpp index fc7ca32e..f6141b53 100644 --- a/tests/audio/RxDrivenTimingTests.cpp +++ b/tests/audio/RxDrivenTimingTests.cpp @@ -256,3 +256,54 @@ TEST(RxDrivenTimingTests, InputSafetyIsVisibilityMarginNotClientWindow) { } } // namespace + +TEST(RxDrivenTimingTests, ReaderReBeginReanchorsAfterHistoryOverwritten) { + RxSequenceReplayState replay{}; + replay.Reset(); + + auto publishCycles = [&replay](uint64_t firstCycle, uint64_t count) { + for (uint64_t cycle = firstCycle; + cycle < firstCycle + count; + ++cycle) { + RxSequenceEntry entry{}; + entry.firstAudioFrame = cycle * 6; + entry.dataBlocks = static_cast( + (cycle % 4) == 3 ? 0 : 8); + entry.sytOffset = entry.dataBlocks == 0 + ? RxSequenceReplayState::kNoInfo + : static_cast(cycle); + replay.Publish(entry); + } + }; + + publishCycles(0, RxSequenceReplayState::kCapacity); + ASSERT_TRUE(replay.MarkEstablished()); + + RxSequenceReplayReader reader{}; + ASSERT_TRUE(reader.Begin(replay)); + const uint32_t epochAtBegin = replay.Epoch(); + + // The producer runs a full capacity plus one ahead while the reader is + // idle: the reader's cursor now points below the retained window. + publishCycles(RxSequenceReplayState::kCapacity, + RxSequenceReplayState::kCapacity + 1); + + RxSequenceEntry entry{}; + RxSequenceReplayReadDiagnostic diagnostic{}; + ASSERT_FALSE(reader.TryRead(replay, entry, &diagnostic)); + EXPECT_EQ(diagnostic.failure, + RxSequenceReplayReadFailure::kHistoryOverwritten); + + // Re-anchoring is a repositioning of the same established stream, not an + // epoch transition: Begin() lands kReadDelay behind the live producer and + // the next read succeeds with the entry published for that cursor. + ASSERT_TRUE(reader.Begin(replay)); + EXPECT_EQ(replay.Epoch(), epochAtBegin); + EXPECT_EQ(reader.NextCursor(), + replay.ProducerCursor() - RxSequenceReplayState::kReadDelay); + + ASSERT_TRUE(reader.TryRead(replay, entry, &diagnostic)); + const uint64_t expectedCycle = + replay.ProducerCursor() - RxSequenceReplayState::kReadDelay; + EXPECT_EQ(entry.firstAudioFrame, expectedCycle * 6); +} From 4b13e1c8381b63c1093d3b5d8fc524e9f8bade74 Mon Sep 17 00:00:00 2001 From: Aleksandr Shabelnikov Date: Sun, 19 Jul 2026 12:08:35 +0200 Subject: [PATCH 3/6] Classify context stall vs lap loss and snapshot fault state The Saffire Pro 24 DSP run showed the lap-loss detector's blind spot: completion timestamps cannot distinguish free-running stale re-transmission from a stalled context whose sparse crawl stamps late timestamps (FireBug counted 13 wire packets where the timestamps implied 64k). Classify by coverage: unaccounted progress within the producer's committed lead is reconciled as before; progress beyond it can only end at an uncommitted slot, so fault immediately as context-stalled with the completion accounting untouched. Record ContextControl and the latched IntEvent bits (visible even when masked) in the lap-loss, context-stalled, and watchdog paths as first-fault evidence for the still-open freeze trigger (TX-STALL-001). Document the Saffire incident, TX-STALL-001, and the confirmed fault-propagation gap TX-FAULT-PROP-001. Co-Authored-By: Claude Fable 5 --- .../Isoch/Transmit/IsochTransmitContext.cpp | 32 ++++++++-- ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp | 61 +++++++++++++----- ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp | 27 +++++--- AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md | 35 +++++++++++ tests/audio/IsochTxDmaRingTests.cpp | 63 +++++++++++++++++++ 5 files changed, 191 insertions(+), 27 deletions(-) diff --git a/ASFWDriver/Isoch/Transmit/IsochTransmitContext.cpp b/ASFWDriver/Isoch/Transmit/IsochTransmitContext.cpp index 57fb8c44..3b38f391 100644 --- a/ASFWDriver/Isoch/Transmit/IsochTransmitContext.cpp +++ b/ASFWDriver/Isoch/Transmit/IsochTransmitContext.cpp @@ -502,11 +502,23 @@ void IsochTransmitContext::Poll() noexcept { irqStallTicks_ = 0; irqWatchdogKicks_.fetch_add(1, std::memory_order_relaxed); ++irqSilentKickStreak_; - if (irqSilentKickStreak_ == 1) { + // Snapshot context + latched interrupt state on the anomaly path + // only. kIntEvent latches raised events even when masked, so a + // cycleInconsistent/cycleTooLong the dispatcher never serviced is + // still visible here (first-fault evidence for the 2026-07-19 + // Saffire dual-context freeze, whose trigger left no interrupt + // record). + if (irqSilentKickStreak_ == 1 && hardware_) { + const uint32_t ctrl = hardware_->Read(static_cast( + DMAContextHelpers::IsoXmitContextControl(contextIndex_))); + const uint32_t latchedIntEvents = + hardware_->Read(Register32::kIntEvent); ASFW_LOG(Isoch, "IT: refill watchdog engaged (no IT interrupts " - "observed; kicks=%llu)", - irqWatchdogKicks_.load(std::memory_order_relaxed)); + "observed; kicks=%llu ctrl=0x%08x intEvent=0x%08x)", + irqWatchdogKicks_.load(std::memory_order_relaxed), + ctrl, + latchedIntEvents); } if (irqSilentKickStreak_ >= kIrqSilentKickFatalThreshold) { // Watchdog-carried streaming re-transmits stale descriptor @@ -514,10 +526,20 @@ void IsochTransmitContext::Poll() noexcept { // interrupt path died mid-session and the watchdog fed the // wire for 35 minutes of corrupt audio). Sustained interrupt // silence is a transport fault, not jitter. + const uint32_t ctrl = hardware_ + ? hardware_->Read(static_cast( + DMAContextHelpers::IsoXmitContextControl( + contextIndex_))) + : 0; + const uint32_t latchedIntEvents = + hardware_ ? hardware_->Read(Register32::kIntEvent) : 0; ASFW_LOG(Isoch, "IT FATAL: interrupt path silent across %u " - "consecutive watchdog kicks; stopping context", - irqSilentKickStreak_); + "consecutive watchdog kicks; stopping context " + "(ctrl=0x%08x intEvent=0x%08x)", + irqSilentKickStreak_, + ctrl, + latchedIntEvents); StopImmediatelyForTxFault(); return; } diff --git a/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp b/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp index 22208146..2e942312 100644 --- a/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp +++ b/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp @@ -355,6 +355,8 @@ const char* IsochTxDmaRing::RefillFailureReasonName( return "uncommitted-slot"; case RefillFailureReason::InvalidPacketSize: return "invalid-packet-size"; + case RefillFailureReason::ContextStalled: + return "context-stalled"; case RefillFailureReason::PayloadMapping: return "payload-mapping"; } @@ -442,30 +444,61 @@ IsochTxDmaRing::RefillOutcome IsochTxDmaRing::Refill( ResyncCycleTracking(hw, hwPacketIndex, deltaConsumed, out); // The free-running ring only exposes progress modulo kNumPackets through - // the command pointer. Recover whole ring laps the hardware executed - // between refills from the completion timestamps and reconcile every - // absolute cursor forward, or the producer/completion clock dilates - // against the bus while the wire re-transmits stale slots indefinitely - // (observed Duet zombie, 2026-07-19: 71% of wire packets were stale - // re-sends with the audio side dragged out of its replay window). + // the command pointer. The completion timestamps recover the unaccounted + // whole ring laps, but they cannot say which of two faults produced them: + // free-running stale re-transmission (2026-07-19 Duet zombie: 71% of wire + // packets were stale re-sends) or a stalled context whose sparse crawl + // stamps late timestamps (2026-07-19 Saffire freeze: 13 wire packets + // while the timestamps implied 64k). Classify by coverage: a jump the + // producer's committed lead can absorb is reconciled so pacing returns to + // true bus time; a larger jump can only end at an uncommitted slot, so + // fault immediately with untouched cursors instead of corrupting the + // accounting on the way to the same stop. const uint32_t lostPackets = DetectLostLapPackets(hwPacketIndex, deltaConsumed); if (lostPackets != 0) { + const uint64_t completedRaw = + controlBlock->completionCursor.load(std::memory_order_relaxed); + const uint64_t consumedEnd = completedRaw + deltaConsumed; + const uint64_t committedNow = + controlBlock->committedEnd.load(std::memory_order_acquire); + const uint64_t committedHeadroom = + committedNow > consumedEnd ? committedNow - consumedEnd : 0; + const uint32_t latchedIntEvents = hw.Read(Register32::kIntEvent); + if (lostPackets > committedHeadroom) { + counters_.contextStallFatals.fetch_add(1, + std::memory_order_relaxed); + ASFW_LOG( + Isoch, + "IT FATAL: context stalled - unaccounted progress %u packets " + "exceeds committed lead %llu (delta=%u completion=%llu " + "committed=%llu ctrl=0x%08x intEvent=0x%08x)", + lostPackets, + committedHeadroom, + deltaConsumed, + completedRaw, + committedNow, + ctrl, + latchedIntEvents); + out.failureReason = RefillFailureReason::ContextStalled; + out.failurePacketAbs = consumedEnd; + return out; + } counters_.lapLossEvents.fetch_add(1, std::memory_order_relaxed); counters_.lapLossPacketsTotal.fetch_add(lostPackets, std::memory_order_relaxed); - // The stale re-transmissions already left the wire (a DBC seam per - // lap); descriptors still queued keep at most one more stale lap. - // Reconciliation restores true bus-time pacing from this refill on. ASFW_LOG( Isoch, - "IT LAP LOSS: ring lapped %u packets between refills " - "delta=%u completion=%llu committed=%llu fill=%llu", + "IT LAP LOSS: %u packets of unaccounted hardware progress " + "(stale re-send or brief stall) delta=%u completion=%llu " + "committed=%llu fill=%llu ctrl=0x%08x intEvent=0x%08x", lostPackets, deltaConsumed, - controlBlock->completionCursor.load(std::memory_order_relaxed), - controlBlock->committedEnd.load(std::memory_order_acquire), - softwareFillAbsIdx_); + completedRaw, + committedNow, + softwareFillAbsIdx_, + ctrl, + latchedIntEvents); if (softwareFillAbsIdx_ != 0) { softwareFillAbsIdx_ += lostPackets; } diff --git a/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp b/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp index 0761bce5..a3f8a0a8 100644 --- a/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp +++ b/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp @@ -49,13 +49,18 @@ class IsochTxDmaRing final { // own the policy that decides whether this is an unsafe cadence. std::atomic maxDeltaConsumed{0}; - // Full descriptor-ring laps the free-running hardware executed between - // two refills. Every lost lap is kNumPackets stale packets re-sent on - // the wire; the completion cursor is reconciled forward so producer - // pacing stays on true bus time instead of dilating. + // Full descriptor-ring laps of unaccounted hardware progress between + // two refills (either free-running stale re-transmission or a brief + // context stall). The completion cursor is reconciled forward so + // producer pacing stays on true bus time instead of dilating. std::atomic lapLossEvents{0}; std::atomic lapLossPacketsTotal{0}; + // Unaccounted progress exceeded the producer's committed lead: the + // context stalled or wedged beyond anything reconciliation can cover + // (2026-07-19 Saffire freeze). Fatal; the stream must stop honestly. + std::atomic contextStallFatals{0}; + // DMA ring gap monitoring std::atomic lastDmaGapPackets{Layout::kNumPackets}; std::atomic minDmaGapPackets{Layout::kNumPackets}; @@ -76,6 +81,7 @@ class IsochTxDmaRing final { UncommittedSlot, InvalidPacketSize, PayloadMapping, + ContextStalled, }; [[nodiscard]] static const char* RefillFailureReasonName( @@ -151,10 +157,15 @@ class IsochTxDmaRing final { // OHCI §9.4.2) recover true progress: the context transmits exactly one // packet per cycle, so cycles elapsed between the last-processed packets // of two refills equals packets truly consumed. Any surplus over the - // modulo delta is whole ring laps of stale re-transmission. Rounding to - // whole laps absorbs single-cycle jitter (missed cycle / cycle-master - // correction). Valid for refill gaps below the 8-second timestamp wrap; - // the transmit context faults out long before that horizon. + // modulo delta is whole ring laps of unaccounted execution: free-running + // stale re-transmission, or a stalled context whose sparse crawl stamps + // late completion timestamps (2026-07-19 Saffire freeze — the wire showed + // 13 packets while the timestamps implied 64k). The two are + // indistinguishable here; the caller classifies by whether the producer's + // committed lead can cover the jump. Rounding to whole laps absorbs + // single-cycle jitter (missed cycle / cycle-master correction). Valid for + // refill gaps below the 8-second timestamp wrap; the transmit context + // faults out long before that horizon. [[nodiscard]] static constexpr uint32_t ComputeLostLapPackets( uint16_t previousTimestamp, uint16_t currentTimestamp, diff --git a/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md b/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md index 594678d8..d4e1e3d6 100644 --- a/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md +++ b/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md @@ -245,6 +245,8 @@ Linux and FFADO, without copying their mechanisms. | `AVC-TX-EXPOSURE-001` | **Confirmed audio-path defect; root scheduling cause open** | The payload writer skips CoreAudio frames which arrive beyond `Timeline().ExposedFrameEnd()` (`framesWithoutPacket`); `TxAlign` later repositions the producer cursor to close the deficit. This can produce audible corruption while DMA/CMP and the TX descriptor lead remain healthy, then self-heal without a stream restart ([`AmdtpPayloadWriter.cpp:90-126`](ASFWDriver/Audio/Wire/AMDTP/AmdtpPayloadWriter.cpp#L90-L126), [`ASFWAudioDriverZts.cpp:360-389`](ASFWDriver/Audio/DriverKit/ASFWAudioDriverZts.cpp#L360-L389)). | Retain pending host frames until slots exist and maintain a data-bearing packet horizon beyond the maximum IO callback plus measured scheduling jitter; never discard a running stream's host frames because their packet is not yet exposed. | | `TX-LAPLOSS-001` | **Confirmed; fixed 2026-07-19, requires hardware confirmation** | IT completion accounting measured hardware progress modulo the 48-packet free-running ring; refill gaps > 6 ms silently discarded whole laps, dilating producer time and re-transmitting stale packets (the 2026-07-19 all-zero Duet zombie). | Validate the lap-loss reconciliation and `IT LAP LOSS` telemetry on hardware; see "2026-07-19 zombie stream" below. | | `TX-IRQ-001` | **Open** | The IT interrupt path went permanently silent ~10 minutes into the 2026-07-19 session; the refill watchdog carried the stream. Cause unknown (mask write, storm mitigation, dispatch loss). | Reproduce with the new watchdog-engagement log; correlate with `IsoXmitIntMask` writes. The 16-kick fatal now bounds the damage. | +| `TX-STALL-001` | **Open root cause; detection fixed 2026-07-19** | Saffire Pro 24 DSP (cycle master) run: both OHCI isoch contexts froze ~8 s at ~67 s while the wire, async, and host stayed healthy; no bus reset or `cycleInconsistent` fired. IR recovered alone; IT crawled 13 packets and died. Trigger unknown (cycle-start recognition, controller wedge, DMA stall). | Refill now faults `context-stalled` (untouched cursors) when unaccounted progress exceeds the committed lead, and records `ContextControl` + latched `IntEvent` at detection/watchdog time. Use those on the next occurrence. | +| `TX-FAULT-PROP-001` | **Confirmed** | After `IT FATAL STOP`/`[TxProducerFatal]`, nothing stops the ADK stream, notifies the backend, or releases CMP/IRM resources: CoreAudio runs IO against a dead stream indefinitely while the DICE backend keeps reporting the device healthy. | Propagate the transport/producer fault to a terminal, user-visible stream state (controlled stop/xrun) and release resources. Interim slice of the single-recovery-epoch design. | | `AVC-SYNC-001` | **Not proven** | Treating raw RX/TX SYT inequality as a fault would be wrong for the captured duplex stream. | Add the normalized, per-direction trace below before adjusting delays or cadence. | | `AVC-HEALTH-001` | **Instrumented; root cause open** | The original RX timing loss occurred without a bus reset in the observed driver ring; successful restart was then masked by `AVC-RECOVERY-001`. | Reproduce with the first-fault record below; it distinguishes a local RX validation failure from a real no-RX/CMP outage. | @@ -670,6 +672,39 @@ Host-side regression coverage: `IsochTxLapLossMath.*`, `IsochTxDmaRingTest.RefillDetectsWholeLapStallWithUnmovedPointer`, `RxDrivenTimingTests.ReaderReBeginReanchorsAfterHistoryOverwritten`. +### 2026-07-19 Saffire Pro 24 DSP run: dual-context freeze and honest death + +The first DICE validation of the lap-loss work (Saffire Pro 24 DSP, 48 kHz, +DICE backend) both validated and corrected it. The stream started cleanly +and reconciled five single-lap losses in its first 35 seconds. At ~67 s — +shortly after the device issued `ExtStatus`/clock notifications — **both of +our OHCI isoch contexts froze for ~8 seconds** while the wire and async +traffic stayed alive (FireBug `!saffire-wire.txt`: channel 1 never missed a +cycle; no bus reset; no `cycleInconsistent` interrupt; host latencies were +double-digit microseconds up to the freeze). The IR side later recovered on +its own; the IT side crawled 13 packets, then died via +`IT FATAL: uncommitted slot` at ~75 s. + +The wire capture corrected the lap-loss interpretation: channel 0 carried +exactly 533,821 packets — the freeze transmitted **nothing**, while the +completion timestamps implied 64,032 packets of progress. A stalled context +whose sparse crawl stamps late timestamps is indistinguishable, at the +timestamp level, from free-running stale re-transmission. The 2026-07-19 +follow-up therefore classifies by coverage: unaccounted progress within the +producer's committed lead is reconciled (the Duet case); progress beyond it +can only end at an uncommitted slot, so the refill now faults immediately as +`context-stalled` with untouched cursors, and both paths record +`ContextControl` plus the latched `IntEvent` bits (visible even when masked) +as first-fault evidence for the freeze trigger. + +The fatal also demonstrated the missing upward propagation +(`TX-FAULT-PROP-001`): after `IT FATAL STOP` + `[TxProducerFatal]`, CoreAudio +kept running IO against the dead stream indefinitely (the `[PayloadWriter]` +deficit passed 1.5 M frames), the DICE backend read the device's next +notification and confirmed it "healthy", no `[RxReplayReset]` ever fired +(total RX silence produces no next packet to detect a gap on), and the IRM +bandwidth/channels were never released. + ### Still open after these fixes - `TX-IRQ-001` — **why the IT interrupt path died ~10 minutes in.** The ring diff --git a/tests/audio/IsochTxDmaRingTests.cpp b/tests/audio/IsochTxDmaRingTests.cpp index 33b0e7a8..e80716ea 100644 --- a/tests/audio/IsochTxDmaRingTests.cpp +++ b/tests/audio/IsochTxDmaRingTests.cpp @@ -1169,6 +1169,9 @@ TEST_F(IsochTxDmaRingTest, RefillReconcilesLostLapForward) { controlBlock.numSlots = kSharedPayloadSlots; controlBlock.slotStrideBytes = kSharedPayloadStride; controlBlock.maxPacketBytes = kSharedPayloadStride; + // The producer runs at its full committed lead; the lap-loss + // classification reconciles only jumps this lead can cover. + controlBlock.committedEnd.store(912, std::memory_order_release); hardware_.SetTestRegister( static_cast(DMAContextHelpers::IsoXmitContextControl(0)), @@ -1247,6 +1250,7 @@ TEST_F(IsochTxDmaRingTest, RefillDetectsWholeLapStallWithUnmovedPointer) { controlBlock.numSlots = kSharedPayloadSlots; controlBlock.slotStrideBytes = kSharedPayloadStride; controlBlock.maxPacketBytes = kSharedPayloadStride; + controlBlock.committedEnd.store(912, std::memory_order_release); hardware_.SetTestRegister( static_cast(DMAContextHelpers::IsoXmitContextControl(0)), @@ -1289,3 +1293,62 @@ TEST_F(IsochTxDmaRingTest, RefillDetectsWholeLapStallWithUnmovedPointer) { EXPECT_EQ(ring_.RTCounters().lapLossPacketsTotal.load(), Layout::kNumPackets); } + +TEST_F(IsochTxDmaRingTest, RefillFaultsWhenStallExceedsCommittedLead) { + auto metadataRing = MakeMetadataRing(); + (void)ring_.Prime( + payloadDmaMap_, kSharedPayloadSlots, kSharedPayloadStride, + metadataRing.data(), Layout::kNumPackets); + ring_.ResetForStart(); + ring_.SeedCycleTracking(hardware_); + + IsochTxQueueControl controlBlock{}; + controlBlock.numSlots = kSharedPayloadSlots; + controlBlock.slotStrideBytes = kSharedPayloadStride; + controlBlock.maxPacketBytes = kSharedPayloadStride; + // A shallow committed lead: the producer has content for 60 packets. + controlBlock.committedEnd.store(60, std::memory_order_release); + + hardware_.SetTestRegister( + static_cast(DMAContextHelpers::IsoXmitContextControl(0)), + 0); + + for (uint32_t i = 0; i < 8; ++i) { + auto* desc = ring_.Slab().GetDescriptorPtr( + i * Layout::kBlocksPerPacket + Layout::kCompletionBlock); + desc->statusWord = + (0x8000u << 16) | ((3u << 13) | (3000u + i)); + } + hardware_.SetTestRegister( + static_cast(DMAContextHelpers::IsoXmitCommandPtr(0)), + ring_.Slab().GetDescriptorIOVA(8 * Layout::kBlocksPerPacket) | + Layout::kBlocksPerPacket); + auto first = ring_.Refill( + hardware_, 0, metadataRing.data(), &controlBlock, + kSharedPayloadSlots, sharedPayload_.data(), payloadDmaMap_); + ASSERT_TRUE(first.ok); + ASSERT_EQ(controlBlock.completionCursor.load(), 8u); + + // The command pointer never moves again, but packet 7's completion + // timestamp advances two whole ring laps: 96 packets of unaccounted + // progress against a 52-packet committed headroom. Reconciliation cannot + // cover the jump — the context stalled/wedged and must fault with the + // completion accounting untouched. + { + auto* desc = ring_.Slab().GetDescriptorPtr( + 7 * Layout::kBlocksPerPacket + Layout::kCompletionBlock); + desc->statusWord = + (0x8000u << 16) | + ((3u << 13) | (3007u + 2u * Layout::kNumPackets)); + } + auto second = ring_.Refill( + hardware_, 0, metadataRing.data(), &controlBlock, + kSharedPayloadSlots, sharedPayload_.data(), payloadDmaMap_); + + EXPECT_FALSE(second.ok); + EXPECT_EQ(second.failureReason, + IsochTxDmaRing::RefillFailureReason::ContextStalled); + EXPECT_EQ(controlBlock.completionCursor.load(), 8u); + EXPECT_EQ(ring_.RTCounters().contextStallFatals.load(), 1u); + EXPECT_EQ(ring_.RTCounters().lapLossEvents.load(), 0u); +} From 940f02dfd9f389e362fdc7d07d42f51a69263f79 Mon Sep 17 00:00:00 2001 From: Aleksandr Shabelnikov Date: Sun, 19 Jul 2026 12:44:26 +0200 Subject: [PATCH 4/6] Document backend boundary leakage as the DICE root cause The Saffire run showed the lap-loss detector phantom-killing a healthy stream (all mod-48 deltas < 48; FireBug 2.24M continuous packets), and DICE was stable before the 2026-07-18 refactors (merge 1bbb70e, no lap-loss logic). Root cause is cross-backend leakage: a shared timingLossCallback_ (AV/C overwrites DICE) and cross-backend RecoverStreaming. references/linux-sound-firewire-stack proves the boundary (per-family recovery, family-blind mechanism, one content callback with errors polled upward); the Focusrite DICE kext corroborates DICE-notification-driven recovery. Records the corrective boundary and withdraws TX-LAPLOSS-001. Co-Authored-By: Claude Fable 5 --- AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md | 93 +++++++++++++++++++++++++- 1 file changed, 92 insertions(+), 1 deletion(-) diff --git a/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md b/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md index d4e1e3d6..38b6bf4b 100644 --- a/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md +++ b/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md @@ -243,7 +243,8 @@ Linux and FFADO, without copying their mechanisms. | `AVC-RECOVERY-002` | **Confirmed critical defect** | FW-64 treats every *established* replay reset as an eventual destructive `RecoverStreaming()`. A reset can mean a malformed RX packet, one cycle gap, rejected cadence, or rejected clock anchor—not necessarily a device outage. The coordinator stops/restarts transport while CoreAudio remains running with its old TX producer state. | Disable AV/C automatic transport restart until recovery atomically quiesces/resets/re-primes the audio producer and transport under one recovery epoch. Report the fault and request an audio-side xrun/controlled restart instead. | | `AVC-PROPERTY-001` | **Fixed; requires hardware confirmation** | `AudioNubPublisher` sets stream mode on the nub, but `ASFWAudioDevice::PopulateNubProperties()` did not publish `ASFWStreamMode`; the driver parser consequently defaulted to non-blocking. The model default is also non-blocking ([`ASFWAudioDevice.hpp:52-60`](ASFWDriver/Audio/Model/ASFWAudioDevice.hpp#L52-L60)); parsing only changes it if the property exists ([`AudioDriverConfig.cpp:67-84`](ASFWDriver/Audio/DriverKit/Config/AudioDriverConfig.cpp#L67-L84)). The matching dictionary now publishes the selected mode. | On the next Duet/BeBoB start, confirm the AudioDriver reports `Stream mode from nub: blocking`; the property path is shared by all published audio nubs. | | `AVC-TX-EXPOSURE-001` | **Confirmed audio-path defect; root scheduling cause open** | The payload writer skips CoreAudio frames which arrive beyond `Timeline().ExposedFrameEnd()` (`framesWithoutPacket`); `TxAlign` later repositions the producer cursor to close the deficit. This can produce audible corruption while DMA/CMP and the TX descriptor lead remain healthy, then self-heal without a stream restart ([`AmdtpPayloadWriter.cpp:90-126`](ASFWDriver/Audio/Wire/AMDTP/AmdtpPayloadWriter.cpp#L90-L126), [`ASFWAudioDriverZts.cpp:360-389`](ASFWDriver/Audio/DriverKit/ASFWAudioDriverZts.cpp#L360-L389)). | Retain pending host frames until slots exist and maintain a data-bearing packet horizon beyond the maximum IO callback plus measured scheduling jitter; never discard a running stream's host frames because their packet is not yet exposed. | -| `TX-LAPLOSS-001` | **Confirmed; fixed 2026-07-19, requires hardware confirmation** | IT completion accounting measured hardware progress modulo the 48-packet free-running ring; refill gaps > 6 ms silently discarded whole laps, dilating producer time and re-transmitting stale packets (the 2026-07-19 all-zero Duet zombie). | Validate the lap-loss reconciliation and `IT LAP LOSS` telemetry on hardware; see "2026-07-19 zombie stream" below. | +| `TX-LAPLOSS-001` | **Withdrawn — the fix was the regression** | The timestamp-based lap-loss detector double-counted a stale completion baseline under coalesced interrupts and phantom-killed a healthy Saffire stream (all mod-48 deltas were < 48; FireBug showed 2.24 M continuous packets). It also treated a symptom of `TX-IRQ-001` and violated the transport boundary. To be reverted. | Revert the reconciliation; keep the watchdog-silence fatal + `ctrl`/`intEvent` snapshot. See "backend boundary leakage" below. | +| `AUDIO-BACKEND-BOUNDARY-001` | **Confirmed (Linux + Focusrite validated)** | AV/C resync machinery leaks into DICE: a single shared `IsochService::timingLossCallback_` (AV/C overwrites DICE) and cross-backend `RecoverStreaming`. Reference stacks keep recovery strictly per-family; the shared core is family-blind. | Sever the shared callback slot; make transport report-only state; re-home DICE recovery onto DICE notifications. | | `TX-IRQ-001` | **Open** | The IT interrupt path went permanently silent ~10 minutes into the 2026-07-19 session; the refill watchdog carried the stream. Cause unknown (mask write, storm mitigation, dispatch loss). | Reproduce with the new watchdog-engagement log; correlate with `IsoXmitIntMask` writes. The 16-kick fatal now bounds the damage. | | `TX-STALL-001` | **Open root cause; detection fixed 2026-07-19** | Saffire Pro 24 DSP (cycle master) run: both OHCI isoch contexts froze ~8 s at ~67 s while the wire, async, and host stayed healthy; no bus reset or `cycleInconsistent` fired. IR recovered alone; IT crawled 13 packets and died. Trigger unknown (cycle-start recognition, controller wedge, DMA stall). | Refill now faults `context-stalled` (untouched cursors) when unaccounted progress exceeds the committed lead, and records `ContextControl` + latched `IntEvent` at detection/watchdog time. Use those on the next occurrence. | | `TX-FAULT-PROP-001` | **Confirmed** | After `IT FATAL STOP`/`[TxProducerFatal]`, nothing stops the ADK stream, notifies the backend, or releases CMP/IRM resources: CoreAudio runs IO against a dead stream indefinitely while the DICE backend keeps reporting the device healthy. | Propagate the transport/producer fault to a terminal, user-visible stream state (controlled stop/xrun) and release resources. Interim slice of the single-recovery-epoch design. | @@ -720,6 +721,96 @@ bandwidth/channels were never released. transport clock no longer dilating it is defense in depth rather than the first-order fault. +## 2026-07-19 architectural root cause: backend boundary leakage (dice ≠ avc ≠ bebob) + +The Saffire Pro 24 DSP run with the lap-loss detector installed forced a +reassessment of the whole 2026-07-19 line of work. Two facts collapsed it: + +1. **The lap-loss detector was killing a healthy Saffire stream.** Every + `IT LAP LOSS` event on that run reported a mod-48 `delta` **below 48** + (`0, 3, 5, 8, 9, 11, 18, 19, 23, 26, 27, 31, 40`), so the hardware never + advanced a full ring between refills — mod-48 accounting was *correct the + entire time*. The timestamp-based detector was double-counting a stale + completion baseline under coalesced interrupts and inventing laps that + were never on the wire; the `delta=0 → "2832 packets"` fatal is that bug + run away (59 phantom laps). FireBug confirms the stream was continuous — + 2,241,634 packets with real PCM — until *our own* fatal fired. The + detector is the regression. +2. **DICE was stable before any of this.** PR #41 (merge `1bbb70e`, + 2026-07-14) had no lap-loss logic at all — pure mod-48 + `ComputeDeltaConsumed` — and DICE streamed cleanly. The zombie only + appeared after the 2026-07-18 receive-seam / FW-64 refactors. + +So the lap-loss reconciliation treats a *symptom* of `TX-IRQ-001` (the Duet's +dead interrupt path, where 68 ms watchdog gaps genuinely exceed the 6 ms +ring) and actively breaks the healthy-coalescing case. It is also a +**boundary violation**: content/timing reconciliation shoved into the +payload-opaque transport (`IsochTxDmaRing`). It should be reverted. + +### The real defect is cross-backend leakage, and the reference stacks prove the boundary + +`references/linux-sound-firewire-stack` enforces `dice ≠ avc ≠ bebob` with +three rules ASFW currently breaks: + +1. **Each family is its own driver; recovery is per-family policy.** `dice/`, + `bebob/`, `oxfw/`, `fireworks/`, `motu/`, `tascam/`, `digi00x/` each own a + `*_stream.c` with their own recovery entry point — + `snd_dice_stream_update_duplex()` (dice-stream.c:587), + `snd_oxfw_stream_update_duplex()` (oxfw-stream.c:472), + `snd_efw_stream_update_duplex()` (fireworks). DICE's is pure DICE + semantics (force-stop on bus reset because the firmware stalls for + hundreds of ms, then let the app restart) — meaningless for AV/C or BeBoB. + There is no shared `recover_streaming`. +2. **The shared core is mechanism and family-blind.** `amdtp-stream.c`, + `cmp.c`, `fcp.c`, `iso-resources.c` contain no backend branching — only + device-*quirk* flags (OXFW970 packet-skip, Dice high-rate). The engine + moves packets and does not know who owns the stream. +3. **The seam is one content callback; errors flow up as state.** The backend + injects `process_ctx_payloads` + an opaque `protocol` pointer + (amdtp-stream.h:205-207). On trouble the engine sets its own state and the + family **polls** `amdtp_streaming_error(s)` (amdtp-stream.h:256) and + decides. Reporting is upward; policy stays in the family. The mechanism + never calls a backend's recovery. + +The Focusrite DICE kext (IDA, `Saffire.i64`) corroborates rule 1 from the +Apple side: its `NotificationWriteCallback` (0x9620) decodes the DICE +notification register and calls `RequestStreamingRestart` — DICE recovery is +driven by **DICE notifications**, guarded against re-entrancy. Its +`adjustOutputPhase` (0xc9c2) is a bounded phase servo in the full 8-second +tick domain (`% 0xBB80000`) that tolerates a standing RX/TX offset and only +re-anchors past a threshold — behavioural proof that a constant SYT offset is +normal (the "SYT OOS" capture was healthy), never a fault. + +### Where ASFW leaks across the boundary + +- **A single shared `IsochService::timingLossCallback_`** that both + `DiceAudioBackend` and `AVCAudioBackend` write (last-writer-wins). AV/C + overwrites DICE's, so a DICE discontinuity is routed to AV/C's non-matching + GUID and dropped. Linux never shares a recovery callback. +- **`RecoverStreaming` as cross-backend machinery** driven by an RX-replay- + reset signal common to both backends, instead of each backend's own device + semantics. +- **The lap-loss detector** — content/timing policy inside the transport + mechanism, the inverse leak. + +### Corrective boundary (Linux- and Focusrite-validated) + +1. Transport (`Isoch/`, `IsochService`, `IsochTxDmaRing`) is family-agnostic: + move packets, publish own fault state, stop. No backend knowledge, no + `RecoverStreaming` dispatch, no replay/timing reconciliation. → **revert + the lap-loss detector**; keep only the transport-state pieces (watchdog- + silence fatal + `ctrl`/`intEvent` snapshot). +2. **Delete the shared `timingLossCallback_` slot.** Transport exposes a + state the backends poll (the existing `statusWord`/`fatalGeneration` is the + `amdtp_streaming_error` analog). No cross-backend callback. +3. **Each backend owns its own recovery.** DICE recovery keyed off DICE + notifications (both references agree); AV/C and BeBoB separate. No + backend's recovery reachable from another's signal. + +Sequence: (a) revert lap-loss, (b) sever the shared slot and make transport +report-only, (c) re-home DICE recovery onto DICE notifications. +`TX-IRQ-001` (why Duet interrupts die) remains an independent open root cause. + ## Minimal anomaly-only telemetry for the next hardware run Keep the MCP ring as the primary evidence path; no Console logging is needed From cc04c8ebdce4c4a87906a8bb9b64e6f93fabdf67 Mon Sep 17 00:00:00 2001 From: Aleksandr Shabelnikov Date: Sun, 19 Jul 2026 12:56:18 +0200 Subject: [PATCH 5/6] Add FFADO as third boundary reference (per-backend virtual dispatch) libffado-2.5.0 confirms dice != avc != bebob in ASFW's own idiom: every device is a FFADODevice subclass with per-family streaming/recovery virtuals (lock/unlock/prepare/resetForStreaming), a family-blind libstreaming manager, and one StreamProcessor-per-stream seam. Directs the corrective to per-backend virtual/override recovery rather than a shared callback slot. Co-Authored-By: Claude Fable 5 --- AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md | 25 ++++++++++++++++++++++--- 1 file changed, 22 insertions(+), 3 deletions(-) diff --git a/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md b/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md index 38b6bf4b..39093c47 100644 --- a/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md +++ b/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md @@ -781,6 +781,24 @@ tick domain (`% 0xBB80000`) that tolerates a standing RX/TX offset and only re-anchors past a threshold — behavioural proof that a constant SYT offset is normal (the "SYT OOS" capture was healthy), never a fault. +`references/libffado-2.5.0` confirms the same boundary in the idiom ASFW +actually uses — C++ virtual dispatch, not C file-per-family. Every device is +a `FFADODevice` subclass (`Dice::DiceAvDevice`, `BeBoB::AvDevice`, +`Motu::MotuDevice`, `GenericAVC::AvDevice`, `Rme::RmeDevice`), and the +streaming/recovery lifecycle is a set of **per-family virtuals** — +`lock()=0`, `unlock()=0`, `prepare()=0`, `resetForStreaming()`, +`enableStreaming()`/`disableStreaming()` (ffadodevice.h:318-413). The generic +`libstreaming` manager has no family branching (the lone family name in it is +a comment noting where a speed constant came from), and the seam is one +`StreamProcessor` per stream that the device hands up via +`getStreamProcessorByIndex()` (ffadodevice.h:413) — the manager drives +transport generically. Transport bus-reset (`IsoHandlerManager::handleBusReset`) +and device recovery (`FFADODevice::handleBusReset` → per-family virtuals) are +separate layers, neither reaching into the other. The lesson for ASFW is +concrete: **recovery belongs as a per-backend virtual/override dispatched +polymorphically**, which is how the backends are already structured — not a +shared `timingLossCallback_` slot one backend overwrites. + ### Where ASFW leaks across the boundary - **A single shared `IsochService::timingLossCallback_`** that both @@ -803,9 +821,10 @@ normal (the "SYT OOS" capture was healthy), never a fault. 2. **Delete the shared `timingLossCallback_` slot.** Transport exposes a state the backends poll (the existing `statusWord`/`fatalGeneration` is the `amdtp_streaming_error` analog). No cross-backend callback. -3. **Each backend owns its own recovery.** DICE recovery keyed off DICE - notifications (both references agree); AV/C and BeBoB separate. No - backend's recovery reachable from another's signal. +3. **Each backend owns its own recovery, as a per-backend override** (FFADO's + virtual model). DICE recovery keyed off DICE notifications (all three + references agree); AV/C and BeBoB separate. No backend's recovery reachable + from another's signal. Sequence: (a) revert lap-loss, (b) sever the shared slot and make transport report-only, (c) re-home DICE recovery onto DICE notifications. From e5e0c1fd94512f2060ca8b8e4f2c4ddbe96cc511 Mon Sep 17 00:00:00 2001 From: Aleksandr Shabelnikov Date: Sun, 19 Jul 2026 13:26:19 +0200 Subject: [PATCH 6/6] =?UTF-8?q?Revert=20the=20IT=20lap-loss=20detector=20?= =?UTF-8?q?=E2=80=94=20it=20kills=20healthy=20streams?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Hardware proved the timestamp-based lap-loss/context-stall detector phantom-kills healthy streams on both devices: Saffire and Duet each ran clean (completion cursor tracking the wire exactly, 0 silent packets) until the detector's stale-baseline double-count fabricated a multi- hundred-lap 'stall' on a single coalesced delta=0 read and faulted the context. It also corrupts audio in real time via the sub-fatal reconciliations that jump softwareFillAbsIdx_. Remove ComputeLostLapPackets, DetectLostLapPackets, the Refill reconcile/context-stalled path, the counters, the ContextStalled reason, and their tests. Kept: the backend-agnostic pieces — failure-class replay handling (hold on ahead, no realign) and the watchdog-silence fatal + ctrl/intEvent snapshot. Root cause is elsewhere (TX-IRQ-001 and backend boundary leakage); see AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md. Co-Authored-By: Claude Fable 5 --- ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp | 111 +-------- ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp | 60 ----- tests/audio/IsochTxDmaRingTests.cpp | 236 ------------------- 3 files changed, 3 insertions(+), 404 deletions(-) diff --git a/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp b/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp index 2e942312..ed7f846a 100644 --- a/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp +++ b/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp @@ -38,8 +38,6 @@ void IsochTxDmaRing::ResetForStart() noexcept { nextTransmitCycle_ = 0; cycleTrackingValid_ = false; lastHwTimestamp_ = 0; - lastLapTimestamp_ = 0; - lapTimestampValid_ = false; counters_.lastDmaGapPackets.store(Layout::kNumPackets, std::memory_order_relaxed); counters_.minDmaGapPackets.store(Layout::kNumPackets, std::memory_order_relaxed); @@ -122,41 +120,6 @@ void IsochTxDmaRing::ResyncCycleTracking(Driver::HardwareInterface& hw, nextTransmitCycle_ = (hwCycle + aheadCount) % 8000; } -uint32_t IsochTxDmaRing::DetectLostLapPackets( - const uint32_t hwPacketIndex, const uint32_t deltaConsumed) noexcept { - if (!cycleTrackingValid_) { - return 0; - } - // Read the completion timestamp of the most recently executed packet. - // This must run even when the modulo delta is zero: a stall of exactly - // whole ring laps leaves the command pointer where it was while the - // timestamp has moved by kNumPackets * laps cycles. - const uint32_t lastProcessedPkt = - (hwPacketIndex + Layout::kNumPackets - 1) % Layout::kNumPackets; - auto* completionDesc = slab_.GetDescriptorPtr( - lastProcessedPkt * Layout::kBlocksPerPacket + - Layout::kCompletionBlock); - if (dmaMemory_) { - dmaMemory_->FetchFromDevice( - reinterpret_cast(completionDesc), - sizeof(*completionDesc)); - } - if (completionDesc->statusWord == 0) { - return 0; - } - const uint16_t rawTimestamp = - static_cast(completionDesc->statusWord & 0xFFFF); - const bool hadPrevious = lapTimestampValid_; - const uint16_t previousTimestamp = lastLapTimestamp_; - lastLapTimestamp_ = rawTimestamp; - lapTimestampValid_ = true; - if (!hadPrevious) { - return 0; - } - return ComputeLostLapPackets(previousTimestamp, rawTimestamp, - deltaConsumed); -} - void IsochTxDmaRing::CommitRefill(const uint32_t toFill) noexcept { softwareFillAbsIdx_ += toFill; ringPacketsAhead_ += toFill; @@ -355,8 +318,6 @@ const char* IsochTxDmaRing::RefillFailureReasonName( return "uncommitted-slot"; case RefillFailureReason::InvalidPacketSize: return "invalid-packet-size"; - case RefillFailureReason::ContextStalled: - return "context-stalled"; case RefillFailureReason::PayloadMapping: return "payload-mapping"; } @@ -443,68 +404,6 @@ IsochTxDmaRing::RefillOutcome IsochTxDmaRing::Refill( UpdateGapCounters(gap); ResyncCycleTracking(hw, hwPacketIndex, deltaConsumed, out); - // The free-running ring only exposes progress modulo kNumPackets through - // the command pointer. The completion timestamps recover the unaccounted - // whole ring laps, but they cannot say which of two faults produced them: - // free-running stale re-transmission (2026-07-19 Duet zombie: 71% of wire - // packets were stale re-sends) or a stalled context whose sparse crawl - // stamps late timestamps (2026-07-19 Saffire freeze: 13 wire packets - // while the timestamps implied 64k). Classify by coverage: a jump the - // producer's committed lead can absorb is reconciled so pacing returns to - // true bus time; a larger jump can only end at an uncommitted slot, so - // fault immediately with untouched cursors instead of corrupting the - // accounting on the way to the same stop. - const uint32_t lostPackets = - DetectLostLapPackets(hwPacketIndex, deltaConsumed); - if (lostPackets != 0) { - const uint64_t completedRaw = - controlBlock->completionCursor.load(std::memory_order_relaxed); - const uint64_t consumedEnd = completedRaw + deltaConsumed; - const uint64_t committedNow = - controlBlock->committedEnd.load(std::memory_order_acquire); - const uint64_t committedHeadroom = - committedNow > consumedEnd ? committedNow - consumedEnd : 0; - const uint32_t latchedIntEvents = hw.Read(Register32::kIntEvent); - if (lostPackets > committedHeadroom) { - counters_.contextStallFatals.fetch_add(1, - std::memory_order_relaxed); - ASFW_LOG( - Isoch, - "IT FATAL: context stalled - unaccounted progress %u packets " - "exceeds committed lead %llu (delta=%u completion=%llu " - "committed=%llu ctrl=0x%08x intEvent=0x%08x)", - lostPackets, - committedHeadroom, - deltaConsumed, - completedRaw, - committedNow, - ctrl, - latchedIntEvents); - out.failureReason = RefillFailureReason::ContextStalled; - out.failurePacketAbs = consumedEnd; - return out; - } - counters_.lapLossEvents.fetch_add(1, std::memory_order_relaxed); - counters_.lapLossPacketsTotal.fetch_add(lostPackets, - std::memory_order_relaxed); - ASFW_LOG( - Isoch, - "IT LAP LOSS: %u packets of unaccounted hardware progress " - "(stale re-send or brief stall) delta=%u completion=%llu " - "committed=%llu fill=%llu ctrl=0x%08x intEvent=0x%08x", - lostPackets, - deltaConsumed, - completedRaw, - committedNow, - softwareFillAbsIdx_, - ctrl, - latchedIntEvents); - if (softwareFillAbsIdx_ != 0) { - softwareFillAbsIdx_ += lostPackets; - } - ringPacketsAhead_ = 0; - } - // Publish a neutral completion-delta high-water. Content consumers decide // whether their own frame/lead policy can tolerate the observed cadence. { @@ -528,12 +427,8 @@ IsochTxDmaRing::RefillOutcome IsochTxDmaRing::Refill( } } - // Fetch and publish completed stamps. Lost laps shift the absolute index - // base: the descriptors read below were last executed in the newest lap, - // so their stamps belong to the reconciled indices, not the stale window. - const uint64_t completedAbsIdx = - controlBlock->completionCursor.load(std::memory_order_relaxed) + - lostPackets; + // Fetch and publish completed stamps + const uint64_t completedAbsIdx = controlBlock->completionCursor.load(std::memory_order_relaxed); for (uint32_t i = 0; i < deltaConsumed; ++i) { const uint64_t currentAbsIdx = completedAbsIdx + i; const uint32_t completedPktSlot = static_cast(currentAbsIdx % Layout::kNumPackets); @@ -556,7 +451,7 @@ IsochTxDmaRing::RefillOutcome IsochTxDmaRing::Refill( controlBlock->PushCompletionStamp(currentAbsIdx, completionCycleTimer); } - if (deltaConsumed > 0 || lostPackets > 0) { + if (deltaConsumed > 0) { controlBlock->completionCursor.store(completedAbsIdx + deltaConsumed, std::memory_order_release); const uint64_t requested = diff --git a/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp b/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp index a3f8a0a8..5da49a17 100644 --- a/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp +++ b/ASFWDriver/Isoch/Transmit/IsochTxDmaRing.hpp @@ -49,18 +49,6 @@ class IsochTxDmaRing final { // own the policy that decides whether this is an unsafe cadence. std::atomic maxDeltaConsumed{0}; - // Full descriptor-ring laps of unaccounted hardware progress between - // two refills (either free-running stale re-transmission or a brief - // context stall). The completion cursor is reconciled forward so - // producer pacing stays on true bus time instead of dilating. - std::atomic lapLossEvents{0}; - std::atomic lapLossPacketsTotal{0}; - - // Unaccounted progress exceeded the producer's committed lead: the - // context stalled or wedged beyond anything reconciliation can cover - // (2026-07-19 Saffire freeze). Fatal; the stream must stop honestly. - std::atomic contextStallFatals{0}; - // DMA ring gap monitoring std::atomic lastDmaGapPackets{Layout::kNumPackets}; std::atomic minDmaGapPackets{Layout::kNumPackets}; @@ -81,7 +69,6 @@ class IsochTxDmaRing final { UncommittedSlot, InvalidPacketSize, PayloadMapping, - ContextStalled, }; [[nodiscard]] static const char* RefillFailureReasonName( @@ -150,46 +137,6 @@ class IsochTxDmaRing final { [[nodiscard]] const Counters& RTCounters() const noexcept { return counters_; } [[nodiscard]] uint32_t LastHwTimestamp() const noexcept { return lastHwTimestamp_; } - // The IT descriptor ring is circular and free-running: hardware keeps - // executing it whether or not software refilled, so per-refill progress - // measured from the command pointer is only known modulo kNumPackets. - // The OUTPUT_LAST completion timestamps (3-bit seconds + 13-bit cycle, - // OHCI §9.4.2) recover true progress: the context transmits exactly one - // packet per cycle, so cycles elapsed between the last-processed packets - // of two refills equals packets truly consumed. Any surplus over the - // modulo delta is whole ring laps of unaccounted execution: free-running - // stale re-transmission, or a stalled context whose sparse crawl stamps - // late completion timestamps (2026-07-19 Saffire freeze — the wire showed - // 13 packets while the timestamps implied 64k). The two are - // indistinguishable here; the caller classifies by whether the producer's - // committed lead can cover the jump. Rounding to whole laps absorbs - // single-cycle jitter (missed cycle / cycle-master correction). Valid for - // refill gaps below the 8-second timestamp wrap; the transmit context - // faults out long before that horizon. - [[nodiscard]] static constexpr uint32_t ComputeLostLapPackets( - uint16_t previousTimestamp, - uint16_t currentTimestamp, - uint32_t deltaConsumed) noexcept { - constexpr uint32_t kCyclesPerSecond = 8000u; - constexpr uint32_t kTimestampDomainCycles = 8u * kCyclesPerSecond; - const uint32_t previousOrdinal = - ((previousTimestamp >> 13) & 0x7u) * kCyclesPerSecond + - ((previousTimestamp & 0x1FFFu) % kCyclesPerSecond); - const uint32_t currentOrdinal = - ((currentTimestamp >> 13) & 0x7u) * kCyclesPerSecond + - ((currentTimestamp & 0x1FFFu) % kCyclesPerSecond); - const uint32_t elapsedCycles = - (currentOrdinal + kTimestampDomainCycles - previousOrdinal) % - kTimestampDomainCycles; - if (elapsedCycles <= deltaConsumed) { - return 0; - } - const uint32_t surplus = elapsedCycles - deltaConsumed; - const uint32_t lostLaps = - (surplus + Layout::kNumPackets / 2) / Layout::kNumPackets; - return lostLaps * Layout::kNumPackets; - } - // Expose slab for audio injection. [[nodiscard]] IsochTxDescriptorSlab& Slab() noexcept { return slab_; } [[nodiscard]] const IsochTxDescriptorSlab& Slab() const noexcept { return slab_; } @@ -202,8 +149,6 @@ class IsochTxDmaRing final { uint32_t deltaConsumed, RefillOutcome& out) noexcept; void CommitRefill(uint32_t toFill) noexcept; - [[nodiscard]] uint32_t DetectLostLapPackets(uint32_t hwPacketIndex, - uint32_t deltaConsumed) noexcept; [[nodiscard]] bool DecodeHardwarePacketIndex(Driver::HardwareInterface& hw, uint8_t contextIndex, uint32_t& outPacketIndex, @@ -223,11 +168,6 @@ class IsochTxDmaRing final { bool cycleTrackingValid_{false}; uint32_t lastHwTimestamp_{0}; - // Previous refill's last-processed completion timestamp; anchors the - // true-cycle lap-loss detection across refills. - uint16_t lastLapTimestamp_{0}; - bool lapTimestampValid_{false}; - Counters counters_{}; }; diff --git a/tests/audio/IsochTxDmaRingTests.cpp b/tests/audio/IsochTxDmaRingTests.cpp index e80716ea..251aeecb 100644 --- a/tests/audio/IsochTxDmaRingTests.cpp +++ b/tests/audio/IsochTxDmaRingTests.cpp @@ -1116,239 +1116,3 @@ TEST(IsochTxQueueControlTests, ProducerAndConsumerResetsHaveDisjointOwnership) { EXPECT_EQ(queue.statusWord.load(std::memory_order_acquire), IsochTxQueueStatus::kRunning); } - -// --- Lap-loss detection: the IT descriptor ring is free-running, so the -// command pointer exposes progress only modulo Layout::kNumPackets. The -// completion timestamps recover true progress; a surplus is whole ring laps -// of stale re-transmission that must reconcile every absolute cursor. - -TEST(IsochTxLapLossMath, ExactLapSurplusYieldsWholeLap) { - const uint16_t prev = static_cast((3u << 13) | 3007u); - const uint16_t cur = static_cast((3u << 13) | 3063u); - EXPECT_EQ(IsochTxDmaRing::ComputeLostLapPackets(prev, cur, 8), - Layout::kNumPackets); -} - -TEST(IsochTxLapLossMath, SecondsFieldWrapIsUnambiguous) { - const uint16_t prev = static_cast((7u << 13) | 7990u); - const uint16_t cur = static_cast((0u << 13) | 50u); - // 60 cycles elapsed across the 8-second wrap, 12 accounted by the - // command-pointer delta: one lost lap. - EXPECT_EQ(IsochTxDmaRing::ComputeLostLapPackets(prev, cur, 12), - Layout::kNumPackets); -} - -TEST(IsochTxLapLossMath, SmallSurplusIsTimestampJitterNotALap) { - const uint16_t prev = static_cast((3u << 13) | 3000u); - const uint16_t cur = static_cast((3u << 13) | 3011u); - EXPECT_EQ(IsochTxDmaRing::ComputeLostLapPackets(prev, cur, 8), 0u); -} - -TEST(IsochTxLapLossMath, NoProgressNoLoss) { - const uint16_t ts = static_cast((2u << 13) | 100u); - EXPECT_EQ(IsochTxDmaRing::ComputeLostLapPackets(ts, ts, 0), 0u); -} - -TEST(IsochTxLapLossMath, MultipleLapsAccumulate) { - const uint16_t prev = static_cast((1u << 13) | 1000u); - const uint16_t cur = static_cast( - (1u << 13) | (1000u + 8u + 2u * Layout::kNumPackets)); - EXPECT_EQ(IsochTxDmaRing::ComputeLostLapPackets(prev, cur, 8), - 2u * Layout::kNumPackets); -} - -TEST_F(IsochTxDmaRingTest, RefillReconcilesLostLapForward) { - auto metadataRing = MakeMetadataRing(); - (void)ring_.Prime( - payloadDmaMap_, kSharedPayloadSlots, kSharedPayloadStride, - metadataRing.data(), Layout::kNumPackets); - ring_.ResetForStart(); - ring_.SeedCycleTracking(hardware_); - - IsochTxQueueControl controlBlock{}; - controlBlock.numSlots = kSharedPayloadSlots; - controlBlock.slotStrideBytes = kSharedPayloadStride; - controlBlock.maxPacketBytes = kSharedPayloadStride; - // The producer runs at its full committed lead; the lap-loss - // classification reconciles only jumps this lead can cover. - controlBlock.committedEnd.store(912, std::memory_order_release); - - hardware_.SetTestRegister( - static_cast(DMAContextHelpers::IsoXmitContextControl(0)), - 0); - - // Refill 1: hardware consumed packets 0..7, completing at cycles - // 3000..3007. This anchors the lap-loss timestamp baseline. - for (uint32_t i = 0; i < 8; ++i) { - auto* desc = ring_.Slab().GetDescriptorPtr( - i * Layout::kBlocksPerPacket + Layout::kCompletionBlock); - desc->statusWord = - (0x8000u << 16) | ((3u << 13) | (3000u + i)); - } - hardware_.SetTestRegister( - static_cast(DMAContextHelpers::IsoXmitCommandPtr(0)), - ring_.Slab().GetDescriptorIOVA(8 * Layout::kBlocksPerPacket) | - Layout::kBlocksPerPacket); - auto first = ring_.Refill( - hardware_, 0, metadataRing.data(), &controlBlock, - kSharedPayloadSlots, sharedPayload_.data(), payloadDmaMap_); - ASSERT_TRUE(first.ok); - ASSERT_EQ(controlBlock.completionCursor.load(), 8u); - - // Refill 2: the command pointer moved 8 positions (mod-48 delta = 8), - // but the completion timestamps show 56 elapsed cycles: the hardware - // lapped the whole ring once, re-transmitting 48 stale packets. - for (uint32_t i = 8; i < 16; ++i) { - auto* desc = ring_.Slab().GetDescriptorPtr( - i * Layout::kBlocksPerPacket + Layout::kCompletionBlock); - desc->statusWord = - (0x8000u << 16) | ((3u << 13) | (3048u + i)); - } - hardware_.SetTestRegister( - static_cast(DMAContextHelpers::IsoXmitCommandPtr(0)), - ring_.Slab().GetDescriptorIOVA(16 * Layout::kBlocksPerPacket) | - Layout::kBlocksPerPacket); - auto second = ring_.Refill( - hardware_, 0, metadataRing.data(), &controlBlock, - kSharedPayloadSlots, sharedPayload_.data(), payloadDmaMap_); - ASSERT_TRUE(second.ok); - - // Completion reconciled: 8 consumed + 48 lost + 8 consumed = 64. - EXPECT_EQ(controlBlock.completionCursor.load(), 64u); - EXPECT_EQ(ring_.RTCounters().lapLossEvents.load(), 1u); - EXPECT_EQ(ring_.RTCounters().lapLossPacketsTotal.load(), - Layout::kNumPackets); - - // Stamps carry the reconciled absolute indices (56..63), so downstream - // packet-to-cycle anchoring stays on true bus time. - for (uint32_t i = 0; i < 8; ++i) { - uint64_t pktIdx = 0; - uint32_t ts = 0; - ASSERT_TRUE(controlBlock.ReadCompletionStamp(8 + i, pktIdx, ts)); - EXPECT_EQ(pktIdx, 56u + i); - } - - // The refill mapped the reconciled absolute window (slots 56..63), not - // the stale pre-lap window (slots 8..15). - for (uint32_t i = 0; i < 8; ++i) { - auto* desc2 = ring_.Slab().GetDescriptorPtr( - (8 + i) * Layout::kBlocksPerPacket + Layout::kFirstPayloadBlock); - EXPECT_EQ(desc2->dataAddress, - kSharedPayloadIOVA + (56u + i) * kSharedPayloadStride); - } -} - -TEST_F(IsochTxDmaRingTest, RefillDetectsWholeLapStallWithUnmovedPointer) { - auto metadataRing = MakeMetadataRing(); - (void)ring_.Prime( - payloadDmaMap_, kSharedPayloadSlots, kSharedPayloadStride, - metadataRing.data(), Layout::kNumPackets); - ring_.ResetForStart(); - ring_.SeedCycleTracking(hardware_); - - IsochTxQueueControl controlBlock{}; - controlBlock.numSlots = kSharedPayloadSlots; - controlBlock.slotStrideBytes = kSharedPayloadStride; - controlBlock.maxPacketBytes = kSharedPayloadStride; - controlBlock.committedEnd.store(912, std::memory_order_release); - - hardware_.SetTestRegister( - static_cast(DMAContextHelpers::IsoXmitContextControl(0)), - 0); - - for (uint32_t i = 0; i < 8; ++i) { - auto* desc = ring_.Slab().GetDescriptorPtr( - i * Layout::kBlocksPerPacket + Layout::kCompletionBlock); - desc->statusWord = - (0x8000u << 16) | ((3u << 13) | (3000u + i)); - } - hardware_.SetTestRegister( - static_cast(DMAContextHelpers::IsoXmitCommandPtr(0)), - ring_.Slab().GetDescriptorIOVA(8 * Layout::kBlocksPerPacket) | - Layout::kBlocksPerPacket); - auto first = ring_.Refill( - hardware_, 0, metadataRing.data(), &controlBlock, - kSharedPayloadSlots, sharedPayload_.data(), payloadDmaMap_); - ASSERT_TRUE(first.ok); - ASSERT_EQ(controlBlock.completionCursor.load(), 8u); - - // The command pointer has not moved (mod-48 delta = 0), but packet 7's - // completion timestamp advanced exactly one ring lap: the stall was an - // invisible whole-lap re-transmission. - { - auto* desc = ring_.Slab().GetDescriptorPtr( - 7 * Layout::kBlocksPerPacket + Layout::kCompletionBlock); - desc->statusWord = - (0x8000u << 16) | - ((3u << 13) | (3007u + Layout::kNumPackets)); - } - auto second = ring_.Refill( - hardware_, 0, metadataRing.data(), &controlBlock, - kSharedPayloadSlots, sharedPayload_.data(), payloadDmaMap_); - ASSERT_TRUE(second.ok); - - EXPECT_EQ(controlBlock.completionCursor.load(), - 8u + Layout::kNumPackets); - EXPECT_EQ(ring_.RTCounters().lapLossEvents.load(), 1u); - EXPECT_EQ(ring_.RTCounters().lapLossPacketsTotal.load(), - Layout::kNumPackets); -} - -TEST_F(IsochTxDmaRingTest, RefillFaultsWhenStallExceedsCommittedLead) { - auto metadataRing = MakeMetadataRing(); - (void)ring_.Prime( - payloadDmaMap_, kSharedPayloadSlots, kSharedPayloadStride, - metadataRing.data(), Layout::kNumPackets); - ring_.ResetForStart(); - ring_.SeedCycleTracking(hardware_); - - IsochTxQueueControl controlBlock{}; - controlBlock.numSlots = kSharedPayloadSlots; - controlBlock.slotStrideBytes = kSharedPayloadStride; - controlBlock.maxPacketBytes = kSharedPayloadStride; - // A shallow committed lead: the producer has content for 60 packets. - controlBlock.committedEnd.store(60, std::memory_order_release); - - hardware_.SetTestRegister( - static_cast(DMAContextHelpers::IsoXmitContextControl(0)), - 0); - - for (uint32_t i = 0; i < 8; ++i) { - auto* desc = ring_.Slab().GetDescriptorPtr( - i * Layout::kBlocksPerPacket + Layout::kCompletionBlock); - desc->statusWord = - (0x8000u << 16) | ((3u << 13) | (3000u + i)); - } - hardware_.SetTestRegister( - static_cast(DMAContextHelpers::IsoXmitCommandPtr(0)), - ring_.Slab().GetDescriptorIOVA(8 * Layout::kBlocksPerPacket) | - Layout::kBlocksPerPacket); - auto first = ring_.Refill( - hardware_, 0, metadataRing.data(), &controlBlock, - kSharedPayloadSlots, sharedPayload_.data(), payloadDmaMap_); - ASSERT_TRUE(first.ok); - ASSERT_EQ(controlBlock.completionCursor.load(), 8u); - - // The command pointer never moves again, but packet 7's completion - // timestamp advances two whole ring laps: 96 packets of unaccounted - // progress against a 52-packet committed headroom. Reconciliation cannot - // cover the jump — the context stalled/wedged and must fault with the - // completion accounting untouched. - { - auto* desc = ring_.Slab().GetDescriptorPtr( - 7 * Layout::kBlocksPerPacket + Layout::kCompletionBlock); - desc->statusWord = - (0x8000u << 16) | - ((3u << 13) | (3007u + 2u * Layout::kNumPackets)); - } - auto second = ring_.Refill( - hardware_, 0, metadataRing.data(), &controlBlock, - kSharedPayloadSlots, sharedPayload_.data(), payloadDmaMap_); - - EXPECT_FALSE(second.ok); - EXPECT_EQ(second.failureReason, - IsochTxDmaRing::RefillFailureReason::ContextStalled); - EXPECT_EQ(controlBlock.completionCursor.load(), 8u); - EXPECT_EQ(ring_.RTCounters().contextStallFatals.load(), 1u); - EXPECT_EQ(ring_.RTCounters().lapLossEvents.load(), 0u); -}