Initial tracing and test, need to compile from CSA and then to move t…

…ests out of src/platformtests

Initial Silabs Tracing object and unit tests. Next step: create silabs  matter tracing backend object and integrate in our Base App / main

examples/platform/silabs/silabs_utils.h

@@ -24,6 +24,8 @@
 extern "C" {
 #endif
 
+bool isLogInitialized(void);
+
 void silabsInitLog(void);
 
 void silabsLog(const char * aFormat, ...);

src/platform/silabs/Logging.cpp

@@ -200,6 +200,13 @@ extern "C" void silabsLog(const char * aFormat, ...)
     va_end(v);
 }
 
+#ifdef SILABS_LOG_ENABLED
+extern bool isLogInitialized()
+{
+    return sLogInitialized;
+}
+#endif // SILABS_LOG_ENABLED
+
 namespace chip {
 namespace DeviceLayer {
 

src/platform/silabs/tracing/BUILD.gn

@@ -0,0 +1,16 @@
+import("//build_overrides/build.gni")
+import("//build_overrides/chip.gni")
+
+static_library("SilabsTracing") {
+  sources = [
+    "SilabsTracing.cpp",
+    "SilabsTracing.h",
+  ]
+
+  deps = [
+    "${chip_root}/src/lib/core",
+    "${chip_root}/src/lib/support",
+    "${chip_root}/src/platform",
+    "${chip_root}/src/system",
+  ]
+}

src/platform/silabs/tracing/SilabsTracing.cpp

@@ -0,0 +1,164 @@
+#include "SilabsTracing.h"
+#include <cstring>
+#include <lib/support/CodeUtils.h>
+#include <lib/support/PersistentData.h>
+
+#if !CONFIG_BUILD_FOR_HOST_UNIT_TEST
+#include <silabs_utils.h> // for isLogInitialized
+#endif
+
+// The following functions needs to be implemented by the application to allows logging or storing the traces /
+// metrics. If the application does not implement them, the traces will simply be ignored.
+bool __attribute__((weak)) isLogInitialized()
+{
+    return false;
+}
+
+namespace chip {
+namespace Tracing {
+namespace Silabs {
+
+static constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES;
+
+struct TimeTrackerStorage : public TimeTracker, PersistentData<kPersistentTimeTrackerBufferMax>
+{
+    // TODO implement the Persistent Array class and use it here for logging the watermark array
+};
+
+SilabsTracer SilabsTracer::sInstance;
+
+SilabsTracer::SilabsTracer()
+{
+    Init();
+}
+
+void SilabsTracer::Init()
+{
+    // Initialize the trace buffer and time trackers
+    memset(mTraceBuffer, 0, sizeof(mTraceBuffer));
+    memset(mWatermark, 0, sizeof(mWatermark));
+}
+
+CHIP_ERROR SilabsTracer::StartTraceStorage(PersistentStorageDelegate * storage)
+{
+    VerifyOrReturnError(nullptr != storage, CHIP_ERROR_INCORRECT_STATE);
+    mStorage = storage;
+    return CHIP_NO_ERROR;
+}
+
+void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation)
+{
+    // Log the start time of the operation
+    auto & tracker = mWatermark[static_cast<size_t>(aOperation)];
+    tracker.mTotalCount++;
+    tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp();
+}
+
+void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error)
+{
+    if (error != CHIP_NO_ERROR)
+    {
+        // Log the error, no need to update the watermark for now as we can get the error count from the
+        // total count - successfull count. We might want to have a separate count for errors in the future.
+        TimeTraceInstant(aOperation);
+        return;
+    }
+
+    // Calculate the duration and update the time tracker
+    auto & tracker   = mWatermark[static_cast<size_t>(aOperation)];
+    tracker.mEndTime = System::SystemClock().GetMonotonicTimestamp();
+    auto duration    = (tracker.mEndTime - tracker.mStartTime).count();
+
+    tracker.mTotalDuration += System::Clock::Milliseconds64(duration);
+
+    if (duration > tracker.mMaxTimeMs.count())
+    {
+        tracker.mMaxTimeMs = System::Clock::Milliseconds32(duration);
+    }
+
+    if (tracker.mMinTimeMs.count() == 0 || duration < tracker.mMinTimeMs.count())
+    {
+        tracker.mMinTimeMs = System::Clock::Milliseconds32(duration);
+    }
+
+    tracker.mSuccessfullCount++;
+    tracker.mMovingAverage = System::Clock::Milliseconds32(tracker.mTotalDuration.count() / tracker.mSuccessfullCount);
+    if (duration > tracker.mMovingAverage.count())
+    {
+        tracker.mCountAboveAvg++;
+    }
+}
+
+void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error)
+{
+    if (CHIP_NO_ERROR == error)
+    {
+        // Will be used to implement count for instant events that do not require watermarks such as failures and others
+        // For now, just log in that order the timestamp and the operation
+        ChipLogProgress(DeviceLayer, "Time: %llu, Instant Trace: %u, ", System::SystemClock().GetMonotonicTimestamp().count(),
+                        static_cast<uint8_t>(aOperation));
+    }
+    else
+    {
+        // Log the error with timestamp and operation
+        ChipLogError(DeviceLayer, "Time: %llu, Instant Trace: %u, Error: %" CHIP_ERROR_FORMAT,
+                     System::SystemClock().GetMonotonicTimestamp().count(), static_cast<uint8_t>(aOperation), error.Format());
+    }
+}
+
+void SilabsTracer::OutputTraces()
+{
+    if (isLogInitialized())
+    {
+        // Output the traces from the buffer
+        for (size_t i = 0; i < kNumTraces; ++i)
+        {
+            auto & tracker = mWatermark[i];
+            ChipLogProgress(DeviceLayer,
+                            "Trace %zu: TotalCount=%u, SuccessFullCount=%u, MaxTime=%u, MinTime=%u, AvgTime=%u, CountAboveAvg=%u",
+                            i, tracker.mTotalCount, tracker.mSuccessfullCount, tracker.mMaxTimeMs.count(),
+                            tracker.mMinTimeMs.count(), tracker.mMovingAverage.count(), tracker.mCountAboveAvg);
+        }
+    }
+    else
+    {
+        // Buffer the traces if logs are not initialized
+        static size_t bufferIndex = 0;
+        if (bufferIndex < kBufferedTracesNumber - 1)
+        {
+            for (size_t i = 0; i < kNumTraces; ++i)
+            {
+                auto & tracker = mWatermark[i];
+                // TODO use c++ copy string
+                snprintf(reinterpret_cast<char *>(mTraceBuffer[bufferIndex]), kBufferedTraceSize,
+                         "Trace %zu: TotalCount=%u, SuccessFullCount=%u, MaxTime=%u, MinTime=%u, AvgTime=%u, CountAboveAvg=%u", i,
+                         tracker.mTotalCount, tracker.mSuccessfullCount, tracker.mMaxTimeMs.count(), tracker.mMinTimeMs.count(),
+                         tracker.mMovingAverage.count(), tracker.mCountAboveAvg);
+                bufferIndex++;
+            }
+        }
+        else
+        {
+            snprintf(reinterpret_cast<char *>(mTraceBuffer[bufferIndex]), kBufferedTraceSize, "Buffer overflow: logs were lost");
+        }
+    }
+}
+
+// Save the traces in the NVM
+CHIP_ERROR SilabsTracer::SaveWatermarks()
+{
+    VerifyOrReturnError(nullptr != mStorage, CHIP_ERROR_INCORRECT_STATE);
+    // TODO implement the save of the watermarks in the NVM
+    return CHIP_NO_ERROR;
+}
+
+CHIP_ERROR SilabsTracer::LoadWatermarks()
+{
+    VerifyOrReturnError(nullptr != mStorage, CHIP_ERROR_INCORRECT_STATE);
+    // TODO implement the load of the watermarks from the NVM
+    return CHIP_NO_ERROR;
+}
+
+} // namespace Silabs
+} // namespace Tracing
+} // namespace chip

