From d045a78c231d64535cc08617816bc50dcab36072 Mon Sep 17 00:00:00 2001 From: lpbeliveau-silabs Date: Mon, 18 Nov 2024 20:04:37 -0500 Subject: [PATCH] Implemented formating for Trace logs, added test for logging as well as reworks to get logging working --- src/platform/silabs/tracing/SilabsTracing.cpp | 94 ++++++++++++------- src/platform/silabs/tracing/SilabsTracing.h | 24 +++-- src/platform/tests/TestSilabsTracing.cpp | 81 ++++++++++++++-- 3 files changed, 150 insertions(+), 49 deletions(-) diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp index 5fe25331f9..f7f262cd81 100644 --- a/src/platform/silabs/tracing/SilabsTracing.cpp +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -85,12 +85,29 @@ const char * TimeTraceOperationToString(TimeTraceOperation operation) return "MatterInit"; case TimeTraceOperation::kNumTraces: return "NumTraces"; + case TimeTraceOperation::kBufferFull: + return "BufferFull"; + default: + return "Unknown"; + } +} + +// String mapping for OperationType +const char * OperationTypeToString(OperationType type) +{ + switch (type) + { + case OperationType::kBegin: + return "Begin"; + case OperationType::kEnd: + return "End"; + case OperationType::kInstant: + return "Instant"; default: return "Unknown"; } } -// TODO add string mapping to log the operation names and types namespace { constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES; } // namespace @@ -99,6 +116,28 @@ struct TimeTrackerStorage : public TimeTracker, PersistentData(aOperation)]; @@ -146,10 +185,10 @@ void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) auto & watermark = mWatermarks[static_cast(aOperation)]; watermark.mTotalCount++; - OutputTrace(tracker); + return OutputTrace(tracker); } -void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error) +CHIP_ERROR SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error) { auto & tracker = mLatestTimeTrackers[static_cast(aOperation)]; tracker.mEndTime = System::SystemClock().GetMonotonicTimestamp(); @@ -183,10 +222,10 @@ void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error) } } - OutputTrace(tracker); + return OutputTrace(tracker); } -void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error) +CHIP_ERROR SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error) { TimeTracker tracker; tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); @@ -194,18 +233,17 @@ void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR er tracker.mOperation = aOperation; tracker.mType = OperationType::kInstant; tracker.mError = error; - OutputTrace(tracker); + return OutputTrace(tracker); } CHIP_ERROR SilabsTracer::OutputTimeTracker(const TimeTracker & tracker) { VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED); - auto duration = tracker.mEndTime - tracker.mStartTime; - ChipLogProgress(DeviceLayer, - "TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Duration: %" PRIu32 - " ms, Operation: %s, Type: %" PRIu8 ", Error: %" CHIP_ERROR_FORMAT, - tracker.mStartTime.count(), tracker.mEndTime.count(), duration.count(), - TimeTraceOperationToString(tracker.mOperation), static_cast(tracker.mType), tracker.mError.Format()); + // Allocate a buffer to store the trace + char buffer[256]; + auto bufferSize = sizeof(buffer); + tracker.ToCharArray(buffer, bufferSize); + ChipLogProgress(DeviceLayer, "%s", buffer); // Use format string literal return CHIP_NO_ERROR; } @@ -225,10 +263,11 @@ CHIP_ERROR SilabsTracer::OutputTrace(const TimeTracker & tracker) TimeTracker resourceExhaustedTracker = tracker; resourceExhaustedTracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); resourceExhaustedTracker.mEndTime = resourceExhaustedTracker.mStartTime; - resourceExhaustedTracker.mOperation = TimeTraceOperation::kNumTraces; + resourceExhaustedTracker.mOperation = TimeTraceOperation::kBufferFull; resourceExhaustedTracker.mType = OperationType::kInstant; resourceExhaustedTracker.mError = CHIP_ERROR_BUFFER_TOO_SMALL; mTimeTrackerList.Insert(resourceExhaustedTracker); + mBufferedTrackerCount++; return CHIP_ERROR_BUFFER_TOO_SMALL; } else @@ -330,43 +369,28 @@ CHIP_ERROR SilabsTracer::LoadWatermarks() return CHIP_NO_ERROR; } -size_t SilabsTracer::GetTraceCount() -{ - return mBufferedTrackerCount; -} - -CHIP_ERROR SilabsTracer::GetTraceByOperation(TimeTraceOperation aOperation, char * buffer, uint16_t & size) const +CHIP_ERROR SilabsTracer::GetTraceByOperation(TimeTraceOperation aOperation, char * buffer, size_t & size) const { auto * current = mTimeTrackerList.head; while (current != nullptr) { if (current->mValue.mOperation == aOperation) { - auto duration = current->mValue.mEndTime.count() - current->mValue.mStartTime.count(); - int requiredSize = snprintf(nullptr, 0, - "TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Duration: %" PRIu32 - " ms, Operation: %s, Type: %" PRIu8 ", Error: %" CHIP_ERROR_FORMAT, - current->mValue.mStartTime.count(), current->mValue.mEndTime.count(), duration, - TimeTraceOperationToString(current->mValue.mOperation), - static_cast(current->mValue.mType), current->mValue.mError.Format()); + // Check if the buffer is large enough + auto requiredSize = current->mValue.ToCharArray(nullptr, 0); if (requiredSize < 0) { return CHIP_ERROR_INTERNAL; } - if (requiredSize >= size) + if (static_cast(requiredSize) >= size) { - size = requiredSize + 1; // Include null terminator + size = static_cast(requiredSize + 1); // Include null terminator return CHIP_ERROR_BUFFER_TOO_SMALL; } - snprintf(buffer, size, - "TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Duration: %" PRIu32 - " ms, Operation: %s, Type: %" PRIu8 ", Error: %" CHIP_ERROR_FORMAT, - current->mValue.mStartTime.count(), current->mValue.mEndTime.count(), duration, - TimeTraceOperationToString(current->mValue.mOperation), static_cast(current->mValue.mType), - current->mValue.mError.Format()); + current->mValue.ToCharArray(buffer, size); return CHIP_NO_ERROR; } current = current->mpNext; diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h index d3532e4552..9d377d7a9f 100644 --- a/src/platform/silabs/tracing/SilabsTracing.h +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -60,6 +60,7 @@ enum class TimeTraceOperation : uint8_t kBootup, kSilabsInit, kMatterInit, + kBufferFull, kNumTraces, }; @@ -78,6 +79,14 @@ struct TimeTracker TimeTraceOperation mOperation; OperationType mType; CHIP_ERROR mError; + + /** @brief Convert the TimeTracker to a string for logs + * Behaves like snprintf, but formats the output differently based on the OperationType + * May be used with nullptr and 0 to get the required buffer size + * @param buffer The buffer to write the string to + * @param bufferSize The size of the buffer + */ + int ToCharArray(char * buffer, size_t bufferSize) const; }; struct Watermark @@ -95,10 +104,10 @@ struct Watermark // class SilabsTracer { +public: static constexpr size_t kNumTraces = to_underlying(TimeTraceOperation::kNumTraces); static constexpr size_t kMaxBufferedTraces = 64; -public: /** @brief Get the singleton instance of SilabsTracer */ static SilabsTracer & Instance() { return sInstance; } @@ -119,24 +128,27 @@ class SilabsTracer * This calls the OutputTrace method to log the trace if logs are enabled, and stores the time tracker in the buffer if the * buffer is not full. * @param aOperation + * @return CHIP_ERROR, returns CHIP_ERROR_BUFFER_TOO_SMALL if the buffer is full */ - void TimeTraceBegin(TimeTraceOperation aOperation); + CHIP_ERROR TimeTraceBegin(TimeTraceOperation aOperation); /** @brief End tracing a time operation * This calls the OutputTrace method to log the trace if logs are enabled, and stores the time tracker in the buffer if the * buffer is not full. * @param aOperation * @param error + * @return CHIP_ERROR, returns CHIP_ERROR_BUFFER_TOO_SMALL if the buffer is full */ - void TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); + CHIP_ERROR TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); /** @brief Trace an instant time operation * This calls the OutputTrace method to log the trace if logs are enabled, and stores the time tracker in the buffer if the * buffer is not full. * @param aOperation * @param error + * @return CHIP_ERROR, returns CHIP_ERROR_BUFFER_TOO_SMALL if the buffer is full */ - void TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); + CHIP_ERROR TimeTraceInstant(TimeTraceOperation aOperation, 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. @@ -198,8 +210,8 @@ class SilabsTracer * @return Watermark, the watermark for the operation */ Watermark GetWatermark(TimeTraceOperation aOperation) { return mWatermarks[to_underlying(aOperation)]; } - CHIP_ERROR GetTimeTracesCount(size_t & count) const; - CHIP_ERROR GetTraceByOperation(TimeTraceOperation aOperation, char * buffer, uint16_t & size) const; + size_t GetTimeTracesCount() { return mBufferedTrackerCount; } + CHIP_ERROR GetTraceByOperation(TimeTraceOperation aOperation, char * buffer, size_t & size) const; private: struct TimeTrackerList diff --git a/src/platform/tests/TestSilabsTracing.cpp b/src/platform/tests/TestSilabsTracing.cpp index 2ff0ec9980..d5170ac9eb 100644 --- a/src/platform/tests/TestSilabsTracing.cpp +++ b/src/platform/tests/TestSilabsTracing.cpp @@ -49,8 +49,14 @@ using namespace chip::Tracing::Silabs; namespace { chip::System::Clock::Internal::MockClock gMockClock; chip::System::Clock::ClockBase * gRealClock; +bool logInitialized = false; } // namespace +bool isLogInitialized() +{ + return logInitialized; +} + class TestSilabsTracing : public ::testing::Test { public: @@ -596,7 +602,7 @@ TEST_F(TestSilabsTracing, TestOTA) EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(1)); // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls - EXPECT_EQ(SilabsTracer::Instance().GetTimeTracesCount(traceCount), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 8u); // 8 calls: 4 TimeTraceBegin and 4 TimeTraceEnd } @@ -604,6 +610,7 @@ TEST_F(TestSilabsTracing, TestLogs) { gMockClock.SetMonotonic(0_ms64); SilabsTracer::Instance().Init(); + logInitialized = true; size_t traceCount = 0; // Simulate OTA steps @@ -643,24 +650,23 @@ TEST_F(TestSilabsTracing, TestLogs) EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls - EXPECT_EQ(SilabsTracer::Instance().GetTimeTracesCount(traceCount), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 4u); // 4 calls: 2 TimeTraceBegin and 2 TimeTraceEnd // Verify the output logs using GetTraceByOperation char logBuffer[256]; - uint16_t bufferSize = sizeof(logBuffer); + auto bufferSize = sizeof(logBuffer); // Verify OTA log EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, logBuffer, bufferSize), CHIP_NO_ERROR); const char * expectedOTALogFormat = - "TimeTracker - StartTime: 0, EndTime: 100, Duration: 100 ms, Operation: OTA, Type: 1, Error: 0"; + "TimeTracker - StartTime: 0, EndTime: 100, Duration: 100 ms, Operation: OTA, Type: End, Error: 0x0"; EXPECT_STREQ(logBuffer, expectedOTALogFormat); // Verify Bootup log - bufferSize = sizeof(logBuffer); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, logBuffer, bufferSize), CHIP_NO_ERROR); const char * expectedBootupLogFormat = - "TimeTracker - StartTime: 100, EndTime: 300, Duration: 200 ms, Operation: Bootup, Type: 1, Error: 0"; + "TimeTracker - StartTime: 100, EndTime: 300, Duration: 200 ms, Operation: Bootup, Type: End, Error: 0x0"; EXPECT_STREQ(logBuffer, expectedBootupLogFormat); // Test buffer too small behavior @@ -672,7 +678,7 @@ TEST_F(TestSilabsTracing, TestLogs) // Test TraceBufferFlushByOperation EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(TimeTraceOperation::kOTA), CHIP_NO_ERROR); - EXPECT_EQ(SilabsTracer::Instance().GetTimeTracesCount(traceCount), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 2u); // Only Bootup traces should remain // Verify Bootup log still exists @@ -686,7 +692,7 @@ TEST_F(TestSilabsTracing, TestLogs) // Test TraceBufferFlushAll EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushAll(), CHIP_NO_ERROR); - EXPECT_EQ(SilabsTracer::Instance().GetTimeTracesCount(traceCount), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 0u); // All traces should be flushed // Verify no logs exist @@ -695,3 +701,62 @@ TEST_F(TestSilabsTracing, TestLogs) CHIP_ERROR_NOT_FOUND); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, logBuffer, bufferSize), CHIP_ERROR_NOT_FOUND); } + +TEST_F(TestSilabsTracing, TestBufferBusting) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + size_t traceCount = 0; + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + EXPECT_EQ(traceCount, 0u); + + // Simulate a large number of traces + while (traceCount < SilabsTracer::kMaxBufferedTraces - 2) + { + EXPECT_EQ(CHIP_NO_ERROR, SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kCaseSession)); + gMockClock.AdvanceMonotonic(100_ms64); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + } + + EXPECT_EQ(SilabsTracer::kMaxBufferedTraces - 2, SilabsTracer::Instance().GetTimeTracesCount()); + EXPECT_EQ(CHIP_NO_ERROR, SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOTA)); + EXPECT_EQ(CHIP_ERROR_BUFFER_TOO_SMALL, SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kImageUpload)); + + // Verify an overflow operation is added (kBufferFull) + EXPECT_EQ(SilabsTracer::kMaxBufferedTraces, SilabsTracer::Instance().GetTimeTracesCount()); + char logBuffer[256]; + auto bufferSize = sizeof(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBufferFull, logBuffer, bufferSize), CHIP_NO_ERROR); + const char * expectedNumLogFormat = "TimeTracker - EventTime: 6200, Operation: BufferFull, Type: Instant, Error: 0x19"; + EXPECT_STREQ(logBuffer, expectedNumLogFormat); + + // Verify the kImageUpload operation was not added + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kImageUpload, logBuffer, bufferSize), + CHIP_ERROR_NOT_FOUND); + + // Flush kOTA operation + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(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, logBuffer, bufferSize), + CHIP_ERROR_NOT_FOUND); + + // Flush the overflow operations + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(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)); + bufferSize = sizeof(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kImageUpload, logBuffer, bufferSize), CHIP_NO_ERROR); + + // Verify that the buffer full operation is removed + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBufferFull, logBuffer, bufferSize), + CHIP_ERROR_NOT_FOUND); + + // Flush all operations + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushAll(), CHIP_NO_ERROR); + EXPECT_EQ(0u, SilabsTracer::Instance().GetTimeTracesCount()); +} \ No newline at end of file