[Logging] Log the duration for successfully establishing a subscripti…

…on (#36115)
project-chip · Oct 25, 2024 · 2868145 · 2868145
1 parent c201733
commit 2868145
Show file tree

Hide file tree

Showing 2 changed files with 16 additions and 2 deletions.
diff --git 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
@@ -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