src/platform/silabs/tracing/SilabsTracing.h

@@ -0,0 +1,131 @@
+/*
+ *    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.
+ */
+#pragma once
+
+// #include "silabs_utils.h"
+#include <cstddef>
+#include <lib/core/CHIPError.h>
+#include <lib/core/CHIPPersistentStorageDelegate.h>
+#include <stdint.h>
+#include <system/SystemClock.h>
+
+#ifndef SERIALIZED_TIME_TRACKERS_SIZE_BYTES
+// Default size, watermarks store 6 uint32_t, which is 24 bytes
+// We currently have 19 operations to track, so 19 * 24 = 456 bytes
+// 512 bytes should be enough including the serialization overhead
+#define SERIALIZED_TIME_TRACKERS_SIZE_BYTES 512
+#endif
+
+namespace chip {
+namespace Tracing {
+namespace Silabs {
+
+// Enum for the different operation to trace
+enum class TimeTraceOperation : uint8_t
+{
+    kSpake2p,
+    kPake1,
+    kPake2,
+    kPake3,
+    kOperationalCredentials,
+    kAttestationVerification,
+    kCSR,
+    kNOC,
+    kTransportLayer,
+    kTransportSetup,
+    kFindOperational,
+    kCaseSession,
+    kSigma1,
+    kSigma2,
+    kSigma3,
+    kOTA,
+    kBootup,
+    kSilabsInit,
+    kMatterInit,
+    kNumTraces,
+};
+
+struct TimeTracker
+{
+    // Temporary values
+    System::Clock::Milliseconds64 mStartTime;
+    System::Clock::Milliseconds64 mEndTime;
+    System::Clock::Milliseconds64 mTotalDuration;
+
+    // Values that will be stored in the NVM
+    System::Clock::Milliseconds32 mMovingAverage; // Successful operation average time
+    System::Clock::Milliseconds32 mMaxTimeMs;     // Successful operation max time
+    System::Clock::Milliseconds32 mMinTimeMs;     // Successful operation min time
+    uint32_t mTotalCount;                         // Total number of times the operation was initiated
+    uint32_t mSuccessfullCount;                   // Number of times the operation was completed without error
+    uint32_t mCountAboveAvg;                      // Number of times the operation was above the average time
+};
+
+// This class instantiates a buffer to store the traces before logs are enabled.
+//
+class SilabsTracer
+{
+    static constexpr size_t kNumTraces            = static_cast<size_t>(TimeTraceOperation::kNumTraces);
+    static constexpr size_t kBufferedTracesNumber = 64;
+    static constexpr size_t kBufferedTraceSize    = 128;
+
+public:
+    static SilabsTracer & Instance() { return sInstance; }
+
+    void Init();
+
+    CHIP_ERROR StartTraceStorage(PersistentStorageDelegate * storage);
+
+    void TimeTraceBegin(TimeTraceOperation aOperation);
+    void TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR);
+    void TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR);
+
+    // This Either Logs the traces or stores them in a buffer
+    void OutputTraces();
+
+    // prevent copy constructor and assignment operator
+    SilabsTracer(SilabsTracer const &)             = delete;
+    SilabsTracer & operator=(SilabsTracer const &) = delete;
+
+    // Methods to get the time trackers metrics values
+    TimeTracker GetTimeTracker(TimeTraceOperation aOperation) { return mWatermark[static_cast<size_t>(aOperation)]; }
+
+    // Method to save the time trackers in the NVM, this will likely be time consuming and should not be called frequently
+    CHIP_ERROR SaveWatermarks();
+
+    // Method to load the time trackers from the NVM, this will be called after the initialization so the bootup watermarks need to
+    // be added to the loaded values
+    CHIP_ERROR LoadWatermarks();
+
+private:
+    // Singleton class with a static instance
+    static SilabsTracer sInstance;
+
+    SilabsTracer();
+
+    // Buffer to store the traces
+    uint8_t mTraceBuffer[kBufferedTracesNumber][kBufferedTraceSize];
+
+    // Time trackers for each operation
+    TimeTracker mWatermark[kNumTraces];
+
+    PersistentStorageDelegate * mStorage = nullptr;
+};
+
+} // namespace Silabs
+} // namespace Tracing
+} // namespace chip

src/platform/tests/BUILD.gn

@@ -92,6 +92,9 @@ if (chip_device_platform != "none" && chip_device_platform != "fake") {
     if (chip_device_platform == "linux") {
       test_sources += [ "TestConnectivityMgr.cpp" ]
     }
+
+    test_sources += [ "TestSilabsTracing.cpp" ]
+    public_deps += [ "${chip_root}/src/platform/silabs/tracing:SilabsTracing" ]
   }
 } else {
   import("${chip_root}/build/chip/chip_test_group.gni")