From 117d3b61115e5de73017b10b2bedecd7908caf65 Mon Sep 17 00:00:00 2001 From: lpbeliveau-silabs Date: Tue, 3 Dec 2024 18:17:20 -0500 Subject: [PATCH] Added API for apps to register custom event to trace. Currently only supports instant trace, could be made to support begin and end if need be. Need to update SilabsTracingMacros and integrate in lighting/zigbee matter app for POC Integrated app specific log for Light On on bootup in lighting app --- examples/lighting-app/silabs/src/AppTask.cpp | 7 +- .../shell/tracing/TracingShellCommands.cpp | 28 ++++-- src/platform/silabs/tracing/BUILD.gn | 2 + src/platform/silabs/tracing/SilabsTracing.cpp | 86 +++++++++++++++-- src/platform/silabs/tracing/SilabsTracing.h | 48 ++++++++-- .../silabs/tracing/SilabsTracingMacros.h | 3 + src/platform/tests/TestSilabsTracing.cpp | 96 +++++++++++++++---- 7 files changed, 234 insertions(+), 36 deletions(-) diff --git a/examples/lighting-app/silabs/src/AppTask.cpp b/examples/lighting-app/silabs/src/AppTask.cpp index 852163087d..ea0c8e1010 100644 --- a/examples/lighting-app/silabs/src/AppTask.cpp +++ b/examples/lighting-app/silabs/src/AppTask.cpp @@ -37,7 +37,9 @@ #include +#include #include +#include #ifdef SL_CATALOG_SIMPLE_LED_LED1_PRESENT #define LIGHT_LED 1 @@ -66,7 +68,9 @@ CHIP_ERROR AppTask::Init() { CHIP_ERROR err = CHIP_NO_ERROR; chip::DeviceLayer::Silabs::GetPlatform().SetButtonsCb(AppTask::ButtonEventHandler); - + char rebootLightOnKey[] = "Reboot->LightOn"; + CharSpan rebootLighOnSpan(rebootLightOnKey); + SILABS_TRACE_REGISTER(rebootLighOnSpan); #ifdef DISPLAY_ENABLED GetLCD().Init((uint8_t *) "Lighting-App"); #endif @@ -89,6 +93,7 @@ CHIP_ERROR AppTask::Init() sLightLED.Init(LIGHT_LED); sLightLED.Set(LightMgr().IsLightOn()); + SILABS_TRACE_INSTANT(rebootLighOnSpan); // Update the LCD with the Stored value. Show QR Code if not provisioned #ifdef DISPLAY_ENABLED diff --git a/examples/platform/silabs/shell/tracing/TracingShellCommands.cpp b/examples/platform/silabs/shell/tracing/TracingShellCommands.cpp index 7bfe89cbea..ebdf62f8d0 100644 --- a/examples/platform/silabs/shell/tracing/TracingShellCommands.cpp +++ b/examples/platform/silabs/shell/tracing/TracingShellCommands.cpp @@ -18,6 +18,7 @@ #include #include #include +#include #include using namespace chip; @@ -29,6 +30,7 @@ using Shell::streamer_printf; namespace { using TimeTraceOperation = Tracing::Silabs::TimeTraceOperation; +using SilabsTracer = Tracing::Silabs::SilabsTracer; TimeTraceOperation StringToTimeTraceOperation(const char * str) { @@ -144,9 +146,12 @@ CHIP_ERROR TracingHelpHandler(int argc, char ** argv) CHIP_ERROR TracingListTimeOperations(int argc, char ** argv) { - for (size_t i = 0; i < static_cast(TimeTraceOperation::kNumTraces); ++i) + + size_t TotalTraceNumber = + to_underlying(TimeTraceOperation::kNumTraces) + SilabsTracer::Instance().GetRegisteredAppOperationsCount(); + for (size_t i = 0; i < TotalTraceNumber; ++i) { - streamer_printf(streamer_get(), "Operation: %s\r\n", TimeTraceOperationToString(static_cast(i))); + streamer_printf(streamer_get(), "Operation: %s\r\n", Tracing::Silabs::TimeTraceOperationToString(i)); } return CHIP_NO_ERROR; } @@ -166,12 +171,12 @@ CHIP_ERROR WatermarksCommandHandler(int argc, char ** argv) CHIP_ERROR error = CHIP_NO_ERROR; if (strcmp(argv[0], "all") == 0) { - error = Tracing::Silabs::SilabsTracer::Instance().OutputAllWaterMarks(); + error = SilabsTracer::Instance().OutputAllWaterMarks(); } else { TimeTraceOperation operation = StringToTimeTraceOperation(argv[0]); - error = Tracing::Silabs::SilabsTracer::Instance().OutputWaterMark(operation); + error = SilabsTracer::Instance().OutputWaterMark(operation); } return error; } @@ -179,14 +184,25 @@ CHIP_ERROR WatermarksCommandHandler(int argc, char ** argv) CHIP_ERROR FlushCommandHandler(int argc, char ** argv) { CHIP_ERROR error = CHIP_NO_ERROR; + size_t index; + CharSpan opKey(argv[0], sizeof(argv[0])); if (strcmp(argv[0], "all") == 0) { - error = Tracing::Silabs::SilabsTracer::Instance().TraceBufferFlushAll(); + error = SilabsTracer::Instance().TraceBufferFlushAll(); + } + else if (CHIP_NO_ERROR == SilabsTracer::Instance().FindAppOperationIndex(opKey, index)) + { + SilabsTracer::Instance().TraceBufferFlushByOperation(opKey); } else { TimeTraceOperation operation = StringToTimeTraceOperation(argv[0]); - error = Tracing::Silabs::SilabsTracer::Instance().TraceBufferFlushByOperation(operation); + if (operation == TimeTraceOperation::kNumTraces) + { + streamer_printf(streamer_get(), "Unknown Operation Key\r\n"); + return CHIP_ERROR_INVALID_ARGUMENT; + } + error = SilabsTracer::Instance().TraceBufferFlushByOperation(to_underlying(operation)); } return error; } diff --git a/src/platform/silabs/tracing/BUILD.gn b/src/platform/silabs/tracing/BUILD.gn index 2c144fae04..09132f7267 100644 --- a/src/platform/silabs/tracing/BUILD.gn +++ b/src/platform/silabs/tracing/BUILD.gn @@ -24,6 +24,8 @@ static_library("SilabsTracing") { "BackendImpl.h", "SilabsTracing.cpp", "SilabsTracing.h", + "SilabsTracingMacros.h", + "SilabsTracingTypes.h", ] deps = [ diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp index 91788b1829..2001d7bf19 100644 --- a/src/platform/silabs/tracing/SilabsTracing.cpp +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -93,6 +93,20 @@ const char * TimeTraceOperationToString(TimeTraceOperation operation) } } +const char * TimeTraceOperationToString(size_t operation) +{ + if (operation >= to_underlying(TimeTraceOperation::kNumTraces)) + { + size_t index = operation - to_underlying(TimeTraceOperation::kNumTraces); + VerifyOrReturnValue(index < SilabsTracer::kMaxAppOperationKeys, "Unknown"); + return SilabsTracer::Instance().GetAppOperationKey(index); + } + else + { + return TimeTraceOperationToString(static_cast(operation)); + } +} + const char * OperationTypeToString(OperationType type) { switch (type) @@ -181,7 +195,7 @@ CHIP_ERROR SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) // Log the start time of the operation auto & tracker = mLatestTimeTrackers[to_underlying(aOperation)]; tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); - tracker.mOperation = aOperation; + tracker.mOperation = to_underlying(aOperation); tracker.mType = OperationType::kBegin; tracker.mError = CHIP_NO_ERROR; @@ -233,7 +247,23 @@ CHIP_ERROR SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ER TimeTracker tracker; tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); tracker.mEndTime = tracker.mStartTime; - tracker.mOperation = aOperation; + tracker.mOperation = to_underlying(aOperation); + tracker.mType = OperationType::kInstant; + tracker.mError = error; + return OutputTrace(tracker); +} + +CHIP_ERROR SilabsTracer::TimeTraceInstant(CharSpan & aOperationKey, CHIP_ERROR error) +{ + + VerifyOrReturnError(aOperationKey.size() <= kMaxAppOperationKeyLength, CHIP_ERROR_BUFFER_TOO_SMALL); + size_t index = 0; + ReturnErrorOnFailure(FindAppOperationIndex(aOperationKey, index)); + + TimeTracker tracker; + tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); + tracker.mEndTime = tracker.mStartTime; + tracker.mOperation = to_underlying(TimeTraceOperation::kNumTraces) + index; tracker.mType = OperationType::kInstant; tracker.mError = error; return OutputTrace(tracker); @@ -241,7 +271,7 @@ CHIP_ERROR SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ER CHIP_ERROR SilabsTracer::OutputTimeTracker(const TimeTracker & tracker) { - VerifyOrReturnError(to_underlying(tracker.mOperation) < kNumTraces, CHIP_ERROR_INVALID_ARGUMENT, + VerifyOrReturnError(tracker.mOperation < kNumTraces + kMaxAppOperationKeys, CHIP_ERROR_INVALID_ARGUMENT, ChipLogError(DeviceLayer, "Invalid tracker")); VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED); // Allocate a buffer to store the trace @@ -268,7 +298,7 @@ CHIP_ERROR SilabsTracer::OutputTrace(const TimeTracker & tracker) TimeTracker resourceExhaustedTracker = tracker; resourceExhaustedTracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); resourceExhaustedTracker.mEndTime = resourceExhaustedTracker.mStartTime; - resourceExhaustedTracker.mOperation = TimeTraceOperation::kBufferFull; + resourceExhaustedTracker.mOperation = to_underlying(TimeTraceOperation::kBufferFull); resourceExhaustedTracker.mType = OperationType::kInstant; resourceExhaustedTracker.mError = CHIP_ERROR_BUFFER_TOO_SMALL; mTimeTrackerList.Insert(resourceExhaustedTracker); @@ -328,9 +358,9 @@ CHIP_ERROR SilabsTracer::TraceBufferFlushAll() return CHIP_NO_ERROR; } -CHIP_ERROR SilabsTracer::TraceBufferFlushByOperation(TimeTraceOperation aOperation) +CHIP_ERROR SilabsTracer::TraceBufferFlushByOperation(size_t aOperation) { - VerifyOrReturnError(to_underlying(aOperation) < kNumTraces, CHIP_ERROR_INVALID_ARGUMENT, + VerifyOrReturnError(aOperation < kNumTraces + kMaxAppOperationKeys, CHIP_ERROR_INVALID_ARGUMENT, ChipLogError(DeviceLayer, "Invalid TimeTraceOperation")); auto * current = mTimeTrackerList.head; auto * prev = static_cast *>(nullptr); @@ -362,6 +392,13 @@ CHIP_ERROR SilabsTracer::TraceBufferFlushByOperation(TimeTraceOperation aOperati return CHIP_NO_ERROR; } +CHIP_ERROR SilabsTracer::TraceBufferFlushByOperation(CharSpan & appOperationKey) +{ + size_t index = 0; + ReturnErrorOnFailure(FindAppOperationIndex(appOperationKey, index)); + return SilabsTracer::Instance().TraceBufferFlushByOperation(index + to_underlying(TimeTraceOperation::kNumTraces)); +} + // Save the traces in the NVM CHIP_ERROR SilabsTracer::SaveWatermarks() { @@ -377,7 +414,7 @@ CHIP_ERROR SilabsTracer::LoadWatermarks() return CHIP_NO_ERROR; } -CHIP_ERROR SilabsTracer::GetTraceByOperation(TimeTraceOperation aOperation, MutableByteSpan & buffer) const +CHIP_ERROR SilabsTracer::GetTraceByOperation(size_t aOperation, MutableByteSpan & buffer) const { auto * current = mTimeTrackerList.head; while (current != nullptr) @@ -405,6 +442,41 @@ CHIP_ERROR SilabsTracer::GetTraceByOperation(TimeTraceOperation aOperation, Muta return CHIP_ERROR_NOT_FOUND; } +CHIP_ERROR SilabsTracer::GetTraceByOperation(CharSpan & appOperationKey, MutableByteSpan & buffer) const +{ + size_t index = 0; + ReturnErrorOnFailure(FindAppOperationIndex(appOperationKey, index)); + return GetTraceByOperation(index + to_underlying(TimeTraceOperation::kNumTraces), buffer); +} + +CHIP_ERROR SilabsTracer::RegisterAppTimeTraceOperation(CharSpan & appOperationKey) +{ + VerifyOrReturnError(appOperationKey.size() <= kMaxAppOperationKeyLength, CHIP_ERROR_BUFFER_TOO_SMALL); + VerifyOrReturnError(mAppOperationKeyCount < kMaxAppOperationKeys, CHIP_ERROR_NO_MEMORY); + VerifyOrReturnError(appOperationKey.data() != nullptr, CHIP_ERROR_INVALID_ARGUMENT); + // Verify the key is not already in the array + size_t index = 0; + VerifyOrReturnError(CHIP_ERROR_NOT_FOUND == FindAppOperationIndex(appOperationKey, index), CHIP_ERROR_INVALID_ARGUMENT); + + memcpy(mAppOperationKeys[mAppOperationKeyCount], appOperationKey.data(), appOperationKey.size()); + mAppOperationKeyCount++; + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::FindAppOperationIndex(CharSpan & appOperationKey, size_t & index) const +{ + for (size_t i = 0; i < mAppOperationKeyCount; ++i) + { + if (strncmp(mAppOperationKeys[i], appOperationKey.data(), appOperationKey.size()) == 0) + { + index = i; + return CHIP_NO_ERROR; + } + } + index = SilabsTracer::kMaxAppOperationKeys; + return CHIP_ERROR_NOT_FOUND; +} + } // namespace Silabs } // namespace Tracing } // namespace chip diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h index d8147c4c2b..fb46cdd901 100644 --- a/src/platform/silabs/tracing/SilabsTracing.h +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -42,7 +42,7 @@ struct TimeTracker // Temporary values System::Clock::Milliseconds32 mStartTime; System::Clock::Milliseconds32 mEndTime; - TimeTraceOperation mOperation; + size_t mOperation; OperationType mType; CHIP_ERROR mError; @@ -80,9 +80,11 @@ struct Watermark class SilabsTracer { public: - static constexpr size_t kNumTraces = to_underlying(TimeTraceOperation::kNumTraces); - static constexpr size_t kMaxBufferedTraces = 64; - static constexpr size_t kMaxTraceSize = 128; + static constexpr size_t kNumTraces = to_underlying(TimeTraceOperation::kNumTraces); + static constexpr size_t kMaxAppOperationKeys = 5; + static constexpr size_t kMaxAppOperationKeyLength = 16; + static constexpr size_t kMaxBufferedTraces = 64; + static constexpr size_t kMaxTraceSize = 128; /** @brief Get the singleton instance of SilabsTracer */ static SilabsTracer & Instance() { return sInstance; } @@ -130,6 +132,12 @@ class SilabsTracer { return TimeTraceInstant(aOperation, ChipError((error))); } + /** @brief TimeTraceInstant + * We currently allow to register App specific operations to be tracked by the time tracer, but only for instant traces, and + * not for watermarks. + * @param appOperation The name of the app operation key to generate a trace for + */ + CHIP_ERROR TimeTraceInstant(CharSpan & appOperationKey, CHIP_ERROR error = CHIP_NO_ERROR); /** @brief Output a time tracker * This will output the latest time tracker for a specific operation, without affecting the buffer. @@ -162,7 +170,8 @@ class SilabsTracer * @param aOperation The operation to flush traces for * @return CHIP_ERROR, returns CHIP_ERROR_UNINITIALIZED if the logs are not initialized */ - CHIP_ERROR TraceBufferFlushByOperation(TimeTraceOperation aOperation); + CHIP_ERROR TraceBufferFlushByOperation(size_t aOperation); + CHIP_ERROR TraceBufferFlushByOperation(CharSpan & appOperationKey); // prevent copy constructor and assignment operator SilabsTracer(SilabsTracer const &) = delete; @@ -192,7 +201,29 @@ class SilabsTracer */ Watermark GetWatermark(TimeTraceOperation aOperation) { return mWatermarks[to_underlying(aOperation)]; } size_t GetTimeTracesCount() { return mBufferedTrackerCount; } - CHIP_ERROR GetTraceByOperation(TimeTraceOperation aOperation, MutableByteSpan & buffer) const; + + CHIP_ERROR GetTraceByOperation(size_t aOperation, MutableByteSpan & buffer) const; + CHIP_ERROR GetTraceByOperation(CharSpan & appOperationKey, MutableByteSpan & buffer) const; + + /** @brief Register an App specific time trace operation + * This will register an App specific operation to be tracked by the time tracer. The string will be mapped to a + * TimeTraceOperation higher than the kNumTraces value. + * @param appOperationKey The key of the custom operation, can only be in the array once + * @return CHIP_ERROR, returns CHIP_ERROR_BUFFER_TOO_SMALL if the key is too long, CHIP_ERROR_NO_MEMORY if the buffer is full, + * and CHIP_ERROR_INVALID_ARGUMENT if the key is null or already in the array. + */ + CHIP_ERROR RegisterAppTimeTraceOperation(CharSpan & appOperationKey); + + /** @brief Find the index of a custom operation + * @param appOperation The key of the custom operation to find + * @param index The index of the custom operation + * @return CHIP_ERROR, returns CHIP_ERROR_NOT_FOUND if the buffer is full, the index will be set to the maximum number of + * custom operations if the operationis not found + */ + CHIP_ERROR FindAppOperationIndex(CharSpan & appOperationKey, size_t & index) const; + + inline size_t GetRegisteredAppOperationsCount() { return mAppOperationKeyCount; } + inline char * GetAppOperationKey(size_t index) { return mAppOperationKeys[index]; } private: struct TimeTrackerList @@ -254,6 +285,10 @@ class SilabsTracer size_t mBufferedTrackerCount = 0; + // App specific Operation keys buffer + char mAppOperationKeys[SilabsTracer::kMaxAppOperationKeys][SilabsTracer::kMaxAppOperationKeyLength]; + size_t mAppOperationKeyCount = 0; + /** @brief Clear the trace buffer */ void TraceBufferClear(); @@ -268,6 +303,7 @@ class SilabsTracer }; const char * TimeTraceOperationToString(TimeTraceOperation operation); +const char * TimeTraceOperationToString(size_t operation); } // namespace Silabs } // namespace Tracing diff --git a/src/platform/silabs/tracing/SilabsTracingMacros.h b/src/platform/silabs/tracing/SilabsTracingMacros.h index e1ba1a8fc2..83a4369c63 100644 --- a/src/platform/silabs/tracing/SilabsTracingMacros.h +++ b/src/platform/silabs/tracing/SilabsTracingMacros.h @@ -47,6 +47,8 @@ ::chip::Tracing::Silabs::SilabsTracer::Instance().TimeTraceInstant(operation, error) #define SILABS_TRACE_FLUSH_ALL() ::chip::Tracing::Silabs::SilabsTracer::Instance().TraceBufferFlushAll() +#define SILABS_TRACE_REGISTER(operationKey) \ + ::chip::Tracing::Silabs::SilabsTracer::Instance().RegisterAppTimeTraceOperation(operationKey) #else // MATTER_TRACING_ENABLED @@ -63,5 +65,6 @@ #define SILABS_TRACE_INSTANT_ERROR(operation, error) _MATTER_TRACE_DISABLE(operation, error) #define SILABS_TRACE_FLUSH_ALL() _MATTER_TRACE_DISABLE() +#define SILABS_TRACE_REGISTER(operationKey) _MATTER_TRACE_DISABLE(operationKey) #endif // MATTER_TRACING_ENABLED diff --git a/src/platform/tests/TestSilabsTracing.cpp b/src/platform/tests/TestSilabsTracing.cpp index f4a34985fa..0c09c6afd7 100644 --- a/src/platform/tests/TestSilabsTracing.cpp +++ b/src/platform/tests/TestSilabsTracing.cpp @@ -660,19 +660,19 @@ TEST_F(TestSilabsTracing, TestLogs) traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 4u); // 4 calls: 2 TimeTraceBegin and 2 TimeTraceEnd - // Verify the output logs using GetTraceByOperation + // Verify the output logs using Operation uint8_t logBuffer[256]; MutableByteSpan span(logBuffer); // Verify OTA log - EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, span), CHIP_NO_ERROR); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kOTA), span), CHIP_NO_ERROR); const char * expectedOTALogFormat = "TimeTracker - Type: End, Operation: OTA, Status: 0x0, StartTime: 0, EndTime: 100, Duration: 100 ms"; EXPECT_STREQ(reinterpret_cast(span.data()), expectedOTALogFormat); // Verify Bootup log span = MutableByteSpan(logBuffer); - EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, span), CHIP_NO_ERROR); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kBootup), span), CHIP_NO_ERROR); const char * expectedBootupLogFormat = "TimeTracker - Type: End, Operation: Bootup, Status: 0x0, StartTime: 100, EndTime: 300, Duration: 200 ms"; EXPECT_STREQ(reinterpret_cast(span.data()), expectedBootupLogFormat); @@ -680,21 +680,22 @@ TEST_F(TestSilabsTracing, TestLogs) // Test buffer too small behavior uint8_t smallBuffer[10]; MutableByteSpan smallSpan(smallBuffer); - EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, smallSpan), CHIP_ERROR_BUFFER_TOO_SMALL); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kOTA), smallSpan), + CHIP_ERROR_BUFFER_TOO_SMALL); // Test TraceBufferFlushByOperation - EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(TimeTraceOperation::kOTA), CHIP_NO_ERROR); + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(to_underlying(TimeTraceOperation::kOTA)), CHIP_NO_ERROR); traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 2u); // Only Bootup traces should remain // Verify Bootup log still exists span = MutableByteSpan(logBuffer); - EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, span), CHIP_NO_ERROR); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kBootup), span), CHIP_NO_ERROR); EXPECT_STREQ(reinterpret_cast(span.data()), expectedBootupLogFormat); // Verify OTA log is removed span = MutableByteSpan(logBuffer); - EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, span), CHIP_ERROR_NOT_FOUND); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kOTA), span), CHIP_ERROR_NOT_FOUND); // Test TraceBufferFlushAll EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushAll(), CHIP_NO_ERROR); @@ -703,9 +704,9 @@ TEST_F(TestSilabsTracing, TestLogs) // Verify no logs exist span = MutableByteSpan(logBuffer); - EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, span), CHIP_ERROR_NOT_FOUND); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kBootup), span), CHIP_ERROR_NOT_FOUND); span = MutableByteSpan(logBuffer); - EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, span), CHIP_ERROR_NOT_FOUND); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kOTA), span), CHIP_ERROR_NOT_FOUND); } TEST_F(TestSilabsTracing, TestBufferBusting) @@ -732,33 +733,96 @@ TEST_F(TestSilabsTracing, TestBufferBusting) EXPECT_EQ(SilabsTracer::kMaxBufferedTraces, SilabsTracer::Instance().GetTimeTracesCount()); uint8_t logBuffer[256]; MutableByteSpan logSpan(logBuffer); - EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBufferFull, logSpan), CHIP_NO_ERROR); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kBufferFull), logSpan), CHIP_NO_ERROR); const char * expectedNumLogFormat = "TimeTracker - Type: Instant, Operation: BufferFull, Status: 0x19, EventTime: 6200"; EXPECT_STREQ(reinterpret_cast(logSpan.data()), expectedNumLogFormat); // Verify the kImageUpload operation was not added - EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kImageUpload, logSpan), CHIP_ERROR_NOT_FOUND); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kImageUpload), logSpan), + CHIP_ERROR_NOT_FOUND); // Flush kOTA operation - EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(TimeTraceOperation::kOTA), CHIP_NO_ERROR); + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(to_underlying(TimeTraceOperation::kOTA)), CHIP_NO_ERROR); EXPECT_EQ(SilabsTracer::kMaxBufferedTraces - 1, SilabsTracer::Instance().GetTimeTracesCount()); // Verify that adding a new operation still results in a buffer full operation since we are at size -1 EXPECT_EQ(CHIP_ERROR_BUFFER_TOO_SMALL, SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kImageUpload)); - EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kImageUpload, logSpan), CHIP_ERROR_NOT_FOUND); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kImageUpload), logSpan), + CHIP_ERROR_NOT_FOUND); // Flush the overflow operations - EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(TimeTraceOperation::kBufferFull), CHIP_NO_ERROR); + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(to_underlying(TimeTraceOperation::kBufferFull)), CHIP_NO_ERROR); EXPECT_EQ(SilabsTracer::kMaxBufferedTraces - 2, SilabsTracer::Instance().GetTimeTracesCount()); // Verify that adding a new operation now succeeds EXPECT_EQ(CHIP_NO_ERROR, SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kImageUpload)); - EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kImageUpload, logSpan), CHIP_NO_ERROR); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kImageUpload), logSpan), + CHIP_NO_ERROR); // Verify that the buffer full operation is removed - EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBufferFull, logSpan), CHIP_ERROR_NOT_FOUND); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kBufferFull), logSpan), + CHIP_ERROR_NOT_FOUND); // Flush all operations EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushAll(), CHIP_NO_ERROR); EXPECT_EQ(0u, SilabsTracer::Instance().GetTimeTracesCount()); } + +TEST_F(TestSilabsTracing, TestAppSpecificTraces) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + size_t traceCount = 0; + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + EXPECT_EQ(traceCount, 0u); + + char appSpecificTrace1[SilabsTracer::kMaxAppOperationKeyLength] = "AppTrace"; + CharSpan appSpecificSpan(appSpecificTrace1); + appSpecificSpan.reduce_size(sizeof("AppTrace")); + // Simulate registering an app specific trace + EXPECT_EQ(SilabsTracer::Instance().RegisterAppTimeTraceOperation(appSpecificSpan), CHIP_NO_ERROR); + + // Simulate an an instant trace for the app specific trace + EXPECT_EQ(SilabsTracer::Instance().TimeTraceInstant(appSpecificSpan), CHIP_NO_ERROR); + + // Veryify the app specific trace is added in the buffer by finding its index + size_t appSpecificIndex; + SilabsTracer::Instance().FindAppOperationIndex(appSpecificSpan, appSpecificIndex); + EXPECT_EQ(appSpecificIndex, 0u); + + // Create a second app specific trace + char appSpecificTrace2[SilabsTracer::kMaxAppOperationKeyLength] = "AppTrace2"; + CharSpan appSpecificSpan2(appSpecificTrace2); + // Verify it is not found in the buffer + EXPECT_EQ(CHIP_ERROR_NOT_FOUND, SilabsTracer::Instance().FindAppOperationIndex(appSpecificSpan2, appSpecificIndex)); + EXPECT_EQ(appSpecificIndex, SilabsTracer::kMaxAppOperationKeys); + + // Register the second app specific trace + EXPECT_EQ(SilabsTracer::Instance().RegisterAppTimeTraceOperation(appSpecificSpan2), CHIP_NO_ERROR); + + // Simulate an an instant trace for the second app specific trace + EXPECT_EQ(SilabsTracer::Instance().TimeTraceInstant(appSpecificSpan2), CHIP_NO_ERROR); + + // Verify that the logs match expectation + uint8_t logBuffer[256]; + MutableByteSpan span(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(appSpecificSpan, span), CHIP_NO_ERROR); + const char * expectedAppSpecificLogFormat = "TimeTracker - Type: Instant, Operation: AppTrace, Status: 0x0, EventTime: 0"; + EXPECT_STREQ(reinterpret_cast(span.data()), expectedAppSpecificLogFormat); + + span = MutableByteSpan(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(appSpecificSpan2, span), CHIP_NO_ERROR); + const char * expectedAppSpecificLogFormat2 = "TimeTracker - Type: Instant, Operation: AppTrace2, Status: 0x0, EventTime: 0"; + EXPECT_STREQ(reinterpret_cast(span.data()), expectedAppSpecificLogFormat2); + + // confirm trace count + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + EXPECT_EQ(traceCount, 2u); + // Flush the app specific traces + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(appSpecificSpan), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + EXPECT_EQ(traceCount, 1u); + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(appSpecificSpan2), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + EXPECT_EQ(traceCount, 0u); +}