Adding a counter trace macro to the tracing for getting insights from…

… counters in chip and implemented the macro for ESP32 platform... (#30591)

* Set up the tracing to support counter macro and added the macro to none and multiplexed

* Added the support of counter macro for esp32

* Added the support of counter macro in perfetto

* Added support of counters for json backend and few traces

* Restyled the code

* Added few counter traces

* Refactored some code

* Addressed Review Comments

* Removed the group from counter trace macro

* Refactored some code

* Addressed the string and class documentation related review comments

scripts/tools/check_includes_config.py

@@ -158,7 +158,7 @@
 
     # Library meant for non-embedded
     'src/tracing/json/json_tracing.cpp': {'string', 'sstream'},
-    'src/tracing/json/json_tracing.h': {'fstream'},
+    'src/tracing/json/json_tracing.h': {'fstream', 'unordered_map'},
 
     # Not intended for embedded clients
     'src/lib/support/jsontlv/JsonToTlv.cpp': {'sstream'},

src/protocols/secure_channel/CASEServer.cpp

@@ -183,6 +183,7 @@ void CASEServer::OnSessionEstablishmentError(CHIP_ERROR err)
     MATTER_TRACE_SCOPE("OnSessionEstablishmentError", "CASEServer");
     ChipLogError(Inet, "CASE Session establishment failed: %" CHIP_ERROR_FORMAT, err.Format());
 
+    MATTER_TRACE_SCOPE("CASEFail", "CASESession");
     PrepareForSessionEstablishment();
 }
 

src/protocols/secure_channel/CASESession.cpp

@@ -552,6 +552,7 @@ void CASESession::OnResponseTimeout(ExchangeContext * ec)
     VerifyOrReturn(mExchangeCtxt == ec, ChipLogError(SecureChannel, "CASESession::OnResponseTimeout exchange doesn't match"));
     ChipLogError(SecureChannel, "CASESession timed out while waiting for a response from the peer. Current state was %u",
                  to_underlying(mState));
+    MATTER_TRACE_COUNTER("CASETimeout");
     // Discard the exchange so that Clear() doesn't try aborting it.  The
     // exchange will handle that.
     DiscardExchange();
@@ -844,6 +845,7 @@ CHIP_ERROR CASESession::HandleSigma1(System::PacketBufferHandle && msg)
     ByteSpan initiatorRandom;
 
     ChipLogProgress(SecureChannel, "Received Sigma1 msg");
+    MATTER_TRACE_COUNTER("Sigma1");
 
     bool sessionResumptionRequested = false;
     ByteSpan resumptionId;
@@ -1100,6 +1102,7 @@ CHIP_ERROR CASESession::SendSigma2()
     mState = State::kSentSigma2;
 
     ChipLogProgress(SecureChannel, "Sent Sigma2 msg");
+    MATTER_TRACE_COUNTER("Sigma2");
 
     return CHIP_NO_ERROR;
 }
@@ -1116,6 +1119,7 @@ CHIP_ERROR CASESession::HandleSigma2Resume(System::PacketBufferHandle && msg)
     uint32_t decodeTagIdSeq = 0;
 
     ChipLogDetail(SecureChannel, "Received Sigma2Resume msg");
+    MATTER_TRACE_COUNTER("Sigma2Resume");
 
     uint8_t sigma2ResumeMIC[CHIP_CRYPTO_AEAD_MIC_LENGTH_BYTES];
 
@@ -1585,6 +1589,7 @@ CHIP_ERROR CASESession::HandleSigma3a(System::PacketBufferHandle && msg)
     uint8_t msg_salt[kIPKSize + kSHA256_Hash_Length];
 
     ChipLogProgress(SecureChannel, "Received Sigma3 msg");
+    MATTER_TRACE_COUNTER("Sigma3");
 
     auto helper = WorkHelper<HandleSigma3Data>::Create(*this, &HandleSigma3b, &CASESession::HandleSigma3c);
     VerifyOrExit(helper, err = CHIP_ERROR_NO_MEMORY);

src/protocols/secure_channel/PASESession.cpp

@@ -251,6 +251,7 @@ void PASESession::OnResponseTimeout(ExchangeContext * ec)
     // If we were waiting for something, mNextExpectedMsg had better have a value.
     ChipLogError(SecureChannel, "PASESession timed out while waiting for a response from the peer. Expected message type was %u",
                  to_underlying(mNextExpectedMsg.Value()));
+    MATTER_TRACE_COUNTER("PASETimeout");
     // Discard the exchange so that Clear() doesn't try closing it.  The
     // exchange will handle that.
     DiscardExchange();
