diff --git a/scripts/tools/check_includes_config.py b/scripts/tools/check_includes_config.py index b4e933f193583c..42920c4014c133 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 d701d8c568c584..2ad196a31b9461 100644 --- a/src/protocols/secure_channel/CASEServer.cpp +++ b/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(); } diff --git a/src/protocols/secure_channel/CASESession.cpp b/src/protocols/secure_channel/CASESession.cpp index 8573d1565686fe..1d6cb27138a496 100644 --- a/src/protocols/secure_channel/CASESession.cpp +++ b/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::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 67da1d103ebf83..980a30de79ec1e 100644 --- a/src/protocols/secure_channel/PASESession.cpp +++ b/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); } diff --git a/src/tracing/backend.h b/src/tracing/backend.h index 7e04490e333ff7..3d8bec8ada501f 100644 --- a/src/tracing/backend.h +++ b/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"); } diff --git a/src/tracing/esp32_trace/BUILD.gn b/src/tracing/esp32_trace/BUILD.gn index 7548894ab072ce..294cf1f5dc160b 100644 --- a/src/tracing/esp32_trace/BUILD.gn +++ b/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") { diff --git a/src/tracing/esp32_trace/counter.cpp b/src/tracing/esp32_trace/counter.cpp new file mode 100644 index 00000000000000..0b315a87007484 --- /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 +#include + +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 00000000000000..bfa6205c341a13 --- /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 +#include +#include +#include +#include + +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 7a1313089703f2..7937772606eec0 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 #include #include #include #include #include +#include +#include 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); diff --git a/src/tracing/esp32_trace/esp32_tracing.h b/src/tracing/esp32_trace/esp32_tracing.h index 7fe783d817d8d8..6d9a277e06561d 100644 --- a/src/tracing/esp32_trace/esp32_tracing.h +++ b/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; 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 4d8a8a2a214525..b95c20754237a1 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 6c651b3190b485..af66e12a61a50b 100644 --- a/src/tracing/json/json_tracing.cpp +++ b/src/tracing/json/json_tracing.cpp @@ -23,9 +23,8 @@ #include #include #include -#include - #include +#include #include @@ -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; diff --git a/src/tracing/json/json_tracing.h b/src/tracing/json/json_tracing.h index 74451b705b73e0..302c4bd5b5a485 100644 --- a/src/tracing/json/json_tracing.h +++ b/src/tracing/json/json_tracing.h @@ -19,6 +19,7 @@ #include #include +#include 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 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 5f836e44d373bc..b456137b88a166 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 e1f2adc56d989e..8b3e728289dc1d 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 3f7f052b5cac0d..3119dce2a2b49f 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 266ac69f5735a0..9b05d2f3539a45 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 @@ 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) diff --git a/src/tracing/perfetto/perfetto_tracing.cpp b/src/tracing/perfetto/perfetto_tracing.cpp index 6d89dbbccc9723..b68ec33d33101d 100644 --- a/src/tracing/perfetto/perfetto_tracing.cpp +++ b/src/tracing/perfetto/perfetto_tracing.cpp @@ -21,10 +21,9 @@ #include #include #include -#include - #include #include +#include namespace chip { namespace Tracing { diff --git a/src/tracing/registry.cpp b/src/tracing/registry.cpp index 9f7507aa9f75a6..7c43442b5b83db 100644 --- a/src/tracing/registry.cpp +++ b/src/tracing/registry.cpp @@ -76,6 +76,14 @@ void Instant(const char * label, const char * group) } } +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 853372585840fa..083ebcb2225ad2 100644 --- a/src/tracing/registry.h +++ b/src/tracing/registry.h @@ -76,6 +76,7 @@ namespace Internal { 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);