Modified the logging methods, added helpers and switched to a dynamical allocation for the trace buffer

lpbeliveau-silabs · lpbeliveau-silabs · commit b8f12ddcef33 · 2024-11-14T20:03:16.000-05:00
diff --git a/examples/platform/silabs/silabs_utils.h b/examples/platform/silabs/silabs_utils.h
@@ -24,8 +24,6 @@
 extern "C" {
 #endif
 
-bool isLogInitialized(void);
-
 void silabsInitLog(void);
 
 void silabsLog(const char * aFormat, ...);
diff --git a/src/platform/silabs/Logging.cpp b/src/platform/silabs/Logging.cpp
@@ -201,7 +201,7 @@ extern "C" void silabsLog(const char * aFormat, ...)
 }
 
 #ifdef SILABS_LOG_ENABLED
-extern bool isLogInitialized()
+bool isLogInitialized()
 {
     return sLogInitialized;
 }
diff --git a/src/platform/silabs/Logging.h b/src/platform/silabs/Logging.h
@@ -0,0 +1,21 @@
+/*
+ *
+ *    Copyright (c) 2024 Silabs.
+ *    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
+
+bool isLogInitialized(void);
diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp
@@ -4,7 +4,7 @@
 #include <lib/support/PersistentData.h>
 
 #if !CONFIG_BUILD_FOR_HOST_UNIT_TEST
-#include <silabs_utils.h> // for isLogInitialized
+#include <Logging.h> // for isLogInitialized
 #endif
 
 // The following functions needs to be implemented by the application to allows logging or storing the traces /
@@ -18,6 +18,8 @@ namespace chip {
 namespace Tracing {
 namespace Silabs {
 
+// TODO add string mapping to log the operation names and types
+
 static constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES;
 
 struct TimeTrackerStorage : public TimeTracker, PersistentData<kPersistentTimeTrackerBufferMax>
@@ -29,14 +31,50 @@ SilabsTracer SilabsTracer::sInstance;
 
 SilabsTracer::SilabsTracer()
 {
-    Init();
+    VerifyOrDie(Init() == CHIP_NO_ERROR);
 }
 
-void SilabsTracer::Init()
+CHIP_ERROR SilabsTracer::TraceBufferClear()
 {
-    // Initialize the trace buffer and time trackers
-    memset(mTraceBuffer, 0, sizeof(mTraceBuffer));
+    // Free the allocated memory for the trace buffer
+    if (nullptr != mTraceBuffer)
+    {
+        for (size_t i = 0; i < kBufferedTracesNumber; ++i)
+        {
+            free(mTraceBuffer[i]);
+        }
+        free(mTraceBuffer);
+        mTraceBuffer = nullptr;
+        mBufferIndex = 0;
+    }
+    return CHIP_NO_ERROR;
+}
+
+CHIP_ERROR SilabsTracer::Init()
+{
+    // Allows to use Init as a Reset function
+    ReturnErrorOnFailure(TraceBufferClear());
+
+    // Allocate memory for the trace buffer
+    mTraceBuffer = static_cast<uint8_t **>(malloc(kBufferedTracesNumber * sizeof(uint8_t *)));
+    VerifyOrReturnError(nullptr != mTraceBuffer, CHIP_ERROR_NO_MEMORY);
+
+    for (size_t i = 0; i < kBufferedTracesNumber; ++i)
+    {
+        mTraceBuffer[i] = static_cast<uint8_t *>(malloc(kBufferedTraceSize * sizeof(uint8_t)));
+        VerifyOrReturnError(nullptr != mTraceBuffer[i], CHIP_ERROR_NO_MEMORY);
+        memset(mTraceBuffer[i], 0, kBufferedTraceSize);
+    }
+
+    // Initialize the time trackers
     memset(mWatermark, 0, sizeof(mWatermark));
+
+    return CHIP_NO_ERROR;
+}
+
+CHIP_ERROR SilabsTracer::StartLogging()
+{
+    return TraceBufferFlush();
 }
 
 CHIP_ERROR SilabsTracer::StartTraceStorage(PersistentStorageDelegate * storage)
@@ -52,96 +90,175 @@ void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation)
     auto & tracker = mWatermark[static_cast<size_t>(aOperation)];
     tracker.mTotalCount++;
     tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp();
+    OutputTrace(aOperation, OperationType::kBegin, CHIP_NO_ERROR);
 }
 
 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);
+        OutputTrace(aOperation, OperationType::kEnd, error);
         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();
+    auto duration    = tracker.mEndTime - tracker.mStartTime;
 
     tracker.mTotalDuration += System::Clock::Milliseconds64(duration);
 
-    if (duration > tracker.mMaxTimeMs.count())
+    if (duration > tracker.mMaxTimeMs)
     {
         tracker.mMaxTimeMs = System::Clock::Milliseconds32(duration);
     }
 
-    if (tracker.mMinTimeMs.count() == 0 || duration < tracker.mMinTimeMs.count())
+    if (tracker.mMinTimeMs.count() == 0 || duration < tracker.mMinTimeMs)
     {
         tracker.mMinTimeMs = System::Clock::Milliseconds32(duration);
     }
 
     tracker.mSuccessfullCount++;
-    tracker.mMovingAverage = System::Clock::Milliseconds32(tracker.mTotalDuration.count() / tracker.mSuccessfullCount);
-    if (duration > tracker.mMovingAverage.count())
+    tracker.mMovingAverage = System::Clock::Milliseconds32(tracker.mTotalDuration / tracker.mSuccessfullCount);
+    if (duration > tracker.mMovingAverage)
     {
         tracker.mCountAboveAvg++;
     }
+
+    OutputTrace(aOperation, OperationType::kEnd, CHIP_NO_ERROR);
 }
 
 void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error)
 {
-    if (CHIP_NO_ERROR == error)
+    OutputTrace(aOperation, OperationType::kInstant, error);
+}
+
+CHIP_ERROR SilabsTracer::OutputTrace(TimeTraceOperation aOperation, OperationType type, CHIP_ERROR error)
+{
+    uint64_t timestamp = System::SystemClock().GetMonotonicTimestamp().count();
+    uint8_t operation  = static_cast<uint8_t>(aOperation);
+    uint8_t opType     = static_cast<uint8_t>(type);
+
+    if (isLogInitialized())
+    {
+        if (error == CHIP_NO_ERROR)
+        {
+            ChipLogProgress(DeviceLayer, "Time: %llu, Operation: %u, Type: %u", timestamp, operation, opType);
+        }
+        else
+        {
+            ChipLogError(DeviceLayer, "Time: %llu, Operation: %u, Type: %u, Error: %" CHIP_ERROR_FORMAT, timestamp, operation,
+                         opType, error.Format());
+            return CHIP_ERROR_INTERNAL;
+        }
+    }
+    else
+    {
+        if (mBufferIndex < kBufferedTracesNumber - 1)
+        {
+            if (error == CHIP_NO_ERROR)
+            {
+                snprintf(reinterpret_cast<char *>(mTraceBuffer[mBufferIndex]), kBufferedTraceSize,
+                         "Time: %llu, Operation: %u, Type: %u", timestamp, operation, opType);
+            }
+            else
+            {
+                snprintf(reinterpret_cast<char *>(mTraceBuffer[mBufferIndex]), kBufferedTraceSize,
+                         "Time: %llu, Operation: %u, Type: %u, Error: %" CHIP_ERROR_FORMAT, timestamp, operation, opType,
+                         error.Format());
+            }
+            mBufferIndex++;
+        }
+        else
+        {
+            snprintf(reinterpret_cast<char *>(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, "Buffer overflow: logs were lost");
+        }
+    }
+
+    return CHIP_NO_ERROR;
+}
+
+void SilabsTracer::BufferTrace(size_t index, const TimeTracker & tracker, CHIP_ERROR error)
+{
+    if (mBufferIndex < kBufferedTracesNumber - 1)
     {
-        // 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));
+        if (error == CHIP_NO_ERROR)
+        {
+            snprintf(reinterpret_cast<char *>(mTraceBuffer[mBufferIndex]), kBufferedTraceSize,
+                     "Trace %zu: TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32
+                     ", AvgTime=%" PRIu32 ", CountAboveAvg=%" PRIu32 "",
+                     index, tracker.mTotalCount, tracker.mSuccessfullCount, tracker.mMaxTimeMs.count(), tracker.mMinTimeMs.count(),
+                     tracker.mMovingAverage.count(), tracker.mCountAboveAvg);
+        }
+        else
+        {
+            snprintf(reinterpret_cast<char *>(mTraceBuffer[mBufferIndex]), kBufferedTraceSize,
+                     "Trace %zu: Error: %" CHIP_ERROR_FORMAT, index, error.Format());
+        }
+        mBufferIndex++;
     }
     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());
+        snprintf(reinterpret_cast<char *>(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, "Buffer overflow: logs were lost");
     }
 }
 
-void SilabsTracer::OutputTraces()
+CHIP_ERROR SilabsTracer::OutputWaterMark(TimeTraceOperation aOperation, CHIP_ERROR error)
 {
+    size_t index   = static_cast<size_t>(aOperation);
+    auto & tracker = mWatermark[index];
+
     if (isLogInitialized())
     {
-        // Output the traces from the buffer
-        for (size_t i = 0; i < kNumTraces; ++i)
+        if (error == CHIP_NO_ERROR)
         {
-            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(),
+                            "Trace %zu: TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32
+                            ", AvgTime=%" PRIu32 ", CountAboveAvg=%" PRIu32 "",
+                            index, tracker.mTotalCount, tracker.mSuccessfullCount, tracker.mMaxTimeMs.count(),
                             tracker.mMinTimeMs.count(), tracker.mMovingAverage.count(), tracker.mCountAboveAvg);
         }
+        else
+        {
+            ChipLogError(DeviceLayer, "Trace %zu: Error: %" CHIP_ERROR_FORMAT, index, error.Format());
+            return CHIP_ERROR_INTERNAL;
+        }
     }
     else
     {
-        // Buffer the traces if logs are not initialized
-        static size_t bufferIndex = 0;
-        if (bufferIndex < kBufferedTracesNumber - 1)
+        BufferTrace(index, tracker, error);
+    }
+
+    return CHIP_NO_ERROR;
+}
+
+CHIP_ERROR SilabsTracer::OutputAllWaterMarks()
+{
+    for (size_t i = 0; i < kNumTraces; ++i)
+    {
+        CHIP_ERROR err = OutputWaterMark(static_cast<TimeTraceOperation>(i), CHIP_NO_ERROR);
+        if (err != CHIP_NO_ERROR)
         {
-            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++;
-            }
+            return err;
         }
-        else
+    }
+    return CHIP_NO_ERROR;
+}
+
+CHIP_ERROR SilabsTracer::TraceBufferFlush()
+{
+    if (isLogInitialized() && (nullptr != mTraceBuffer))
+    {
+        for (size_t i = 0; i < kBufferedTracesNumber; ++i)
         {
-            snprintf(reinterpret_cast<char *>(mTraceBuffer[bufferIndex]), kBufferedTraceSize, "Buffer overflow: logs were lost");
+            if (mTraceBuffer[i][0] != '\0') // Check if the buffer is not empty
+            {
+                ChipLogProgress(DeviceLayer, "%s", mTraceBuffer[i]);
+            }
         }
     }
+
+    return TraceBufferClear();
 }
 
 // Save the traces in the NVM
@@ -159,6 +276,23 @@ CHIP_ERROR SilabsTracer::LoadWatermarks()
     return CHIP_NO_ERROR;
 }
 
+#if CONFIG_BUILD_FOR_HOST_UNIT_TEST
+CHIP_ERROR SilabsTracer::GetTraceCount(size_t & count) const
+{
+    VerifyOrReturnError(nullptr != mTraceBuffer, CHIP_ERROR_INCORRECT_STATE);
+    count = mBufferIndex;
+    return CHIP_NO_ERROR;
+}
+
+CHIP_ERROR SilabsTracer::GetTraceByIndex(size_t index, const char *& trace) const
+{
+    VerifyOrReturnError(nullptr != mTraceBuffer, CHIP_ERROR_INCORRECT_STATE);
+    VerifyOrReturnError(index < mBufferIndex, CHIP_ERROR_INVALID_ARGUMENT);
+    trace = reinterpret_cast<const char *>(mTraceBuffer[index]);
+    return CHIP_NO_ERROR;
+}
+#endif
+
 } // namespace Silabs
 } // namespace Tracing
 } // namespace chip
diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h
diff --git a/src/platform/tests/TestSilabsTracing.cpp b/src/platform/tests/TestSilabsTracing.cpp

Original file line number	Diff line number	Diff line change
`@@ -201,7 +201,7 @@ extern "C" void silabsLog(const char * aFormat, ...)`
`201`	`201`	`}`
`202`	`202`
`203`	`203`	`#ifdef SILABS_LOG_ENABLED`
`204`		`-extern bool isLogInitialized()`
	`204`	`+bool isLogInitialized()`
`205`	`205`	`{`
`206`	`206`	`return sLogInitialized;`
`207`	`207`	`}`