diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp index dc88ba45d0..e9940bac02 100644 --- a/src/platform/silabs/tracing/SilabsTracing.cpp +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -34,7 +34,78 @@ namespace chip { namespace Tracing { namespace Silabs { -// TODO add string mapping to log the operation names and types +const char * TimeTraceOperationToString(TimeTraceOperation operation) +{ + switch (operation) + { + case TimeTraceOperation::kSpake2p: + return "Spake2p"; + case TimeTraceOperation::kPake1: + return "Pake1"; + case TimeTraceOperation::kPake2: + return "Pake2"; + case TimeTraceOperation::kPake3: + return "Pake3"; + case TimeTraceOperation::kOperationalCredentials: + return "OperationalCredentials"; + case TimeTraceOperation::kAttestationVerification: + return "AttestationVerification"; + case TimeTraceOperation::kCSR: + return "CSR"; + case TimeTraceOperation::kNOC: + return "NOC"; + case TimeTraceOperation::kTransportLayer: + return "TransportLayer"; + case TimeTraceOperation::kTransportSetup: + return "TransportSetup"; + case TimeTraceOperation::kFindOperational: + return "FindOperational"; + case TimeTraceOperation::kCaseSession: + return "CaseSession"; + case TimeTraceOperation::kSigma1: + return "Sigma1"; + case TimeTraceOperation::kSigma2: + return "Sigma2"; + case TimeTraceOperation::kSigma3: + return "Sigma3"; + case TimeTraceOperation::kOTA: + return "OTA"; + case TimeTraceOperation::kImageUpload: + return "ImageUpload"; + case TimeTraceOperation::kImageVerification: + return "ImageVerification"; + case TimeTraceOperation::kAppApplyTime: + return "AppApplyTime"; + case TimeTraceOperation::kBootup: + return "Bootup"; + case TimeTraceOperation::kSilabsInit: + return "SilabsInit"; + case TimeTraceOperation::kMatterInit: + return "MatterInit"; + case TimeTraceOperation::kNumTraces: + return "NumTraces"; + case TimeTraceOperation::kBufferFull: + return "BufferFull"; + default: + return "Unknown"; + } +} + +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"; + } +} + namespace { constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES; } // namespace @@ -43,6 +114,29 @@ struct TimeTrackerStorage : public TimeTracker, PersistentData(buffer.data()), buffer.size(), + "TimeTracker - StartTime: %" PRIu32 ", Operation: %s, Type: %s, Error: 0x%" PRIx32, mStartTime.count(), + TimeTraceOperationToString(mOperation), OperationTypeToString(mType), mError.AsInteger()); + case OperationType::kEnd: + return snprintf(reinterpret_cast(buffer.data()), buffer.size(), + "TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Duration: %" PRIu32 + " ms, Operation: %s, Type: %s, Error: 0x%" PRIx32, + mStartTime.count(), mEndTime.count(), (mEndTime - mStartTime).count(), + TimeTraceOperationToString(mOperation), OperationTypeToString(mType), mError.AsInteger()); + case OperationType::kInstant: + return snprintf(reinterpret_cast(buffer.data()), buffer.size(), + "TimeTracker - EventTime: %" PRIu32 ", Operation: %s, Type: %s, Error: 0x%" PRIx32, mStartTime.count(), + TimeTraceOperationToString(mOperation), OperationTypeToString(mType), mError.AsInteger()); + default: + return snprintf(reinterpret_cast(buffer.data()), buffer.size(), "TimeTracker - Unknown operation type"); + } +} + SilabsTracer SilabsTracer::sInstance; SilabsTracer::SilabsTracer() @@ -78,7 +172,7 @@ CHIP_ERROR SilabsTracer::StartWatermarksStorage(PersistentStorageDelegate * stor return CHIP_NO_ERROR; } -void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) +CHIP_ERROR SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) { // Log the start time of the operation auto & tracker = mLatestTimeTrackers[static_cast(aOperation)]; @@ -90,10 +184,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(); @@ -127,10 +221,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(); @@ -138,17 +232,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); - ChipLogProgress(DeviceLayer, - "TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Operation: %" PRIu8 ", Type: %" PRIu8 - ", Error: %" CHIP_ERROR_FORMAT, - tracker.mStartTime.count(), tracker.mEndTime.count(), static_cast(tracker.mOperation), - static_cast(tracker.mType), tracker.mError.Format()); + // Allocate a buffer to store the trace + uint8_t buffer[kMaxTraceSize]; + MutableByteSpan span(buffer); + tracker.ToCharArray(span); + ChipLogProgress(DeviceLayer, "%s", buffer); // Use format string literal return CHIP_NO_ERROR; } @@ -168,10 +262,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 @@ -189,10 +284,11 @@ CHIP_ERROR SilabsTracer::OutputWaterMark(TimeTraceOperation aOperation) VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED); ChipLogProgress(DeviceLayer, - "Trace %zu: TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32 + "Operation: %s, TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32 ", AvgTime=%" PRIu32 ", CountAboveAvg=%" PRIu32 "", - index, watermark.mTotalCount, watermark.mSuccessfullCount, watermark.mMaxTimeMs.count(), - watermark.mMinTimeMs.count(), watermark.mMovingAverage.count(), watermark.mCountAboveAvg); + TimeTraceOperationToString(aOperation), watermark.mTotalCount, watermark.mSuccessfullCount, + watermark.mMaxTimeMs.count(), watermark.mMinTimeMs.count(), watermark.mMovingAverage.count(), + watermark.mCountAboveAvg); return CHIP_NO_ERROR; } @@ -272,24 +368,33 @@ CHIP_ERROR SilabsTracer::LoadWatermarks() return CHIP_NO_ERROR; } -#if CONFIG_BUILD_FOR_HOST_UNIT_TEST -size_t SilabsTracer::GetTraceCount() -{ - return mBufferedTrackerCount; -} - -CHIP_ERROR SilabsTracer::GetTraceByIndex(size_t index, const char *& trace) const +CHIP_ERROR SilabsTracer::GetTraceByOperation(TimeTraceOperation aOperation, MutableByteSpan & buffer) const { auto * current = mTimeTrackerList.head; - for (size_t i = 0; i < index && current != nullptr; ++i) + while (current != nullptr) { + if (current->mValue.mOperation == aOperation) + { + // Check if the buffer is large enough + auto requiredSize = current->mValue.GetSize(); + + if (requiredSize < 0) + { + return CHIP_ERROR_INTERNAL; + } + + if (static_cast(requiredSize) >= buffer.size()) + { + return CHIP_ERROR_BUFFER_TOO_SMALL; + } + + current->mValue.ToCharArray(buffer); + return CHIP_NO_ERROR; + } current = current->mpNext; } - VerifyOrReturnError(current != nullptr, CHIP_ERROR_INVALID_ARGUMENT); - trace = reinterpret_cast(¤t->mValue); - return CHIP_NO_ERROR; + return CHIP_ERROR_NOT_FOUND; } -#endif } // namespace Silabs } // namespace Tracing diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h index 4699f708ee..5bfc912f8c 100644 --- a/src/platform/silabs/tracing/SilabsTracing.h +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -21,6 +21,7 @@ #include #include #include +#include #include #include @@ -60,6 +61,7 @@ enum class TimeTraceOperation : uint8_t kBootup, kSilabsInit, kMatterInit, + kBufferFull, kNumTraces, }; @@ -78,6 +80,23 @@ 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 a buffer of size == 0 to get the required buffer size + * @param buffer The buffer to write the string to + * @return The number of characters written to the buffer, or the size of the buffer required if the buffer is too small + */ + int ToCharArray(MutableByteSpan & buffer) const; + + /** @brief Get the size of the string representation of the TimeTracker + * @return The size of the string representation of the TimeTracker + */ + int GetSize() const + { + MutableByteSpan temp; + return ToCharArray(temp); + } }; struct Watermark @@ -95,10 +114,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 = 256; -public: /** @brief Get the singleton instance of SilabsTracer */ static SilabsTracer & Instance() { return sInstance; } @@ -119,24 +139,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. @@ -175,18 +198,6 @@ class SilabsTracer SilabsTracer(SilabsTracer const &) = delete; SilabsTracer & operator=(SilabsTracer const &) = delete; - /** @brief Get the latest time tracker for a specific operation - * @param aOperation The operation to get the time tracker for - * @return TimeTracker, the latest time tracker for the operation - */ - TimeTracker GetTimeTracker(TimeTraceOperation aOperation) { return mLatestTimeTrackers[to_underlying(aOperation)]; } - - /** @brief Get the watermark for a specific operation - * @param aOperation The operation to get the watermark for - * @return Watermark, the watermark for the operation - */ - Watermark GetWatermark(TimeTraceOperation aOperation) { return mWatermarks[to_underlying(aOperation)]; } - /** @brief Save the watermarks to persistent storage * @return CHIP_ERROR, returns an error if the storage is not initialized */ @@ -197,19 +208,21 @@ class SilabsTracer */ CHIP_ERROR LoadWatermarks(); -#if CONFIG_BUILD_FOR_HOST_UNIT_TEST - /** @brief Get the count of buffered traces - * @param count Reference to store the count of buffered traces + // Methods to get the time trackers metrics values + + /** @brief Get the latest time tracker for a specific operation + * @param aOperation The operation to get the time tracker for + * @return TimeTracker, the latest time tracker for the operation */ - size_t GetTraceCount(); + TimeTracker GetTimeTracker(TimeTraceOperation aOperation) { return mLatestTimeTrackers[to_underlying(aOperation)]; } - /** @brief Get a trace by its index - * @param index The index of the trace to retrieve - * @param trace Reference to store the trace - * @return CHIP_ERROR, returns CHIP_ERROR_INVALID_ARGUMENT if the index is invalid + /** @brief Get the watermark for a specific operation + * @param aOperation The operation to get the watermark for + * @return Watermark, the watermark for the operation */ - CHIP_ERROR GetTraceByIndex(size_t index, const char *& trace) const; -#endif + Watermark GetWatermark(TimeTraceOperation aOperation) { return mWatermarks[to_underlying(aOperation)]; } + size_t GetTimeTracesCount() { return mBufferedTrackerCount; } + CHIP_ERROR GetTraceByOperation(TimeTraceOperation aOperation, MutableByteSpan & buffer) const; private: struct TimeTrackerList diff --git a/src/platform/tests/TestSilabsTracing.cpp b/src/platform/tests/TestSilabsTracing.cpp index 2db2bd979e..1634b93191 100644 --- a/src/platform/tests/TestSilabsTracing.cpp +++ b/src/platform/tests/TestSilabsTracing.cpp @@ -49,8 +49,18 @@ using namespace chip::Tracing::Silabs; namespace { chip::System::Clock::Internal::MockClock gMockClock; chip::System::Clock::ClockBase * gRealClock; +#ifndef SILABS_LOG_ENABLED +bool logInitialized = false; +#endif } // namespace +#ifndef SILABS_LOG_ENABLED +bool isLogInitialized() +{ + return logInitialized; +} +#endif + class TestSilabsTracing : public ::testing::Test { public: @@ -76,7 +86,7 @@ TEST_F(TestSilabsTracing, TestTimeTrackerMethods) SilabsTracer::Instance().Init(); - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 0u); // Start tracking time for a specific event @@ -173,7 +183,7 @@ TEST_F(TestSilabsTracing, TestTimeTrackerMethods) EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(2)); // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 11u); // 11 calls: 6 TimeTraceBegin and 5 TimeTraceEnd } @@ -183,7 +193,7 @@ TEST_F(TestSilabsTracing, TestBootupSequence) SilabsTracer::Instance().Init(); size_t traceCount = 0; - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 0u); SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); @@ -238,12 +248,12 @@ TEST_F(TestSilabsTracing, TestBootupSequence) // Simulate a second simulation where we have a reboot during Silabs Init gMockClock.SetMonotonic(0_ms64); - // TODO : Here we simulate that we have restore the number of traces from NVM so we do not do the Init, we should call it and - // call the LoadWatermarks method here + // TODO : Here we simulate that we have restore the watermarks stored in the NVM so we do not do the Init, we should call it + // and call the LoadWatermarks method here // SilabsTracer::Instance().Init(); - // traceCount = SilabsTracer::Instance().GetTraceCount(); + // traceCount = SilabsTracer::Instance().GetTimeTracesCount(); // EXPECT_EQ(traceCount, 0u); SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); @@ -300,7 +310,7 @@ TEST_F(TestSilabsTracing, TestBootupSequence) EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 14u); // 14 calls: 8 TimeTraceBegin and 6 TimeTraceEnd } @@ -310,7 +320,7 @@ TEST_F(TestSilabsTracing, TestCommissioning) SilabsTracer::Instance().Init(); size_t traceCount = 0; - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 0u); // Simulate Spake2p steps @@ -512,7 +522,7 @@ TEST_F(TestSilabsTracing, TestCommissioning) EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 27u); } @@ -521,7 +531,7 @@ TEST_F(TestSilabsTracing, TestOTA) gMockClock.SetMonotonic(0_ms64); SilabsTracer::Instance().Init(); size_t traceCount = 0; - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 0u); // Simulate OTA steps @@ -596,8 +606,159 @@ TEST_F(TestSilabsTracing, TestOTA) EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(1)); // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 8u); // 8 calls: 4 TimeTraceBegin and 4 TimeTraceEnd } -// TODO Implement a function that test the Logs formating depending on the operation, event type, error, etc. +TEST_F(TestSilabsTracing, TestLogs) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + +#ifndef SILABS_LOG_ENABLED + logInitialized = true; +#endif + size_t traceCount = 0; + + // Simulate OTA steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOTA); + gMockClock.AdvanceMonotonic(100_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kOTA); + + // Simulate Bootup steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kBootup); + + // Verify the time tracker values for OTA + auto timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kOTA); + auto trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(100)); + + // Retrieve the watermark for the operation + auto watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kOTA); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Bootup + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kBootup); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kBootup); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + EXPECT_EQ(traceCount, 4u); // 4 calls: 2 TimeTraceBegin and 2 TimeTraceEnd + + // Verify the output logs using GetTraceByOperation + uint8_t logBuffer[256]; + MutableByteSpan span(logBuffer); + + // Verify OTA log + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, span), CHIP_NO_ERROR); + const char * expectedOTALogFormat = + "TimeTracker - StartTime: 0, EndTime: 100, Duration: 100 ms, Operation: OTA, Type: End, Error: 0x0"; + EXPECT_STREQ(reinterpret_cast(span.data()), expectedOTALogFormat); + + // Verify Bootup log + span = MutableByteSpan(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, span), CHIP_NO_ERROR); + const char * expectedBootupLogFormat = + "TimeTracker - StartTime: 100, EndTime: 300, Duration: 200 ms, Operation: Bootup, Type: End, Error: 0x0"; + EXPECT_STREQ(reinterpret_cast(span.data()), expectedBootupLogFormat); + + // 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); + + // Test TraceBufferFlushByOperation + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(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_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); + + // Test TraceBufferFlushAll + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushAll(), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + EXPECT_EQ(traceCount, 0u); // All traces should be flushed + + // Verify no logs exist + span = MutableByteSpan(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, span), CHIP_ERROR_NOT_FOUND); + span = MutableByteSpan(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, span), 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()); + uint8_t logBuffer[256]; + MutableByteSpan logSpan(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBufferFull, logSpan), CHIP_NO_ERROR); + const char * expectedNumLogFormat = "TimeTracker - EventTime: 6200, Operation: BufferFull, Type: Instant, Error: 0x19"; + 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); + + // 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, logSpan), 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)); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(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); + + // Flush all operations + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushAll(), CHIP_NO_ERROR); + EXPECT_EQ(0u, SilabsTracer::Instance().GetTimeTracesCount()); +}