From 984f6eed5516a2116d550cce8d2a1e770626130f Mon Sep 17 00:00:00 2001 From: lpbeliveau-silabs Date: Thu, 7 Nov 2024 16:39:47 -0500 Subject: [PATCH 1/5] 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)); +} From 40d903fc0d4a9dbc01f120fb7ca3e9c8ea2fd7a5 Mon Sep 17 00:00:00 2001 From: lpbeliveau-silabs Date: Thu, 14 Nov 2024 19:49:29 -0500 Subject: [PATCH 2/5] Modified the logging methods, added helpers and switched to a dynamical allocation for the trace buffer --- examples/platform/silabs/silabs_utils.h | 2 - src/platform/silabs/Logging.cpp | 3 +- src/platform/silabs/Logging.h | 21 ++ src/platform/silabs/tracing/SilabsTracing.cpp | 219 ++++++++++++++---- src/platform/silabs/tracing/SilabsTracing.h | 31 ++- src/platform/tests/TestSilabsTracing.cpp | 42 ++++ 6 files changed, 268 insertions(+), 50 deletions(-) create mode 100644 src/platform/silabs/Logging.h diff --git a/examples/platform/silabs/silabs_utils.h b/examples/platform/silabs/silabs_utils.h index 8c5ebfa946..93941fbf9c 100644 --- a/examples/platform/silabs/silabs_utils.h +++ b/examples/platform/silabs/silabs_utils.h @@ -24,8 +24,6 @@ extern "C" { #endif -bool isLogInitialized(void); - void silabsInitLog(void); void silabsLog(const char * aFormat, ...); diff --git a/src/platform/silabs/Logging.cpp b/src/platform/silabs/Logging.cpp index 98a23f987f..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 @@ -201,7 +202,7 @@ extern "C" void silabsLog(const char * aFormat, ...) } #ifdef SILABS_LOG_ENABLED -extern bool isLogInitialized() +bool isLogInitialized() { return sLogInitialized; } diff --git a/src/platform/silabs/Logging.h b/src/platform/silabs/Logging.h new file mode 100644 index 0000000000..4400d858f8 --- /dev/null +++ b/src/platform/silabs/Logging.h @@ -0,0 +1,21 @@ +/* + * + * Copyright (c) 2024 Silabs. + * All rights reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#pragma once + +bool isLogInitialized(void); diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp index 94a94a957a..2a7efe43c8 100644 --- a/src/platform/silabs/tracing/SilabsTracing.cpp +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -4,7 +4,7 @@ #include #if !CONFIG_BUILD_FOR_HOST_UNIT_TEST -#include // for isLogInitialized +#include // for isLogInitialized #endif // The following functions needs to be implemented by the application to allows logging or storing the traces / @@ -18,6 +18,8 @@ namespace chip { namespace Tracing { namespace Silabs { +// TODO add string mapping to log the operation names and types + static constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES; struct TimeTrackerStorage : public TimeTracker, PersistentData @@ -29,14 +31,50 @@ SilabsTracer SilabsTracer::sInstance; SilabsTracer::SilabsTracer() { - Init(); + VerifyOrDie(Init() == CHIP_NO_ERROR); } -void SilabsTracer::Init() +CHIP_ERROR SilabsTracer::TraceBufferClear() { - // Initialize the trace buffer and time trackers - memset(mTraceBuffer, 0, sizeof(mTraceBuffer)); + // Free the allocated memory for the trace buffer + if (nullptr != mTraceBuffer) + { + for (size_t i = 0; i < kBufferedTracesNumber; ++i) + { + free(mTraceBuffer[i]); + } + free(mTraceBuffer); + mTraceBuffer = nullptr; + mBufferIndex = 0; + } + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::Init() +{ + // Allows to use Init as a Reset function + ReturnErrorOnFailure(TraceBufferClear()); + + // Allocate memory for the trace buffer + mTraceBuffer = static_cast(malloc(kBufferedTracesNumber * sizeof(uint8_t *))); + VerifyOrReturnError(nullptr != mTraceBuffer, CHIP_ERROR_NO_MEMORY); + + for (size_t i = 0; i < kBufferedTracesNumber; ++i) + { + mTraceBuffer[i] = static_cast(malloc(kBufferedTraceSize * sizeof(uint8_t))); + VerifyOrReturnError(nullptr != mTraceBuffer[i], CHIP_ERROR_NO_MEMORY); + memset(mTraceBuffer[i], 0, kBufferedTraceSize); + } + + // Initialize the time trackers memset(mWatermark, 0, sizeof(mWatermark)); + + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::StartLogging() +{ + return TraceBufferFlush(); } CHIP_ERROR SilabsTracer::StartTraceStorage(PersistentStorageDelegate * storage) @@ -52,96 +90,176 @@ void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) auto & tracker = mWatermark[static_cast(aOperation)]; tracker.mTotalCount++; tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); + OutputTrace(aOperation, OperationType::kBegin, CHIP_NO_ERROR); } void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error) { if (error != CHIP_NO_ERROR) { - // Log the error, no need to update the watermark for now as we can get the error count from the - // total count - successfull count. We might want to have a separate count for errors in the future. - TimeTraceInstant(aOperation); + OutputTrace(aOperation, OperationType::kEnd, error); return; } // Calculate the duration and update the time tracker auto & tracker = mWatermark[static_cast(aOperation)]; tracker.mEndTime = System::SystemClock().GetMonotonicTimestamp(); - auto duration = (tracker.mEndTime - tracker.mStartTime).count(); + auto duration = tracker.mEndTime - tracker.mStartTime; tracker.mTotalDuration += System::Clock::Milliseconds64(duration); - if (duration > tracker.mMaxTimeMs.count()) + if (duration > tracker.mMaxTimeMs) { tracker.mMaxTimeMs = System::Clock::Milliseconds32(duration); } - if (tracker.mMinTimeMs.count() == 0 || duration < tracker.mMinTimeMs.count()) + if (tracker.mMinTimeMs.count() == 0 || duration < tracker.mMinTimeMs) { tracker.mMinTimeMs = System::Clock::Milliseconds32(duration); } tracker.mSuccessfullCount++; - tracker.mMovingAverage = System::Clock::Milliseconds32(tracker.mTotalDuration.count() / tracker.mSuccessfullCount); - if (duration > tracker.mMovingAverage.count()) + tracker.mMovingAverage = System::Clock::Milliseconds32(tracker.mTotalDuration / tracker.mSuccessfullCount); + if (duration > tracker.mMovingAverage) { tracker.mCountAboveAvg++; } + + OutputTrace(aOperation, OperationType::kEnd, CHIP_NO_ERROR); } void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error) { - if (CHIP_NO_ERROR == error) + OutputTrace(aOperation, OperationType::kInstant, error); +} + +CHIP_ERROR SilabsTracer::OutputTrace(TimeTraceOperation aOperation, OperationType type, CHIP_ERROR error) +{ + uint64_t timestamp = System::SystemClock().GetMonotonicTimestamp().count(); + uint8_t operation = static_cast(aOperation); + uint8_t opType = static_cast(type); + + if (isLogInitialized()) + { + if (error == CHIP_NO_ERROR) + { + ChipLogProgress(DeviceLayer, "Time: %" PRIu64 ", Operation: %" PRIu32 ", Type: %" PRIu32 "", timestamp, operation, + opType); + } + else + { + ChipLogError(DeviceLayer, "Time: %" PRIu64 ", Operation: %" PRIu32 ", Type: %" PRIu32 ", Error: %" CHIP_ERROR_FORMAT, + timestamp, operation, opType, error.Format()); + return CHIP_ERROR_INTERNAL; + } + } + else + { + if (mBufferIndex < kBufferedTracesNumber - 1) + { + if (error == CHIP_NO_ERROR) + { + snprintf(reinterpret_cast(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, + "Time: %" PRIu64 ", Operation: %" PRIu32 ", Type: %" PRIu32 "", timestamp, operation, opType); + } + else + { + snprintf(reinterpret_cast(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, + "Time: %" PRIu64 ", Operation: %" PRIu32 ", Type: %" PRIu32 ", Error: %" CHIP_ERROR_FORMAT, timestamp, + operation, opType, error.Format()); + } + mBufferIndex++; + } + else + { + snprintf(reinterpret_cast(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, "Buffer overflow: logs were lost"); + } + } + + return CHIP_NO_ERROR; +} + +void SilabsTracer::BufferTrace(size_t index, const TimeTracker & tracker, CHIP_ERROR error) +{ + if (mBufferIndex < kBufferedTracesNumber - 1) { - // Will be used to implement count for instant events that do not require watermarks such as failures and others - // For now, just log in that order the timestamp and the operation - ChipLogProgress(DeviceLayer, "Time: %llu, Instant Trace: %u, ", System::SystemClock().GetMonotonicTimestamp().count(), - static_cast(aOperation)); + if (error == CHIP_NO_ERROR) + { + snprintf(reinterpret_cast(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, + "Trace %zu: TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32 + ", AvgTime=%" PRIu32 ", CountAboveAvg=%" PRIu32 "", + index, tracker.mTotalCount, tracker.mSuccessfullCount, tracker.mMaxTimeMs.count(), tracker.mMinTimeMs.count(), + tracker.mMovingAverage.count(), tracker.mCountAboveAvg); + } + else + { + snprintf(reinterpret_cast(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, + "Trace %zu: Error: %" CHIP_ERROR_FORMAT, index, error.Format()); + } + mBufferIndex++; } else { - // Log the error with timestamp and operation - ChipLogError(DeviceLayer, "Time: %llu, Instant Trace: %u, Error: %" CHIP_ERROR_FORMAT, - System::SystemClock().GetMonotonicTimestamp().count(), static_cast(aOperation), error.Format()); + snprintf(reinterpret_cast(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, "Buffer overflow: logs were lost"); } } -void SilabsTracer::OutputTraces() +CHIP_ERROR SilabsTracer::OutputWaterMark(TimeTraceOperation aOperation, CHIP_ERROR error) { + size_t index = static_cast(aOperation); + auto & tracker = mWatermark[index]; + if (isLogInitialized()) { - // Output the traces from the buffer - for (size_t i = 0; i < kNumTraces; ++i) + if (error == CHIP_NO_ERROR) { - auto & tracker = mWatermark[i]; ChipLogProgress(DeviceLayer, - "Trace %zu: TotalCount=%u, SuccessFullCount=%u, MaxTime=%u, MinTime=%u, AvgTime=%u, CountAboveAvg=%u", - i, tracker.mTotalCount, tracker.mSuccessfullCount, tracker.mMaxTimeMs.count(), + "Trace %zu: TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32 + ", AvgTime=%" PRIu32 ", CountAboveAvg=%" PRIu32 "", + index, tracker.mTotalCount, tracker.mSuccessfullCount, tracker.mMaxTimeMs.count(), tracker.mMinTimeMs.count(), tracker.mMovingAverage.count(), tracker.mCountAboveAvg); } + else + { + ChipLogError(DeviceLayer, "Trace %zu: Error: %" CHIP_ERROR_FORMAT, index, error.Format()); + return CHIP_ERROR_INTERNAL; + } } else { - // Buffer the traces if logs are not initialized - static size_t bufferIndex = 0; - if (bufferIndex < kBufferedTracesNumber - 1) + BufferTrace(index, tracker, error); + } + + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::OutputAllWaterMarks() +{ + for (size_t i = 0; i < kNumTraces; ++i) + { + CHIP_ERROR err = OutputWaterMark(static_cast(i), CHIP_NO_ERROR); + if (err != CHIP_NO_ERROR) { - for (size_t i = 0; i < kNumTraces; ++i) - { - auto & tracker = mWatermark[i]; - // TODO use c++ copy string - snprintf(reinterpret_cast(mTraceBuffer[bufferIndex]), kBufferedTraceSize, - "Trace %zu: TotalCount=%u, SuccessFullCount=%u, MaxTime=%u, MinTime=%u, AvgTime=%u, CountAboveAvg=%u", i, - tracker.mTotalCount, tracker.mSuccessfullCount, tracker.mMaxTimeMs.count(), tracker.mMinTimeMs.count(), - tracker.mMovingAverage.count(), tracker.mCountAboveAvg); - bufferIndex++; - } + return err; } - else + } + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::TraceBufferFlush() +{ + if (isLogInitialized() && (nullptr != mTraceBuffer)) + { + for (size_t i = 0; i < kBufferedTracesNumber; ++i) { - snprintf(reinterpret_cast(mTraceBuffer[bufferIndex]), kBufferedTraceSize, "Buffer overflow: logs were lost"); + if (mTraceBuffer[i][0] != '\0') // Check if the buffer is not empty + { + ChipLogProgress(DeviceLayer, "%s", mTraceBuffer[i]); + } } } + + return TraceBufferClear(); } // Save the traces in the NVM @@ -159,6 +277,23 @@ CHIP_ERROR SilabsTracer::LoadWatermarks() return CHIP_NO_ERROR; } +#if CONFIG_BUILD_FOR_HOST_UNIT_TEST +CHIP_ERROR SilabsTracer::GetTraceCount(size_t & count) const +{ + VerifyOrReturnError(nullptr != mTraceBuffer, CHIP_ERROR_INCORRECT_STATE); + count = mBufferIndex; + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::GetTraceByIndex(size_t index, const char *& trace) const +{ + VerifyOrReturnError(nullptr != mTraceBuffer, CHIP_ERROR_INCORRECT_STATE); + VerifyOrReturnError(index < mBufferIndex, CHIP_ERROR_INVALID_ARGUMENT); + trace = reinterpret_cast(mTraceBuffer[index]); + return CHIP_NO_ERROR; +} +#endif + } // namespace Silabs } // namespace Tracing } // namespace chip diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h index f942683efa..b6c26702cd 100644 --- a/src/platform/silabs/tracing/SilabsTracing.h +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -16,7 +16,6 @@ */ #pragma once -// #include "silabs_utils.h" #include #include #include @@ -59,6 +58,13 @@ enum class TimeTraceOperation : uint8_t kNumTraces, }; +enum class OperationType : uint8_t +{ + kBegin, + kEnd, + kInstant, +}; + struct TimeTracker { // Temporary values @@ -86,7 +92,9 @@ class SilabsTracer public: static SilabsTracer & Instance() { return sInstance; } - void Init(); + CHIP_ERROR Init(); + + CHIP_ERROR StartLogging(); CHIP_ERROR StartTraceStorage(PersistentStorageDelegate * storage); @@ -95,14 +103,16 @@ class SilabsTracer void TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); // This Either Logs the traces or stores them in a buffer - void OutputTraces(); + CHIP_ERROR OutputWaterMark(TimeTraceOperation aOperation, CHIP_ERROR error); + CHIP_ERROR OutputAllWaterMarks(); + CHIP_ERROR TraceBufferFlush(); // 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)]; } + TimeTracker GetTimeTracker(TimeTraceOperation aOperation) { return mWatermark[to_underlying(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(); @@ -111,6 +121,11 @@ class SilabsTracer // be added to the loaded values CHIP_ERROR LoadWatermarks(); +#if CONFIG_BUILD_FOR_HOST_UNIT_TEST + CHIP_ERROR GetTraceCount(size_t & count) const; + CHIP_ERROR GetTraceByIndex(size_t index, const char *& trace) const; +#endif + private: // Singleton class with a static instance static SilabsTracer sInstance; @@ -118,12 +133,18 @@ class SilabsTracer SilabsTracer(); // Buffer to store the traces - uint8_t mTraceBuffer[kBufferedTracesNumber][kBufferedTraceSize]; + uint8_t ** mTraceBuffer = nullptr; // Time trackers for each operation TimeTracker mWatermark[kNumTraces]; PersistentStorageDelegate * mStorage = nullptr; + + size_t mBufferIndex = 0; + + CHIP_ERROR TraceBufferClear(); + void BufferTrace(size_t index, const TimeTracker & tracker, CHIP_ERROR error); + CHIP_ERROR OutputTrace(TimeTraceOperation aOperation, OperationType type, CHIP_ERROR error); }; } // namespace Silabs diff --git a/src/platform/tests/TestSilabsTracing.cpp b/src/platform/tests/TestSilabsTracing.cpp index f1f50f1952..68f7d89f67 100644 --- a/src/platform/tests/TestSilabsTracing.cpp +++ b/src/platform/tests/TestSilabsTracing.cpp @@ -76,8 +76,13 @@ class TestSilabsTracing : public ::testing::Test TEST_F(TestSilabsTracing, TestTimeTrackerMethods) { gMockClock.SetMonotonic(0_ms64); + size_t traceCount = 0; + SilabsTracer::Instance().Init(); + EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + EXPECT_EQ(traceCount, 0u); + // Start tracking time for a specific event SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); // Simulate some delay or work @@ -163,6 +168,10 @@ TEST_F(TestSilabsTracing, TestTimeTrackerMethods) EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(100)); EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(4)); EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(2)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + EXPECT_EQ(traceCount, 11u); // 11 calls: 6 TimeTraceBegin and 5 TimeTraceEnd } TEST_F(TestSilabsTracing, TestBootupSequence) @@ -170,6 +179,10 @@ TEST_F(TestSilabsTracing, TestBootupSequence) gMockClock.SetMonotonic(0_ms64); SilabsTracer::Instance().Init(); + size_t traceCount = 0; + EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + EXPECT_EQ(traceCount, 0u); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); // Simulate Silabs Init SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSilabsInit); @@ -216,6 +229,14 @@ 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 + + // SilabsTracer::Instance().Init(); + + // EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + // EXPECT_EQ(traceCount, 0u); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); // Simulate Silabs Init @@ -265,6 +286,10 @@ TEST_F(TestSilabsTracing, TestBootupSequence) EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(250)); EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(2)); EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + EXPECT_EQ(traceCount, 14u); // 14 calls: 8 TimeTraceBegin and 6 TimeTraceEnd } TEST_F(TestSilabsTracing, TestCommissioning) @@ -272,6 +297,10 @@ TEST_F(TestSilabsTracing, TestCommissioning) gMockClock.SetMonotonic(0_ms64); SilabsTracer::Instance().Init(); + size_t traceCount = 0; + EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + EXPECT_EQ(traceCount, 0u); + // Simulate Spake2p steps SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake1); @@ -454,12 +483,19 @@ TEST_F(TestSilabsTracing, TestCommissioning) EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(200)); EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(1)); EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(0)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + EXPECT_EQ(traceCount, 27u); } TEST_F(TestSilabsTracing, TestOTA) { gMockClock.SetMonotonic(0_ms64); SilabsTracer::Instance().Init(); + size_t traceCount = 0; + EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + EXPECT_EQ(traceCount, 0u); // Simulate OTA steps SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOTA); @@ -524,4 +560,10 @@ TEST_F(TestSilabsTracing, TestOTA) EXPECT_EQ(timeTracker.mMinTimeMs.count(), uint32_t(100)); EXPECT_EQ(timeTracker.mSuccessfullCount, uint32_t(2)); EXPECT_EQ(timeTracker.mCountAboveAvg, uint32_t(1)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + 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. From dc8cb19a0fd61cb5467f69097edc820c27234576 Mon Sep 17 00:00:00 2001 From: lpbeliveau-silabs Date: Fri, 15 Nov 2024 16:30:29 -0500 Subject: [PATCH 3/5] Updated the tracing structures, added metrics for OTA and now using a list and buffering traces of events --- src/platform/silabs/tracing/SilabsTracing.cpp | 284 +++++++------- src/platform/silabs/tracing/SilabsTracing.h | 93 ++++- src/platform/tests/TestSilabsTracing.cpp | 364 ++++++++++-------- 3 files changed, 405 insertions(+), 336 deletions(-) diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp index 2a7efe43c8..5a1c5de607 100644 --- a/src/platform/silabs/tracing/SilabsTracing.cpp +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -34,50 +34,28 @@ SilabsTracer::SilabsTracer() VerifyOrDie(Init() == CHIP_NO_ERROR); } -CHIP_ERROR SilabsTracer::TraceBufferClear() +void SilabsTracer::TraceBufferClear() { - // Free the allocated memory for the trace buffer - if (nullptr != mTraceBuffer) + // Clear the time tracker list + while (mTimeTrackerList.head != nullptr) { - for (size_t i = 0; i < kBufferedTracesNumber; ++i) - { - free(mTraceBuffer[i]); - } - free(mTraceBuffer); - mTraceBuffer = nullptr; - mBufferIndex = 0; + mTimeTrackerList.Remove(0); } - return CHIP_NO_ERROR; + mBufferedTrackerCount = 0; } CHIP_ERROR SilabsTracer::Init() { - // Allows to use Init as a Reset function - ReturnErrorOnFailure(TraceBufferClear()); - - // Allocate memory for the trace buffer - mTraceBuffer = static_cast(malloc(kBufferedTracesNumber * sizeof(uint8_t *))); - VerifyOrReturnError(nullptr != mTraceBuffer, CHIP_ERROR_NO_MEMORY); - - for (size_t i = 0; i < kBufferedTracesNumber; ++i) - { - mTraceBuffer[i] = static_cast(malloc(kBufferedTraceSize * sizeof(uint8_t))); - VerifyOrReturnError(nullptr != mTraceBuffer[i], CHIP_ERROR_NO_MEMORY); - memset(mTraceBuffer[i], 0, kBufferedTraceSize); - } + TraceBufferClear(); // Initialize the time trackers - memset(mWatermark, 0, sizeof(mWatermark)); + memset(mTimeTrackers, 0, sizeof(mTimeTrackers)); + memset(mWatermarks, 0, sizeof(mWatermarks)); return CHIP_NO_ERROR; } -CHIP_ERROR SilabsTracer::StartLogging() -{ - return TraceBufferFlush(); -} - -CHIP_ERROR SilabsTracer::StartTraceStorage(PersistentStorageDelegate * storage) +CHIP_ERROR SilabsTracer::StartWatermarksStorage(PersistentStorageDelegate * storage) { VerifyOrReturnError(nullptr != storage, CHIP_ERROR_INCORRECT_STATE); mStorage = storage; @@ -87,148 +65,114 @@ CHIP_ERROR SilabsTracer::StartTraceStorage(PersistentStorageDelegate * storage) void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) { // Log the start time of the operation - auto & tracker = mWatermark[static_cast(aOperation)]; - tracker.mTotalCount++; + auto & tracker = mTimeTrackers[static_cast(aOperation)]; tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); - OutputTrace(aOperation, OperationType::kBegin, CHIP_NO_ERROR); + 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) { - if (error != CHIP_NO_ERROR) - { - OutputTrace(aOperation, OperationType::kEnd, error); - return; - } - - // Calculate the duration and update the time tracker - auto & tracker = mWatermark[static_cast(aOperation)]; + auto & tracker = mTimeTrackers[static_cast(aOperation)]; tracker.mEndTime = System::SystemClock().GetMonotonicTimestamp(); - auto duration = tracker.mEndTime - tracker.mStartTime; - - tracker.mTotalDuration += System::Clock::Milliseconds64(duration); + tracker.mType = OperationType::kEnd; + tracker.mError = error; - if (duration > tracker.mMaxTimeMs) + if (error == CHIP_NO_ERROR) { - tracker.mMaxTimeMs = System::Clock::Milliseconds32(duration); - } + // Calculate the duration and update the time tracker + auto duration = tracker.mEndTime - tracker.mStartTime; - if (tracker.mMinTimeMs.count() == 0 || duration < tracker.mMinTimeMs) - { - tracker.mMinTimeMs = System::Clock::Milliseconds32(duration); - } + auto & watermark = mWatermarks[static_cast(aOperation)]; + watermark.mSuccessfullCount++; + watermark.mMovingAverage = System::Clock::Milliseconds32( + (watermark.mMovingAverage.count() * (watermark.mSuccessfullCount - 1) + duration.count()) / + watermark.mSuccessfullCount); - tracker.mSuccessfullCount++; - tracker.mMovingAverage = System::Clock::Milliseconds32(tracker.mTotalDuration / tracker.mSuccessfullCount); - if (duration > tracker.mMovingAverage) - { - tracker.mCountAboveAvg++; + 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(aOperation, OperationType::kEnd, CHIP_NO_ERROR); + OutputTrace(tracker); } void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error) { - OutputTrace(aOperation, OperationType::kInstant, error); + auto & tracker = mTimeTrackers[static_cast(aOperation)]; + tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); + tracker.mEndTime = tracker.mStartTime; + tracker.mOperation = aOperation; + tracker.mType = OperationType::kInstant; + tracker.mError = error; + OutputTrace(tracker); } -CHIP_ERROR SilabsTracer::OutputTrace(TimeTraceOperation aOperation, OperationType type, CHIP_ERROR error) +CHIP_ERROR SilabsTracer::OutputTimeTracker(const TimeTracker & tracker) { - uint64_t timestamp = System::SystemClock().GetMonotonicTimestamp().count(); - uint8_t operation = static_cast(aOperation); - uint8_t opType = static_cast(type); - - if (isLogInitialized()) - { - if (error == CHIP_NO_ERROR) - { - ChipLogProgress(DeviceLayer, "Time: %" PRIu64 ", Operation: %" PRIu32 ", Type: %" PRIu32 "", timestamp, operation, - opType); - } - else - { - ChipLogError(DeviceLayer, "Time: %" PRIu64 ", Operation: %" PRIu32 ", Type: %" PRIu32 ", Error: %" CHIP_ERROR_FORMAT, - timestamp, operation, opType, error.Format()); - return CHIP_ERROR_INTERNAL; - } - } - else - { - if (mBufferIndex < kBufferedTracesNumber - 1) - { - if (error == CHIP_NO_ERROR) - { - snprintf(reinterpret_cast(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, - "Time: %" PRIu64 ", Operation: %" PRIu32 ", Type: %" PRIu32 "", timestamp, operation, opType); - } - else - { - snprintf(reinterpret_cast(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, - "Time: %" PRIu64 ", Operation: %" PRIu32 ", Type: %" PRIu32 ", Error: %" CHIP_ERROR_FORMAT, timestamp, - operation, opType, error.Format()); - } - mBufferIndex++; - } - else - { - snprintf(reinterpret_cast(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, "Buffer overflow: logs were lost"); - } - } - + 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; } -void SilabsTracer::BufferTrace(size_t index, const TimeTracker & tracker, CHIP_ERROR error) +CHIP_ERROR SilabsTracer::OutputTrace(const TimeTracker & tracker) { - if (mBufferIndex < kBufferedTracesNumber - 1) + // We allow error here as we want to buffer even if the logs are currently uninitialized + OutputTimeTracker(tracker); + + if (mBufferedTrackerCount < kMaxBufferedTraces - 1) { - if (error == CHIP_NO_ERROR) - { - snprintf(reinterpret_cast(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, - "Trace %zu: TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32 - ", AvgTime=%" PRIu32 ", CountAboveAvg=%" PRIu32 "", - index, tracker.mTotalCount, tracker.mSuccessfullCount, tracker.mMaxTimeMs.count(), tracker.mMinTimeMs.count(), - tracker.mMovingAverage.count(), tracker.mCountAboveAvg); - } - else - { - snprintf(reinterpret_cast(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, - "Trace %zu: Error: %" CHIP_ERROR_FORMAT, index, error.Format()); - } - mBufferIndex++; + mTimeTrackerList.Insert(tracker); + mBufferedTrackerCount++; } else { - snprintf(reinterpret_cast(mTraceBuffer[mBufferIndex]), kBufferedTraceSize, "Buffer overflow: logs were lost"); + // Save a tracker with 0xFFFF 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; } + + return CHIP_NO_ERROR; } -CHIP_ERROR SilabsTracer::OutputWaterMark(TimeTraceOperation aOperation, CHIP_ERROR error) +CHIP_ERROR SilabsTracer::OutputWaterMark(TimeTraceOperation aOperation) { - size_t index = static_cast(aOperation); - auto & tracker = mWatermark[index]; + size_t index = static_cast(aOperation); + auto & watermark = mWatermarks[index]; - if (isLogInitialized()) - { - if (error == CHIP_NO_ERROR) - { - ChipLogProgress(DeviceLayer, - "Trace %zu: TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32 - ", AvgTime=%" PRIu32 ", CountAboveAvg=%" PRIu32 "", - index, tracker.mTotalCount, tracker.mSuccessfullCount, tracker.mMaxTimeMs.count(), - tracker.mMinTimeMs.count(), tracker.mMovingAverage.count(), tracker.mCountAboveAvg); - } - else - { - ChipLogError(DeviceLayer, "Trace %zu: Error: %" CHIP_ERROR_FORMAT, index, error.Format()); - return CHIP_ERROR_INTERNAL; - } - } - else - { - BufferTrace(index, tracker, error); - } + 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; } @@ -237,7 +181,7 @@ CHIP_ERROR SilabsTracer::OutputAllWaterMarks() { for (size_t i = 0; i < kNumTraces; ++i) { - CHIP_ERROR err = OutputWaterMark(static_cast(i), CHIP_NO_ERROR); + CHIP_ERROR err = OutputWaterMark(static_cast(i)); if (err != CHIP_NO_ERROR) { return err; @@ -246,20 +190,51 @@ CHIP_ERROR SilabsTracer::OutputAllWaterMarks() return CHIP_NO_ERROR; } -CHIP_ERROR SilabsTracer::TraceBufferFlush() +CHIP_ERROR SilabsTracer::TraceBufferFlushAll() { - if (isLogInitialized() && (nullptr != mTraceBuffer)) + auto * current = mTimeTrackerList.head; + while (current != nullptr) { - for (size_t i = 0; i < kBufferedTracesNumber; ++i) + // 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) { - if (mTraceBuffer[i][0] != '\0') // Check if the buffer is not empty + ReturnErrorOnFailure(OutputTimeTracker(current->mValue)); + if (prev == nullptr) { - ChipLogProgress(DeviceLayer, "%s", mTraceBuffer[i]); + 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 TraceBufferClear(); + return CHIP_NO_ERROR; } // Save the traces in the NVM @@ -280,16 +255,19 @@ CHIP_ERROR SilabsTracer::LoadWatermarks() #if CONFIG_BUILD_FOR_HOST_UNIT_TEST CHIP_ERROR SilabsTracer::GetTraceCount(size_t & count) const { - VerifyOrReturnError(nullptr != mTraceBuffer, CHIP_ERROR_INCORRECT_STATE); - count = mBufferIndex; + count = mBufferedTrackerCount; return CHIP_NO_ERROR; } CHIP_ERROR SilabsTracer::GetTraceByIndex(size_t index, const char *& trace) const { - VerifyOrReturnError(nullptr != mTraceBuffer, CHIP_ERROR_INCORRECT_STATE); - VerifyOrReturnError(index < mBufferIndex, CHIP_ERROR_INVALID_ARGUMENT); - trace = reinterpret_cast(mTraceBuffer[index]); + 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 diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h index b6c26702cd..696696b959 100644 --- a/src/platform/silabs/tracing/SilabsTracing.h +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -17,8 +17,10 @@ #pragma once #include +#include #include #include +#include #include #include @@ -52,6 +54,9 @@ enum class TimeTraceOperation : uint8_t kSigma2, kSigma3, kOTA, + kImageUpload, + kImageVerification, + kAppApplyTime, kBootup, kSilabsInit, kMatterInit, @@ -68,10 +73,15 @@ enum class OperationType : uint8_t struct TimeTracker { // Temporary values - System::Clock::Milliseconds64 mStartTime; - System::Clock::Milliseconds64 mEndTime; - System::Clock::Milliseconds64 mTotalDuration; + 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 @@ -85,34 +95,34 @@ struct TimeTracker // class SilabsTracer { - static constexpr size_t kNumTraces = static_cast(TimeTraceOperation::kNumTraces); - static constexpr size_t kBufferedTracesNumber = 64; - static constexpr size_t kBufferedTraceSize = 128; + static constexpr size_t kNumTraces = to_underlying(TimeTraceOperation::kNumTraces); + static constexpr size_t kMaxBufferedTraces = 64; public: static SilabsTracer & Instance() { return sInstance; } CHIP_ERROR Init(); - CHIP_ERROR StartLogging(); - - CHIP_ERROR StartTraceStorage(PersistentStorageDelegate * storage); + CHIP_ERROR StartWatermarksStorage(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 - CHIP_ERROR OutputWaterMark(TimeTraceOperation aOperation, CHIP_ERROR error); + CHIP_ERROR OutputTimeTracker(const TimeTracker & tracker); + CHIP_ERROR OutputWaterMark(TimeTraceOperation aOperation); CHIP_ERROR OutputAllWaterMarks(); - CHIP_ERROR TraceBufferFlush(); + CHIP_ERROR TraceBufferFlushAll(); + CHIP_ERROR TraceBufferFlushByOperation(TimeTraceOperation aOperation); // 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[to_underlying(aOperation)]; } + TimeTracker GetTimeTracker(TimeTraceOperation aOperation) { return mTimeTrackers[to_underlying(aOperation)]; } + Watermark GetWatermark(TimeTraceOperation aOperation) { return mWatermarks[to_underlying(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(); @@ -127,24 +137,67 @@ class SilabsTracer #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(); - // Buffer to store the traces - uint8_t ** mTraceBuffer = nullptr; + // List of past time trackers + TimeTrackerList mTimeTrackerList; + + // Time trackers to store time stamps for ongoing operations + TimeTracker mTimeTrackers[kNumTraces]; - // Time trackers for each operation - TimeTracker mWatermark[kNumTraces]; + // Watermarks for each operation + Watermark mWatermarks[kNumTraces]; PersistentStorageDelegate * mStorage = nullptr; - size_t mBufferIndex = 0; + size_t mBufferedTrackerCount = 0; - CHIP_ERROR TraceBufferClear(); - void BufferTrace(size_t index, const TimeTracker & tracker, CHIP_ERROR error); - CHIP_ERROR OutputTrace(TimeTraceOperation aOperation, OperationType type, CHIP_ERROR error); + void TraceBufferClear(); + CHIP_ERROR OutputTrace(const TimeTracker & tracker); }; } // namespace Silabs diff --git a/src/platform/tests/TestSilabsTracing.cpp b/src/platform/tests/TestSilabsTracing.cpp index 68f7d89f67..45991893e1 100644 --- a/src/platform/tests/TestSilabsTracing.cpp +++ b/src/platform/tests/TestSilabsTracing.cpp @@ -97,13 +97,16 @@ TEST_F(TestSilabsTracing, TestTimeTrackerMethods) // 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(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)); + 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); @@ -112,13 +115,14 @@ TEST_F(TestSilabsTracing, TestTimeTrackerMethods) 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(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)); + 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); @@ -127,15 +131,16 @@ TEST_F(TestSilabsTracing, TestTimeTrackerMethods) 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(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)); + 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); @@ -144,13 +149,14 @@ TEST_F(TestSilabsTracing, TestTimeTrackerMethods) 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(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)); + 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); @@ -161,13 +167,14 @@ TEST_F(TestSilabsTracing, TestTimeTrackerMethods) 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(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)); + 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 EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); @@ -200,32 +207,38 @@ TEST_F(TestSilabsTracing, TestBootupSequence) 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)); + + // 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(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)); + 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(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)); + 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); @@ -259,33 +272,36 @@ TEST_F(TestSilabsTracing, TestBootupSequence) // 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(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)); + 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(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)); + 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(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)); + 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 EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); @@ -324,45 +340,52 @@ TEST_F(TestSilabsTracing, TestCommissioning) 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)); + + // 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(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)); + 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(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)); + 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(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)); + 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); @@ -371,13 +394,14 @@ TEST_F(TestSilabsTracing, TestCommissioning) 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(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)); + 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); @@ -393,35 +417,38 @@ TEST_F(TestSilabsTracing, TestCommissioning) // 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(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)); + 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(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)); + 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(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)); + 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); @@ -443,46 +470,50 @@ TEST_F(TestSilabsTracing, TestCommissioning) // 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(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)); + 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(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)); + 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(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)); + 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(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)); + 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 EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); @@ -506,12 +537,16 @@ TEST_F(TestSilabsTracing, TestOTA) 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)); + + // 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); @@ -521,13 +556,14 @@ TEST_F(TestSilabsTracing, TestOTA) // 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)); + 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); @@ -537,13 +573,14 @@ TEST_F(TestSilabsTracing, TestOTA) // 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(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)); + 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); @@ -553,13 +590,14 @@ TEST_F(TestSilabsTracing, TestOTA) // 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(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)); + 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 EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); From 889037a4a62e413017081ff01625539dbe3ce3ad Mon Sep 17 00:00:00 2001 From: lpbeliveau-silabs Date: Fri, 15 Nov 2024 19:19:56 -0500 Subject: [PATCH 4/5] Renamed mTimeTrackers to mLatestTimeTrackers for the sake of clarity --- src/platform/silabs/tracing/SilabsTracing.cpp | 8 ++++---- src/platform/silabs/tracing/SilabsTracing.h | 4 ++-- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp index 5a1c5de607..159194c6e3 100644 --- a/src/platform/silabs/tracing/SilabsTracing.cpp +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -49,7 +49,7 @@ CHIP_ERROR SilabsTracer::Init() TraceBufferClear(); // Initialize the time trackers - memset(mTimeTrackers, 0, sizeof(mTimeTrackers)); + memset(mLatestTimeTrackers, 0, sizeof(mLatestTimeTrackers)); memset(mWatermarks, 0, sizeof(mWatermarks)); return CHIP_NO_ERROR; @@ -65,7 +65,7 @@ CHIP_ERROR SilabsTracer::StartWatermarksStorage(PersistentStorageDelegate * stor void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) { // Log the start time of the operation - auto & tracker = mTimeTrackers[static_cast(aOperation)]; + auto & tracker = mLatestTimeTrackers[static_cast(aOperation)]; tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); tracker.mOperation = aOperation; tracker.mType = OperationType::kBegin; @@ -79,7 +79,7 @@ void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error) { - auto & tracker = mTimeTrackers[static_cast(aOperation)]; + auto & tracker = mLatestTimeTrackers[static_cast(aOperation)]; tracker.mEndTime = System::SystemClock().GetMonotonicTimestamp(); tracker.mType = OperationType::kEnd; tracker.mError = error; @@ -116,7 +116,7 @@ void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error) void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error) { - auto & tracker = mTimeTrackers[static_cast(aOperation)]; + TimeTracker tracker; tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); tracker.mEndTime = tracker.mStartTime; tracker.mOperation = aOperation; diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h index 696696b959..c0930f0906 100644 --- a/src/platform/silabs/tracing/SilabsTracing.h +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -121,7 +121,7 @@ class SilabsTracer SilabsTracer & operator=(SilabsTracer const &) = delete; // Methods to get the time trackers metrics values - TimeTracker GetTimeTracker(TimeTraceOperation aOperation) { return mTimeTrackers[to_underlying(aOperation)]; } + TimeTracker GetTimeTracker(TimeTraceOperation aOperation) { return mLatestTimeTrackers[to_underlying(aOperation)]; } Watermark GetWatermark(TimeTraceOperation aOperation) { return mWatermarks[to_underlying(aOperation)]; } // Method to save the time trackers in the NVM, this will likely be time consuming and should not be called frequently @@ -187,7 +187,7 @@ class SilabsTracer TimeTrackerList mTimeTrackerList; // Time trackers to store time stamps for ongoing operations - TimeTracker mTimeTrackers[kNumTraces]; + TimeTracker mLatestTimeTrackers[kNumTraces]; // Watermarks for each operation Watermark mWatermarks[kNumTraces]; From 4a224836f0be909b42301b37845d01a0e008a632 Mon Sep 17 00:00:00 2001 From: lpbeliveau-silabs Date: Mon, 18 Nov 2024 16:18:46 -0500 Subject: [PATCH 5/5] Added commenting, licensing and addressed styling comments --- src/platform/silabs/Logging.h | 19 +-- src/platform/silabs/tracing/BUILD.gn | 17 +++ src/platform/silabs/tracing/SilabsTracing.cpp | 35 +++-- src/platform/silabs/tracing/SilabsTracing.h | 124 +++++++++++++++--- src/platform/tests/TestSilabsTracing.cpp | 22 ++-- 5 files changed, 158 insertions(+), 59 deletions(-) diff --git a/src/platform/silabs/Logging.h b/src/platform/silabs/Logging.h index 4400d858f8..f12b97b3f6 100644 --- a/src/platform/silabs/Logging.h +++ b/src/platform/silabs/Logging.h @@ -1,21 +1,4 @@ -/* - * - * Copyright (c) 2024 Silabs. - * All rights reserved. - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ - +/* 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 index a745864502..78b339d19c 100644 --- a/src/platform/silabs/tracing/BUILD.gn +++ b/src/platform/silabs/tracing/BUILD.gn @@ -1,3 +1,20 @@ +#/*************************************************************************** +# * @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") diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp index 159194c6e3..dc88ba45d0 100644 --- a/src/platform/silabs/tracing/SilabsTracing.cpp +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -1,3 +1,19 @@ +/*************************************************************************** + * @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 @@ -19,9 +35,9 @@ namespace Tracing { namespace Silabs { // TODO add string mapping to log the operation names and types - -static constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES; - +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 @@ -146,9 +162,9 @@ CHIP_ERROR SilabsTracer::OutputTrace(const TimeTracker & tracker) mTimeTrackerList.Insert(tracker); mBufferedTrackerCount++; } - else + else if (mBufferedTrackerCount == kMaxBufferedTraces - 1) { - // Save a tracker with 0xFFFF to indicate that the buffer is full + // 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; @@ -158,6 +174,10 @@ CHIP_ERROR SilabsTracer::OutputTrace(const TimeTracker & tracker) mTimeTrackerList.Insert(resourceExhaustedTracker); return CHIP_ERROR_BUFFER_TOO_SMALL; } + else + { + return CHIP_ERROR_BUFFER_TOO_SMALL; + } return CHIP_NO_ERROR; } @@ -253,10 +273,9 @@ CHIP_ERROR SilabsTracer::LoadWatermarks() } #if CONFIG_BUILD_FOR_HOST_UNIT_TEST -CHIP_ERROR SilabsTracer::GetTraceCount(size_t & count) const +size_t SilabsTracer::GetTraceCount() { - count = mBufferedTrackerCount; - return CHIP_NO_ERROR; + return mBufferedTrackerCount; } CHIP_ERROR SilabsTracer::GetTraceByIndex(size_t index, const char *& trace) const diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h index c0930f0906..4699f708ee 100644 --- a/src/platform/silabs/tracing/SilabsTracing.h +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -1,19 +1,19 @@ -/* - * Copyright (c) 2024 Project CHIP Authors - * All rights reserved. +/*************************************************************************** + * @file SilabsTracing.h + * @brief Instrumenting for matter operation tracing for the Silicon Labs platform. + ******************************************************************************* + * # License + * Copyright 2024 Silicon Laboratories Inc. www.silabs.com + ******************************************************************************* * - * 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 + * 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. * - * 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 @@ -99,40 +99,115 @@ class SilabsTracer 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); - // This Either Logs the traces or stores them in a buffer + /** @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; - // 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 + */ 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)]; } - // Method to save the time trackers in the NVM, this will likely be time consuming and should not be called frequently + /** @brief Save the watermarks to persistent storage + * @return CHIP_ERROR, returns an error if the storage is not initialized + */ 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 + /** @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 - CHIP_ERROR GetTraceCount(size_t & count) const; + /** @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 @@ -196,7 +271,16 @@ class SilabsTracer 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); }; diff --git a/src/platform/tests/TestSilabsTracing.cpp b/src/platform/tests/TestSilabsTracing.cpp index 45991893e1..2db2bd979e 100644 --- a/src/platform/tests/TestSilabsTracing.cpp +++ b/src/platform/tests/TestSilabsTracing.cpp @@ -51,10 +51,6 @@ chip::System::Clock::Internal::MockClock gMockClock; chip::System::Clock::ClockBase * gRealClock; } // namespace -// ================================= -// Unit tests -// ================================= - class TestSilabsTracing : public ::testing::Test { public: @@ -80,7 +76,7 @@ TEST_F(TestSilabsTracing, TestTimeTrackerMethods) SilabsTracer::Instance().Init(); - EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTraceCount(); EXPECT_EQ(traceCount, 0u); // Start tracking time for a specific event @@ -177,7 +173,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 - EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTraceCount(); EXPECT_EQ(traceCount, 11u); // 11 calls: 6 TimeTraceBegin and 5 TimeTraceEnd } @@ -187,7 +183,7 @@ TEST_F(TestSilabsTracing, TestBootupSequence) SilabsTracer::Instance().Init(); size_t traceCount = 0; - EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTraceCount(); EXPECT_EQ(traceCount, 0u); SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); @@ -247,7 +243,7 @@ TEST_F(TestSilabsTracing, TestBootupSequence) // SilabsTracer::Instance().Init(); - // EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + // traceCount = SilabsTracer::Instance().GetTraceCount(); // EXPECT_EQ(traceCount, 0u); SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); @@ -304,7 +300,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 - EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTraceCount(); EXPECT_EQ(traceCount, 14u); // 14 calls: 8 TimeTraceBegin and 6 TimeTraceEnd } @@ -314,7 +310,7 @@ TEST_F(TestSilabsTracing, TestCommissioning) SilabsTracer::Instance().Init(); size_t traceCount = 0; - EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTraceCount(); EXPECT_EQ(traceCount, 0u); // Simulate Spake2p steps @@ -516,7 +512,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 - EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTraceCount(); EXPECT_EQ(traceCount, 27u); } @@ -525,7 +521,7 @@ TEST_F(TestSilabsTracing, TestOTA) gMockClock.SetMonotonic(0_ms64); SilabsTracer::Instance().Init(); size_t traceCount = 0; - EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTraceCount(); EXPECT_EQ(traceCount, 0u); // Simulate OTA steps @@ -600,7 +596,7 @@ TEST_F(TestSilabsTracing, TestOTA) EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(1)); // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls - EXPECT_EQ(SilabsTracer::Instance().GetTraceCount(traceCount), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTraceCount(); EXPECT_EQ(traceCount, 8u); // 8 calls: 4 TimeTraceBegin and 4 TimeTraceEnd }