diff --git a/src/core/mac/sub_mac.cpp b/src/core/mac/sub_mac.cpp index df103c636..9b6879ff0 100644 --- a/src/core/mac/sub_mac.cpp +++ b/src/core/mac/sub_mac.cpp @@ -276,6 +276,61 @@ exit: } #endif // OPENTHREAD_CONFIG_MAC_CSL_RECEIVER_ENABLE +#if OPENTHREAD_CONFIG_MAC_CSL_DEBUG_ENABLE +void SubMac::LogReceived(RxFrame *aFrame) +{ + static constexpr uint8_t kLogStringSize = 72; + + String logString; + Address dst; + int32_t deviation; + uint32_t sampleTime, ahead, after; + + IgnoreError(aFrame->GetDstAddr(dst)); + + VerifyOrExit((dst.GetType() == Address::kTypeShort && dst.GetShort() == GetShortAddress()) || + (dst.GetType() == Address::kTypeExtended && dst.GetExtended() == GetExtAddress())); + + LogDebg("Received frame in state (SubMac %s, CSL %s), timestamp %lu", StateToString(mState), + mIsCslSampling ? "CslSample" : "CslSleep", + ToUlong(static_cast(aFrame->mInfo.mRxInfo.mTimestamp))); + + VerifyOrExit(mState == kStateCslSample); + + GetCslWindowEdges(ahead, after); + ahead -= kMinReceiveOnAhead + kCslReceiveTimeAhead; + + sampleTime = mCslSampleTime.GetValue() - mCslPeriod * kUsPerTenSymbols; + deviation = aFrame->mInfo.mRxInfo.mTimestamp + kRadioHeaderPhrDuration - sampleTime; + + // This logs three values (all in microseconds): + // - Absolute sample time in which the CSL receiver expected the MHR of the received frame. + // - Allowed margin around that time accounting for accuracy and uncertainty from both devices. + // - Real deviation on the reception of the MHR with regards to expected sample time. This can + // be due to clocks drift and/or CSL Phase rounding error. + // This means that a deviation absolute value greater than the margin would result in the frame + // not being received out of the debug mode. + logString.Append("Expected sample time %lu, margin ±%lu, deviation %d", ToUlong(sampleTime), ToUlong(ahead), + deviation); + + // Treat as a warning when the deviation is not within the margins. Neither kCslReceiveTimeAhead + // or kMinReceiveOnAhead/kMinReceiveOnAfter are considered for the margin since they have no + // impact on understanding possible deviation errors between transmitter and receiver. So in this + // case ahead equals after. + if ((deviation + ahead > 0) && (deviation < static_cast(ahead))) + { + LogDebg("%s", logString.AsCString()); + } + else + { + LogWarn("%s", logString.AsCString()); + } + +exit: + return; +} +#endif + void SubMac::HandleReceiveDone(RxFrame *aFrame, Error aError) { if (mPcapCallback.IsSet() && (aFrame != nullptr) && (aError == kErrorNone)) @@ -291,20 +346,14 @@ void SubMac::HandleReceiveDone(RxFrame *aFrame, Error aError) #if OPENTHREAD_CONFIG_MAC_CSL_RECEIVER_ENABLE if (aFrame != nullptr && aError == kErrorNone) { +#if OPENTHREAD_CONFIG_MAC_CSL_DEBUG_ENABLE + LogReceived(aFrame); +#endif // Assuming the risk of the parent missing the Enh-ACK in favor of smaller CSL receive window if ((mCslPeriod > 0) && aFrame->mInfo.mRxInfo.mAckedWithSecEnhAck) { mCslLastSync = TimeMicro(static_cast(aFrame->mInfo.mRxInfo.mTimestamp)); } - -#if OPENTHREAD_CONFIG_MAC_CSL_DEBUG_ENABLE - // Split the log into two lines for RTT to output - LogDebg("Received frame in state (SubMac %s, CSL %s), timestamp %lu", StateToString(mState), - mIsCslSampling ? "CslSample" : "CslSleep", - ToUlong(static_cast(aFrame->mInfo.mRxInfo.mTimestamp))); - LogDebg("Target sample start time %lu, time drift %lu", ToUlong(mCslSampleTime.GetValue()), - ToUlong(static_cast(aFrame->mInfo.mRxInfo.mTimestamp) - mCslSampleTime.GetValue())); -#endif } #endif // OPENTHREAD_CONFIG_MAC_CSL_RECEIVER_ENABLE @@ -1129,7 +1178,7 @@ void SubMac::HandleCslTimer(void) * */ uint32_t periodUs = mCslPeriod * kUsPerTenSymbols; - uint32_t timeAhead, timeAfter; + uint32_t timeAhead, timeAfter, winStart, winDuration; GetCslWindowEdges(timeAhead, timeAfter); @@ -1149,32 +1198,34 @@ void SubMac::HandleCslTimer(void) { if (RadioSupportsReceiveTiming()) { - mCslSampleTime += periodUs; - mCslTimer.FireAt(mCslSampleTime - timeAhead); + mCslTimer.FireAt(mCslSampleTime - timeAhead + periodUs); timeAhead -= kCslReceiveTimeAhead; + winStart = mCslSampleTime.GetValue() - timeAhead; } else { mCslTimer.FireAt(mCslSampleTime + timeAfter); mIsCslSampling = true; - mCslSampleTime += periodUs; + winStart = ot::TimerMicro::GetNow().GetValue(); } + winDuration = timeAhead + timeAfter; + mCslSampleTime += periodUs; + Get().UpdateCslSampleTime(mCslSampleTime.GetValue()); // Schedule reception window for any state except RX - so that CSL RX Window has lower priority // than scanning or RX after the data poll. if (RadioSupportsReceiveTiming() && (mState != kStateDisabled) && (mState != kStateReceive)) { - IgnoreError(Get().ReceiveAt(mCslChannel, mCslSampleTime.GetValue() - periodUs - timeAhead, - timeAhead + timeAfter)); + IgnoreError(Get().ReceiveAt(mCslChannel, winStart, winDuration)); } else if (mState == kStateCslSample) { IgnoreError(Get().Receive(mCslChannel)); - LogDebg("CSL sample %lu, duration %lu", ToUlong(mCslTimer.GetNow().GetValue()), - ToUlong(timeAhead + timeAfter)); } + + LogDebg("CSL window start %lu, duration %lu", ToUlong(winStart), ToUlong(winDuration)); } } diff --git a/src/core/mac/sub_mac.hpp b/src/core/mac/sub_mac.hpp index 7074ca2fd..5c244fd03 100644 --- a/src/core/mac/sub_mac.hpp +++ b/src/core/mac/sub_mac.hpp @@ -534,6 +534,9 @@ private: static void HandleCslTimer(Timer &aTimer); void HandleCslTimer(void); void GetCslWindowEdges(uint32_t &aAhead, uint32_t &aAfter); +#if OPENTHREAD_CONFIG_MAC_CSL_DEBUG_ENABLE + void LogReceived(RxFrame *aFrame); +#endif #endif static constexpr uint8_t kCsmaMinBe = 3; // macMinBE (IEEE 802.15.4-2006). diff --git a/src/core/radio/radio.hpp b/src/core/radio/radio.hpp index 3a8566d9e..4d3227443 100644 --- a/src/core/radio/radio.hpp +++ b/src/core/radio/radio.hpp @@ -47,6 +47,7 @@ namespace ot { static constexpr uint32_t kUsPerTenSymbols = OT_US_PER_TEN_SYMBOLS; ///< Time for 10 symbols in units of microseconds static constexpr uint32_t kRadioHeaderShrDuration = 160; ///< Duration of SHR in us +static constexpr uint32_t kRadioHeaderPhrDuration = 32; ///< Duration of PHR in us #if OPENTHREAD_CONFIG_MAC_CSL_RECEIVER_ENABLE /**