diff --git a/src/app/ReadClient.cpp b/src/app/ReadClient.cpp index 1e9c7e727f409c..2d609eb1afa05a 100644 --- a/src/app/ReadClient.cpp +++ b/src/app/ReadClient.cpp @@ -1081,10 +1081,14 @@ CHIP_ERROR ReadClient::ProcessSubscribeResponse(System::PacketBufferHandle && aP VerifyOrReturnError(IsMatchingSubscriptionId(subscriptionId), CHIP_ERROR_INVALID_SUBSCRIPTION); ReturnErrorOnFailure(subscribeResponse.GetMaxInterval(&mMaxInterval)); +#if CHIP_PROGRESS_LOGGING + auto duration = System::Clock::Milliseconds32(System::SystemClock().GetMonotonicTimestamp() - mSubscribeRequestTime); +#endif ChipLogProgress(DataManagement, - "Subscription established with SubscriptionID = 0x%08" PRIx32 " MinInterval = %u" + "Subscription established in %" PRIu32 "ms with SubscriptionID = 0x%08" PRIx32 " MinInterval = %u" "s MaxInterval = %us Peer = %02x:" ChipLogFormatX64, - mSubscriptionId, mMinIntervalFloorSeconds, mMaxInterval, GetFabricIndex(), ChipLogValueX64(GetPeerNodeId())); + duration.count(), mSubscriptionId, mMinIntervalFloorSeconds, mMaxInterval, GetFabricIndex(), + ChipLogValueX64(GetPeerNodeId())); ReturnErrorOnFailure(subscribeResponse.ExitContainer()); @@ -1144,6 +1148,10 @@ CHIP_ERROR ReadClient::SendSubscribeRequestImpl(const ReadPrepareParams & aReadP { MATTER_LOG_METRIC_BEGIN(Tracing::kMetricDeviceSubscriptionSetup); +#if CHIP_PROGRESS_LOGGING + mSubscribeRequestTime = System::SystemClock().GetMonotonicTimestamp(); +#endif + VerifyOrReturnError(ClientState::Idle == mState, CHIP_ERROR_INCORRECT_STATE); if (&aReadPrepareParams != &mReadPrepareParams) diff --git a/src/app/ReadClient.h b/src/app/ReadClient.h index fd27f0afc9e959..d8b8a971db8c28 100644 --- a/src/app/ReadClient.h +++ b/src/app/ReadClient.h @@ -676,6 +676,12 @@ class ReadClient : public Messaging::ExchangeDelegate // of RequestMessage (another end of container)). static constexpr uint16_t kReservedSizeForTLVEncodingOverhead = kReservedSizeForEndOfContainer + kReservedSizeForIMRevision + kReservedSizeForEndOfContainer; + +#if CHIP_PROGRESS_LOGGING + // Tracks the time when a subscribe request is successfully sent. + // This timestamp allows for logging the duration taken to established the subscription. + System::Clock::Timestamp mSubscribeRequestTime = System::Clock::kZero; +#endif }; }; // namespace app