From d0cfea813a38077607ce5d86cf2b7df6d2a43249 Mon Sep 17 00:00:00 2001 From: lpbeliveau-silabs <112982107+lpbeliveau-silabs@users.noreply.github.com> Date: Mon, 18 Nov 2024 19:58:05 -0500 Subject: [PATCH 1/2] [SL-ONLY] Initial SilabsTracing object (#106) --- src/platform/silabs/Logging.cpp | 8 + src/platform/silabs/Logging.h | 4 + src/platform/silabs/tracing/BUILD.gn | 33 + src/platform/silabs/tracing/SilabsTracing.cpp | 296 +++++++++ src/platform/silabs/tracing/SilabsTracing.h | 289 +++++++++ src/platform/tests/BUILD.gn | 3 + src/platform/tests/TestSilabsTracing.cpp | 603 ++++++++++++++++++ 7 files changed, 1236 insertions(+) create mode 100644 src/platform/silabs/Logging.h 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/src/platform/silabs/Logging.cpp b/src/platform/silabs/Logging.cpp index 339bc8ae07..16a64d693f 100644 --- a/src/platform/silabs/Logging.cpp +++ b/src/platform/silabs/Logging.cpp @@ -1,5 +1,6 @@ /* See Project CHIP LICENSE file for licensing information. */ #include +#include #include #include @@ -200,6 +201,13 @@ extern "C" void silabsLog(const char * aFormat, ...) va_end(v); } +#ifdef SILABS_LOG_ENABLED +bool isLogInitialized() +{ + return sLogInitialized; +} +#endif // SILABS_LOG_ENABLED + namespace chip { namespace DeviceLayer { diff --git a/src/platform/silabs/Logging.h b/src/platform/silabs/Logging.h new file mode 100644 index 0000000000..f12b97b3f6 --- /dev/null +++ b/src/platform/silabs/Logging.h @@ -0,0 +1,4 @@ +/* See Project CHIP LICENSE file for licensing information. */ +#pragma once + +bool isLogInitialized(void); diff --git a/src/platform/silabs/tracing/BUILD.gn b/src/platform/silabs/tracing/BUILD.gn new file mode 100644 index 0000000000..78b339d19c --- /dev/null +++ b/src/platform/silabs/tracing/BUILD.gn @@ -0,0 +1,33 @@ +#/*************************************************************************** +# * @file BUILD.gn +# * @brief Instrumenting for matter operation tracing for the Silicon Labs platform. +# ******************************************************************************* +# * # License +# * Copyright 2024 Silicon Laboratories Inc. www.silabs.com +# ******************************************************************************* +# * +# * The licensor of this software is Silicon Laboratories Inc. Your use of this +# * software is governed by the terms of Silicon Labs Master Software License +# * Agreement (MSLA) available at +# * www.silabs.com/about-us/legal/master-software-license-agreement. This +# * software is distributed to you in Source Code format and is governed by the +# * sections of the MSLA applicable to Source Code. +# * +# ******************************************************************************/ + +import("//build_overrides/build.gni") +import("//build_overrides/chip.gni") + +static_library("SilabsTracing") { + sources = [ + "SilabsTracing.cpp", + "SilabsTracing.h", + ] + + deps = [ + "${chip_root}/src/lib/core", + "${chip_root}/src/lib/support", + "${chip_root}/src/platform", + "${chip_root}/src/system", + ] +} diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp new file mode 100644 index 0000000000..dc88ba45d0 --- /dev/null +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -0,0 +1,296 @@ +/*************************************************************************** + * @file SilabsTracing.cpp + * @brief Instrumenting for matter operation tracing for the Silicon Labs platform. + ******************************************************************************* + * # License + * Copyright 2024 Silicon Laboratories Inc. www.silabs.com + ******************************************************************************* + * + * The licensor of this software is Silicon Laboratories Inc. Your use of this + * software is governed by the terms of Silicon Labs Master Software License + * Agreement (MSLA) available at + * www.silabs.com/about-us/legal/master-software-license-agreement. This + * software is distributed to you in Source Code format and is governed by the + * sections of the MSLA applicable to Source Code. + * + ******************************************************************************/ +#include "SilabsTracing.h" +#include +#include +#include + +#if !CONFIG_BUILD_FOR_HOST_UNIT_TEST +#include // for isLogInitialized +#endif + +// The following functions needs to be implemented by the application to allows logging or storing the traces / +// metrics. If the application does not implement them, the traces will simply be ignored. +bool __attribute__((weak)) isLogInitialized() +{ + return false; +} + +namespace chip { +namespace Tracing { +namespace Silabs { + +// TODO add string mapping to log the operation names and types +namespace { +constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES; +} // namespace +struct TimeTrackerStorage : public TimeTracker, PersistentData +{ + // TODO implement the Persistent Array class and use it here for logging the watermark array +}; + +SilabsTracer SilabsTracer::sInstance; + +SilabsTracer::SilabsTracer() +{ + VerifyOrDie(Init() == CHIP_NO_ERROR); +} + +void SilabsTracer::TraceBufferClear() +{ + // Clear the time tracker list + while (mTimeTrackerList.head != nullptr) + { + mTimeTrackerList.Remove(0); + } + mBufferedTrackerCount = 0; +} + +CHIP_ERROR SilabsTracer::Init() +{ + TraceBufferClear(); + + // Initialize the time trackers + memset(mLatestTimeTrackers, 0, sizeof(mLatestTimeTrackers)); + memset(mWatermarks, 0, sizeof(mWatermarks)); + + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::StartWatermarksStorage(PersistentStorageDelegate * storage) +{ + VerifyOrReturnError(nullptr != storage, CHIP_ERROR_INCORRECT_STATE); + mStorage = storage; + return CHIP_NO_ERROR; +} + +void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) +{ + // Log the start time of the operation + auto & tracker = mLatestTimeTrackers[static_cast(aOperation)]; + tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); + tracker.mOperation = aOperation; + tracker.mType = OperationType::kBegin; + tracker.mError = CHIP_NO_ERROR; + + auto & watermark = mWatermarks[static_cast(aOperation)]; + watermark.mTotalCount++; + + OutputTrace(tracker); +} + +void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error) +{ + auto & tracker = mLatestTimeTrackers[static_cast(aOperation)]; + tracker.mEndTime = System::SystemClock().GetMonotonicTimestamp(); + tracker.mType = OperationType::kEnd; + tracker.mError = error; + + if (error == CHIP_NO_ERROR) + { + // Calculate the duration and update the time tracker + auto duration = tracker.mEndTime - tracker.mStartTime; + + auto & watermark = mWatermarks[static_cast(aOperation)]; + watermark.mSuccessfullCount++; + watermark.mMovingAverage = System::Clock::Milliseconds32( + (watermark.mMovingAverage.count() * (watermark.mSuccessfullCount - 1) + duration.count()) / + watermark.mSuccessfullCount); + + if (duration > watermark.mMaxTimeMs) + { + watermark.mMaxTimeMs = System::Clock::Milliseconds32(duration); + } + + if (watermark.mMinTimeMs.count() == 0 || duration < watermark.mMinTimeMs) + { + watermark.mMinTimeMs = System::Clock::Milliseconds32(duration); + } + + if (duration > watermark.mMovingAverage) + { + watermark.mCountAboveAvg++; + } + } + + OutputTrace(tracker); +} + +void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error) +{ + TimeTracker tracker; + tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); + tracker.mEndTime = tracker.mStartTime; + tracker.mOperation = aOperation; + tracker.mType = OperationType::kInstant; + tracker.mError = error; + OutputTrace(tracker); +} + +CHIP_ERROR SilabsTracer::OutputTimeTracker(const TimeTracker & tracker) +{ + VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED); + ChipLogProgress(DeviceLayer, + "TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Operation: %" PRIu8 ", Type: %" PRIu8 + ", Error: %" CHIP_ERROR_FORMAT, + tracker.mStartTime.count(), tracker.mEndTime.count(), static_cast(tracker.mOperation), + static_cast(tracker.mType), tracker.mError.Format()); + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::OutputTrace(const TimeTracker & tracker) +{ + // We allow error here as we want to buffer even if the logs are currently uninitialized + OutputTimeTracker(tracker); + + if (mBufferedTrackerCount < kMaxBufferedTraces - 1) + { + mTimeTrackerList.Insert(tracker); + mBufferedTrackerCount++; + } + else if (mBufferedTrackerCount == kMaxBufferedTraces - 1) + { + // Save a tracker with TimeTraceOperation::kNumTraces and CHIP_ERROR_BUFFER_TOO_SMALL to indicate that the buffer is full + TimeTracker resourceExhaustedTracker = tracker; + resourceExhaustedTracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); + resourceExhaustedTracker.mEndTime = resourceExhaustedTracker.mStartTime; + resourceExhaustedTracker.mOperation = TimeTraceOperation::kNumTraces; + resourceExhaustedTracker.mType = OperationType::kInstant; + resourceExhaustedTracker.mError = CHIP_ERROR_BUFFER_TOO_SMALL; + mTimeTrackerList.Insert(resourceExhaustedTracker); + return CHIP_ERROR_BUFFER_TOO_SMALL; + } + else + { + return CHIP_ERROR_BUFFER_TOO_SMALL; + } + + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::OutputWaterMark(TimeTraceOperation aOperation) +{ + size_t index = static_cast(aOperation); + auto & watermark = mWatermarks[index]; + + VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED); + ChipLogProgress(DeviceLayer, + "Trace %zu: TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32 + ", AvgTime=%" PRIu32 ", CountAboveAvg=%" PRIu32 "", + index, watermark.mTotalCount, watermark.mSuccessfullCount, watermark.mMaxTimeMs.count(), + watermark.mMinTimeMs.count(), watermark.mMovingAverage.count(), watermark.mCountAboveAvg); + + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::OutputAllWaterMarks() +{ + for (size_t i = 0; i < kNumTraces; ++i) + { + CHIP_ERROR err = OutputWaterMark(static_cast(i)); + if (err != CHIP_NO_ERROR) + { + return err; + } + } + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::TraceBufferFlushAll() +{ + auto * current = mTimeTrackerList.head; + while (current != nullptr) + { + // We do not want to loose the traces if the logs are not initialized + ReturnErrorOnFailure(OutputTimeTracker(current->mValue)); + current = current->mpNext; + } + + TraceBufferClear(); + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::TraceBufferFlushByOperation(TimeTraceOperation aOperation) +{ + + auto * current = mTimeTrackerList.head; + auto * prev = static_cast *>(nullptr); + while (current != nullptr) + { + if (current->mValue.mOperation == aOperation) + { + ReturnErrorOnFailure(OutputTimeTracker(current->mValue)); + if (prev == nullptr) + { + mTimeTrackerList.head = current->mpNext; + } + else + { + prev->mpNext = current->mpNext; + } + auto * temp = current; + current = current->mpNext; + free(temp); + mBufferedTrackerCount--; + } + else + { + prev = current; + current = current->mpNext; + } + } + + return CHIP_NO_ERROR; +} + +// Save the traces in the NVM +CHIP_ERROR SilabsTracer::SaveWatermarks() +{ + VerifyOrReturnError(nullptr != mStorage, CHIP_ERROR_INCORRECT_STATE); + // TODO implement the save of the watermarks in the NVM + return CHIP_NO_ERROR; +} + +CHIP_ERROR SilabsTracer::LoadWatermarks() +{ + VerifyOrReturnError(nullptr != mStorage, CHIP_ERROR_INCORRECT_STATE); + // TODO implement the load of the watermarks from the NVM + return CHIP_NO_ERROR; +} + +#if CONFIG_BUILD_FOR_HOST_UNIT_TEST +size_t SilabsTracer::GetTraceCount() +{ + return mBufferedTrackerCount; +} + +CHIP_ERROR SilabsTracer::GetTraceByIndex(size_t index, const char *& trace) const +{ + auto * current = mTimeTrackerList.head; + for (size_t i = 0; i < index && current != nullptr; ++i) + { + current = current->mpNext; + } + VerifyOrReturnError(current != nullptr, CHIP_ERROR_INVALID_ARGUMENT); + trace = reinterpret_cast(¤t->mValue); + return CHIP_NO_ERROR; +} +#endif + +} // namespace Silabs +} // namespace Tracing +} // namespace chip diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h new file mode 100644 index 0000000000..4699f708ee --- /dev/null +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -0,0 +1,289 @@ +/*************************************************************************** + * @file SilabsTracing.h + * @brief Instrumenting for matter operation tracing for the Silicon Labs platform. + ******************************************************************************* + * # License + * Copyright 2024 Silicon Laboratories Inc. www.silabs.com + ******************************************************************************* + * + * The licensor of this software is Silicon Laboratories Inc. Your use of this + * software is governed by the terms of Silicon Labs Master Software License + * Agreement (MSLA) available at + * www.silabs.com/about-us/legal/master-software-license-agreement. This + * software is distributed to you in Source Code format and is governed by the + * sections of the MSLA applicable to Source Code. + * + ******************************************************************************/ +#pragma once + +#include +#include +#include +#include +#include +#include +#include + +#ifndef SERIALIZED_TIME_TRACKERS_SIZE_BYTES +// Default size, watermarks store 6 uint32_t, which is 24 bytes +// We currently have 19 operations to track, so 19 * 24 = 456 bytes +// 512 bytes should be enough including the serialization overhead +#define SERIALIZED_TIME_TRACKERS_SIZE_BYTES 512 +#endif + +namespace chip { +namespace Tracing { +namespace Silabs { + +// Enum for the different operation to trace +enum class TimeTraceOperation : uint8_t +{ + kSpake2p, + kPake1, + kPake2, + kPake3, + kOperationalCredentials, + kAttestationVerification, + kCSR, + kNOC, + kTransportLayer, + kTransportSetup, + kFindOperational, + kCaseSession, + kSigma1, + kSigma2, + kSigma3, + kOTA, + kImageUpload, + kImageVerification, + kAppApplyTime, + kBootup, + kSilabsInit, + kMatterInit, + kNumTraces, +}; + +enum class OperationType : uint8_t +{ + kBegin, + kEnd, + kInstant, +}; + +struct TimeTracker +{ + // Temporary values + System::Clock::Milliseconds32 mStartTime; + System::Clock::Milliseconds32 mEndTime; + TimeTraceOperation mOperation; + OperationType mType; + CHIP_ERROR mError; +}; + +struct Watermark +{ + // Values that will be stored in the NVM + System::Clock::Milliseconds32 mMovingAverage; // Successful operation average time + System::Clock::Milliseconds32 mMaxTimeMs; // Successful operation max time + System::Clock::Milliseconds32 mMinTimeMs; // Successful operation min time + uint32_t mTotalCount; // Total number of times the operation was initiated + uint32_t mSuccessfullCount; // Number of times the operation was completed without error + uint32_t mCountAboveAvg; // Number of times the operation was above the average time +}; + +// This class instantiates a buffer to store the traces before logs are enabled. +// +class SilabsTracer +{ + static constexpr size_t kNumTraces = to_underlying(TimeTraceOperation::kNumTraces); + static constexpr size_t kMaxBufferedTraces = 64; + +public: + /** @brief Get the singleton instance of SilabsTracer */ + static SilabsTracer & Instance() { return sInstance; } + + /** @brief Initialize the SilabsTracer + * This method initializes sets the watermarks and time trackers to 0 and clears the traces buffer. + * @return CHIP_ERROR, currently no failure is implemented but when the NVM is added this will return an error if the NVM + * initialization fails. + */ + CHIP_ERROR Init(); + + /** @brief Start storing watermarks in persistent storage + * @param storage Pointer to the persistent storage delegate + * @return CHIP_ERROR, returns an error if the storage is null + */ + CHIP_ERROR StartWatermarksStorage(PersistentStorageDelegate * storage); + + /** @brief Begin tracing a time operation + * This calls the OutputTrace method to log the trace if logs are enabled, and stores the time tracker in the buffer if the + * buffer is not full. + * @param aOperation + */ + void TimeTraceBegin(TimeTraceOperation aOperation); + + /** @brief End tracing a time operation + * This calls the OutputTrace method to log the trace if logs are enabled, and stores the time tracker in the buffer if the + * buffer is not full. + * @param aOperation + * @param error + */ + void TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); + + /** @brief Trace an instant time operation + * This calls the OutputTrace method to log the trace if logs are enabled, and stores the time tracker in the buffer if the + * buffer is not full. + * @param aOperation + * @param error + */ + void TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); + + /** @brief Output a time tracker + * This will output the latest time tracker for a specific operation, without affecting the buffer. + * @param tracker The time tracker to output + * @return CHIP_ERROR, returns CHIP_ERROR_UNINITIALIZED if the log is not initialized + */ + CHIP_ERROR OutputTimeTracker(const TimeTracker & tracker); + + /** @brief Output a watermark for a specific operation + * @param aOperation The operation to output the watermark for + * @return CHIP_ERROR, returns CHIP_ERROR_UNINITIALIZED if the log is not initialized + */ + CHIP_ERROR OutputWaterMark(TimeTraceOperation aOperation); + + /** @brief Output all watermarks + * @return CHIP_ERROR, CHIP_ERROR_UNINITIALIZED error if any watermark output fails + */ + CHIP_ERROR OutputAllWaterMarks(); + + /** @brief Flush all traces from the buffer in the order they were added + * If logs are enabled, this will output all the traces in the buffer and clear the buffer. + * If logs are not enabled, this will throw an error and preserve the traces in the buffer. + * @return CHIP_ERROR, returns CHIP_ERROR_UNINITIALIZED if the logs are not initialized + */ + CHIP_ERROR TraceBufferFlushAll(); + + /** @brief Flush traces for a specific operation from the buffer + * If logs are enabled, this will output all the traces for the operation in the buffer and clear the buffer. + * If logs are not enabled, this will throw an error and preserve the traces in the buffer. + * @param aOperation The operation to flush traces for + * @return CHIP_ERROR, returns CHIP_ERROR_UNINITIALIZED if the logs are not initialized + */ + CHIP_ERROR TraceBufferFlushByOperation(TimeTraceOperation aOperation); + + // prevent copy constructor and assignment operator + SilabsTracer(SilabsTracer const &) = delete; + SilabsTracer & operator=(SilabsTracer const &) = delete; + + /** @brief Get the latest time tracker for a specific operation + * @param aOperation The operation to get the time tracker for + * @return TimeTracker, the latest time tracker for the operation + */ + TimeTracker GetTimeTracker(TimeTraceOperation aOperation) { return mLatestTimeTrackers[to_underlying(aOperation)]; } + + /** @brief Get the watermark for a specific operation + * @param aOperation The operation to get the watermark for + * @return Watermark, the watermark for the operation + */ + Watermark GetWatermark(TimeTraceOperation aOperation) { return mWatermarks[to_underlying(aOperation)]; } + + /** @brief Save the watermarks to persistent storage + * @return CHIP_ERROR, returns an error if the storage is not initialized + */ + CHIP_ERROR SaveWatermarks(); + + /** @brief Load the watermarks from persistent storage + * @return CHIP_ERROR, returns an error if the storage is not initialized + */ + CHIP_ERROR LoadWatermarks(); + +#if CONFIG_BUILD_FOR_HOST_UNIT_TEST + /** @brief Get the count of buffered traces + * @param count Reference to store the count of buffered traces + */ + size_t GetTraceCount(); + + /** @brief Get a trace by its index + * @param index The index of the trace to retrieve + * @param trace Reference to store the trace + * @return CHIP_ERROR, returns CHIP_ERROR_INVALID_ARGUMENT if the index is invalid + */ + CHIP_ERROR GetTraceByIndex(size_t index, const char *& trace) const; +#endif + +private: + struct TimeTrackerList + { + chip::SingleLinkedListNode * head = nullptr; + + void Insert(const TimeTracker & tracker) + { + auto * newNode = + static_cast *>(malloc(sizeof(chip::SingleLinkedListNode))); + if (newNode != nullptr) + { + newNode->mValue = tracker; + newNode->mpNext = head; + head = newNode; + } + } + + void Remove(size_t index) + { + if (index == 0 && head != nullptr) + { + auto * temp = head; + head = head->mpNext; + free(temp); + return; + } + + auto * current = head; + for (size_t i = 0; i < index - 1 && current != nullptr; ++i) + { + current = current->mpNext; + } + + if (current && current->mpNext) + { + auto * temp = current->mpNext; + current->mpNext = current->mpNext->mpNext; + free(temp); + } + } + }; + + // Singleton class with a static instance + static SilabsTracer sInstance; + + SilabsTracer(); + + // List of past time trackers + TimeTrackerList mTimeTrackerList; + + // Time trackers to store time stamps for ongoing operations + TimeTracker mLatestTimeTrackers[kNumTraces]; + + // Watermarks for each operation + Watermark mWatermarks[kNumTraces]; + + PersistentStorageDelegate * mStorage = nullptr; + + size_t mBufferedTrackerCount = 0; + + /** @brief Clear the trace buffer */ + void TraceBufferClear(); + + /** @brief Output the values of a time tracker formatted as a string + * This will log the trace if logs are enabled, fruthermore, the time tracker will be stored in the buffer if the buffer is not + * full, regardless of the logs being enabled. If the buffer is filled at capacity - -1, this will store a tracker indicating + * when the buffer full event happened for the first time. Afterwards, this will simply return CHIP_ERROR_BUFFER_TOO_SMALL. + * @param tracker The time tracker to output + * @return CHIP_ERROR, returns CHIP_ERROR_BUFFER_TOO_SMALL if the buffer is full + */ + CHIP_ERROR OutputTrace(const TimeTracker & tracker); +}; + +} // namespace Silabs +} // namespace Tracing +} // namespace chip diff --git a/src/platform/tests/BUILD.gn b/src/platform/tests/BUILD.gn index ba092e2f7e..1f7e8a4079 100644 --- a/src/platform/tests/BUILD.gn +++ b/src/platform/tests/BUILD.gn @@ -92,6 +92,9 @@ if (chip_device_platform != "none" && chip_device_platform != "fake") { if (chip_device_platform == "linux") { test_sources += [ "TestConnectivityMgr.cpp" ] } + + test_sources += [ "TestSilabsTracing.cpp" ] + public_deps += [ "${chip_root}/src/platform/silabs/tracing:SilabsTracing" ] } } else { import("${chip_root}/build/chip/chip_test_group.gni") diff --git a/src/platform/tests/TestSilabsTracing.cpp b/src/platform/tests/TestSilabsTracing.cpp new file mode 100644 index 0000000000..2db2bd979e --- /dev/null +++ b/src/platform/tests/TestSilabsTracing.cpp @@ -0,0 +1,603 @@ +/* + * + * Copyright (c) 2020 Project CHIP Authors + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +/** + * @file + * This file implements a unit test suite for the Platform Time + * code functionality. + * + */ + +#include +#include +#include +#include +#include + +#include + +#include +#include +#include +#include + +#include + +#include + +using namespace chip; +using namespace chip::Logging; +using namespace chip::System; +using namespace chip::System::Clock::Literals; + +using namespace chip::Tracing::Silabs; + +namespace { +chip::System::Clock::Internal::MockClock gMockClock; +chip::System::Clock::ClockBase * gRealClock; +} // namespace + +class TestSilabsTracing : public ::testing::Test +{ +public: + static void SetUpTestSuite() + { + ASSERT_EQ(chip::Platform::MemoryInit(), CHIP_NO_ERROR); + + gRealClock = &chip::System::SystemClock(); + chip::System::Clock::Internal::SetSystemClockForTesting(&gMockClock); + } + + static void TearDownTestSuite() + { + chip::System::Clock::Internal::SetSystemClockForTesting(gRealClock); + chip::Platform::MemoryShutdown(); + } +}; + +TEST_F(TestSilabsTracing, TestTimeTrackerMethods) +{ + gMockClock.SetMonotonic(0_ms64); + size_t traceCount = 0; + + SilabsTracer::Instance().Init(); + + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 0u); + + // Start tracking time for a specific event + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); + // Simulate some delay or work + gMockClock.AdvanceMonotonic(100_ms64); + // Stop tracking time for the event + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSpake2p); + + // Retrieve the tracked time + auto timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSpake2p); + auto trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + + // Check that the tracked time is within an expected range + EXPECT_EQ(trackedTime, uint32_t(100)); + + // Retrieve the watermark for the operation + auto watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSpake2p); + + // Verify the count, moving average, highest, and lowest functionalities + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(trackedTime)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(trackedTime)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(trackedTime)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Repeat and verify the count and moving average, high and low got updated properly + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); + gMockClock.AdvanceMonotonic(150_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSpake2p); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSpake2p); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSpake2p); + EXPECT_EQ(trackedTime, uint32_t(150)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(2)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(125)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(150)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(1)); + + // Repeat for another event to verify multiple tracking works + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake1); + gMockClock.AdvanceMonotonic(50_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kPake1); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kPake1); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kPake1); + EXPECT_EQ(trackedTime, uint32_t(50)); + + // Verify the count, moving average, highest, and lowest functionalities + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), trackedTime); + EXPECT_EQ(watermark.mMaxTimeMs.count(), trackedTime); + EXPECT_EQ(watermark.mMinTimeMs.count(), trackedTime); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Repeat Again for first event to verify multiple tracking works + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSpake2p); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSpake2p); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSpake2p); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(3)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(150)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(3)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(2)); + + // Verify a double start to simulate a failure + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); + gMockClock.AdvanceMonotonic(150_ms64); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); + gMockClock.AdvanceMonotonic(110_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSpake2p); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSpake2p); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSpake2p); + EXPECT_EQ(trackedTime, uint32_t(110)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(5)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(140)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(4)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(2)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 11u); // 11 calls: 6 TimeTraceBegin and 5 TimeTraceEnd +} + +TEST_F(TestSilabsTracing, TestBootupSequence) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + + size_t traceCount = 0; + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 0u); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); + // Simulate Silabs Init + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSilabsInit); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSilabsInit); + + // Simulate Matter Init + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kMatterInit); + gMockClock.AdvanceMonotonic(300_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kMatterInit); + + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kBootup); + + // Verify the time tracker values for each operation + auto timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kBootup); + auto trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(500)); + + // Retrieve the watermark for the operation + auto watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kBootup); + + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(500)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(500)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(500)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSilabsInit); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSilabsInit); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kMatterInit); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kMatterInit); + EXPECT_EQ(trackedTime, uint32_t(300)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(300)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(300)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(300)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Simulate a second simulation where we have a reboot during Silabs Init + gMockClock.SetMonotonic(0_ms64); + // TODO : Here we simulate that we have restore the number of traces from NVM so we do not do the Init, we should call it and + // call the LoadWatermarks method here + + // SilabsTracer::Instance().Init(); + + // traceCount = SilabsTracer::Instance().GetTraceCount(); + // EXPECT_EQ(traceCount, 0u); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); + + // Simulate Silabs Init + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSilabsInit); + gMockClock.AdvanceMonotonic(150_ms64); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); + // Simulate Silabs Init + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSilabsInit); + gMockClock.AdvanceMonotonic(350_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSilabsInit); + + // Simulate Matter Init + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kMatterInit); + gMockClock.AdvanceMonotonic(250_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kMatterInit); + + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kBootup); + + // Verify the time tracker values for each operation after reboot + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kBootup); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kBootup); + EXPECT_EQ(trackedTime, uint32_t(600)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(3)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(550)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(600)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(500)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(1)); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSilabsInit); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSilabsInit); + EXPECT_EQ(trackedTime, uint32_t(350)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(3)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(275)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(350)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(1)); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kMatterInit); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kMatterInit); + EXPECT_EQ(trackedTime, uint32_t(250)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(2)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(275)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(300)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(250)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 14u); // 14 calls: 8 TimeTraceBegin and 6 TimeTraceEnd +} + +TEST_F(TestSilabsTracing, TestCommissioning) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + + size_t traceCount = 0; + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 0u); + + // Simulate Spake2p steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSpake2p); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake1); + gMockClock.AdvanceMonotonic(50_ms64); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake1); + gMockClock.AdvanceMonotonic(100_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kPake1); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake2); + gMockClock.AdvanceMonotonic(150_ms64); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake2); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kPake2); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kPake3); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kPake3); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSpake2p); + + // Verify the time tracker values for Spake2p + auto timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSpake2p); + auto trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(700)); + + // Retrieve the watermark for the operation + auto watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSpake2p); + + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(700)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(700)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(700)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Pake1 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kPake1); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kPake1); + EXPECT_EQ(trackedTime, uint32_t(100)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(2)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Pake2 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kPake2); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kPake2); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(2)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Pake3 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kPake3); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kPake3); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Simulate Operational Credentials steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOperationalCredentials); + gMockClock.AdvanceMonotonic(300_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kOperationalCredentials); + + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kOperationalCredentials); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kOperationalCredentials); + EXPECT_EQ(trackedTime, uint32_t(300)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(300)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(300)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(300)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Simulate Transport Layer steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kTransportLayer); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kTransportSetup); + gMockClock.AdvanceMonotonic(100_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kTransportSetup); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kFindOperational); + gMockClock.AdvanceMonotonic(150_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kFindOperational); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kTransportLayer); + + // Verify the time tracker values for Transport Layer + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kTransportLayer); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kTransportLayer); + EXPECT_EQ(trackedTime, uint32_t(250)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(250)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(250)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(250)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Transport Setup + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kTransportSetup); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kTransportSetup); + EXPECT_EQ(trackedTime, uint32_t(100)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Find Operational + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kFindOperational); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kFindOperational); + EXPECT_EQ(trackedTime, uint32_t(150)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(150)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(150)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(150)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Simulate Case Session steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kCaseSession); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSigma1); + gMockClock.AdvanceMonotonic(100_ms64); + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSigma1); + gMockClock.AdvanceMonotonic(100_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSigma1); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSigma2); + gMockClock.AdvanceMonotonic(150_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSigma2); + + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kSigma3); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kSigma3); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kCaseSession); + + // Verify the time tracker values for Case Session + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kCaseSession); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kCaseSession); + EXPECT_EQ(trackedTime, uint32_t(550)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(550)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(550)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(550)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Sigma1 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSigma1); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSigma1); + EXPECT_EQ(trackedTime, uint32_t(100)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(2)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Sigma2 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSigma2); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSigma2); + EXPECT_EQ(trackedTime, uint32_t(150)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(150)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(150)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(150)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Sigma3 + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kSigma3); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kSigma3); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 27u); +} + +TEST_F(TestSilabsTracing, TestOTA) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + size_t traceCount = 0; + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 0u); + + // Simulate OTA steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOTA); + gMockClock.AdvanceMonotonic(100_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kOTA); + + // Verify the time tracker values for OTA + auto timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kOTA); + auto trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(100)); + + // Retrieve the watermark for the operation + auto watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kOTA); + + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Simulate OTA steps with failure + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOTA); + gMockClock.AdvanceMonotonic(150_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kOTA, CHIP_ERROR_INTERNAL); + + // Verify the time tracker values for OTA after failure + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kOTA); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kOTA); + EXPECT_EQ(trackedTime, uint32_t(150)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(2)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Simulate Bootup steps after OTA failure + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kBootup); + + // Verify the time tracker values for Bootup + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kBootup); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kBootup); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Simulate subsequent OTA steps that succeed + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOTA); + gMockClock.AdvanceMonotonic(120_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kOTA); + + // Verify the time tracker values for OTA after success + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kOTA); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kOTA); + EXPECT_EQ(trackedTime, uint32_t(120)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(3)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(110)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(120)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(2)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(1)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + traceCount = SilabsTracer::Instance().GetTraceCount(); + EXPECT_EQ(traceCount, 8u); // 8 calls: 4 TimeTraceBegin and 4 TimeTraceEnd +} + +// TODO Implement a function that test the Logs formating depending on the operation, event type, error, etc. From 8c9c81453cef48f2f7765147626e0e4b1dd94635 Mon Sep 17 00:00:00 2001 From: lpbeliveau-silabs <112982107+lpbeliveau-silabs@users.noreply.github.com> Date: Wed, 20 Nov 2024 08:45:44 -0500 Subject: [PATCH 2/2] [SL-ONLY] Feature/silabs tracing logs formating (#114) --- src/platform/silabs/tracing/SilabsTracing.cpp | 161 ++++++++++++--- src/platform/silabs/tracing/SilabsTracing.h | 65 +++--- src/platform/tests/TestSilabsTracing.cpp | 185 ++++++++++++++++-- 3 files changed, 345 insertions(+), 66 deletions(-) diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp index dc88ba45d0..e9940bac02 100644 --- a/src/platform/silabs/tracing/SilabsTracing.cpp +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -34,7 +34,78 @@ namespace chip { namespace Tracing { namespace Silabs { -// TODO add string mapping to log the operation names and types +const char * TimeTraceOperationToString(TimeTraceOperation operation) +{ + switch (operation) + { + case TimeTraceOperation::kSpake2p: + return "Spake2p"; + case TimeTraceOperation::kPake1: + return "Pake1"; + case TimeTraceOperation::kPake2: + return "Pake2"; + case TimeTraceOperation::kPake3: + return "Pake3"; + case TimeTraceOperation::kOperationalCredentials: + return "OperationalCredentials"; + case TimeTraceOperation::kAttestationVerification: + return "AttestationVerification"; + case TimeTraceOperation::kCSR: + return "CSR"; + case TimeTraceOperation::kNOC: + return "NOC"; + case TimeTraceOperation::kTransportLayer: + return "TransportLayer"; + case TimeTraceOperation::kTransportSetup: + return "TransportSetup"; + case TimeTraceOperation::kFindOperational: + return "FindOperational"; + case TimeTraceOperation::kCaseSession: + return "CaseSession"; + case TimeTraceOperation::kSigma1: + return "Sigma1"; + case TimeTraceOperation::kSigma2: + return "Sigma2"; + case TimeTraceOperation::kSigma3: + return "Sigma3"; + case TimeTraceOperation::kOTA: + return "OTA"; + case TimeTraceOperation::kImageUpload: + return "ImageUpload"; + case TimeTraceOperation::kImageVerification: + return "ImageVerification"; + case TimeTraceOperation::kAppApplyTime: + return "AppApplyTime"; + case TimeTraceOperation::kBootup: + return "Bootup"; + case TimeTraceOperation::kSilabsInit: + return "SilabsInit"; + case TimeTraceOperation::kMatterInit: + return "MatterInit"; + case TimeTraceOperation::kNumTraces: + return "NumTraces"; + case TimeTraceOperation::kBufferFull: + return "BufferFull"; + default: + return "Unknown"; + } +} + +const char * OperationTypeToString(OperationType type) +{ + switch (type) + { + case OperationType::kBegin: + return "Begin"; + case OperationType::kEnd: + return "End"; + case OperationType::kInstant: + return "Instant"; + default: + return "Unknown"; + } +} + namespace { constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES; } // namespace @@ -43,6 +114,29 @@ struct TimeTrackerStorage : public TimeTracker, PersistentData(buffer.data()), buffer.size(), + "TimeTracker - StartTime: %" PRIu32 ", Operation: %s, Type: %s, Error: 0x%" PRIx32, mStartTime.count(), + TimeTraceOperationToString(mOperation), OperationTypeToString(mType), mError.AsInteger()); + case OperationType::kEnd: + return snprintf(reinterpret_cast(buffer.data()), buffer.size(), + "TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Duration: %" PRIu32 + " ms, Operation: %s, Type: %s, Error: 0x%" PRIx32, + mStartTime.count(), mEndTime.count(), (mEndTime - mStartTime).count(), + TimeTraceOperationToString(mOperation), OperationTypeToString(mType), mError.AsInteger()); + case OperationType::kInstant: + return snprintf(reinterpret_cast(buffer.data()), buffer.size(), + "TimeTracker - EventTime: %" PRIu32 ", Operation: %s, Type: %s, Error: 0x%" PRIx32, mStartTime.count(), + TimeTraceOperationToString(mOperation), OperationTypeToString(mType), mError.AsInteger()); + default: + return snprintf(reinterpret_cast(buffer.data()), buffer.size(), "TimeTracker - Unknown operation type"); + } +} + SilabsTracer SilabsTracer::sInstance; SilabsTracer::SilabsTracer() @@ -78,7 +172,7 @@ CHIP_ERROR SilabsTracer::StartWatermarksStorage(PersistentStorageDelegate * stor return CHIP_NO_ERROR; } -void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) +CHIP_ERROR SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) { // Log the start time of the operation auto & tracker = mLatestTimeTrackers[static_cast(aOperation)]; @@ -90,10 +184,10 @@ void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation) auto & watermark = mWatermarks[static_cast(aOperation)]; watermark.mTotalCount++; - OutputTrace(tracker); + return OutputTrace(tracker); } -void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error) +CHIP_ERROR SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error) { auto & tracker = mLatestTimeTrackers[static_cast(aOperation)]; tracker.mEndTime = System::SystemClock().GetMonotonicTimestamp(); @@ -127,10 +221,10 @@ void SilabsTracer::TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error) } } - OutputTrace(tracker); + return OutputTrace(tracker); } -void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error) +CHIP_ERROR SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error) { TimeTracker tracker; tracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); @@ -138,17 +232,17 @@ void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR er tracker.mOperation = aOperation; tracker.mType = OperationType::kInstant; tracker.mError = error; - OutputTrace(tracker); + return OutputTrace(tracker); } CHIP_ERROR SilabsTracer::OutputTimeTracker(const TimeTracker & tracker) { VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED); - ChipLogProgress(DeviceLayer, - "TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Operation: %" PRIu8 ", Type: %" PRIu8 - ", Error: %" CHIP_ERROR_FORMAT, - tracker.mStartTime.count(), tracker.mEndTime.count(), static_cast(tracker.mOperation), - static_cast(tracker.mType), tracker.mError.Format()); + // Allocate a buffer to store the trace + uint8_t buffer[kMaxTraceSize]; + MutableByteSpan span(buffer); + tracker.ToCharArray(span); + ChipLogProgress(DeviceLayer, "%s", buffer); // Use format string literal return CHIP_NO_ERROR; } @@ -168,10 +262,11 @@ CHIP_ERROR SilabsTracer::OutputTrace(const TimeTracker & tracker) TimeTracker resourceExhaustedTracker = tracker; resourceExhaustedTracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); resourceExhaustedTracker.mEndTime = resourceExhaustedTracker.mStartTime; - resourceExhaustedTracker.mOperation = TimeTraceOperation::kNumTraces; + resourceExhaustedTracker.mOperation = TimeTraceOperation::kBufferFull; resourceExhaustedTracker.mType = OperationType::kInstant; resourceExhaustedTracker.mError = CHIP_ERROR_BUFFER_TOO_SMALL; mTimeTrackerList.Insert(resourceExhaustedTracker); + mBufferedTrackerCount++; return CHIP_ERROR_BUFFER_TOO_SMALL; } else @@ -189,10 +284,11 @@ CHIP_ERROR SilabsTracer::OutputWaterMark(TimeTraceOperation aOperation) VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED); ChipLogProgress(DeviceLayer, - "Trace %zu: TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32 + "Operation: %s, TotalCount=%" PRIu32 ", SuccessFullCount=%" PRIu32 ", MaxTime=%" PRIu32 ", MinTime=%" PRIu32 ", AvgTime=%" PRIu32 ", CountAboveAvg=%" PRIu32 "", - index, watermark.mTotalCount, watermark.mSuccessfullCount, watermark.mMaxTimeMs.count(), - watermark.mMinTimeMs.count(), watermark.mMovingAverage.count(), watermark.mCountAboveAvg); + TimeTraceOperationToString(aOperation), watermark.mTotalCount, watermark.mSuccessfullCount, + watermark.mMaxTimeMs.count(), watermark.mMinTimeMs.count(), watermark.mMovingAverage.count(), + watermark.mCountAboveAvg); return CHIP_NO_ERROR; } @@ -272,24 +368,33 @@ CHIP_ERROR SilabsTracer::LoadWatermarks() return CHIP_NO_ERROR; } -#if CONFIG_BUILD_FOR_HOST_UNIT_TEST -size_t SilabsTracer::GetTraceCount() -{ - return mBufferedTrackerCount; -} - -CHIP_ERROR SilabsTracer::GetTraceByIndex(size_t index, const char *& trace) const +CHIP_ERROR SilabsTracer::GetTraceByOperation(TimeTraceOperation aOperation, MutableByteSpan & buffer) const { auto * current = mTimeTrackerList.head; - for (size_t i = 0; i < index && current != nullptr; ++i) + while (current != nullptr) { + if (current->mValue.mOperation == aOperation) + { + // Check if the buffer is large enough + auto requiredSize = current->mValue.GetSize(); + + if (requiredSize < 0) + { + return CHIP_ERROR_INTERNAL; + } + + if (static_cast(requiredSize) >= buffer.size()) + { + return CHIP_ERROR_BUFFER_TOO_SMALL; + } + + current->mValue.ToCharArray(buffer); + return CHIP_NO_ERROR; + } current = current->mpNext; } - VerifyOrReturnError(current != nullptr, CHIP_ERROR_INVALID_ARGUMENT); - trace = reinterpret_cast(¤t->mValue); - return CHIP_NO_ERROR; + return CHIP_ERROR_NOT_FOUND; } -#endif } // namespace Silabs } // namespace Tracing diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h index 4699f708ee..5bfc912f8c 100644 --- a/src/platform/silabs/tracing/SilabsTracing.h +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -21,6 +21,7 @@ #include #include #include +#include #include #include @@ -60,6 +61,7 @@ enum class TimeTraceOperation : uint8_t kBootup, kSilabsInit, kMatterInit, + kBufferFull, kNumTraces, }; @@ -78,6 +80,23 @@ struct TimeTracker TimeTraceOperation mOperation; OperationType mType; CHIP_ERROR mError; + + /** @brief Convert the TimeTracker to a string for logs + * Behaves like snprintf, but formats the output differently based on the OperationType + * May be used with a buffer of size == 0 to get the required buffer size + * @param buffer The buffer to write the string to + * @return The number of characters written to the buffer, or the size of the buffer required if the buffer is too small + */ + int ToCharArray(MutableByteSpan & buffer) const; + + /** @brief Get the size of the string representation of the TimeTracker + * @return The size of the string representation of the TimeTracker + */ + int GetSize() const + { + MutableByteSpan temp; + return ToCharArray(temp); + } }; struct Watermark @@ -95,10 +114,11 @@ struct Watermark // class SilabsTracer { +public: static constexpr size_t kNumTraces = to_underlying(TimeTraceOperation::kNumTraces); static constexpr size_t kMaxBufferedTraces = 64; + static constexpr size_t kMaxTraceSize = 256; -public: /** @brief Get the singleton instance of SilabsTracer */ static SilabsTracer & Instance() { return sInstance; } @@ -119,24 +139,27 @@ class SilabsTracer * This calls the OutputTrace method to log the trace if logs are enabled, and stores the time tracker in the buffer if the * buffer is not full. * @param aOperation + * @return CHIP_ERROR, returns CHIP_ERROR_BUFFER_TOO_SMALL if the buffer is full */ - void TimeTraceBegin(TimeTraceOperation aOperation); + CHIP_ERROR TimeTraceBegin(TimeTraceOperation aOperation); /** @brief End tracing a time operation * This calls the OutputTrace method to log the trace if logs are enabled, and stores the time tracker in the buffer if the * buffer is not full. * @param aOperation * @param error + * @return CHIP_ERROR, returns CHIP_ERROR_BUFFER_TOO_SMALL if the buffer is full */ - void TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); + CHIP_ERROR TimeTraceEnd(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); /** @brief Trace an instant time operation * This calls the OutputTrace method to log the trace if logs are enabled, and stores the time tracker in the buffer if the * buffer is not full. * @param aOperation * @param error + * @return CHIP_ERROR, returns CHIP_ERROR_BUFFER_TOO_SMALL if the buffer is full */ - void TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); + CHIP_ERROR TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR error = CHIP_NO_ERROR); /** @brief Output a time tracker * This will output the latest time tracker for a specific operation, without affecting the buffer. @@ -175,18 +198,6 @@ class SilabsTracer SilabsTracer(SilabsTracer const &) = delete; SilabsTracer & operator=(SilabsTracer const &) = delete; - /** @brief Get the latest time tracker for a specific operation - * @param aOperation The operation to get the time tracker for - * @return TimeTracker, the latest time tracker for the operation - */ - TimeTracker GetTimeTracker(TimeTraceOperation aOperation) { return mLatestTimeTrackers[to_underlying(aOperation)]; } - - /** @brief Get the watermark for a specific operation - * @param aOperation The operation to get the watermark for - * @return Watermark, the watermark for the operation - */ - Watermark GetWatermark(TimeTraceOperation aOperation) { return mWatermarks[to_underlying(aOperation)]; } - /** @brief Save the watermarks to persistent storage * @return CHIP_ERROR, returns an error if the storage is not initialized */ @@ -197,19 +208,21 @@ class SilabsTracer */ CHIP_ERROR LoadWatermarks(); -#if CONFIG_BUILD_FOR_HOST_UNIT_TEST - /** @brief Get the count of buffered traces - * @param count Reference to store the count of buffered traces + // Methods to get the time trackers metrics values + + /** @brief Get the latest time tracker for a specific operation + * @param aOperation The operation to get the time tracker for + * @return TimeTracker, the latest time tracker for the operation */ - size_t GetTraceCount(); + TimeTracker GetTimeTracker(TimeTraceOperation aOperation) { return mLatestTimeTrackers[to_underlying(aOperation)]; } - /** @brief Get a trace by its index - * @param index The index of the trace to retrieve - * @param trace Reference to store the trace - * @return CHIP_ERROR, returns CHIP_ERROR_INVALID_ARGUMENT if the index is invalid + /** @brief Get the watermark for a specific operation + * @param aOperation The operation to get the watermark for + * @return Watermark, the watermark for the operation */ - CHIP_ERROR GetTraceByIndex(size_t index, const char *& trace) const; -#endif + Watermark GetWatermark(TimeTraceOperation aOperation) { return mWatermarks[to_underlying(aOperation)]; } + size_t GetTimeTracesCount() { return mBufferedTrackerCount; } + CHIP_ERROR GetTraceByOperation(TimeTraceOperation aOperation, MutableByteSpan & buffer) const; private: struct TimeTrackerList diff --git a/src/platform/tests/TestSilabsTracing.cpp b/src/platform/tests/TestSilabsTracing.cpp index 2db2bd979e..1634b93191 100644 --- a/src/platform/tests/TestSilabsTracing.cpp +++ b/src/platform/tests/TestSilabsTracing.cpp @@ -49,8 +49,18 @@ using namespace chip::Tracing::Silabs; namespace { chip::System::Clock::Internal::MockClock gMockClock; chip::System::Clock::ClockBase * gRealClock; +#ifndef SILABS_LOG_ENABLED +bool logInitialized = false; +#endif } // namespace +#ifndef SILABS_LOG_ENABLED +bool isLogInitialized() +{ + return logInitialized; +} +#endif + class TestSilabsTracing : public ::testing::Test { public: @@ -76,7 +86,7 @@ TEST_F(TestSilabsTracing, TestTimeTrackerMethods) SilabsTracer::Instance().Init(); - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 0u); // Start tracking time for a specific event @@ -173,7 +183,7 @@ TEST_F(TestSilabsTracing, TestTimeTrackerMethods) EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(2)); // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 11u); // 11 calls: 6 TimeTraceBegin and 5 TimeTraceEnd } @@ -183,7 +193,7 @@ TEST_F(TestSilabsTracing, TestBootupSequence) SilabsTracer::Instance().Init(); size_t traceCount = 0; - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 0u); SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); @@ -238,12 +248,12 @@ TEST_F(TestSilabsTracing, TestBootupSequence) // Simulate a second simulation where we have a reboot during Silabs Init gMockClock.SetMonotonic(0_ms64); - // TODO : Here we simulate that we have restore the number of traces from NVM so we do not do the Init, we should call it and - // call the LoadWatermarks method here + // TODO : Here we simulate that we have restore the watermarks stored in the NVM so we do not do the Init, we should call it + // and call the LoadWatermarks method here // SilabsTracer::Instance().Init(); - // traceCount = SilabsTracer::Instance().GetTraceCount(); + // traceCount = SilabsTracer::Instance().GetTimeTracesCount(); // EXPECT_EQ(traceCount, 0u); SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); @@ -300,7 +310,7 @@ TEST_F(TestSilabsTracing, TestBootupSequence) EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 14u); // 14 calls: 8 TimeTraceBegin and 6 TimeTraceEnd } @@ -310,7 +320,7 @@ TEST_F(TestSilabsTracing, TestCommissioning) SilabsTracer::Instance().Init(); size_t traceCount = 0; - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 0u); // Simulate Spake2p steps @@ -512,7 +522,7 @@ TEST_F(TestSilabsTracing, TestCommissioning) EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 27u); } @@ -521,7 +531,7 @@ TEST_F(TestSilabsTracing, TestOTA) gMockClock.SetMonotonic(0_ms64); SilabsTracer::Instance().Init(); size_t traceCount = 0; - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 0u); // Simulate OTA steps @@ -596,8 +606,159 @@ TEST_F(TestSilabsTracing, TestOTA) EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(1)); // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls - traceCount = SilabsTracer::Instance().GetTraceCount(); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); EXPECT_EQ(traceCount, 8u); // 8 calls: 4 TimeTraceBegin and 4 TimeTraceEnd } -// TODO Implement a function that test the Logs formating depending on the operation, event type, error, etc. +TEST_F(TestSilabsTracing, TestLogs) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + +#ifndef SILABS_LOG_ENABLED + logInitialized = true; +#endif + size_t traceCount = 0; + + // Simulate OTA steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOTA); + gMockClock.AdvanceMonotonic(100_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kOTA); + + // Simulate Bootup steps + SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kBootup); + gMockClock.AdvanceMonotonic(200_ms64); + SilabsTracer::Instance().TimeTraceEnd(TimeTraceOperation::kBootup); + + // Verify the time tracker values for OTA + auto timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kOTA); + auto trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + EXPECT_EQ(trackedTime, uint32_t(100)); + + // Retrieve the watermark for the operation + auto watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kOTA); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(100)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Verify the time tracker values for Bootup + timeTracker = SilabsTracer::Instance().GetTimeTracker(TimeTraceOperation::kBootup); + trackedTime = timeTracker.mEndTime.count() - timeTracker.mStartTime.count(); + watermark = SilabsTracer::Instance().GetWatermark(TimeTraceOperation::kBootup); + EXPECT_EQ(trackedTime, uint32_t(200)); + EXPECT_EQ(watermark.mTotalCount, uint32_t(1)); + EXPECT_EQ(watermark.mMovingAverage.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMaxTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mMinTimeMs.count(), uint32_t(200)); + EXPECT_EQ(watermark.mSuccessfullCount, uint32_t(1)); + EXPECT_EQ(watermark.mCountAboveAvg, uint32_t(0)); + + // Check that traceCount is equal to the number of TimeTraceBegin and TimeTraceEnd calls + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + EXPECT_EQ(traceCount, 4u); // 4 calls: 2 TimeTraceBegin and 2 TimeTraceEnd + + // Verify the output logs using GetTraceByOperation + uint8_t logBuffer[256]; + MutableByteSpan span(logBuffer); + + // Verify OTA log + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, span), CHIP_NO_ERROR); + const char * expectedOTALogFormat = + "TimeTracker - StartTime: 0, EndTime: 100, Duration: 100 ms, Operation: OTA, Type: End, Error: 0x0"; + EXPECT_STREQ(reinterpret_cast(span.data()), expectedOTALogFormat); + + // Verify Bootup log + span = MutableByteSpan(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, span), CHIP_NO_ERROR); + const char * expectedBootupLogFormat = + "TimeTracker - StartTime: 100, EndTime: 300, Duration: 200 ms, Operation: Bootup, Type: End, Error: 0x0"; + EXPECT_STREQ(reinterpret_cast(span.data()), expectedBootupLogFormat); + + // Test buffer too small behavior + uint8_t smallBuffer[10]; + MutableByteSpan smallSpan(smallBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, smallSpan), CHIP_ERROR_BUFFER_TOO_SMALL); + + // Test TraceBufferFlushByOperation + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(TimeTraceOperation::kOTA), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + EXPECT_EQ(traceCount, 2u); // Only Bootup traces should remain + + // Verify Bootup log still exists + span = MutableByteSpan(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, span), CHIP_NO_ERROR); + EXPECT_STREQ(reinterpret_cast(span.data()), expectedBootupLogFormat); + + // Verify OTA log is removed + span = MutableByteSpan(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, span), CHIP_ERROR_NOT_FOUND); + + // Test TraceBufferFlushAll + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushAll(), CHIP_NO_ERROR); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + EXPECT_EQ(traceCount, 0u); // All traces should be flushed + + // Verify no logs exist + span = MutableByteSpan(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, span), CHIP_ERROR_NOT_FOUND); + span = MutableByteSpan(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, span), CHIP_ERROR_NOT_FOUND); +} + +TEST_F(TestSilabsTracing, TestBufferBusting) +{ + gMockClock.SetMonotonic(0_ms64); + SilabsTracer::Instance().Init(); + size_t traceCount = 0; + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + EXPECT_EQ(traceCount, 0u); + + // Simulate a large number of traces + while (traceCount < SilabsTracer::kMaxBufferedTraces - 2) + { + EXPECT_EQ(CHIP_NO_ERROR, SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kCaseSession)); + gMockClock.AdvanceMonotonic(100_ms64); + traceCount = SilabsTracer::Instance().GetTimeTracesCount(); + } + + EXPECT_EQ(SilabsTracer::kMaxBufferedTraces - 2, SilabsTracer::Instance().GetTimeTracesCount()); + EXPECT_EQ(CHIP_NO_ERROR, SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kOTA)); + EXPECT_EQ(CHIP_ERROR_BUFFER_TOO_SMALL, SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kImageUpload)); + + // Verify an overflow operation is added (kBufferFull) + EXPECT_EQ(SilabsTracer::kMaxBufferedTraces, SilabsTracer::Instance().GetTimeTracesCount()); + uint8_t logBuffer[256]; + MutableByteSpan logSpan(logBuffer); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBufferFull, logSpan), CHIP_NO_ERROR); + const char * expectedNumLogFormat = "TimeTracker - EventTime: 6200, Operation: BufferFull, Type: Instant, Error: 0x19"; + EXPECT_STREQ(reinterpret_cast(logSpan.data()), expectedNumLogFormat); + + // Verify the kImageUpload operation was not added + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kImageUpload, logSpan), CHIP_ERROR_NOT_FOUND); + + // Flush kOTA operation + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(TimeTraceOperation::kOTA), CHIP_NO_ERROR); + EXPECT_EQ(SilabsTracer::kMaxBufferedTraces - 1, SilabsTracer::Instance().GetTimeTracesCount()); + + // Verify that adding a new operation still results in a buffer full operation since we are at size -1 + EXPECT_EQ(CHIP_ERROR_BUFFER_TOO_SMALL, SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kImageUpload)); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kImageUpload, logSpan), CHIP_ERROR_NOT_FOUND); + + // Flush the overflow operations + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(TimeTraceOperation::kBufferFull), CHIP_NO_ERROR); + EXPECT_EQ(SilabsTracer::kMaxBufferedTraces - 2, SilabsTracer::Instance().GetTimeTracesCount()); + + // Verify that adding a new operation now succeeds + EXPECT_EQ(CHIP_NO_ERROR, SilabsTracer::Instance().TimeTraceBegin(TimeTraceOperation::kImageUpload)); + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kImageUpload, logSpan), CHIP_NO_ERROR); + + // Verify that the buffer full operation is removed + EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBufferFull, logSpan), CHIP_ERROR_NOT_FOUND); + + // Flush all operations + EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushAll(), CHIP_NO_ERROR); + EXPECT_EQ(0u, SilabsTracer::Instance().GetTimeTracesCount()); +}