Skip to content

Commit

Permalink
WIP
Browse files Browse the repository at this point in the history
  • Loading branch information
@lpbeliveau-silabs
lpbeliveau-silabs committed Nov 19, 2024
1 parent a70f40e commit cbdbd28
Show file tree
Hide file tree
Showing 3 changed files with 215 additions and 48 deletions.
111 changes: 97 additions & 14 deletions src/platform/silabs/tracing/SilabsTracing.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -34,6 +34,62 @@ namespace chip {
namespace Tracing {
namespace Silabs {

// String mapping for TimeTraceOperation
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";
default:
return "Unknown";
}
}

// TODO add string mapping to log the operation names and types
namespace {
constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES;
Expand Down Expand Up @@ -144,11 +200,12 @@ void SilabsTracer::TimeTraceInstant(TimeTraceOperation aOperation, CHIP_ERROR er
CHIP_ERROR SilabsTracer::OutputTimeTracker(const TimeTracker & tracker)
{
VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED);
auto duration = tracker.mEndTime - tracker.mStartTime;
ChipLogProgress(DeviceLayer,
"TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Operation: %" PRIu8 ", Type: %" PRIu8
", Error: %" CHIP_ERROR_FORMAT,
tracker.mStartTime.count(), tracker.mEndTime.count(), static_cast<uint8_t>(tracker.mOperation),
static_cast<uint8_t>(tracker.mType), tracker.mError.Format());
"TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Duration: %" PRIu32
" ms, Operation: %s, Type: %" PRIu8 ", Error: %" CHIP_ERROR_FORMAT,
tracker.mStartTime.count(), tracker.mEndTime.count(), duration.count(),
TimeTraceOperationToString(tracker.mOperation), static_cast<uint8_t>(tracker.mType), tracker.mError.Format());
return CHIP_NO_ERROR;
}

Expand Down Expand Up @@ -189,10 +246,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;
}
Expand Down Expand Up @@ -272,24 +330,49 @@ 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, char * buffer, uint16_t & size) const
{
auto * current = mTimeTrackerList.head;
for (size_t i = 0; i < index && current != nullptr; ++i)
while (current != nullptr)
{
if (current->mValue.mOperation == aOperation)
{
auto duration = current->mValue.mEndTime.count() - current->mValue.mStartTime.count();
int requiredSize = snprintf(nullptr, 0,
"TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Duration: %" PRIu32
" ms, Operation: %s, Type: %" PRIu8 ", Error: %" CHIP_ERROR_FORMAT,
current->mValue.mStartTime.count(), current->mValue.mEndTime.count(), duration,
TimeTraceOperationToString(current->mValue.mOperation),
static_cast<uint8_t>(current->mValue.mType), current->mValue.mError.Format());

if (requiredSize < 0)
{
return CHIP_ERROR_INTERNAL;
}

if (requiredSize >= size)
{
size = requiredSize + 1; // Include null terminator
return CHIP_ERROR_BUFFER_TOO_SMALL;
}

snprintf(buffer, size,
"TimeTracker - StartTime: %" PRIu32 ", EndTime: %" PRIu32 ", Duration: %" PRIu32
" ms, Operation: %s, Type: %" PRIu8 ", Error: %" CHIP_ERROR_FORMAT,
current->mValue.mStartTime.count(), current->mValue.mEndTime.count(), duration,
TimeTraceOperationToString(current->mValue.mOperation), static_cast<uint8_t>(current->mValue.mType),
current->mValue.mError.Format());
return CHIP_NO_ERROR;
}
current = current->mpNext;
}
VerifyOrReturnError(current != nullptr, CHIP_ERROR_INVALID_ARGUMENT);
trace = reinterpret_cast<const char *>(&current->mValue);
return CHIP_NO_ERROR;
return CHIP_ERROR_NOT_FOUND;
}
#endif

} // namespace Silabs
} // namespace Tracing
Expand Down
34 changes: 12 additions & 22 deletions src/platform/silabs/tracing/SilabsTracing.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -175,18 +175,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
*/
Expand All @@ -197,19 +185,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)]; }
CHIP_ERROR GetTimeTracesCount(size_t & count) const;
CHIP_ERROR GetTraceByOperation(TimeTraceOperation aOperation, char * buffer, uint16_t & size) const;

