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
diff --git a/scripts/tools/check_includes_config.py b/scripts/tools/check_includes_config.py
index b4e933f..42920c4 100644
--- a/scripts/tools/check_includes_config.py
+++ b/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'},
diff --git a/src/protocols/secure_channel/CASEServer.cpp b/src/protocols/secure_channel/CASEServer.cpp
index d701d8c..2ad196a 100644
--- a/src/protocols/secure_channel/CASEServer.cpp
+++ b/src/protocols/secure_channel/CASEServer.cpp
@@ -183,6 +183,7 @@
MATTER_TRACE_SCOPE("OnSessionEstablishmentError", "CASEServer");
ChipLogError(Inet, "CASE Session establishment failed: %" CHIP_ERROR_FORMAT, err.Format());
+ MATTER_TRACE_SCOPE("CASEFail", "CASESession");
PrepareForSessionEstablishment();
}
diff --git a/src/protocols/secure_channel/CASESession.cpp b/src/protocols/secure_channel/CASESession.cpp
index 8573d15..1d6cb27 100644
--- a/src/protocols/secure_channel/CASESession.cpp
+++ b/src/protocols/secure_channel/CASESession.cpp
@@ -552,6 +552,7 @@
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 @@
ByteSpan initiatorRandom;
ChipLogProgress(SecureChannel, "Received Sigma1 msg");
+ MATTER_TRACE_COUNTER("Sigma1");
bool sessionResumptionRequested = false;
ByteSpan resumptionId;
@@ -1100,6 +1102,7 @@
mState = State::kSentSigma2;
ChipLogProgress(SecureChannel, "Sent Sigma2 msg");
+ MATTER_TRACE_COUNTER("Sigma2");
return CHIP_NO_ERROR;
}
@@ -1116,6 +1119,7 @@
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 @@
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);
diff --git a/src/protocols/secure_channel/PASESession.cpp b/src/protocols/secure_channel/PASESession.cpp
index 67da1d1..980a30d 100644
--- a/src/protocols/secure_channel/PASESession.cpp
+++ b/src/protocols/secure_channel/PASESession.cpp
@@ -251,6 +251,7 @@
// 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 @@
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 @@
}
ChipLogDetail(SecureChannel, "Sent spake2p msg2");
+ MATTER_TRACE_COUNTER("Pake2");
exit:
@@ -711,6 +714,7 @@
CHIP_ERROR err = CHIP_NO_ERROR;
ChipLogDetail(SecureChannel, "Received spake2p msg3");
+ MATTER_TRACE_COUNTER("Pake3");
mNextExpectedMsg.ClearValue();
@@ -871,6 +875,7 @@
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);
}
diff --git a/src/tracing/backend.h b/src/tracing/backend.h
index 7e04490..3d8bec8 100644
--- a/src/tracing/backend.h
+++ b/src/tracing/backend.h
@@ -63,6 +63,7 @@
/// 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"); }
diff --git a/src/tracing/esp32_trace/BUILD.gn b/src/tracing/esp32_trace/BUILD.gn
index 7548894..294cf1f 100644
--- a/src/tracing/esp32_trace/BUILD.gn
+++ b/src/tracing/esp32_trace/BUILD.gn
@@ -29,6 +29,8 @@
output_dir = "${root_out_dir}/lib"
sources = [
+ "counter.cpp",
+ "counter.h",
"esp32_tracing.cpp",
"esp32_tracing.h",
]
@@ -43,7 +45,10 @@
"${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") {
diff --git a/src/tracing/esp32_trace/counter.cpp b/src/tracing/esp32_trace/counter.cpp
new file mode 100644
index 0000000..0b315a8
--- /dev/null
+++ b/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
diff --git a/src/tracing/esp32_trace/counter.h b/src/tracing/esp32_trace/counter.h
new file mode 100644
index 0000000..bfa6205
--- /dev/null
+++ b/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
diff --git a/src/tracing/esp32_trace/esp32_tracing.cpp b/src/tracing/esp32_trace/esp32_tracing.cpp
index 7a13130..7937772 100644
--- a/src/tracing/esp32_trace/esp32_tracing.cpp
+++ b/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::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);
diff --git a/src/tracing/esp32_trace/esp32_tracing.h b/src/tracing/esp32_trace/esp32_tracing.h
index 7fe783d..6d9a277 100644
--- a/src/tracing/esp32_trace/esp32_tracing.h
+++ b/src/tracing/esp32_trace/esp32_tracing.h
@@ -28,6 +28,8 @@
/// 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;
diff --git a/src/tracing/esp32_trace/include/matter/tracing/macros_impl.h b/src/tracing/esp32_trace/include/matter/tracing/macros_impl.h
index 4d8a8a2..b95c207 100644
--- a/src/tracing/esp32_trace/include/matter/tracing/macros_impl.h
+++ b/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 {
diff --git a/src/tracing/json/json_tracing.cpp b/src/tracing/json/json_tracing.cpp
index 6c651b3..af66e12 100644
--- a/src/tracing/json/json_tracing.cpp
+++ b/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 @@
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;
diff --git a/src/tracing/json/json_tracing.h b/src/tracing/json/json_tracing.h
index 74451b7..302c4bd 100644
--- a/src/tracing/json/json_tracing.h
+++ b/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 @@
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 @@
/// 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;
diff --git a/src/tracing/macros.h b/src/tracing/macros.h
index 5f836e4..b456137 100644
--- a/src/tracing/macros.h
+++ b/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__)
diff --git a/src/tracing/multiplexed/include/matter/tracing/macros_impl.h b/src/tracing/multiplexed/include/matter/tracing/macros_impl.h
index e1f2adc..8b3e728 100644
--- a/src/tracing/multiplexed/include/matter/tracing/macros_impl.h
+++ b/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 {
diff --git a/src/tracing/none/include/matter/tracing/macros_impl.h b/src/tracing/none/include/matter/tracing/macros_impl.h
index 3f7f052..3119dce 100644
--- a/src/tracing/none/include/matter/tracing/macros_impl.h
+++ b/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__)
diff --git a/src/tracing/perfetto/include/matter/tracing/macros_impl.h b/src/tracing/perfetto/include/matter/tracing/macros_impl.h
index 266ac69..9b05d2f 100644
--- a/src/tracing/perfetto/include/matter/tracing/macros_impl.h
+++ b/src/tracing/perfetto/include/matter/tracing/macros_impl.h
@@ -30,3 +30,10 @@
#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)
diff --git a/src/tracing/perfetto/perfetto_tracing.cpp b/src/tracing/perfetto/perfetto_tracing.cpp
index 6d89dbb..b68ec33 100644
--- a/src/tracing/perfetto/perfetto_tracing.cpp
+++ b/src/tracing/perfetto/perfetto_tracing.cpp
@@ -21,10 +21,9 @@
#include <lib/address_resolve/TracingStructs.h>
#include <lib/core/ErrorStr.h>
#include <lib/support/StringBuilder.h>
-#include <transport/TracingStructs.h>
-
#include <matter/tracing/macros_impl.h>
#include <perfetto.h>
+#include <transport/TracingStructs.h>
namespace chip {
namespace Tracing {
diff --git a/src/tracing/registry.cpp b/src/tracing/registry.cpp
index 9f7507a..7c43442 100644
--- a/src/tracing/registry.cpp
+++ b/src/tracing/registry.cpp
@@ -76,6 +76,14 @@
}
}
+void Counter(const char * label)
+{
+ for (auto & backend : gTracingBackends)
+ {
+ backend.TraceCounter(label);
+ }
+}
+
void LogMessageSend(::chip::Tracing::MessageSendInfo & info)
{
for (auto & backend : gTracingBackends)
diff --git a/src/tracing/registry.h b/src/tracing/registry.h
index 8533725..083ebcb 100644
--- a/src/tracing/registry.h
+++ b/src/tracing/registry.h
@@ -76,6 +76,7 @@
void Begin(const char * label, const char * group);
void End(const char * label, const char * group);
void Instant(const char * label, const char * group);
+void Counter(const char * label);
void LogMessageSend(::chip::Tracing::MessageSendInfo & info);
void LogMessageReceived(::chip::Tracing::MessageReceivedInfo & info);
