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

@@ -37,7 +37,9 @@
 
 #include <lib/support/CodeUtils.h>
 
+#include <lib/support/Span.h>
 #include <platform/CHIPDeviceLayer.h>
+#include <platform/silabs/tracing/SilabsTracingMacros.h>
 
 #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

examples/platform/silabs/shell/tracing/TracingShellCommands.cpp

@@ -18,6 +18,7 @@
 #include <lib/shell/Command.h>
 #include <lib/shell/Engine.h>
 #include <lib/shell/commands/Help.h>
+#include <lib/support/Span.h>
 #include <platform/silabs/tracing/SilabsTracing.h>
 
 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<size_t>(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<TimeTraceOperation>(i)));
+        streamer_printf(streamer_get(), "Operation: %s\r\n", Tracing::Silabs::TimeTraceOperationToString(i));
     }
     return CHIP_NO_ERROR;
 }
@@ -166,27 +171,38 @@ 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;
 }
 
 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;
 }

src/platform/silabs/tracing/BUILD.gn

@@ -24,6 +24,8 @@ static_library("SilabsTracing") {
     "BackendImpl.h",
     "SilabsTracing.cpp",
     "SilabsTracing.h",
+    "SilabsTracingMacros.h",
+    "SilabsTracingTypes.h",
   ]
 
   deps = [

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<TimeTraceOperation>(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,15 +247,31 @@ 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);
 }
 
 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<chip::SingleLinkedListNode<TimeTracker> *>(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

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

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