private:
struct TimeTrackerList
Expand Down
118 changes: 106 additions & 12 deletions src/platform/tests/TestSilabsTracing.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -76,7 +76,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
Expand Down Expand Up @@ -173,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
traceCount = SilabsTracer::Instance().GetTraceCount();
traceCount = SilabsTracer::Instance().GetTimeTracesCount();
EXPECT_EQ(traceCount, 11u); // 11 calls: 6 TimeTraceBegin and 5 TimeTraceEnd
}

Expand All @@ -183,7 +183,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);
Expand Down Expand Up @@ -238,12 +238,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);
Expand Down Expand Up @@ -300,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
traceCount = SilabsTracer::Instance().GetTraceCount();
traceCount = SilabsTracer::Instance().GetTimeTracesCount();
EXPECT_EQ(traceCount, 14u); // 14 calls: 8 TimeTraceBegin and 6 TimeTraceEnd
}

Expand All @@ -310,7 +310,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
Expand Down Expand Up @@ -512,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
traceCount = SilabsTracer::Instance().GetTraceCount();
traceCount = SilabsTracer::Instance().GetTimeTracesCount();
EXPECT_EQ(traceCount, 27u);
}

Expand All @@ -521,7 +521,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
Expand Down Expand Up @@ -596,8 +596,102 @@ 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();
EXPECT_EQ(SilabsTracer::Instance().GetTimeTracesCount(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.
TEST_F(TestSilabsTracing, TestLogs)
{
gMockClock.SetMonotonic(0_ms64);
SilabsTracer::Instance().Init();
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
EXPECT_EQ(SilabsTracer::Instance().GetTimeTracesCount(traceCount), CHIP_NO_ERROR);
EXPECT_EQ(traceCount, 4u); // 4 calls: 2 TimeTraceBegin and 2 TimeTraceEnd

// Verify the output logs using GetTraceByOperation
char logBuffer[256];
uint16_t bufferSize = sizeof(logBuffer);

// Verify OTA log
EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, logBuffer, bufferSize), CHIP_NO_ERROR);
const char * expectedOTALogFormat =
"TimeTracker - StartTime: 0, EndTime: 100, Duration: 100 ms, Operation: OTA, Type: 1, Error: 0";
EXPECT_STREQ(logBuffer, expectedOTALogFormat);

// Verify Bootup log
bufferSize = sizeof(logBuffer);
EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, logBuffer, bufferSize), CHIP_NO_ERROR);
const char * expectedBootupLogFormat =
"TimeTracker - StartTime: 100, EndTime: 300, Duration: 200 ms, Operation: Bootup, Type: 1, Error: 0";
EXPECT_STREQ(logBuffer, expectedBootupLogFormat);

// Test buffer too small behavior
char smallBuffer[10];
bufferSize = sizeof(smallBuffer);
EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, smallBuffer, bufferSize),
CHIP_ERROR_BUFFER_TOO_SMALL);
EXPECT_GT(bufferSize, sizeof(smallBuffer)); // Ensure the required size is greater than the small buffer

// Test TraceBufferFlushByOperation
EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushByOperation(TimeTraceOperation::kOTA), CHIP_NO_ERROR);
EXPECT_EQ(SilabsTracer::Instance().GetTimeTracesCount(traceCount), CHIP_NO_ERROR);
EXPECT_EQ(traceCount, 2u); // Only Bootup traces should remain

// Verify Bootup log still exists
bufferSize = sizeof(logBuffer);
EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, logBuffer, bufferSize), CHIP_NO_ERROR);
EXPECT_STREQ(logBuffer, expectedBootupLogFormat);

// Verify OTA log is removed
bufferSize = sizeof(logBuffer);
EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, logBuffer, bufferSize), CHIP_ERROR_NOT_FOUND);

// Test TraceBufferFlushAll
EXPECT_EQ(SilabsTracer::Instance().TraceBufferFlushAll(), CHIP_NO_ERROR);
EXPECT_EQ(SilabsTracer::Instance().GetTimeTracesCount(traceCount), CHIP_NO_ERROR);
EXPECT_EQ(traceCount, 0u); // All traces should be flushed

// Verify no logs exist
bufferSize = sizeof(logBuffer);
EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kBootup, logBuffer, bufferSize),
CHIP_ERROR_NOT_FOUND);
EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(TimeTraceOperation::kOTA, logBuffer, bufferSize), CHIP_ERROR_NOT_FOUND);
}

0 comments on commit cbdbd28

Please sign in to comment.