diff --git a/src/platform/silabs/Logging.cpp b/src/platform/silabs/Logging.cpp index dea8913791..0247c52ffb 100644 --- a/src/platform/silabs/Logging.cpp +++ b/src/platform/silabs/Logging.cpp @@ -1,5 +1,6 @@ /* See Project CHIP LICENSE file for licensing information. */ #include +#include #include #include @@ -200,6 +201,13 @@ extern "C" void silabsLog(const char * aFormat, ...) va_end(v); } +#ifdef SILABS_LOG_ENABLED +bool isLogInitialized() +{ + return sLogInitialized; +} +#endif // SILABS_LOG_ENABLED + namespace chip { namespace DeviceLayer { diff --git a/src/platform/silabs/Logging.h b/src/platform/silabs/Logging.h new file mode 100644 index 0000000000..f12b97b3f6 --- /dev/null +++ b/src/platform/silabs/Logging.h @@ -0,0 +1,4 @@ +/* See Project CHIP LICENSE file for licensing information. */ +#pragma once + +bool isLogInitialized(void); diff --git a/src/platform/silabs/tracing/BUILD.gn b/src/platform/silabs/tracing/BUILD.gn new file mode 100644 index 0000000000..78b339d19c --- /dev/null +++ b/src/platform/silabs/tracing/BUILD.gn @@ -0,0 +1,33 @@ +#/*************************************************************************** +# * @file BUILD.gn +# * @brief Instrumenting for matter operation tracing for the Silicon Labs platform. +# ******************************************************************************* +# * # License +# * Copyright 2024 Silicon Laboratories Inc. www.silabs.com +# ******************************************************************************* +# * +# * The licensor of this software is Silicon Laboratories Inc. Your use of this +# * software is governed by the terms of Silicon Labs Master Software License +# * Agreement (MSLA) available at +# * www.silabs.com/about-us/legal/master-software-license-agreement. This +# * software is distributed to you in Source Code format and is governed by the +# * sections of the MSLA applicable to Source Code. +# * +# ******************************************************************************/ + +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", + ] +} diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp new file mode 100644 index 0000000000..dc88ba45d0 --- /dev/null +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -0,0 +1,296 @@ +/*************************************************************************** + * @file SilabsTracing.cpp + * @brief Instrumenting for matter operation tracing for the Silicon Labs platform. + ******************************************************************************* + * # License + * Copyright 2024 Silicon Laboratories Inc. www.silabs.com + ******************************************************************************* + * + * The licensor of this software is Silicon Laboratories Inc. Your use of this + * software is governed by the terms of Silicon Labs Master Software License + * Agreement (MSLA) available at + * www.silabs.com/about-us/legal/master-software-license-agreement. This + * software is distributed to you in Source Code format and is governed by the + * sections of the MSLA applicable to Source Code. + * + ******************************************************************************/ +#include "SilabsTracing.h" +#include +#include +#include + +#if !CONFIG_BUILD_FOR_HOST_UNIT_TEST +#include // 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 { + +// TODO add string mapping to log the operation names and types +namespace { +constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES; +} // namespace +struct TimeTrackerStorage : public TimeTracker, PersistentData +{ + // TODO implement the Persistent Array class and use it here for logging the watermark array +}; + +SilabsTracer SilabsTracer::sInstance; + +SilabsTracer::SilabsTracer() +{ + VerifyOrDie(Init() == CHIP_NO_ERROR); +} + +void SilabsTracer::TraceBufferClear() +{ + // Clear the time tracker list + while (mTimeTrackerList.head != nullptr) + { + mTimeTrackerList.Remove(0); + } + mBufferedTrackerCount = 0; +} + +CHIP_ERROR SilabsTracer::Init() +{ + TraceBufferClear(); + + // Initialize the time trackers + memset(mLatestTimeTrackers, 0, sizeof(mLatestTimeTrackers)); + memset(mWatermarks, 0, sizeof(mWatermarks)); + + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::StartWatermarksStorage(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 = mLatestTimeTrackers[static_cast(aOperation)]; + tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); + tracker.mOperation = aOperation; + tracker.mType = OperationType::kBegin; + tracker.mError = CHIP_NO_ERROR; + + auto & watermark = mWatermarks[static_cast(aOperation)]; + watermark.mTotalCount++; + + OutputTrace(tracker); +} + +void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error) +{ + auto & tracker = mLatestTimeTrackers[static_cast(aOperation)]; + tracker.mEndTime = System::SystemClock().GetMonotonicTimestamp(); + tracker.mType = OperationType::kEnd; + tracker.mError = error; + + if (error == CHIP_NO_ERROR) + { + // Calculate the duration and update the time tracker + auto duration = tracker.mEndTime - tracker.mStartTime; + + auto & watermark = mWatermarks[static_cast(aOperation)]; + watermark.mSuccessfullCount++; + watermark.mMovingAverage = System::Clock::Milliseconds32( + (watermark.mMovingAverage.count() * (watermark.mSuccessfullCount - 1) + duration.count()) / + watermark.mSuccessfullCount); + + if (duration > watermark.mMaxTimeMs) + { + watermark.mMaxTimeMs = System::Clock::Milliseconds32(duration); + } + + if (watermark.mMinTimeMs.count() == 0 || duration < watermark.mMinTimeMs) + { + watermark.mMinTimeMs = System::Clock::Milliseconds32(duration); + } + + if (duration > watermark.mMovingAverage) + { + watermark.mCountAboveAvg++; + } + } + + OutputTrace(tracker); +} + +void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error) +{ + TimeTracker tracker; + tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); + tracker.mEndTime = tracker.mStartTime; + tracker.mOperation = aOperation; + tracker.mType = OperationType::kInstant; + tracker.mError = error; + 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()); + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::OutputTrace(const TimeTracker & tracker) +{ + // We allow error here as we want to buffer even if the logs are currently uninitialized + OutputTimeTracker(tracker); + + if (mBufferedTrackerCount < kMaxBufferedTraces - 1) + { + mTimeTrackerList.Insert(tracker); + mBufferedTrackerCount++; + } + else if (mBufferedTrackerCount == kMaxBufferedTraces - 1) + { + // Save a tracker with TimeTraceOperation::kNumTraces and CHIP_ERROR_BUFFER_TOO_SMALL to indicate that the buffer is full + TimeTracker resourceExhaustedTracker = tracker; + resourceExhaustedTracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); + resourceExhaustedTracker.mEndTime = resourceExhaustedTracker.mStartTime; + resourceExhaustedTracker.mOperation = TimeTraceOperation::kNumTraces; + resourceExhaustedTracker.mType = OperationType::kInstant; + resourceExhaustedTracker.mError = CHIP_ERROR_BUFFER_TOO_SMALL; + mTimeTrackerList.Insert(resourceExhaustedTracker); + return CHIP_ERROR_BUFFER_TOO_SMALL; + } + else + { + return CHIP_ERROR_BUFFER_TOO_SMALL; + } + + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::OutputWaterMark(TimeTraceOperation aOperation) +{ + size_t index = static_cast(aOperation); + auto & watermark = mWatermarks[index]; + + VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED); + ChipLogProgress(DeviceLayer, + "Trace %zu: 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); + + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::OutputAllWaterMarks() +{ + for (size_t i = 0; i < kNumTraces; ++i) + { + CHIP_ERROR err = OutputWaterMark(static_cast(i)); + if (err != CHIP_NO_ERROR) + { + return err; + } + } + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::TraceBufferFlushAll() +{ + auto * current = mTimeTrackerList.head; + while (current != nullptr) + { + // We do not want to loose the traces if the logs are not initialized + ReturnErrorOnFailure(OutputTimeTracker(current->mValue)); + current = current->mpNext; + } + + TraceBufferClear(); + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::TraceBufferFlushByOperation(TimeTraceOperation aOperation) +{ + + auto * current = mTimeTrackerList.head; + auto * prev = static_cast *>(nullptr); + while (current != nullptr) + { + if (current->mValue.mOperation == aOperation) + { + ReturnErrorOnFailure(OutputTimeTracker(current->mValue)); + if (prev == nullptr) + { + mTimeTrackerList.head = current->mpNext; + } + else + { + prev->mpNext = current->mpNext; + } + auto * temp = current; + current = current->mpNext; + free(temp); + mBufferedTrackerCount--; + } + else + { + prev = current; + current = current->mpNext; + } + } + + return CHIP_NO_ERROR; +} + +// 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; +} + +#if CONFIG_BUILD_FOR_HOST_UNIT_TEST +size_t SilabsTracer::GetTraceCount() +{ + return mBufferedTrackerCount; +} + +CHIP_ERROR SilabsTracer::GetTraceByIndex(size_t index, const char *& trace) const +{ + auto * current = mTimeTrackerList.head; + for (size_t i = 0; i < index && current != nullptr; ++i) + { + current = current->mpNext; + } + VerifyOrReturnError(current != nullptr, CHIP_ERROR_INVALID_ARGUMENT); + trace = reinterpret_cast(¤t->mValue); + 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 new file mode 100644 index 0000000000..4699f708ee --- /dev/null +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -0,0 +1,289 @@ +/*************************************************************************** + * @file SilabsTracing.h + * @brief Instrumenting for matter operation tracing for the Silicon Labs platform. + ******************************************************************************* + * # License + * Copyright 2024 Silicon Laboratories Inc. www.silabs.com + ******************************************************************************* + * + * The licensor of this software is Silicon Laboratories Inc. Your use of this + * software is governed by the terms of Silicon Labs Master Software License + * Agreement (MSLA) available at + * www.silabs.com/about-us/legal/master-software-license-agreement. This + * software is distributed to you in Source Code format and is governed by the + * sections of the MSLA applicable to Source Code. + * + ******************************************************************************/ +#pragma once + +#include +#include +#include +#include +#include +#include +#include + +#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, + kImageUpload, + kImageVerification, + kAppApplyTime, + kBootup, + kSilabsInit, + kMatterInit, + kNumTraces, +}; + +enum class OperationType : uint8_t +{ + kBegin, + kEnd, + kInstant, +}; + +struct TimeTracker +{ + // Temporary values + System::Clock::Milliseconds32 mStartTime; + System::Clock::Milliseconds32 mEndTime; + TimeTraceOperation mOperation; + OperationType mType; + CHIP_ERROR mError; +}; + +struct Watermark +{ + // 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 = to_underlying(TimeTraceOperation::kNumTraces); + static constexpr size_t kMaxBufferedTraces = 64; + +public: + /** @brief Get the singleton instance of SilabsTracer */ + static SilabsTracer & Instance() { return sInstance; } + + /** @brief Initialize the SilabsTracer + * This method initializes sets the watermarks and time trackers to 0 and clears the traces buffer. + * @return CHIP_ERROR, currently no failure is implemented but when the NVM is added this will return an error if the NVM + * initialization fails. + */ + CHIP_ERROR Init(); + + /** @brief Start storing watermarks in persistent storage + * @param storage Pointer to the persistent storage delegate + * @return CHIP_ERROR, returns an error if the storage is null + */ + CHIP_ERROR StartWatermarksStorage(PersistentStorageDelegate * storage); + + /** @brief Begin 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 + */ + void 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 + */ + void 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 + */ + void 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. + * @param tracker The time tracker to output + * @return CHIP_ERROR, returns CHIP_ERROR_UNINITIALIZED if the log is not initialized + */ + CHIP_ERROR OutputTimeTracker(const TimeTracker & tracker); + + /** @brief Output a watermark for a specific operation + * @param aOperation The operation to output the watermark for + * @return CHIP_ERROR, returns CHIP_ERROR_UNINITIALIZED if the log is not initialized + */ + CHIP_ERROR OutputWaterMark(TimeTraceOperation aOperation); + + /** @brief Output all watermarks + * @return CHIP_ERROR, CHIP_ERROR_UNINITIALIZED error if any watermark output fails + */ + CHIP_ERROR OutputAllWaterMarks(); + + /** @brief Flush all traces from the buffer in the order they were added + * If logs are enabled, this will output all the traces in the buffer and clear the buffer. + * If logs are not enabled, this will throw an error and preserve the traces in the buffer. + * @return CHIP_ERROR, returns CHIP_ERROR_UNINITIALIZED if the logs are not initialized + */ + CHIP_ERROR TraceBufferFlushAll(); + + /** @brief Flush traces for a specific operation from the buffer + * If logs are enabled, this will output all the traces for the operation in the buffer and clear the buffer. + * If logs are not enabled, this will throw an error and preserve the traces in the buffer. + * @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); + + // prevent copy constructor and assignment operator + 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 + */ + CHIP_ERROR SaveWatermarks(); + + /** @brief Load the watermarks from persistent storage + * @return CHIP_ERROR, returns an error if the storage is not initialized + */ + 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 + */ + size_t GetTraceCount(); + + /** @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 + */ + CHIP_ERROR GetTraceByIndex(size_t index, const char *& trace) const; +#endif + +private: + struct TimeTrackerList + { + chip::SingleLinkedListNode * head = nullptr; + + void Insert(const TimeTracker & tracker) + { + auto * newNode = + static_cast *>(malloc(sizeof(chip::SingleLinkedListNode))); + if (newNode != nullptr) + { + newNode->mValue = tracker; + newNode->mpNext = head; + head = newNode; + } + } + + void Remove(size_t index) + { + if (index == 0 && head != nullptr) + { + auto * temp = head; + head = head->mpNext; + free(temp); + return; + } + + auto * current = head; + for (size_t i = 0; i < index - 1 && current != nullptr; ++i) + { + current = current->mpNext; + } + + if (current && current->mpNext) + { + auto * temp = current->mpNext; + current->mpNext = current->mpNext->mpNext; + free(temp); + } + } + }; + + // Singleton class with a static instance + static SilabsTracer sInstance; + + SilabsTracer(); + + // List of past time trackers + TimeTrackerList mTimeTrackerList; + + // Time trackers to store time stamps for ongoing operations + TimeTracker mLatestTimeTrackers[kNumTraces]; + + // Watermarks for each operation + Watermark mWatermarks[kNumTraces]; + + PersistentStorageDelegate * mStorage = nullptr; + + size_t mBufferedTrackerCount = 0; + + /** @brief Clear the trace buffer */ + void TraceBufferClear(); + + /** @brief Output the values of a time tracker formatted as a string + * This will log the trace if logs are enabled, fruthermore, the time tracker will be stored in the buffer if the buffer is not + * full, regardless of the logs being enabled. If the buffer is filled at capacity - -1, this will store a tracker indicating + * when the buffer full event happened for the first time. Afterwards, this will simply return CHIP_ERROR_BUFFER_TOO_SMALL. + * @param tracker The time tracker to output + * @return CHIP_ERROR, returns CHIP_ERROR_BUFFER_TOO_SMALL if the buffer is full + */ + CHIP_ERROR OutputTrace(const TimeTracker & tracker); +}; + +} // namespace Silabs +} // namespace Tracing +} // namespace chip diff --git a/src/platform/tests/BUILD.gn b/src/platform/tests/BUILD.gn index ba092e2f7e..1f7e8a4079 100644 --- a/src/platform/tests/BUILD.gn +++ b/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") diff --git a/src/platform/tests/TestSilabsTracing.cpp b/src/platform/tests/TestSilabsTracing.cpp new file mode 100644 index 0000000000..2db2bd979e --- /dev/null +++ b/src/platform/tests/TestSilabsTracing.cpp @@ -0,0 +1,603 @@ +/* + * + * Copyright (c) 2020 Project CHIP Authors + * + * 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. + */ + +/** + * @file + * This file implements a unit test suite for the Platform Time + * code functionality. + * + */ + +#include +#include +#include +#include +#include + +#include + +#include +#include +#include +#include + +#include + +#include + +using namespace chip; +using namespace chip::Logging; +using namespace chip::System; +using namespace chip::System::Clock::Literals; + +using namespace chip::Tracing::Silabs; + +namespace { +chip::System::Clock::Internal::MockClock gMockClock; +chip::System::Clock::ClockBase * gRealClock; +} // namespace + +class TestSilabsTracing : public ::testing::Test +{ +public: + static void SetUpTestSuite() + { + ASSERT_EQ(chip::Platform::MemoryInit(), CHIP_NO_ERROR); + + gRealClock = &chip::System::SystemClock(); + chip::System::Clock::Internal::SetSystemClockForTesting(&gMockClock); + } + + static void TearDownTestSuite() + { + chip::System::Clock::Internal::SetSystemClockForTesting(gRealClock); + chip::Platform::MemoryShutdown(); + } +}; + +TEST_F(TestSilabsTracing, TestTimeTrackerMethods) +{ + gMockClock.SetMonotonic(0_ms64); + size_t traceCount = 0; + + SilabsTracer::Instance().Init(); + + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 0u); + + // Start tracking time for a specific event + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); + // Simulate some delay or work + gMockClock.AdvanceMonotonic(100_ms64); + // Stop tracking time for the event + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSpake2p); + + // Retrieve the tracked time + auto timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSpake2p); + auto trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + + // Check that the tracked time is within an expected range + EXPECT_EQ(trackedTime, uint32_t(100)); + + // Retrieve the watermark for the operation + auto watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSpake2p); + + // Verify the count, moving average, highest, and lowest functionalities + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(trackedTime)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(trackedTime)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(trackedTime)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Repeat and verify the count and moving average, high and low got updated properly + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); + gMockClock.AdvanceMonotonic(150_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSpake2p); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSpake2p); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSpake2p); + EXPECT_EQ(trackedTime, uint32_t(150)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(2)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(125)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(150)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(1)); + + // Repeat for another event to verify multiple tracking works + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake1); + gMockClock.AdvanceMonotonic(50_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kPake1); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kPake1); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kPake1); + EXPECT_EQ(trackedTime, uint32_t(50)); + + // Verify the count, moving average, highest, and lowest functionalities + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), trackedTime); + EXPECT_EQ(watermark.mMaxTimeMs.count(), trackedTime); + EXPECT_EQ(watermark.mMinTimeMs.count(), trackedTime); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Repeat Again for first event to verify multiple tracking works + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSpake2p); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSpake2p); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSpake2p); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(3)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(150)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(3)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(2)); + + // Verify a double start to simulate a failure + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); + gMockClock.AdvanceMonotonic(150_ms64); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); + gMockClock.AdvanceMonotonic(110_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSpake2p); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSpake2p); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSpake2p); + EXPECT_EQ(trackedTime, uint32_t(110)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(5)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(140)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(4)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(2)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 11u); // 11 calls: 6 TimeTraceBegin and 5 TimeTraceEnd +} + +TEST_F(TestSilabsTracing, TestBootupSequence) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + + size_t traceCount = 0; + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 0u); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); + // Simulate Silabs Init + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSilabsInit); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSilabsInit); + + // Simulate Matter Init + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kMatterInit); + gMockClock.AdvanceMonotonic(300_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kMatterInit); + + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kBootup); + + // Verify the time tracker values for each operation + auto timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kBootup); + auto trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(500)); + + // Retrieve the watermark for the operation + auto watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kBootup); + + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(500)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(500)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(500)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSilabsInit); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSilabsInit); + 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)); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kMatterInit); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kMatterInit); + EXPECT_EQ(trackedTime, uint32_t(300)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(300)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(300)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(300)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // 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 + + // SilabsTracer::Instance().Init(); + + // traceCount = SilabsTracer::Instance().GetTraceCount(); + // EXPECT_EQ(traceCount, 0u); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); + + // Simulate Silabs Init + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSilabsInit); + gMockClock.AdvanceMonotonic(150_ms64); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); + // Simulate Silabs Init + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSilabsInit); + gMockClock.AdvanceMonotonic(350_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSilabsInit); + + // Simulate Matter Init + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kMatterInit); + gMockClock.AdvanceMonotonic(250_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kMatterInit); + + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kBootup); + + // Verify the time tracker values for each operation after reboot + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kBootup); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kBootup); + EXPECT_EQ(trackedTime, uint32_t(600)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(3)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(550)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(600)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(500)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(1)); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSilabsInit); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSilabsInit); + EXPECT_EQ(trackedTime, uint32_t(350)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(3)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(275)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(350)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(1)); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kMatterInit); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kMatterInit); + EXPECT_EQ(trackedTime, uint32_t(250)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(2)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(275)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(300)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(250)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 14u); // 14 calls: 8 TimeTraceBegin and 6 TimeTraceEnd +} + +TEST_F(TestSilabsTracing, TestCommissioning) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + + size_t traceCount = 0; + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 0u); + + // Simulate Spake2p steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake1); + gMockClock.AdvanceMonotonic(50_ms64); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake1); + gMockClock.AdvanceMonotonic(100_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kPake1); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake2); + gMockClock.AdvanceMonotonic(150_ms64); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake2); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kPake2); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake3); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kPake3); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSpake2p); + + // Verify the time tracker values for Spake2p + auto timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSpake2p); + auto trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(700)); + + // Retrieve the watermark for the operation + auto watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSpake2p); + + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(700)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(700)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(700)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Pake1 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kPake1); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kPake1); + EXPECT_EQ(trackedTime, uint32_t(100)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(2)); + 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 Pake2 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kPake2); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kPake2); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(2)); + 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)); + + // Verify the time tracker values for Pake3 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kPake3); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kPake3); + 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)); + + // Simulate Operational Credentials steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOperationalCredentials); + gMockClock.AdvanceMonotonic(300_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kOperationalCredentials); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kOperationalCredentials); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kOperationalCredentials); + EXPECT_EQ(trackedTime, uint32_t(300)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(300)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(300)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(300)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Simulate Transport Layer steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kTransportLayer); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kTransportSetup); + gMockClock.AdvanceMonotonic(100_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kTransportSetup); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kFindOperational); + gMockClock.AdvanceMonotonic(150_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kFindOperational); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kTransportLayer); + + // Verify the time tracker values for Transport Layer + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kTransportLayer); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kTransportLayer); + EXPECT_EQ(trackedTime, uint32_t(250)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(250)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(250)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(250)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Transport Setup + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kTransportSetup); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kTransportSetup); + EXPECT_EQ(trackedTime, uint32_t(100)); + 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 Find Operational + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kFindOperational); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kFindOperational); + EXPECT_EQ(trackedTime, uint32_t(150)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(150)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(150)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(150)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Simulate Case Session steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kCaseSession); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSigma1); + gMockClock.AdvanceMonotonic(100_ms64); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSigma1); + gMockClock.AdvanceMonotonic(100_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSigma1); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSigma2); + gMockClock.AdvanceMonotonic(150_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSigma2); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSigma3); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSigma3); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kCaseSession); + + // Verify the time tracker values for Case Session + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kCaseSession); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kCaseSession); + EXPECT_EQ(trackedTime, uint32_t(550)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(550)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(550)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(550)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Sigma1 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSigma1); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSigma1); + EXPECT_EQ(trackedTime, uint32_t(100)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(2)); + 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 Sigma2 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSigma2); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSigma2); + EXPECT_EQ(trackedTime, uint32_t(150)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(150)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(150)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(150)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Sigma3 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSigma3); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSigma3); + 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().GetTraceCount(); + EXPECT_EQ(traceCount, 27u); +} + +TEST_F(TestSilabsTracing, TestOTA) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + size_t traceCount = 0; + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 0u); + + // Simulate OTA steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOTA); + gMockClock.AdvanceMonotonic(100_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kOTA); + + // 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)); + + // Simulate OTA steps with failure + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOTA); + gMockClock.AdvanceMonotonic(150_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kOTA, CHIP_ERROR_INTERNAL); + + // Verify the time tracker values for OTA after failure + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kOTA); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kOTA); + EXPECT_EQ(trackedTime, uint32_t(150)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(2)); + 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)); + + // Simulate Bootup steps after OTA failure + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kBootup); + + // 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)); + + // Simulate subsequent OTA steps that succeed + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOTA); + gMockClock.AdvanceMonotonic(120_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kOTA); + + // Verify the time tracker values for OTA after success + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kOTA); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kOTA); + EXPECT_EQ(trackedTime, uint32_t(120)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(3)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(110)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(120)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(1)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + traceCount = SilabsTracer::Instance().GetTraceCount(); + 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.