From 12810449ffa94ff2b1e6942375386c51ac98f170 Mon Sep 17 00:00:00 2001
From: Vivien Nicolas <vnicolas@apple.com>
Date: Fri, 18 Oct 2024 04:16:19 +0200
Subject: [PATCH] [Logging] Log the duration for successfully establishing a
 subscription (#36115)

---
 src/app/ReadClient.cpp | 12 ++++++++++--
 src/app/ReadClient.h   |  6 ++++++
 2 files changed, 16 insertions(+), 2 deletions(-)

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