diff --git a/ASFWDriver/Audio/DriverKit/ASFWAudioDriverIO.cpp b/ASFWDriver/Audio/DriverKit/ASFWAudioDriverIO.cpp index f114b662..be4c59f2 100644 --- a/ASFWDriver/Audio/DriverKit/ASFWAudioDriverIO.cpp +++ b/ASFWDriver/Audio/DriverKit/ASFWAudioDriverIO.cpp @@ -210,6 +210,12 @@ kern_return_t InstallIOOperationHandler(IOUserAudioDevice& audioDevice, hostBuffer, completionCursor); + const auto packetizerSnapshot = + driverIvars->runtime.txStreamEngine + .PacketizerTelemetrySnapshot(); + const auto& txCounters = + driverIvars->runtime.txStreamEngine.Counters(); + // Fan out the same host buffer to the secondary stream; its // payload writer reads channels [16, 32) via sourceChannelOffset. if (driverIvars->runtime.txSecondaryActive) { @@ -246,6 +252,28 @@ kern_return_t InstallIOOperationHandler(IOUserAudioDevice& audioDevice, cw.underExposureCalls.load(std::memory_order_relaxed); rec.underExposureFrames = cw.underExposureFrames.load(std::memory_order_relaxed); + rec.packetizerNextAudioFrame = + packetizerSnapshot.nextAudioFrame; + rec.packetizerLastDataFirstAudioFrame = + packetizerSnapshot.lastDataFirstAudioFrame; + rec.packetizerLastDataEndAudioFrame = + packetizerSnapshot.lastDataEndAudioFrame; + rec.packetizerLastDataPacketIndex = + packetizerSnapshot.lastDataPacketIndex; + rec.packetizerCursorEpoch = + packetizerSnapshot.cursorEpoch; + rec.packetizerFrameCursorAligned = + packetizerSnapshot.frameCursorAligned; + rec.packetizerHasLastDataPacket = + packetizerSnapshot.hasLastDataPacket; + rec.packetsPrepared = + txCounters.packetsPrepared.load(std::memory_order_relaxed); + rec.dataPacketsPrepared = + txCounters.dataPacketsPrepared.load(std::memory_order_relaxed); + rec.noDataPacketsPrepared = + txCounters.noDataPacketsPrepared.load(std::memory_order_relaxed); + rec.slotAcquireFailures = + txCounters.slotAcquireFailures.load(std::memory_order_relaxed); const uint32_t bits = cw.maxAbsSampleBits.load(std::memory_order_relaxed); std::memcpy(&rec.maxAbsSample, &bits, sizeof(bits)); diff --git a/ASFWDriver/Audio/DriverKit/Runtime/PayloadWriterTelemetry.hpp b/ASFWDriver/Audio/DriverKit/Runtime/PayloadWriterTelemetry.hpp index 3d5b8a62..1bd2aa1e 100644 --- a/ASFWDriver/Audio/DriverKit/Runtime/PayloadWriterTelemetry.hpp +++ b/ASFWDriver/Audio/DriverKit/Runtime/PayloadWriterTelemetry.hpp @@ -25,6 +25,20 @@ struct PayloadWriterTelemetryRecord final { uint64_t underExposureFrames{0}; float maxAbsSample{0.0f}; + // Snapshot of the TX packetizer state. This is published through atomic + // mirrors by the TX preparation side; it is diagnostic only. + uint64_t packetizerNextAudioFrame{0}; + uint64_t packetizerLastDataFirstAudioFrame{0}; + uint64_t packetizerLastDataEndAudioFrame{0}; + uint64_t packetizerLastDataPacketIndex{0}; + uint64_t packetizerCursorEpoch{0}; + uint64_t packetsPrepared{0}; + uint64_t dataPacketsPrepared{0}; + uint64_t noDataPacketsPrepared{0}; + uint64_t slotAcquireFailures{0}; + bool packetizerFrameCursorAligned{false}; + bool packetizerHasLastDataPacket{false}; + // Additional cursors and addresses for diagnosing buffer mapping / pointer alignment uint64_t playbackRingReadFrame{0}; uint64_t playbackRingWriteFrame{0}; diff --git a/ASFWDriver/Audio/Engine/Direct/Rx/DirectAudioReceiveConsumer.cpp b/ASFWDriver/Audio/Engine/Direct/Rx/DirectAudioReceiveConsumer.cpp index 7e5137d5..7cb4d8cf 100644 --- a/ASFWDriver/Audio/Engine/Direct/Rx/DirectAudioReceiveConsumer.cpp +++ b/ASFWDriver/Audio/Engine/Direct/Rx/DirectAudioReceiveConsumer.cpp @@ -11,6 +11,23 @@ namespace ASFW::AudioEngine::Direct::Rx { +const char* DirectAudioReceiveConsumer::ReplayResetReasonName( + ReplayResetReason reason) noexcept { + switch (reason) { + case ReplayResetReason::kPacketProcessorStatus: + return "packet-status"; + case ReplayResetReason::kInvalidReceiveTimestamp: + return "invalid-rx-timestamp"; + case ReplayResetReason::kReceiveCycleGap: + return "receive-cycle-gap"; + case ReplayResetReason::kSytCadenceRejected: + return "syt-cadence-rejected"; + case ReplayResetReason::kClockAnchorRejected: + return "clock-anchor-rejected"; + } + return "unknown"; +} + DirectAudioReceiveConsumer::DirectAudioReceiveConsumer( ::ASFW::Audio::Runtime::IDirectAudioBindingSource* bindingSource, Configuration configuration) noexcept @@ -162,7 +179,17 @@ void DirectAudioReceiveConsumer::ConsumePacket( result.status == DirectRxWriteStatus::kInvalidBinding) { absoluteFrameCursor_ += result.framesDecoded; } else { - ResetReplayEpochForDiscontinuity(); + ResetReplayEpochForDiscontinuity( + ReplayResetReason::kPacketProcessorStatus, + { + .descriptorIndex = packet.descriptorIndex, + .payloadBytes = static_cast(packet.payload.size()), + .drainCycleTimer = batch.drainCycleTimer, + .receiveCycleTimestamp = result.receiveCycleTimestamp, + .syt = result.syt, + .packetStatus = static_cast(result.status), + .sampleFrame = absoluteFrameCursor_, + }); return; } @@ -186,7 +213,16 @@ void DirectAudioReceiveConsumer::ConsumePacket( result.receiveCycleTimestamp, batch.drainCycleTimer, timestamp); if (!validTimestamp) { ++timestampInvalidCount_; - ResetReplayEpochForDiscontinuity(); + ResetReplayEpochForDiscontinuity( + ReplayResetReason::kInvalidReceiveTimestamp, + { + .descriptorIndex = packet.descriptorIndex, + .payloadBytes = static_cast(packet.payload.size()), + .drainCycleTimer = batch.drainCycleTimer, + .receiveCycleTimestamp = result.receiveCycleTimestamp, + .syt = result.syt, + .sampleFrame = absoluteFrameCursor_, + }); return; } @@ -198,7 +234,18 @@ void DirectAudioReceiveConsumer::ConsumePacket( ::ASFW::Timing::kFWTimeWrapSeconds * ::ASFW::Timing::kCyclesPerSecond; if (replayCycleInitialized_ && cycleOrdinal != (lastReplayCycleOrdinal_ + 1) % kCycleDomain) { - ResetReplayEpochForDiscontinuity(); + ResetReplayEpochForDiscontinuity( + ReplayResetReason::kReceiveCycleGap, + { + .descriptorIndex = packet.descriptorIndex, + .payloadBytes = static_cast(packet.payload.size()), + .drainCycleTimer = batch.drainCycleTimer, + .receiveCycleTimestamp = result.receiveCycleTimestamp, + .syt = result.syt, + .expectedCycleOrdinal = (lastReplayCycleOrdinal_ + 1) % kCycleDomain, + .observedCycleOrdinal = cycleOrdinal, + .sampleFrame = absoluteFrameCursor_, + }); } lastReplayCycleOrdinal_ = cycleOrdinal; replayCycleInitialized_ = true; @@ -215,7 +262,17 @@ void DirectAudioReceiveConsumer::ConsumePacket( const bool cadenceAccepted = inputView_.control->rxSytCadence.Observe( result.syt, timestamp.cycleTimer); if (!cadenceAccepted && inputView_.control->rxSequenceReplay.IsEstablished()) { - ResetReplayEpochForDiscontinuity(); + ResetReplayEpochForDiscontinuity( + ReplayResetReason::kSytCadenceRejected, + { + .descriptorIndex = packet.descriptorIndex, + .payloadBytes = static_cast(packet.payload.size()), + .drainCycleTimer = batch.drainCycleTimer, + .receiveCycleTimestamp = result.receiveCycleTimestamp, + .syt = result.syt, + .observedCycleOrdinal = cycleOrdinal, + .sampleFrame = absoluteFrameCursor_, + }); } replayEntry.sytOffset = ::ASFW::Audio::Runtime::ComputeReplaySytOffset( result.syt, timestamp.cycleTimer, @@ -266,7 +323,17 @@ void DirectAudioReceiveConsumer::ConsumePacket( const auto publish = clockPublisher_.Publish(packetFirstFrame, packetHostTicks, nanosPerSampleQ8); if (!publish.accepted) { - ResetReplayEpochForDiscontinuity(); + ResetReplayEpochForDiscontinuity( + ReplayResetReason::kClockAnchorRejected, + { + .descriptorIndex = packet.descriptorIndex, + .payloadBytes = static_cast(packet.payload.size()), + .drainCycleTimer = batch.drainCycleTimer, + .receiveCycleTimestamp = result.receiveCycleTimestamp, + .syt = result.syt, + .observedCycleOrdinal = cycleOrdinal, + .sampleFrame = packetFirstFrame, + }); } else { ++ztsPublishCount_; if (publish.notifyConsumer && ztsAnchorReadyCallback_) { @@ -294,7 +361,9 @@ void DirectAudioReceiveConsumer::ConsumePacket( } } -void DirectAudioReceiveConsumer::ResetReplayEpochForDiscontinuity() noexcept { +void DirectAudioReceiveConsumer::ResetReplayEpochForDiscontinuity( + ReplayResetReason reason, + const ReplayResetContext& context) noexcept { auto* control = inputView_.control; if (!control || !replayResetForStart_) { replayCycleInitialized_ = false; @@ -303,11 +372,23 @@ void DirectAudioReceiveConsumer::ResetReplayEpochForDiscontinuity() noexcept { const bool wasEstablished = control->rxSequenceReplay.IsEstablished(); control->rxSytCadence.Reset(); control->rxSequenceReplay.Reset(); - control->rxReplayEpochResets.fetch_add(1, std::memory_order_relaxed); + const uint64_t resetEpoch = + control->rxReplayEpochResets.fetch_add(1, std::memory_order_relaxed) + 1; replayReadyNotified_ = false; cadenceEstablishedLogged_ = false; replayCycleInitialized_ = false; dbcInitialized_ = false; + if (wasEstablished) { + ASFW_LOG_ERROR( + DirectAudio, + "[RxReplayReset] epoch=%llu reason=%{public}s desc=%u bytes=%u " + "drain=0x%08x rawTs=0x%04x syt=0x%04x expectedCycle=%u observedCycle=%u " + "status=%u frame=%llu validTs=%llu invalidTs=%llu", + resetEpoch, ReplayResetReasonName(reason), context.descriptorIndex, + context.payloadBytes, context.drainCycleTimer, context.receiveCycleTimestamp, + context.syt, context.expectedCycleOrdinal, context.observedCycleOrdinal, + context.packetStatus, context.sampleFrame, timestampValidCount_, timestampInvalidCount_); + } if (wasEstablished && timingLossCallback_) { timingLossCallback_(); } @@ -366,27 +447,76 @@ void DirectAudioReceiveConsumer::DrainPayloadTelemetry() { } payloadWriterTelemetryAggregator_.BeginDrain(); + ::ASFW::Audio::Runtime::PayloadWriterTelemetryRecord firstDeficitRecord{}; ::ASFW::Audio::Runtime::PayloadWriterTelemetryRecord lastRecord{}; + bool haveFirstDeficitRecord = false; bool haveLastRecord = false; const uint64_t dropped = control->payloadWriterTelemetry.Drain( - [this, &lastRecord, &haveLastRecord]( + [this, &firstDeficitRecord, &haveFirstDeficitRecord, + &lastRecord, &haveLastRecord]( const ::ASFW::Audio::Runtime::PayloadWriterTelemetryRecord& record) { payloadWriterTelemetryAggregator_.Observe(record); + if (!haveFirstDeficitRecord && record.exposureDeficitFrames != 0) { + firstDeficitRecord = record; + haveFirstDeficitRecord = true; + } lastRecord = record; haveLastRecord = true; }); const auto& summary = payloadWriterTelemetryAggregator_.Summary(); if (haveLastRecord && summary.HasAnomaly()) { ASFW_LOG(DirectAudio, - "[PayloadWriter] anomaly lastSample=%llu completion=%llu deficitMax=%llu " + "[PayloadWriter] anomaly firstSample=%llu firstRange=[%llu,%llu) " + "firstExposedEnd=%llu firstDeficit=%llu firstCompletion=%llu " + "firstPacketizer={next=%llu aligned=%u epoch=%llu lastPacket=%llu lastRange=[%llu,%llu) valid=%u} " + "lastSample=%llu completion=%llu deficitMax=%llu " "visitedDelta=%llu writtenDelta=%llu withoutPktDelta=%llu outsidePktDelta=%llu " - "racedDelta=%llu transmittedDelta=%llu underExpCallsDelta=%llu underExpFramesDelta=%llu", + "racedDelta=%llu transmittedDelta=%llu underExpCallsDelta=%llu underExpFramesDelta=%llu " + "lastPacketizer={next=%llu aligned=%u epoch=%llu lastPacket=%llu lastRange=[%llu,%llu) valid=%u} " + "prepared={all=%llu data=%llu noData=%llu acquireFail=%llu} playbackRange=[%llu,%llu)", + haveFirstDeficitRecord ? firstDeficitRecord.sampleTime : 0, + haveFirstDeficitRecord ? firstDeficitRecord.sampleTime : 0, + haveFirstDeficitRecord ? firstDeficitRecord.writeEndFrame : 0, + haveFirstDeficitRecord ? firstDeficitRecord.exposedFrameEnd : 0, + haveFirstDeficitRecord ? firstDeficitRecord.exposureDeficitFrames : 0, + haveFirstDeficitRecord ? firstDeficitRecord.completionCursor : 0, + haveFirstDeficitRecord + ? firstDeficitRecord.packetizerNextAudioFrame + : 0, + haveFirstDeficitRecord && + firstDeficitRecord.packetizerFrameCursorAligned + ? 1u + : 0u, + haveFirstDeficitRecord ? firstDeficitRecord.packetizerCursorEpoch : 0, + haveFirstDeficitRecord + ? firstDeficitRecord.packetizerLastDataPacketIndex + : 0, + haveFirstDeficitRecord + ? firstDeficitRecord.packetizerLastDataFirstAudioFrame + : 0, + haveFirstDeficitRecord + ? firstDeficitRecord.packetizerLastDataEndAudioFrame + : 0, + haveFirstDeficitRecord && + firstDeficitRecord.packetizerHasLastDataPacket + ? 1u + : 0u, lastRecord.sampleTime, lastRecord.completionCursor, summary.maxExposureDeficitFrames, summary.visitedDelta, summary.writtenDelta, summary.withoutPacketDelta, summary.outsidePacketDelta, summary.racedReuseDelta, summary.wroteIntoTransmittedDelta, summary.underExposureCallsDelta, - summary.underExposureFramesDelta); + summary.underExposureFramesDelta, + lastRecord.packetizerNextAudioFrame, + lastRecord.packetizerFrameCursorAligned ? 1u : 0u, + lastRecord.packetizerCursorEpoch, + lastRecord.packetizerLastDataPacketIndex, + lastRecord.packetizerLastDataFirstAudioFrame, + lastRecord.packetizerLastDataEndAudioFrame, + lastRecord.packetizerHasLastDataPacket ? 1u : 0u, + lastRecord.packetsPrepared, lastRecord.dataPacketsPrepared, + lastRecord.noDataPacketsPrepared, lastRecord.slotAcquireFailures, + lastRecord.playbackRingReadFrame, lastRecord.playbackRingWriteFrame); } if (dropped != 0) { ASFW_LOG(DirectAudio, "[PayloadWriter] drain overflow: dropped=%llu (capacity=%u)", diff --git a/ASFWDriver/Audio/Engine/Direct/Rx/DirectAudioReceiveConsumer.hpp b/ASFWDriver/Audio/Engine/Direct/Rx/DirectAudioReceiveConsumer.hpp index 631615ca..4cbf6380 100644 --- a/ASFWDriver/Audio/Engine/Direct/Rx/DirectAudioReceiveConsumer.hpp +++ b/ASFWDriver/Audio/Engine/Direct/Rx/DirectAudioReceiveConsumer.hpp @@ -56,7 +56,29 @@ class DirectAudioReceiveConsumer final : public ::ASFW::Isoch::IIsochReceiveCons void LogTransmitTimingTrace() override; private: - void ResetReplayEpochForDiscontinuity() noexcept; + enum class ReplayResetReason : uint8_t { + kPacketProcessorStatus, + kInvalidReceiveTimestamp, + kReceiveCycleGap, + kSytCadenceRejected, + kClockAnchorRejected, + }; + + struct ReplayResetContext final { + uint32_t descriptorIndex{0}; + uint32_t payloadBytes{0}; + uint32_t drainCycleTimer{0}; + uint16_t receiveCycleTimestamp{0}; + uint16_t syt{0xffff}; + uint32_t expectedCycleOrdinal{0}; + uint32_t observedCycleOrdinal{0}; + uint32_t packetStatus{0}; + uint64_t sampleFrame{0}; + }; + + [[nodiscard]] static const char* ReplayResetReasonName(ReplayResetReason reason) noexcept; + void ResetReplayEpochForDiscontinuity(ReplayResetReason reason, + const ReplayResetContext& context) noexcept; ::ASFW::Audio::Runtime::IDirectAudioBindingSource* bindingSource_{nullptr}; uint64_t lastBindingGeneration_{0}; diff --git a/ASFWDriver/Audio/Engine/Direct/Tx/DiceTxStreamEngine.cpp b/ASFWDriver/Audio/Engine/Direct/Tx/DiceTxStreamEngine.cpp index 56524acd..575510a7 100644 --- a/ASFWDriver/Audio/Engine/Direct/Tx/DiceTxStreamEngine.cpp +++ b/ASFWDriver/Audio/Engine/Direct/Tx/DiceTxStreamEngine.cpp @@ -126,6 +126,11 @@ const AMDTP::AmdtpStreamConfig& DiceTxStreamEngine::StreamConfig() const noexcep return packetizer_.StreamConfig(); } +AMDTP::AmdtpTxPacketizerTelemetrySnapshot +DiceTxStreamEngine::PacketizerTelemetrySnapshot() const noexcept { + return packetizer_.TelemetrySnapshot(); +} + const DiceTxEngineCounters& DiceTxStreamEngine::Counters() const noexcept { return counters_; } diff --git a/ASFWDriver/Audio/Engine/Direct/Tx/DiceTxStreamEngine.hpp b/ASFWDriver/Audio/Engine/Direct/Tx/DiceTxStreamEngine.hpp index e5d7ba3d..2b626177 100644 --- a/ASFWDriver/Audio/Engine/Direct/Tx/DiceTxStreamEngine.hpp +++ b/ASFWDriver/Audio/Engine/Direct/Tx/DiceTxStreamEngine.hpp @@ -64,6 +64,9 @@ class DiceTxStreamEngine final { [[nodiscard]] const AMDTP::AmdtpStreamConfig& StreamConfig() const noexcept; + [[nodiscard]] AMDTP::AmdtpTxPacketizerTelemetrySnapshot + PacketizerTelemetrySnapshot() const noexcept; + [[nodiscard]] const DiceTxEngineCounters& Counters() const noexcept; [[nodiscard]] const AMDTP::AmdtpPayloadWriterCounters& diff --git a/ASFWDriver/Audio/Model/ASFWAudioDevice.hpp b/ASFWDriver/Audio/Model/ASFWAudioDevice.hpp index 92d0ae9f..b537a582 100644 --- a/ASFWDriver/Audio/Model/ASFWAudioDevice.hpp +++ b/ASFWDriver/Audio/Model/ASFWAudioDevice.hpp @@ -76,10 +76,12 @@ struct ASFWAudioDevice { auto inputPlugNameStr = OSSharedPtr(OSString::withCString(inputPlugName.c_str()), OSNoRetain); auto outputPlugNameStr = OSSharedPtr(OSString::withCString(outputPlugName.c_str()), OSNoRetain); auto currentRateNum = OSSharedPtr(OSNumber::withNumber(currentSampleRate, 32), OSNoRetain); + auto streamModeNum = OSSharedPtr( + OSNumber::withNumber(static_cast(streamMode), 32), OSNoRetain); if (!deviceNameStr || !channelCountNum || !guidNum || !vendorIdNum || !modelIdNum || !inputChannelCountNum || !outputChannelCountNum || !sampleRatesArray || - !inputPlugNameStr || !outputPlugNameStr || !currentRateNum) { + !inputPlugNameStr || !outputPlugNameStr || !currentRateNum || !streamModeNum) { return false; } @@ -101,6 +103,7 @@ struct ASFWAudioDevice { properties->setObject(PropertyKeys::kInputPlugName, inputPlugNameStr.get()); properties->setObject(PropertyKeys::kOutputPlugName, outputPlugNameStr.get()); properties->setObject(PropertyKeys::kCurrentSampleRate, currentRateNum.get()); + properties->setObject(PropertyKeys::kStreamMode, streamModeNum.get()); // Sample rates advertised to CoreAudio. The HAL builds a stream format // per entry (ASFWAudioDriverGraph), so this is what the user can select. diff --git a/ASFWDriver/Audio/Wire/AMDTP/AmdtpTxPacketizer.cpp b/ASFWDriver/Audio/Wire/AMDTP/AmdtpTxPacketizer.cpp index 1ebe88dc..4a0f1ce3 100644 --- a/ASFWDriver/Audio/Wire/AMDTP/AmdtpTxPacketizer.cpp +++ b/ASFWDriver/Audio/Wire/AMDTP/AmdtpTxPacketizer.cpp @@ -112,9 +112,15 @@ void AmdtpTxPacketizer::Reset(uint8_t initialDbc, dbcCounter_.Reset(initialDbc); nextAudioFrame_ = initialAudioFrame; frameCursorAligned_ = false; + ++cursorEpoch_; + lastDataFirstAudioFrame_ = 0; + lastDataEndAudioFrame_ = 0; + lastDataPacketIndex_ = 0; + hasLastDataPacket_ = false; if (cadence_ != nullptr) { cadence_->Reset(); } + PublishTelemetrySnapshot(); } bool AmdtpTxPacketizer::AlignFrameCursorOnce(uint64_t frameIndex) noexcept { @@ -123,11 +129,15 @@ bool AmdtpTxPacketizer::AlignFrameCursorOnce(uint64_t frameIndex) noexcept { } nextAudioFrame_ = frameIndex; frameCursorAligned_ = true; + ++cursorEpoch_; + PublishTelemetrySnapshot(); return true; } void AmdtpTxPacketizer::ReArmFrameCursorAlignment() noexcept { frameCursorAligned_ = false; + ++cursorEpoch_; + PublishTelemetrySnapshot(); } bool AmdtpTxPacketizer::PrepareNextPacket(TxPacketSlotView slot, @@ -191,6 +201,11 @@ bool AmdtpTxPacketizer::PrepareNextPacket(TxPacketSlotView slot, dbcCounter_.AdvanceDataBlocks(frames); nextAudioFrame_ += frames; + lastDataFirstAudioFrame_ = outPacket.firstAudioFrame; + lastDataEndAudioFrame_ = nextAudioFrame_; + lastDataPacketIndex_ = outPacket.packetIndex; + hasLastDataPacket_ = true; + PublishTelemetrySnapshot(); } else { outPacket.syt = IEC61883::SytFormatter::kNoInfo; @@ -221,6 +236,43 @@ bool AmdtpTxPacketizer::NextPacketWouldCarryData() const noexcept { return cadence_ != nullptr && cadence_->CurrentCycleIsData(); } +AmdtpTxPacketizerTelemetrySnapshot +AmdtpTxPacketizer::TelemetrySnapshot() const noexcept { + AmdtpTxPacketizerTelemetrySnapshot snapshot{}; + snapshot.nextAudioFrame = + telemetryNextAudioFrame_.load(std::memory_order_acquire); + snapshot.lastDataFirstAudioFrame = + telemetryLastDataFirstAudioFrame_.load(std::memory_order_relaxed); + snapshot.lastDataEndAudioFrame = + telemetryLastDataEndAudioFrame_.load(std::memory_order_relaxed); + snapshot.lastDataPacketIndex = + telemetryLastDataPacketIndex_.load(std::memory_order_relaxed); + snapshot.cursorEpoch = telemetryCursorEpoch_.load(std::memory_order_relaxed); + snapshot.frameCursorAligned = + telemetryFrameCursorAligned_.load(std::memory_order_relaxed); + snapshot.hasLastDataPacket = + telemetryHasLastDataPacket_.load(std::memory_order_relaxed); + return snapshot; +} + +void AmdtpTxPacketizer::PublishTelemetrySnapshot() noexcept { + // Publish data fields before the acquire load of nextAudioFrame in + // TelemetrySnapshot(). The snapshot is deliberately best-effort: it is + // diagnostic only and never participates in packet preparation. + telemetryLastDataFirstAudioFrame_.store(lastDataFirstAudioFrame_, + std::memory_order_relaxed); + telemetryLastDataEndAudioFrame_.store(lastDataEndAudioFrame_, + std::memory_order_relaxed); + telemetryLastDataPacketIndex_.store(lastDataPacketIndex_, + std::memory_order_relaxed); + telemetryCursorEpoch_.store(cursorEpoch_, std::memory_order_relaxed); + telemetryFrameCursorAligned_.store(frameCursorAligned_, + std::memory_order_relaxed); + telemetryHasLastDataPacket_.store(hasLastDataPacket_, + std::memory_order_relaxed); + telemetryNextAudioFrame_.store(nextAudioFrame_, std::memory_order_release); +} + void AmdtpTxPacketizer::WriteDataPacketDefaults(uint8_t* packetBytes, uint32_t packetCapacityBytes, uint32_t payloadBytes) noexcept { diff --git a/ASFWDriver/Audio/Wire/AMDTP/AmdtpTxPacketizer.hpp b/ASFWDriver/Audio/Wire/AMDTP/AmdtpTxPacketizer.hpp index 0936beca..aac50ae2 100644 --- a/ASFWDriver/Audio/Wire/AMDTP/AmdtpTxPacketizer.hpp +++ b/ASFWDriver/Audio/Wire/AMDTP/AmdtpTxPacketizer.hpp @@ -6,11 +6,25 @@ #include "../IEC61883/CipHeader.hpp" #include "../IEC61883/DbcCounter.hpp" +#include #include #include namespace ASFW::Protocols::Audio::AMDTP { +// Lock-free, best-effort view for the CoreAudio callback / diagnostic drain. +// Packet preparation owns the mutable cursor; diagnostics must not read that +// state directly across the queue boundary. +struct AmdtpTxPacketizerTelemetrySnapshot final { + uint64_t nextAudioFrame{0}; + uint64_t lastDataFirstAudioFrame{0}; + uint64_t lastDataEndAudioFrame{0}; + uint64_t lastDataPacketIndex{0}; + uint64_t cursorEpoch{0}; + bool frameCursorAligned{false}; + bool hasLastDataPacket{false}; +}; + class AmdtpTxPacketizer final { public: AmdtpTxPacketizer() noexcept = default; @@ -47,7 +61,12 @@ class AmdtpTxPacketizer final { [[nodiscard]] const AmdtpTxPolicy& TxPolicy() const noexcept; [[nodiscard]] bool NextPacketWouldCarryData() const noexcept; + [[nodiscard]] AmdtpTxPacketizerTelemetrySnapshot + TelemetrySnapshot() const noexcept; + private: + void PublishTelemetrySnapshot() noexcept; + void WriteDataPacketDefaults(uint8_t* packetBytes, uint32_t packetCapacityBytes, uint32_t payloadBytes) noexcept; @@ -72,6 +91,19 @@ class AmdtpTxPacketizer final { uint64_t nextAudioFrame_{0}; bool frameCursorAligned_{false}; + uint64_t cursorEpoch_{0}; + uint64_t lastDataFirstAudioFrame_{0}; + uint64_t lastDataEndAudioFrame_{0}; + uint64_t lastDataPacketIndex_{0}; + bool hasLastDataPacket_{false}; + + std::atomic telemetryNextAudioFrame_{0}; + std::atomic telemetryLastDataFirstAudioFrame_{0}; + std::atomic telemetryLastDataEndAudioFrame_{0}; + std::atomic telemetryLastDataPacketIndex_{0}; + std::atomic telemetryCursorEpoch_{0}; + std::atomic telemetryFrameCursorAligned_{false}; + std::atomic telemetryHasLastDataPacket_{false}; }; } // namespace ASFW::Protocols::Audio::AMDTP diff --git a/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md b/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md new file mode 100644 index 00000000..6dfbc93f --- /dev/null +++ b/AVC_RECOVERY_AND_SYNC_ALGO_AND_BUGS.md @@ -0,0 +1,449 @@ +# AV/C recovery and duplex SYT: algorithm, evidence, and bugs + +Status: design/incident note, 2026-07-18. This is deliberately a behavioural +cross-reference, not source reuse. Linux is GPL and FFADO is LGPL; neither is +copied into ASFW. + +## Executive conclusion + +The Duet's RX and TX SYT fields must **not** be compared as equal 16-bit +numbers. They are timestamps for two independently packetised directions, +each with its own empty-packet placement, transfer delay, packet-to-frame +mapping, and device buffering. A fixed *or patterned* phase difference can be +normal. A fault is a discontinuity, an implausible per-direction cadence, or +a changing phase after each direction has been mapped into the same unwrapped +FireWire time domain and its own transfer delay has been accounted for. + +The demonstrated ASFW failure is separate and concrete: its AV/C timing-loss +recovery restarts the transport without asking the audio-side producer to reset +and prefill its shared TX queue. The old live `committedEnd` is then passed to +IT prime as the initial prefill count. It is far beyond the 408-slot ring and +prime rejects the restart. That explains why the recovery path dies; it does +not yet identify the original RX timing loss after several minutes. + +The target is **continuous playback for days**, not a restart which happens to +sound acceptable. Recovery is a last-resort response to a proven xrun, bus +reset, unplug, or clock-source change. It must never be used to paper over a +local SYT, descriptor, or queue-accounting defect. + +## Evidence used + +| Evidence | What it establishes | Limits | +| --- | --- | --- | +| Duet driver-ring incident (the `AUDIO DUPLEX START` log supplied with this task) | The first stream start succeeds; later timing-loss recovery reaches `IT: Prime failed - committed prefill=13626402 must cover 48 descriptors within 408 slots`, then returns `0xe00002c9`. | It does not say why RX cadence initially stopped. | +| Apple FireBug 2.3 trace supplied on 2026-07-18 (not committed) | The Duet emits on channels 0 and 1 every isochronous cycle, with 8-byte empty/no-info and 72-byte audio packets in each direction. The capture reports 0 silent cycles on both active channels. | A FireBug packet trace alone does not label host-to-device versus device-to-host; map that through the CMP connection record. | +| AppleFWAudio static inspection via the attached IDA MCP instance | Apple stops the direction, prepares/rebuilds stream state, reconnects it, then starts it; it is not a transport-only arm. Its AM824 writer also maintains a 400-cycle (48 kHz) content horizon inside an 800-cycle default ring. | Decompiler field names and inferred structs are not a contract. Do not copy Apple code. | +| `references/linux-sound-firewire-stack` | Current Linux AMDTP/BeBoB/OXFW behaviour: separate direction state, SYT/DBC validation, no-data handling, restart/replay tolerances. | Linux implementation and naming are not an ASFW architecture template. | +| `references/libffado-2.5.0/src` | FFADO keeps full per-direction timestamps, turns an RX SYT into full ticks, and uses a TX transfer delay plus a prebuffered timeline. | FFADO uses a different userspace/raw1394 mechanism. | + +## What the FireBug capture says + +At the beginning of the capture, channel 1 has a 72-byte data packet with +`SYT=0xa31a`; channel 0 has an 8-byte packet with `SYT=0xffff`. In the next +cycle the roles change: channel 1 is empty and channel 0 carries data with +`SYT=0xa71a`. This continues with each direction independently interleaving +72-byte audio packets and 8-byte packets: + +```text +cycle 7632: channel 1 data SYT a31a; channel 0 empty SYT ffff +cycle 7633: channel 1 empty SYT ffff; channel 0 data SYT a71a +cycle 7634: channel 1 data SYT b71a; channel 0 data SYT bb1a +``` + +The concrete packets are at capture lines 4-31. Its end counters (lines +503-509) show one packet per cycle, 0 silent cycles, and the same approximately +6:38 active duration for both channels. + +Two important details: + +1. `0xffff` is **no presentation timestamp**. In this trace it accompanies + an 8-byte CIP-only packet. Do not use it as a clock observation. Also do + not require `FDF == 0xff` to identify an empty packet: this capture has the + active FDF sample-rate value (`0x02`) with `SYT=0xffff` and no payload. +2. The FireBug `seconds:cycle:offset` at the left is packet observation time. + CIP SYT is a separate, 16-cycle-modulo presentation time. Raw subtraction + across channels loses wrap information and confuses packet scheduling with + the time at which a device presents samples. + +Therefore the capture is evidence *against* an assumption that TX SYT must +equal RX SYT. It is **not**, by itself, proof that either direction is out of +sync. + +## Cross-reference: the reference stacks agree + +### Linux AMDTP/AV-C family + +Linux treats AMDTP direction state as independent: + +- A blocking stream includes empty/NODATA packets; a non-blocking stream has a + variable number of events per packet + ([`amdtp-stream.c:213-240`](references/linux-sound-firewire-stack/amdtp-stream.c#L213-L240)). + At 48 kHz, blocking packets are aligned to the 8-frame SYT interval, not to + “one audio packet every cycle” + ([`amdtp-stream.c:236-240`](references/linux-sound-firewire-stack/amdtp-stream.c#L236-L240)). +- It gives a blocking direction an *additional direction-local transfer + delay* to accommodate no-data packets + ([`amdtp-stream.c:271-296`](references/linux-sound-firewire-stack/amdtp-stream.c#L271-L296)). + This alone makes raw RX/TX SYT equality an invalid invariant. +- On receive it checks DBC continuity and separately extracts SYT + ([`amdtp-stream.c:772-810`](references/linux-sound-firewire-stack/amdtp-stream.c#L772-L810)); + it rejects discontinuous cycle sequences rather than treating a different + opposite-direction SYT as an error + ([`amdtp-stream.c:935-1001`](references/linux-sound-firewire-stack/amdtp-stream.c#L935-L1001)). +- On transmit it computes each direction's SYT from that packet's output cycle + plus a per-stream sequence offset and transfer delay + ([`amdtp-stream.c:1004-1057`](references/linux-sound-firewire-stack/amdtp-stream.c#L1004-L1057)). + It resets its packet/DBC/sequence state when creating the stream, before it + is armed ([`amdtp-stream.c:1666-1773`](references/linux-sound-firewire-stack/amdtp-stream.c#L1666-L1773)). + +The device-family drivers reinforce that this is device policy, not a universal +SYT-equality rule: + +- BeBoB starts both prepared streams, allows initial NODATA packets, and waits + for valid SYT-bearing traffic before declaring the domain ready + ([`bebob_stream.c:620-665`](references/linux-sound-firewire-stack/bebob/bebob_stream.c#L620-L665)). +- OXFW explicitly has models which ignore playback SYT; for those models the + data-block sequence is the media-clock signal + ([`oxfw-stream.c:360-390`](references/linux-sound-firewire-stack/oxfw/oxfw-stream.c#L360-L390)). + Its quirk selection can mark a stream SYT-unaware + ([`oxfw-stream.c:151-180`](references/linux-sound-firewire-stack/oxfw/oxfw-stream.c#L151-L180)). + +The Duet is AV/C/CMP, not evidence that it uses an OXFW controller. The OXFW +lesson is narrower: an AV/C backend must make device-specific timestamp policy +explicit; it cannot quietly promote raw cross-direction SYT equality to a +generic invariant. + +### FFADO AMDTP + +FFADO likewise keeps a full direction-local timeline: + +- Its receive processor accepts only a valid CIP/SYT packet and converts SYT + plus the packet cycle timer into full ticks + ([`AmdtpReceiveStreamProcessor.cpp:97-123`](references/libffado-2.5.0/src/libstreaming/amdtp/AmdtpReceiveStreamProcessor.cpp#L97-L123)). +- Its transmit processor starts from the presentation timestamp of the next + audio block, subtracts its own transmit transfer delay, and schedules the + packet in a send window + ([`AmdtpTransmitStreamProcessor.cpp:100-128`](references/libffado-2.5.0/src/libstreaming/amdtp/AmdtpTransmitStreamProcessor.cpp#L100-L128), + [`:184-238`](references/libffado-2.5.0/src/libstreaming/amdtp/AmdtpTransmitStreamProcessor.cpp#L184-L238)). +- Its diagnostics validate the delta between *successive timestamps of one + processor* against nominal rate; they do not compare RX and TX raw SYTs + ([`StreamProcessor.cpp:463-490`](references/libffado-2.5.0/src/libstreaming/generic/StreamProcessor.cpp#L463-L490)). +- It initializes a transmit tail timestamp from the transfer time and + prebuffer, then separately aligns received streams + ([`StreamProcessorManager.cpp:840-879`](references/libffado-2.5.0/src/libstreaming/StreamProcessorManager.cpp#L840-L879)). + +For a bus reset, FFADO locks out the manager's wait loop before the per-stream +handler runs ([`StreamProcessor.cpp:153-168`](references/libffado-2.5.0/src/libstreaming/generic/StreamProcessor.cpp#L153-L168)). +Its default handler declares an xrun/error, rather than pretending an existing +running producer queue can simply be re-armed +([`StreamProcessor.cpp:141-149`](references/libffado-2.5.0/src/libstreaming/generic/StreamProcessor.cpp#L141-L149)). + +## Correct ASFW duplex timing model + +ASFW already has the right *building blocks*, but they must remain distinct: + +- RX consumes a valid CIP/SYT packet, observes cadence, stores its + source-cycle/SYT/DBC sequence, and resets the replay epoch on a discontinuity + ([`DirectAudioReceiveConsumer.cpp:206-236`](ASFWDriver/Audio/Engine/Direct/Rx/DirectAudioReceiveConsumer.cpp#L206-L236), + [`:297-310`](ASFWDriver/Audio/Engine/Direct/Rx/DirectAudioReceiveConsumer.cpp#L297-L310)). +- `ComputeReplaySytOffset()` turns the RX 16-bit SYT into a delay-free offset + relative to the received packet; `ComputeReplaySyt()` applies an output + packet cycle and a TX transfer delay + ([`RxSequenceReplay.hpp:26-92`](ASFWDriver/Audio/Wire/AMDTP/RxSequenceReplay.hpp#L26-L92)). +- The timing helpers correctly describe the 16-cycle SYT field and provide a + full-cycle expansion which preserves seconds and handles a cycle-second + boundary ([`TimingUtils.hpp:55-93`](ASFWDriver/Audio/Wire/AMDTP/TimingUtils.hpp#L55-L93), + [`:178-200`](ASFWDriver/Audio/Wire/AMDTP/TimingUtils.hpp#L178-L200)). + +The required algorithm is: + +1. For **each direction**, reject a no-info SYT and retain `(packet cycle + timer, SYT, DBC, data blocks, discontinuity)`. Do not feed 8-byte/no-info + packets into cadence estimation. +2. Expand a valid SYT using its own packet's full cycle timer into presentation + ticks. The 16-bit field alone is never a timeline. +3. Validate each direction locally: packet-cycle continuity, DBC progression, + valid-SYT cadence, data-block cadence, and rate error. At 48 kHz one sample + is 512 FireWire ticks and a blocking SYT interval is eight frames/4096 + ticks; packet presence can still be interleaved with empty packets. +4. For TX, take a presentation epoch from the selected clock source, apply the + **TX** transfer delay, then encode an SYT for the actual output packet + cycle. RX transfer delay and TX transfer delay are separate profile + parameters. +5. Only for a duplex diagnostic, compare the two expanded presentation + timelines after direction-local delays. Track a robust phase distribution + and drift over many valid packets. Accept a stable device-specific + phase/pattern; flag a step, a growing rate error, or a local cadence/DBC + break. + +This makes an explicit policy decision possible: + +| Device policy | Clock source / validation | +| --- | --- | +| SYT-aware AV/C device (the current Duet hypothesis) | RX valid-SYT cadence establishes the device timeline; TX is generated from that timeline with its TX delay. | +| SYT-unaware playback device (an OXFW-style quirk) | Do not derive correctness from TX SYT. Preserve the correct data-block cadence/DBC sequence and use the device's permitted no-info policy. | +| No valid RX timing source | Do not silently reuse stale replay state indefinitely. Declare timing loss, stop safely, and enter a full producer+transport recovery epoch. | + +## Confirmed recovery bug: stale TX producer cursor + +### Reproduction chain + +1. Normal `StartIO` explicitly runs the producer-owned + `ResetProducerForStart()` before prefill and then validates that prefill + exposed exactly `numSlots` + ([`ASFWAudioDevice.cpp:221-245`](ASFWDriver/Audio/DriverKit/ASFWAudioDevice.cpp#L221-L245), + [`:341-360`](ASFWDriver/Audio/DriverKit/ASFWAudioDevice.cpp#L341-L360)). +2. `committedEnd` is producer-to-consumer, while + `ResetConsumerForArm()` intentionally does not alter that producer cursor + ([`IsochTxQueue.hpp:132-155`](ASFWDriver/Isoch/Core/IsochTxQueue.hpp#L132-L155)). +3. IT `Start()` reads `committedEnd` and passes it as `preFillCount` to DMA + prime ([`IsochTransmitContext.cpp:286-296`](ASFWDriver/Isoch/Transmit/IsochTransmitContext.cpp#L286-L296)). +4. Prime accepts only `48 <= preFillCount <= numSlots`; the live Duet incident + supplied `13,626,402` for a 408-slot queue + ([`IsochTxDmaRing.cpp:133-179`](ASFWDriver/Isoch/Transmit/IsochTxDmaRing.cpp#L133-L179)). +5. AV/C recovery calls `duplexCoordinator_.RecoverStreaming()` after RX replay + has not recovered ([`AVCAudioBackend.cpp:231-288`](ASFWDriver/Audio/Protocols/Backends/AVCAudioBackend.cpp#L231-L288)). + It does not pass through the normal audio producer reset+prefill sequence. + +**Root cause:** recovery has consumer/transport authority but tries to restart +an audio-owned producer contract. This violates the seam ownership rule even +though the cursor happens to be in shared memory. + +### Required recovery transaction + +Do not “fix” this by having `IsochTransmitContext` zero `committedEnd`: that +would race the audio producer and would move audio semantics into transport. +Instead add a generation/acknowledgement recovery protocol across the existing +neutral control block/ports seam: + +```text +timing-loss verdict + -> block new TX production at recovery epoch E + -> quiesce RX/TX DMA and disconnect CMP in the profile-defined order + -> audio producer resets packetizer, DBC/SYT/replay state and committedEnd + -> audio producer writes and commits exactly numSlots safe prefill packets + -> producer publishes PrefillReady(E, committedEnd == numSlots) + -> transport validates E + committed slots, resets only consumer state, primes, arms + -> reconnect/enable CMP, wait for valid RX cadence, release producer +``` + +All async callbacks must carry/check epoch `E`; a late refill, completion, or +timing-loss callback from the old session must be ignored. The failure path +must leave the audio engine stopped/xrun, never a half-running CMP connection. +This mirrors the *behavioural ordering* seen in AppleFWAudio (stop direction → +prepare stream state → reconnect → start) and the ownership/reset discipline in +Linux and FFADO, without copying their mechanisms. + +## Other known/suspected bugs + +| ID | Status | Finding | Required action | +| --- | --- | --- | --- | +| `AVC-RECOVERY-001` | **Confirmed** | Stale `committedEnd` makes IT prime reject timing-loss recovery. | Implement the producer-owned recovery epoch above, then test a forced RX-cadence loss. | +| `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. | +| `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. | + +## Implemented first-fault MCP instrumentation + +The driver log ring is the source of truth for this fault. It retained all +13,480 records from the observed run with zero drops, but it previously did not +identify *which* RX validation path reset an established replay epoch. That +gap is now closed by `[RxReplayReset]` in +[`DirectAudioReceiveConsumer.cpp:175-395`](ASFWDriver/Audio/Engine/Direct/Rx/DirectAudioReceiveConsumer.cpp#L175-L395). + +The record is emitted exactly once per established replay epoch, immediately +before the timing-loss callback. It is anomaly-only; a normal stream produces +no such records. `reason` is one of: + +| Reason | Meaning | Discriminating fields | +| --- | --- | --- | +| `packet-status` | CIP/payload processing could not produce a usable packet. | `status`, `bytes`, `desc`, `rawTs`, `syt` | +| `invalid-rx-timestamp` | The descriptor's compact receive timestamp could not be correlated with the drain cycle timer. | `drain`, `rawTs`, `syt`, `validTs`, `invalidTs` | +| `receive-cycle-gap` | The strict one-received-packet-per-cycle invariant was broken. | `expectedCycle`, `observedCycle`, `desc` | +| `syt-cadence-rejected` | A valid-SYT observation produced a non-positive or out-of-range cadence delta. | `syt`, `observedCycle`, `rawTs` | +| `clock-anchor-rejected` | The host clock anchor was invalid when the RX side tried to publish it. | `frame`, `drain`, `rawTs`, `syt` | + +From the repository root, after reproducing, retrieve it without Console: + +```bash +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py \ + --endpoint http://127.0.0.1:8765/mcp \ + call asfw_log_query \ + '{"afterSequence":0,"categories":["DirectAudio"],"contains":"[RxReplayReset]","maxLevel":"debug","maxRecords":20}' +``` + +Interpret the first matching record before changing any SYT delay or recovery +constant. In particular, `receive-cycle-gap` means ASFW did not observe a +packet in a cycle where the FireBug capture says the Duet normally sends one; +that points at IR DMA/descriptor/drain accounting, not raw cross-direction SYT +phase. `syt-cadence-rejected` instead points at the device-timestamp/replay +model. The other three paths identify their own layer directly. + +## Confirmed TX audio-timeline underexposure + +The Duet run at 20:30 on 2026-07-18 produced severe audible corruption, then +continued normally without a bus reset, CMP reconnect, or fatal stream +recovery. Its retained driver records establish that this was not an isoch +descriptor shortage: + +```text +[PayloadWriter] deficitMax=380 visitedDelta=6144 writtenDelta=2381 + withoutPktDelta=3760 outsidePktDelta=3 + underExpCallsDelta=12 +[TxPrep] margin=355 ... maxLatUs=9472 late1500=4 +``` + +The following measurements are representative across the contiguous anomaly +records: + +| Measurement | Observed value | Consequence | +| --- | --- | --- | +| CoreAudio host frames offered per drain | 5,632–6,144 | The host continued to supply audio. | +| Frames written into AMDTP packets | 2,220–2,460 | Only about 40% reached packet images. | +| `framesWithoutPacket` | 3,378–3,823 | About 60% of offered frames were ahead of the packet timeline and were dropped. | +| `framesOutsidePacket` | 1–4 | This is not principally a stale/retired-slot race. | +| Maximum exposure deficit | 364–404 frames | The host was 7.6–8.4 ms ahead of exposed data packets at 48 kHz. | +| Maximum TX-preparation latency | 9.472 ms | A preparation scheduling slip consumed the usable data horizon. | +| TX descriptor margin | 355 packets | DMA still had descriptors to transmit; those descriptors did not guarantee valid host audio content. | + +The relevant buffers must not be conflated: + +- The host output ring is 1,536 frames (32 ms at 48 kHz). +- A normal maximum CoreAudio callback is 512 frames (10.7 ms). +- The reported data exposure lead is 576 frames (12 ms). +- The hardware descriptor queue can remain full of safe NODATA packets even + while the data-bearing audio timeline is too short. + +### AppleFWAudio comparison: a half-ring content horizon + +The attached IDA database's `AM824NuDCLWrite` decompilation is strong +behavioural evidence for the size and placement of a durable TX horizon. This +is a static comparison only: field names are decompiler inferences, and ASFW +must not copy Apple implementation code. + +Apple configures a default circular NuDCL ring of 100 buffer groups with eight +packets per group, i.e. 800 isochronous packet positions (local-only IDA +export `/Users/mrmidi/.idapro/AM824NuDCLWrite_methods.txt:1878-1906`). At +stream start it derives the total packet count as their product (same export, +`6143-6147`). + +Its normal-sync insert target is the live input/extract position plus measured +cycle displacement plus a fixed **400 packet-cycle** lead for the 48 kHz +family; 44.1-kHz-family rates use 450 (same export, `3758-3809`). The +Mac-sync initialization path uses 400 or 476 packet cycles (same export, +`3818-3849`). +`PerformClientIOOutput()` writes only until its sample-insert packet cursor +reaches this target (same export, `3248-3253`). + +For 48 kHz, 400 bus cycles is 50 ms and corresponds to approximately 2,400 +audio frames (six frames/cycle on average). The important property is the +relationship, not a magic number: Apple's content target is roughly **half of +an 800-cycle / 100-ms circular ring**, leaving the other half for in-flight +transport and wrap/reuse slack. + +| Geometry | Current ASFW Duet run | Apple 48 kHz writer pattern | +| --- | ---: | ---: | +| Data-bearing horizon | 576 frames / 12 ms | ~2,400 frames / 50 ms (400 cycles) | +| Hardware packet ring | 408 cycles / 51 ms | 800 cycles / 100 ms | +| Layout | Data horizon is much shorter than the transport queue. | Content horizon is approximately half of the circular packet ring. | + +This rules out treating 1,536 frames (32 ms) as a final target merely because +it is the current host output-ring size. A future ASFW implementation may +write packet frames for future absolute sample times before those samples +arrive; the audio callback later fills those already-exposed packet images. +The packet timeline must therefore be sized independently from the host sample +ring, while preserving the audio-side ownership boundary. + +`AmdtpPayloadWriter::WriteFloat32Interleaved()` only writes a host frame when +`SnapshotSlotForAudioFrame()` finds an already-exposed packet. If not, it +increments `framesWithoutPacket` and permanently skips that frame +([`AmdtpPayloadWriter.cpp:90-126`](ASFWDriver/Audio/Wire/AMDTP/AmdtpPayloadWriter.cpp#L90-L126)). +When TX preparation later resumes, the RX-derived `TxAlign` path can reposition +the frame cursor to the current timeline ([`ASFWAudioDriverZts.cpp:360-389`](ASFWDriver/Audio/DriverKit/ASFWAudioDriverZts.cpp#L360-L389)). +That is the observed “self-heal”: future samples become writable again; the +discarded samples are never recovered, so a click/gap is unavoidable. + +### Follow-up observation: corrupt audio can later become clean without a restart + +In the same deployed Duet stream, a later interval at 20:36 showed complete +content starvation for consecutive drains: `writtenDelta=0` while +`withoutPktDelta=5,632–6,144`, with `outsidePktDelta=0`. The user did not +stop the stream, rebuild, redeploy, reconnect CMP, or touch the device. It +continued to emit badly corrupted audio for a period, then became audibly +clean by itself. + +The subsequent 20:37–20:38 records still showed continuous TX SYT/ZTS +progress and descriptor margins of 277–354; current preparation latency was +30–265 us. The retained `maxLatUs=9472` and `late1500=8` values were +historical high-water counters from the preceding incident. There was no +logged bus reset, CMP reconnect, IT restart, or fatal recovery in that slice. + +This is **not** evidence that the old stream has been repaired. It proves +that DMA/clock liveness and audio-content correctness are independent in the +current implementation: once a future host range and a future exposed packet +range overlap again, the existing re-alignment path can make newly emitted +audio coherent. Frames dropped during the bad interval remain lost. The +next fault must record the packetizer cursor/alignment state as well as the +first deficit range, so that the transition back to overlap is attributable +rather than inferred. + +### Required fix + +Increasing the DMA descriptor count alone is insufficient. ASFW must: + +1. Make TX preparation a data-horizon scheduler, not only a descriptor-refill + scheduler. Every monotonic CoreAudio write-frontier update must publish a + neutral target; preparation must continue until `ExposedFrameEnd` reaches + that target as well as maintaining descriptor margin. +2. For Duet at 48 kHz, design and validate toward an initial **400-cycle / ~50 + ms** content target, not the present 576-frame / 12-ms lead. Match the + Apple-derived half-ring relationship by enlarging the TX descriptor and + packet-timeline capacity (likely around 800+ and 1,024 slots respectively), + rather than placing a 400-cycle target at the unsafe edge of ASFW's + 408-slot transport ring. +3. Preserve a pending absolute host-frame range whenever a packet slot is not + yet exposed, then flush it once the timeline exposes that range. It may + only discard a frame after proving the CoreAudio ring has overwritten it; + it must account for that as an xrun. +4. Keep descriptor/NODATA prefill separate from this guarantee. A full DMA + queue is transport liveness, not audio-content liveness. +5. Continue to report `framesWithoutPacket`, first deficit range, timeline + exposure end, TX preparation latency, pending-range age, and packetizer + absolute cursor/alignment state as anomaly-only MCP-ring telemetry. + +The first-deficit log now records the CoreAudio range, exposed end, deficit, +completion cursor, playback range, packetizer absolute cursor/alignment epoch, +and its last DATA packet range. It also records total/DATA/NODATA preparation +and slot-acquisition-failure counters. These are lock-free, best-effort +diagnostic snapshots across the callback/preparation boundary; they must never +be used to control the stream. The producer/pending-range redesign is still +required for a real fix. + +## Minimal anomaly-only telemetry for the next hardware run + +Keep the MCP ring as the primary evidence path; no Console logging is needed +for this diagnosis. Emit only on state transition or anomaly, with recovery +epoch and direction in every record: + +```text +[RxClock] E=.. validSyt/run, packetCycle, fullPresentationTicks, dbc, + dataBlocks, sytDeltaTicks, ratePpm, discontinuityReason +[TxClock] E=.. outputCycle, sourcePresentationTicks, txDelayTicks, + encodedSyt, dbc, dataBlocks, queueLead +[PayloadWriter] firstCoreAudioRange, firstExposedEnd, firstDeficitFrames, + completionCursor, playbackRingRange, miss-counter deltas, + firstPacketizer={next, aligned, epoch, lastPacket, lastRange}, + lastPacketizer={next, aligned, epoch, lastPacket, lastRange}, + prepared={all, data, noData, acquireFail} +[DuplexPhase] E=.. rxPresentationTicks, txPresentationTicks, + rxDelay, txDelay, normalizedPhaseTicks, phasePpm +[Recovery] E=.. producerQuiesced, producerReset, prefillCommitted/slots, + transportArmed, cmpConnected, firstValidRx +``` + +Thresholds should be direction-local: one malformed/no-info packet is not a +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. diff --git a/skills/asfw-mcp-control-plane/SKILL.md b/skills/asfw-mcp-control-plane/SKILL.md index 349b2b89..58587ce5 100644 --- a/skills/asfw-mcp-control-plane/SKILL.md +++ b/skills/asfw-mcp-control-plane/SKILL.md @@ -9,11 +9,20 @@ Use the bundled client instead of reconstructing MCP HTTP/SSE sessions or pastin ## Default workflow -1. Confirm the app-hosted MCP server is enabled. Its default endpoint is `http://127.0.0.1:8766/mcp`. +Run these commands from the ASFireWire repository root. + +1. Confirm the app-hosted MCP server is enabled. The current local endpoint is + `http://127.0.0.1:8765/mcp` (do not rely on the stale `8766` default in old + examples). Set it explicitly for every investigation: + + ```bash + export ASFW_MCP_ENDPOINT=http://127.0.0.1:8765/mcp + ``` + 2. Ask the versioned health resource whether deeper reads are trustworthy: ```bash - python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py health + python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py health ``` `ready` permits targeted read-only diagnostics. `degraded` permits only @@ -24,15 +33,15 @@ Use the bundled client instead of reconstructing MCP HTTP/SSE sessions or pastin 3. Run the compact read-only summary when node or protocol detail is needed: ```bash - python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py summary + python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py summary ``` 4. Use `tools` or `resources` only when the summary lacks the needed detail. 5. Call a read tool with typed JSON arguments only after checking its schema: ```bash - python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py tools - python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_read_quadlet '{"nodeId":0,"generation":9,"addressHigh":65535,"addressLow":4026532864}' + python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py tools + python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_read_quadlet '{"nodeId":0,"generation":9,"addressHigh":65535,"addressLow":4026532864}' ``` Pass `--endpoint` or set `ASFW_MCP_ENDPOINT` when the server uses a non-default loopback port. @@ -60,15 +69,70 @@ Useful incident queries: ```bash # Was a reset requested locally, and which node's accepted Self-ID attributed it? -python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_query '{"categories":["BusReset"],"contains":"Reset ","maxRecords":100}' +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_query '{"categories":["BusReset"],"contains":"Reset ","maxRecords":100}' # Compare the physical topology role with Config-ROM capability claims. -python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_query '{"categories":["ConfigROM"],"contains":"[RoleEvidence]","maxRecords":50}' +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_query '{"categories":["ConfigROM"],"contains":"[RoleEvidence]","maxRecords":50}' # Inspect only CMP/FCP activity while audio is stopped or running. -python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_query '{"categories":["CMP","FCP"],"maxLevel":"debug","maxRecords":200}' +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_query '{"categories":["CMP","FCP"],"maxLevel":"debug","maxRecords":200}' +``` + +### Active audio-run rule + +During an active audio endurance or fault-reproduction run, do **not** call +`health`, `summary`, discovery, or any control tool unless the user explicitly +requests it. They can perturb the app/control plane while the issue is being +timed. A small, targeted driver-ring query is permitted only when requested; +it is read-only and never changes stream state. Do not run broad or parallel +queries while audio is playing. + +For a live TX-content incident, use the retained `DirectAudio` anomaly record: + +```bash +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_query \ + '{"categories":["DirectAudio"],"contains":"[PayloadWriter] anomaly","maxLevel":"debug","maxRecords":20}' ``` +`[PayloadWriter] anomaly` is already MCP-visible because `ASFW_LOG` writes to +the driver-owned ring. The first-deficit and last-callback sections include: + +- host range, exposed timeline end, and exposure deficit; +- `firstPacketizer` / `lastPacketizer`: absolute `next` cursor, alignment bit, + cursor epoch, last DATA packet index, and its `[first,end)` audio range; +- `prepared`: total, DATA, NODATA, and slot-acquisition-failure counters. + +The packetizer snapshot is intentionally best-effort and read-only across the +audio callback/TX-preparation boundary. Interpret a cursor mismatch or a +cursor-epoch change as evidence for a timeline transition; do not treat the +diagnostic snapshot as a synchronization primitive. + +### Audio timing-loss first-fault query + +For an AV/C duplex click, stall, or timing-loss recovery, query the driver ring +before theorizing about SYT phase. The driver emits `[RxReplayReset]` exactly +when an already-established RX replay epoch is invalidated and before it calls +the recovery callback. It is anomaly-only; a healthy stream has no matching +records. + +```bash +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_stats '{}' +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_query \ + '{"afterSequence":0,"categories":["DirectAudio"],"contains":"[RxReplayReset]","maxLevel":"debug","maxRecords":20}' +``` + +The record's `reason` identifies the layer that failed: + +- `packet-status`: CIP/payload decoding or input-buffer writing rejected a packet. +- `invalid-rx-timestamp`: descriptor timestamp could not be correlated with the drain cycle. +- `receive-cycle-gap`: ASFW observed a gap in its one-received-packet-per-cycle model. +- `syt-cadence-rejected`: a valid SYT produced an invalid cadence delta. +- `clock-anchor-rejected`: RX could not publish a host clock anchor. + +Always report `droppedRecords` from `asfw_log_stats`. A zero drop count makes +the first matching record authoritative for the local reset; it does not by +itself prove whether the original fault was device-side or host-side. + After the reset-provenance change is installed, interpret the two records as a pair: `Reset request: origin=local ...` describes ASFW's outgoing action; `Reset provenance: ... initiator=nodeN` is the accepted Self-ID attribution for @@ -123,38 +187,36 @@ the device changed its ROM. ```bash # Discover tool/resource names without expanding every response in the prompt. -python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py tools -python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py resources +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py tools +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py resources # Read an advertised resource. -python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py read asfw://telemetry/snapshot +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py read asfw://telemetry/snapshot # Inspect a read-only tool's full result when needed. -python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_avc_list_units '{}' +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_avc_list_units '{}' # Query the bounded driver-owned log ring. `nextSequence` is an exclusive # cursor for the next call; an empty page can still advance it when a sparse # filter consumed its scan budget. -python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_query '{"categories":["CMP"],"contains":"iPCR","maxLevel":"debug","maxRecords":200}' -python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_stats '{}' +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_query '{"categories":["CMP"],"contains":"iPCR","maxLevel":"debug","maxRecords":200}' +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_log_stats '{}' # BridgeCo/BeBoB generic unit PLUG_INFO (fixed, STATUS-only FCP command). -python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_bebob_get_unit_plug_info '{"targetGuid":3003878663639543,"nodeId":0,"generation":2}' +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_bebob_get_unit_plug_info '{"targetGuid":3003878663639543,"nodeId":0,"generation":2}' # Music Subunit SYNC input and current BridgeCo clock-source topology. -python3 /Users/mrmidi/.codex/skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_bebob_get_clock_topology '{"targetGuid":3003878663639543,"nodeId":0,"generation":2}' +python3 skills/asfw-mcp-control-plane/scripts/asfw_mcp.py call asfw_bebob_get_clock_topology '{"targetGuid":3003878663639543,"nodeId":0,"generation":2}' ``` If the endpoint is unavailable, report the connection failure and ask the user to enable the MCP Control Plane in ASFW. Do not fall back to guessed driver state. -## Console correlation +## Optional Console correlation -Every tool call and resource read is mirrored into the unified log by the ASFW -app with an `[MCP]` message prefix (`call`/`done`/`fail` lines carry the tool -name, compact JSON arguments and result data, duration, and error codes; byte -payloads render as quadlet-grouped hex). To correlate control-plane requests -with the driver traffic they trigger, hand the user one predicate covering -both sides (resource reads log at debug level, so keep `--debug`): +Do not use Console as the normal ASFW driver-diagnosis path: the MCP driver ring +is retained, queryable, and gives the chronology needed for transport/audio +incidents. Unified-log correlation is optional only when the question lies +outside the ring, such as app/UI behaviour around an MCP call. ```bash log stream --info --debug --predicate 'eventMessage CONTAINS "[MCP]" OR eventMessage CONTAINS "[UserClient]" OR eventMessage CONTAINS "[FCP]"' diff --git a/tests/audio/AmdtpDirectTxTests.cpp b/tests/audio/AmdtpDirectTxTests.cpp index 472e6865..13af7716 100644 --- a/tests/audio/AmdtpDirectTxTests.cpp +++ b/tests/audio/AmdtpDirectTxTests.cpp @@ -287,6 +287,43 @@ TEST(AmdtpDirectTxTests, AlignFrameCursorIsAcceptedOnlyOncePerReset) { EXPECT_TRUE(packetizer.AlignFrameCursorOnce(3000U)); } +TEST(AmdtpDirectTxTests, PacketizerTelemetryTracksCursorAlignmentAndLastDataRange) { + AmdtpPacketTimeline timeline{}; + std::array timelineSlots{}; + ASSERT_TRUE(timeline.AttachSlots(timelineSlots.data(), timelineSlots.size())); + + AmdtpTxPacketizer packetizer{}; + packetizer.BindTimeline(&timeline); + ASSERT_TRUE(packetizer.Configure(BlockingStereoConfig(), AmdtpTxPolicy{})); + EXPECT_TRUE(packetizer.AlignFrameCursorOnce(960U)); + + std::array, 2> bytes{}; + AmdtpTimingState timing{}; + timing.txClockValid = true; + timing.disposition = AmdtpPacketDisposition::Data; + timing.nextDataSyt = 0x1234; + PreparedTxPacket packet{}; + ASSERT_TRUE(packetizer.PrepareNextPacket( + {0, bytes[0].data(), bytes[0].size()}, timing, packet)); + ASSERT_FALSE(packet.isData); + ASSERT_TRUE(packetizer.PrepareNextPacket( + {1, bytes[1].data(), bytes[1].size()}, timing, packet)); + ASSERT_TRUE(packet.isData); + + const auto snapshot = packetizer.TelemetrySnapshot(); + EXPECT_TRUE(snapshot.frameCursorAligned); + EXPECT_TRUE(snapshot.hasLastDataPacket); + EXPECT_EQ(snapshot.nextAudioFrame, 968U); + EXPECT_EQ(snapshot.lastDataFirstAudioFrame, 960U); + EXPECT_EQ(snapshot.lastDataEndAudioFrame, 968U); + EXPECT_EQ(snapshot.lastDataPacketIndex, 1U); + + packetizer.ReArmFrameCursorAlignment(); + const auto rearmed = packetizer.TelemetrySnapshot(); + EXPECT_FALSE(rearmed.frameCursorAligned); + EXPECT_GT(rearmed.cursorEpoch, snapshot.cursorEpoch); +} + TEST(AmdtpDirectTxTests, TxEngineReportsPreparationFailureStage) { DiceTxStreamEngine engine{}; AmdtpTimingState timing{};