@@ -572,6 +573,7 @@ CHIP_ERROR PASESession::HandleMsg1_and_SendMsg2(System::PacketBufferHandle && ms
     size_t verifier_len = kMAX_Hash_Length;
 
     ChipLogDetail(SecureChannel, "Received spake2p msg1");
+    MATTER_TRACE_SCOPE("Pake1", "PASESession");
 
     System::PacketBufferTLVReader tlvReader;
     TLV::TLVType containerType = TLV::kTLVType_Structure;
@@ -620,6 +622,7 @@ CHIP_ERROR PASESession::HandleMsg1_and_SendMsg2(System::PacketBufferHandle && ms
     }
 
     ChipLogDetail(SecureChannel, "Sent spake2p msg2");
+    MATTER_TRACE_COUNTER("Pake2");
 
 exit:
 
@@ -711,6 +714,7 @@ CHIP_ERROR PASESession::HandleMsg3(System::PacketBufferHandle && msg)
     CHIP_ERROR err = CHIP_NO_ERROR;
 
     ChipLogDetail(SecureChannel, "Received spake2p msg3");
+    MATTER_TRACE_COUNTER("Pake3");
 
     mNextExpectedMsg.ClearValue();
 
@@ -871,6 +875,7 @@ CHIP_ERROR PASESession::OnMessageReceived(ExchangeContext * exchange, const Payl
         DiscardExchange();
         Clear();
         ChipLogError(SecureChannel, "Failed during PASE session setup: %" CHIP_ERROR_FORMAT, err.Format());
+        MATTER_TRACE_COUNTER("PASEFail");
         // Do this last in case the delegate frees us.
         NotifySessionEstablishmentError(err);
     }

src/tracing/backend.h

@@ -63,6 +63,7 @@ class Backend : public ::chip::IntrusiveListNodeBase<>
     /// Trace a zero-sized event
     virtual void TraceInstant(const char * label, const char * group) {}
 
+    virtual void TraceCounter(const char * label) {}
     virtual void LogMessageSend(MessageSendInfo &) { TraceInstant("MessageSent", "Messaging"); }
     virtual void LogMessageReceived(MessageReceivedInfo &) { TraceInstant("MessageReceived", "Messaging"); }
 

src/tracing/esp32_trace/BUILD.gn

@@ -29,6 +29,8 @@ static_library("backend") {
   output_dir = "${root_out_dir}/lib"
 
   sources = [
+    "counter.cpp",
+    "counter.h",
     "esp32_tracing.cpp",
     "esp32_tracing.h",
   ]
@@ -43,7 +45,10 @@ static_library("backend") {
       "${chip_root}/src/system",
     ]
   }
-  public_deps = [ "${chip_root}/src/tracing" ]
+  public_deps = [
+    "${chip_root}/src/lib/core",
+    "${chip_root}/src/tracing",
+  ]
 }
 
 source_set("esp32_trace_tracing") {

src/tracing/esp32_trace/counter.cpp

@@ -0,0 +1,72 @@
+/*
+ *
+ *    Copyright (c) 2024 Project CHIP Authors
+ *    All rights reserved.
+ *
+ *    Licensed under the Apache License, Version 2.0 (the "License");
+ *    you may not use this file except in compliance with the License.
+ *    You may obtain a copy of the License at
+ *
+ *        http://www.apache.org/licenses/LICENSE-2.0
+ *
+ *    Unless required by applicable law or agreed to in writing, software
+ *    distributed under the License is distributed on an "AS IS" BASIS,
+ *    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ *    See the License for the specific language governing permissions and
+ *    limitations under the License.
+ */
+
+#include <string.h>
+#include <tracing/esp32_trace/counter.h>
+
+using namespace chip;
+
+namespace Insights {
+
+// This is a one time allocation for counters. It is not supposed to be freed.
+ESPInsightsCounter * ESPInsightsCounter::mHead = nullptr;
+
+ESPInsightsCounter * ESPInsightsCounter::GetInstance(const char * label)
+{
+    ESPInsightsCounter * current = mHead;
+
+    while (current != nullptr)
+    {
+        if (strcmp(current->label, label) == 0)
+        {
+            current->instanceCount++;
+            return current;
+        }
+        current = current->mNext;
+    }
+
+    // Allocate a new instance if counter is not present in the list.
+    void * ptr = Platform::MemoryAlloc(sizeof(ESPInsightsCounter));
+    VerifyOrDie(ptr != nullptr);
+
+    ESPInsightsCounter * newInstance = new (ptr) ESPInsightsCounter(label);
+    newInstance->mNext               = mHead;
+    mHead                            = newInstance;
+
+    return newInstance;
+}
+
+int ESPInsightsCounter::GetInstanceCount() const
+{
+    return instanceCount;
+}
+
+void ESPInsightsCounter::ReportMetrics()
+{
+    if (!registered)
+    {
+        esp_diag_metrics_register("SYS_CNT" /* Tag of metrics */, label /* Unique key 8 */,
+                                  label /* label displayed on dashboard */, "insights.cnt" /* hierarchical path */,
+                                  ESP_DIAG_DATA_TYPE_UINT /* data_type */);
+        registered = true;
+    }
+    ESP_LOGI("mtr", "Label = %s Count = %d", label, instanceCount);
+    esp_diag_metrics_add_uint(label, instanceCount);
+}
+
+} // namespace Insights

src/tracing/esp32_trace/counter.h

@@ -0,0 +1,55 @@
+/*
+ *
+ *    Copyright (c) 2024 Project CHIP Authors
+ *    All rights reserved.
+ *
+ *    Licensed under the Apache License, Version 2.0 (the "License");
+ *    you may not use this file except in compliance with the License.
+ *    You may obtain a copy of the License at
+ *
+ *        http://www.apache.org/licenses/LICENSE-2.0
+ *
+ *    Unless required by applicable law or agreed to in writing, software
+ *    distributed under the License is distributed on an "AS IS" BASIS,
+ *    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ *    See the License for the specific language governing permissions and
+ *    limitations under the License.
+ */
+
+#include <esp_diagnostics_metrics.h>
+#include <esp_log.h>
+#include <lib/support/CHIPMem.h>
+#include <lib/support/CHIPMemString.h>
+#include <string.h>
+
+namespace Insights {
+
+/*
+ *
+ * This class is used to monotonically increment the counters as per the label of the counter macro
+ * 'MATTER_TRACE_COUNTER(label)' and report the metrics to esp-insights.
+ * As per the label of the counter macro, it adds the counter in the linked list with the name label if not
+ * present and returns the same instance and increments the value if the counter is already present
+ * in the list.
+ */
+
+class ESPInsightsCounter
+{
+private:
+    static ESPInsightsCounter * mHead; // head of the counter list
+    const char * label;                // unique key
+    int instanceCount;
+    ESPInsightsCounter * mNext; // pointer to point to the next entry in the list
+    bool registered = false;
+
+    ESPInsightsCounter(const char * labelParam) : label(labelParam), instanceCount(1), mNext(nullptr) {}
+
+public:
+    static ESPInsightsCounter * GetInstance(const char * label);
+
+    int GetInstanceCount() const;
+
+    void ReportMetrics();
+};
+
+} // namespace Insights

src/tracing/esp32_trace/esp32_tracing.cpp

@@ -16,13 +16,14 @@
  *    limitations under the License.
  */
 
-#include "esp32_tracing.h"
 #include <algorithm>
 #include <esp_heap_caps.h>
 #include <esp_insights.h>
 #include <esp_log.h>
 #include <memory>
 #include <tracing/backend.h>
+#include <tracing/esp32_trace/counter.h>
+#include <tracing/esp32_trace/esp32_tracing.h>
 
 namespace chip {
 namespace Tracing {
@@ -148,6 +149,10 @@ void ESP32Backend::LogNodeDiscovered(NodeDiscoveredInfo & info) {}
 
 void ESP32Backend::LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo & info) {}
 
+void ESP32Backend::TraceCounter(const char * label)
+{
+    ::Insights::ESPInsightsCounter::GetInstance(label)->ReportMetrics();
+}
 void ESP32Backend::TraceBegin(const char * label, const char * group)
 {
     HashValue hashValue = MurmurHash(group);

src/tracing/esp32_trace/esp32_tracing.h

@@ -28,6 +28,8 @@ class ESP32Backend : public ::chip::Tracing::Backend
     /// Trace a zero-sized event
     void TraceInstant(const char * label, const char * group) override;
 
+    void TraceCounter(const char * label) override;
+
     void LogMessageSend(MessageSendInfo &) override;
     void LogMessageReceived(MessageReceivedInfo &) override;
 

src/tracing/esp32_trace/include/matter/tracing/macros_impl.h

@@ -28,6 +28,7 @@
 #define MATTER_TRACE_BEGIN(label, group) ::chip::Tracing::Internal::Begin(label, group)
 #define MATTER_TRACE_END(label, group) ::chip::Tracing::Internal::End(label, group)
 #define MATTER_TRACE_INSTANT(label, group) ::chip::Tracing::Internal::Instant(label, group)
+#define MATTER_TRACE_COUNTER(label) ::chip::Tracing::Internal::Counter(label)
 
 namespace chip {
 namespace Tracing {

src/tracing/json/json_tracing.cpp

@@ -23,9 +23,8 @@
 #include <lib/support/CHIPMem.h>
 #include <lib/support/StringBuilder.h>
 #include <lib/support/StringSplitter.h>
-#include <transport/TracingStructs.h>
-
 #include <log_json/log_json_build_config.h>
+#include <transport/TracingStructs.h>
 
 #include <json/json.h>
 
@@ -276,6 +275,26 @@ void JsonBackend::TraceInstant(const char * label, const char * group)
     OutputValue(value);
 }
 
+void JsonBackend::TraceCounter(const char * label)
+{
+    std::string counterId = std::string(label);
+    if (mCounters.find(counterId) == mCounters.end())
+    {
+        mCounters[counterId] = 1;
+    }
+    else
+    {
+        mCounters[counterId]++;
+    }
+    ::Json::Value value;
+    value["event"] = "TraceCounter";
+    value["label"] = label;
+    value["count"] = mCounters[counterId];
+
+    // Output the counter event
+    OutputValue(value);
+}
+
 void JsonBackend::LogMessageSend(MessageSendInfo & info)
 {
     ::Json::Value value;

src/tracing/json/json_tracing.h

@@ -19,6 +19,7 @@
 
 #include <fstream>
 #include <tracing/backend.h>
+#include <unordered_map>
 
 namespace Json {
 class Value;
@@ -50,6 +51,7 @@ class JsonBackend : public ::chip::Tracing::Backend
     void TraceBegin(const char * label, const char * group) override;
     void TraceEnd(const char * label, const char * group) override;
     void TraceInstant(const char * label, const char * group) override;
+    void TraceCounter(const char * label) override;
     void LogMessageSend(MessageSendInfo &) override;
     void LogMessageReceived(MessageReceivedInfo &) override;
     void LogNodeLookup(NodeLookupInfo &) override;
@@ -61,6 +63,8 @@ class JsonBackend : public ::chip::Tracing::Backend
     /// Does the actual write of the value
     void OutputValue(::Json::Value & value);
 
+    std::unordered_map<std::string, int> mCounters;
+
     // Output file if writing to a file. If closed, writing
     // to ChipLog*
     std::fstream mOutputFile;

src/tracing/macros.h

@@ -78,6 +78,7 @@
 #define MATTER_TRACE_END(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
 #define MATTER_TRACE_INSTANT(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
 #define MATTER_TRACE_SCOPE(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
+#define MATTER_TRACE_COUNTER(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
 
 #define MATTER_LOG_MESSAGE_SEND(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
 #define MATTER_LOG_MESSAGE_RECEIVED(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)

src/tracing/multiplexed/include/matter/tracing/macros_impl.h

@@ -28,6 +28,7 @@
 #define MATTER_TRACE_BEGIN(label, group) ::chip::Tracing::Internal::Begin(label, group)
 #define MATTER_TRACE_END(label, group) ::chip::Tracing::Internal::End(label, group)
 #define MATTER_TRACE_INSTANT(label, group) ::chip::Tracing::Internal::Instant(label, group)
+#define MATTER_TRACE_COUNTER(label) ::chip::Tracing::Internal::Counter(label)
 
 namespace chip {
 namespace Tracing {

src/tracing/none/include/matter/tracing/macros_impl.h

@@ -31,3 +31,4 @@
 #define MATTER_TRACE_END(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
 #define MATTER_TRACE_INSTANT(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
 #define MATTER_TRACE_SCOPE(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
+#define MATTER_TRACE_COUNTER(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)

src/tracing/perfetto/include/matter/tracing/macros_impl.h

@@ -30,3 +30,10 @@ PERFETTO_DEFINE_CATEGORIES(perfetto::Category("Matter").SetDescription("Matter t
 #define MATTER_TRACE_END(label, group) TRACE_EVENT_END("Matter")
 #define MATTER_TRACE_INSTANT(label, group) TRACE_EVENT_INSTANT("Matter", label, "class_name", group)
 #define MATTER_TRACE_SCOPE(label, group) TRACE_EVENT("Matter", label, "class_name", group)
+
+#define MATTER_TRACE_COUNTER(label)                                                                                                \
+    do                                                                                                                             \
+    {                                                                                                                              \
+        static int count##_label = 0;                                                                                              \
+        TRACE_COUNTER("Matter", label, ++count##_label);                                                                           \
+    } while (0)