From 984f6eed5516a2116d550cce8d2a1e770626130f Mon Sep 17 00:00:00 2001 From: lpbeliveau-silabs Date: Thu, 7 Nov 2024 16:39:47 -0500 Subject: [PATCH] Initial tracing and test, need to compile from CSA and then to move tests out of src/platformtests Initial Silabs Tracing object and unit tests. Next step: create silabs matter tracing backend object and integrate in our Base App / main --- examples/platform/silabs/silabs_utils.h | 2 + src/platform/silabs/Logging.cpp | 7 + src/platform/silabs/tracing/BUILD.gn | 16 + src/platform/silabs/tracing/SilabsTracing.cpp | 164 ++++++ src/platform/silabs/tracing/SilabsTracing.h | 131 +++++ src/platform/tests/BUILD.gn | 3 + src/platform/tests/TestSilabsTracing.cpp | 527 ++++++++++++++++++ 7 files changed, 850 insertions(+) create mode 100644 src/platform/silabs/tracing/BUILD.gn create mode 100644 src/platform/silabs/tracing/SilabsTracing.cpp create mode 100644 src/platform/silabs/tracing/SilabsTracing.h create mode 100644 src/platform/tests/TestSilabsTracing.cpp diff --git a/examples/platform/silabs/silabs_utils.h b/examples/platform/silabs/silabs_utils.h index 93941fbf9c..8c5ebfa946 100644 --- a/examples/platform/silabs/silabs_utils.h +++ b/examples/platform/silabs/silabs_utils.h @@ -24,6 +24,8 @@ extern "C" { #endif +bool isLogInitialized(void); + void silabsInitLog(void); void silabsLog(const char * aFormat, ...); diff --git a/src/platform/silabs/Logging.cpp b/src/platform/silabs/Logging.cpp index dea8913791..98a23f987f 100644 --- a/src/platform/silabs/Logging.cpp +++ b/src/platform/silabs/Logging.cpp @@ -200,6 +200,13 @@ extern "C" void silabsLog(const char * aFormat, ...) va_end(v); } +#ifdef SILABS_LOG_ENABLED +extern bool isLogInitialized() +{ + return sLogInitialized; +} +#endif // SILABS_LOG_ENABLED + namespace chip { namespace DeviceLayer { diff --git a/src/platform/silabs/tracing/BUILD.gn b/src/platform/silabs/tracing/BUILD.gn new file mode 100644 index 0000000000..a745864502 --- /dev/null +++ b/src/platform/silabs/tracing/BUILD.gn @@ -0,0 +1,16 @@ +import("//build_overrides/build.gni") +import("//build_overrides/chip.gni") + +static_library("SilabsTracing") { + sources = [ + "SilabsTracing.cpp", + "SilabsTracing.h", + ] + + deps = [ + "${chip_root}/src/lib/core", + "${chip_root}/src/lib/support", + "${chip_root}/src/platform", + "${chip_root}/src/system", + ] +} diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp new file mode 100644 index 0000000000..94a94a957a --- /dev/null +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -0,0 +1,164 @@ +#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 { + +static constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES; + +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() +{ + Init(); +} + +void SilabsTracer::Init() +{ + // Initialize the trace buffer and time trackers + memset(mTraceBuffer, 0, sizeof(mTraceBuffer)); + memset(mWatermark, 0, sizeof(mWatermark)); +} + +CHIP_ERROR SilabsTracer::StartTraceStorage(PersistentStorageDelegate * storage) +{ + VerifyOrReturnError(nullptr != storage, CHIP_ERROR_INCORRECT_STATE); + mStorage = storage; + return CHIP_NO_ERROR; +} + +void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) +{ + // Log the start time of the operation + auto & tracker = mWatermark[static_cast(aOperation)]; + tracker.mTotalCount++; + tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); +} + +void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error) +{ + if (error != CHIP_NO_ERROR) + { + // Log the error, no need to update the watermark for now as we can get the error count from the + // total count - successfull count. We might want to have a separate count for errors in the future. + TimeTraceInstant(aOperation); + return; + } + + // Calculate the duration and update the time tracker + auto & tracker = mWatermark[static_cast(aOperation)]; + tracker.mEndTime = System::SystemClock().GetMonotonicTimestamp(); + auto duration = (tracker.mEndTime - tracker.mStartTime).count(); + + tracker.mTotalDuration += System::Clock::Milliseconds64(duration); + + if (duration > tracker.mMaxTimeMs.count()) + { + tracker.mMaxTimeMs = System::Clock::Milliseconds32(duration); + } + + if (tracker.mMinTimeMs.count() == 0 || duration < tracker.mMinTimeMs.count()) + { + tracker.mMinTimeMs = System::Clock::Milliseconds32(duration); + } + + tracker.mSuccessfullCount++; + tracker.mMovingAverage = System::Clock::Milliseconds32(tracker.mTotalDuration.count() / tracker.mSuccessfullCount); + if (duration > tracker.mMovingAverage.count()) + { + tracker.mCountAboveAvg++; + } +} + +void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error) +{ + if (CHIP_NO_ERROR == error) + { + // Will be used to implement count for instant events that do not require watermarks such as failures and others + // For now, just log in that order the timestamp and the operation + ChipLogProgress(DeviceLayer, "Time: %llu, Instant Trace: %u, ", System::SystemClock().GetMonotonicTimestamp().count(), + static_cast(aOperation)); + } + else + { + // Log the error with timestamp and operation + ChipLogError(DeviceLayer, "Time: %llu, Instant Trace: %u, Error: %" CHIP_ERROR_FORMAT, + System::SystemClock().GetMonotonicTimestamp().count(), static_cast(aOperation), error.Format()); + } +} + +void SilabsTracer::OutputTraces() +{ + if (isLogInitialized()) + { + // Output the traces from the buffer + for (size_t i = 0; i < kNumTraces; ++i) + { + auto & tracker = mWatermark[i]; + ChipLogProgress(DeviceLayer, + "Trace %zu: TotalCount=%u, SuccessFullCount=%u, MaxTime=%u, MinTime=%u, AvgTime=%u, CountAboveAvg=%u", + i, tracker.mTotalCount, tracker.mSuccessfullCount, tracker.mMaxTimeMs.count(), + tracker.mMinTimeMs.count(), tracker.mMovingAverage.count(), tracker.mCountAboveAvg); + } + } + else + { + // Buffer the traces if logs are not initialized + static size_t bufferIndex = 0; + if (bufferIndex < kBufferedTracesNumber - 1) + { + for (size_t i = 0; i < kNumTraces; ++i) + { + auto & tracker = mWatermark[i]; + // TODO use c++ copy string + snprintf(reinterpret_cast(mTraceBuffer[bufferIndex]), kBufferedTraceSize, + "Trace %zu: TotalCount=%u, SuccessFullCount=%u, MaxTime=%u, MinTime=%u, AvgTime=%u, CountAboveAvg=%u", i, + tracker.mTotalCount, tracker.mSuccessfullCount, tracker.mMaxTimeMs.count(), tracker.mMinTimeMs.count(), + tracker.mMovingAverage.count(), tracker.mCountAboveAvg); + bufferIndex++; + } + } + else + { + snprintf(reinterpret_cast(mTraceBuffer[bufferIndex]), kBufferedTraceSize, "Buffer overflow: logs were lost"); + } + } +} + +// Save the traces in the NVM +CHIP_ERROR SilabsTracer::SaveWatermarks() +{ + VerifyOrReturnError(nullptr != mStorage, CHIP_ERROR_INCORRECT_STATE); + // TODO implement the save of the watermarks in the NVM + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::LoadWatermarks() +{ + VerifyOrReturnError(nullptr != mStorage, CHIP_ERROR_INCORRECT_STATE); + // TODO implement the load of the watermarks from the NVM + return CHIP_NO_ERROR; +} + +} // namespace Silabs +} // namespace Tracing +} // namespace chip diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h new file mode 100644 index 0000000000..f942683efa --- /dev/null +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -0,0 +1,131 @@ +/* + * Copyright (c) 2024 Project CHIP Authors + * All rights reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +#pragma once + +// #include "silabs_utils.h" +#include +#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, + kBootup, + kSilabsInit, + kMatterInit, + kNumTraces, +}; + +struct TimeTracker +{ + // Temporary values + System::Clock::Milliseconds64 mStartTime; + System::Clock::Milliseconds64 mEndTime; + System::Clock::Milliseconds64 mTotalDuration; + + // Values that will be stored in the NVM + System::Clock::Milliseconds32 mMovingAverage; // Successful operation average time + System::Clock::Milliseconds32 mMaxTimeMs; // Successful operation max time + System::Clock::Milliseconds32 mMinTimeMs; // Successful operation min time + uint32_t mTotalCount; // Total number of times the operation was initiated + uint32_t mSuccessfullCount; // Number of times the operation was completed without error + uint32_t mCountAboveAvg; // Number of times the operation was above the average time +}; + +// This class instantiates a buffer to store the traces before logs are enabled. +// +class SilabsTracer +{ + static constexpr size_t kNumTraces = static_cast(TimeTraceOperation::kNumTraces); + static constexpr size_t kBufferedTracesNumber = 64; + static constexpr size_t kBufferedTraceSize = 128; + +public: + static SilabsTracer & Instance() { return sInstance; } + + void Init(); + + CHIP_ERROR StartTraceStorage(PersistentStorageDelegate * storage); + + void TimeTraceBegin(TimeTraceOperation aOperation); + void TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); + void TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); + + // This Either Logs the traces or stores them in a buffer + void OutputTraces(); + + // prevent copy constructor and assignment operator + SilabsTracer(SilabsTracer const &) = delete; + SilabsTracer & operator=(SilabsTracer const &) = delete; + + // Methods to get the time trackers metrics values + TimeTracker GetTimeTracker(TimeTraceOperation aOperation) { return mWatermark[static_cast(aOperation)]; } + + // Method to save the time trackers in the NVM, this will likely be time consuming and should not be called frequently + CHIP_ERROR SaveWatermarks(); + + // Method to load the time trackers from the NVM, this will be called after the initialization so the bootup watermarks need to + // be added to the loaded values + CHIP_ERROR LoadWatermarks(); + +private: + // Singleton class with a static instance + static SilabsTracer sInstance; + + SilabsTracer(); + + // Buffer to store the traces + uint8_t mTraceBuffer[kBufferedTracesNumber][kBufferedTraceSize]; + + // Time trackers for each operation + TimeTracker mWatermark[kNumTraces]; + + PersistentStorageDelegate * mStorage = nullptr; +}; + +} // namespace Silabs +} // namespace Tracing +} // namespace chip 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..f1f50f1952 --- /dev/null +++ b/src/platform/tests/TestSilabsTracing.cpp @@ -0,0 +1,527 @@ +/* + * + * 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 + +// ================================= +// Unit tests +// ================================= + +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); + SilabsTracer::Instance().Init(); + + // 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)); + + // Verify the count, moving average, highest, and lowest functionalities + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(trackedTime)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(trackedTime)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(trackedTime)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.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(); + EXPECT_EQ(trackedTime, uint32_t(150)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(2)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(125)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(150)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(timeTracker.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(); + EXPECT_EQ(trackedTime, uint32_t(50)); + + // Verify the count, moving average, highest, and lowest functionalities + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), trackedTime); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), trackedTime); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), trackedTime); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.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(); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(3)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(150)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(3)); + EXPECT_EQ(timeTracker.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(); + EXPECT_EQ(trackedTime, uint32_t(110)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(5)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(140)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(4)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(2)); +} + +TEST_F(TestSilabsTracing, TestBootupSequence) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + + 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)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(500)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(500)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(500)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSilabsInit); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kMatterInit); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(300)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(300)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(300)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(300)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); + + // Simulate a second simulation where we have a reboot during Silabs Init + gMockClock.SetMonotonic(0_ms64); + 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(); + EXPECT_EQ(trackedTime, uint32_t(600)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(3)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(550)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(600)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(500)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(1)); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSilabsInit); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(350)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(3)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(275)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(350)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(1)); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kMatterInit); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(250)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(2)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(275)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(300)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(250)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); +} + +TEST_F(TestSilabsTracing, TestCommissioning) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + + // 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)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(700)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(700)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(700)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Pake1 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kPake1); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(100)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(2)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Pake2 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kPake2); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(2)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Pake3 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kPake3); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.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(); + EXPECT_EQ(trackedTime, uint32_t(300)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(300)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(300)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(300)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.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(); + EXPECT_EQ(trackedTime, uint32_t(250)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(250)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(250)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(250)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.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(); + EXPECT_EQ(trackedTime, uint32_t(100)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.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(); + EXPECT_EQ(trackedTime, uint32_t(150)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(150)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(150)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(150)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.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(); + EXPECT_EQ(trackedTime, uint32_t(550)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(550)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(550)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(550)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Sigma1 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSigma1); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(100)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(2)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Sigma2 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSigma2); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(150)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(150)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(150)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(150)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Sigma3 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSigma3); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); +} + +TEST_F(TestSilabsTracing, TestOTA) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + + // 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)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.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(); + EXPECT_EQ(trackedTime, uint32_t(0)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(2)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.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(); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(1)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(timeTracker.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(); + EXPECT_EQ(trackedTime, uint32_t(120)); + EXPECT_EQ(timeTracker.mTotalCount, uint32_t(3)); + EXPECT_EQ(timeTracker.mMovingAverage.count(), uint32_t(110)); + EXPECT_EQ(timeTracker.mMaxTimeMs.count(), uint32_t(120)); + EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(1)); +}