Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Adding a counter trace macro to the tracing for getting insights from counters in chip and implemented the macro for ESP32 platform... #30591

Merged
merged 11 commits into from
Feb 2, 2024
Merged
2 changes: 1 addition & 1 deletion scripts/tools/check_includes_config.py
Original file line number Diff line number Diff line change
Expand Up @@ -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'},
Expand Down
1 change: 1 addition & 0 deletions src/protocols/secure_channel/CASEServer.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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();
}

Expand Down
5 changes: 5 additions & 0 deletions src/protocols/secure_channel/CASESession.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -1100,6 +1102,7 @@ CHIP_ERROR CASESession::SendSigma2()
mState = State::kSentSigma2;

ChipLogProgress(SecureChannel, "Sent Sigma2 msg");
MATTER_TRACE_COUNTER("Sigma2");

return CHIP_NO_ERROR;
}
Expand All @@ -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];

Expand Down Expand Up @@ -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);
Expand Down
5 changes: 5 additions & 0 deletions src/protocols/secure_channel/PASESession.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -620,6 +622,7 @@ CHIP_ERROR PASESession::HandleMsg1_and_SendMsg2(System::PacketBufferHandle && ms
}

ChipLogDetail(SecureChannel, "Sent spake2p msg2");
MATTER_TRACE_COUNTER("Pake2");

exit:

Expand Down Expand Up @@ -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();

Expand Down Expand Up @@ -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);
}
Expand Down
1 change: 1 addition & 0 deletions src/tracing/backend.h
Original file line number Diff line number Diff line change
Expand Up @@ -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"); }

Expand Down
7 changes: 6 additions & 1 deletion src/tracing/esp32_trace/BUILD.gn
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,8 @@ static_library("backend") {
output_dir = "${root_out_dir}/lib"

sources = [
"counter.cpp",
"counter.h",
"esp32_tracing.cpp",
"esp32_tracing.h",
]
Expand All @@ -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") {
Expand Down
72 changes: 72 additions & 0 deletions src/tracing/esp32_trace/counter.cpp
Original file line number Diff line number Diff line change
@@ -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;
andy31415 marked this conversation as resolved.
Show resolved Hide resolved

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;
andy31415 marked this conversation as resolved.
Show resolved Hide resolved
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
55 changes: 55 additions & 0 deletions src/tracing/esp32_trace/counter.h
Original file line number Diff line number Diff line change
@@ -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
andy31415 marked this conversation as resolved.
Show resolved Hide resolved
{
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
7 changes: 6 additions & 1 deletion src/tracing/esp32_trace/esp32_tracing.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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);
Expand Down
2 changes: 2 additions & 0 deletions src/tracing/esp32_trace/esp32_tracing.h
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
23 changes: 21 additions & 2 deletions src/tracing/json/json_tracing.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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>

Expand Down Expand Up @@ -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;
Expand Down
4 changes: 4 additions & 0 deletions src/tracing/json/json_tracing.h
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@

#include <fstream>
#include <tracing/backend.h>
#include <unordered_map>

namespace Json {
class Value;
Expand Down Expand Up @@ -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;
Expand All @@ -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;
Expand Down
1 change: 1 addition & 0 deletions src/tracing/macros.h
Original file line number Diff line number Diff line change
Expand Up @@ -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__)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
1 change: 1 addition & 0 deletions src/tracing/none/include/matter/tracing/macros_impl.h
Original file line number Diff line number Diff line change
Expand Up @@ -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__)
7 changes: 7 additions & 0 deletions src/tracing/perfetto/include/matter/tracing/macros_impl.h
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Loading
Loading