diff --git a/examples/platform/silabs/shell/tracing/TracingShellCommands.cpp b/examples/platform/silabs/shell/tracing/TracingShellCommands.cpp index ebdf62f8d0..6f3ee593b3 100644 --- a/examples/platform/silabs/shell/tracing/TracingShellCommands.cpp +++ b/examples/platform/silabs/shell/tracing/TracingShellCommands.cpp @@ -146,7 +146,6 @@ CHIP_ERROR TracingHelpHandler(int argc, char ** argv) CHIP_ERROR TracingListTimeOperations(int argc, char ** argv) { - size_t TotalTraceNumber = to_underlying(TimeTraceOperation::kNumTraces) + SilabsTracer::Instance().GetRegisteredAppOperationsCount(); for (size_t i = 0; i < TotalTraceNumber; ++i) @@ -169,6 +168,12 @@ CHIP_ERROR TracingCommandHandler(int argc, char ** argv) CHIP_ERROR WatermarksCommandHandler(int argc, char ** argv) { CHIP_ERROR error = CHIP_NO_ERROR; + if (argc == 0 || argv == nullptr || argv[0] == nullptr) + { + streamer_printf(streamer_get(), "Usage: tracing watermarks \r\n"); + return CHIP_ERROR_INVALID_ARGUMENT; + } + if (strcmp(argv[0], "all") == 0) { error = SilabsTracer::Instance().OutputAllWaterMarks(); @@ -185,6 +190,12 @@ CHIP_ERROR FlushCommandHandler(int argc, char ** argv) { CHIP_ERROR error = CHIP_NO_ERROR; size_t index; + if (argc == 0 || argv == nullptr || argv[0] == nullptr) + { + streamer_printf(streamer_get(), "Usage: tracing flush \r\n"); + return CHIP_ERROR_INVALID_ARGUMENT; + } + CharSpan opKey(argv[0], sizeof(argv[0])); if (strcmp(argv[0], "all") == 0) { diff --git a/src/platform/silabs/tracing/SilabsTracing.cpp b/src/platform/silabs/tracing/SilabsTracing.cpp index eb8ab0f2d3..5867e7856e 100644 --- a/src/platform/silabs/tracing/SilabsTracing.cpp +++ b/src/platform/silabs/tracing/SilabsTracing.cpp @@ -15,9 +15,11 @@ * ******************************************************************************/ #include "SilabsTracing.h" +#include // for snprintf #include #include #include +#include // Include the necessary header for std::string #if !CONFIG_BUILD_FOR_HOST_UNIT_TEST #include // for isLogInitialized @@ -122,6 +124,20 @@ const char * OperationTypeToString(OperationType type) } } +int FormatTimeStamp(std::chrono::milliseconds time, MutableCharSpan & buffer) +{ + using namespace std::chrono; + auto h = duration_cast(time); + time -= duration_cast(h); + auto m = duration_cast(time); + time -= duration_cast(m); + auto s = duration_cast(time); + time -= duration_cast(s); + + return snprintf(buffer.data(), buffer.size(), "%02d:%02d:%02d.%03d", static_cast(h.count()), static_cast(m.count()), + static_cast(s.count()), static_cast(time.count())); +} + namespace { constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES; } // namespace @@ -130,28 +146,73 @@ struct TimeTrackerStorage : public TimeTracker, PersistentData(buffer.data()), buffer.size(), - "TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", StartTime: %" PRIu32 "", - OperationTypeToString(mType), TimeTraceOperationToString(mOperation), mError.AsInteger(), - mStartTime.count()); - case OperationType::kEnd: - return snprintf(reinterpret_cast(buffer.data()), buffer.size(), - "TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", StartTime: %" PRIu32 ", EndTime: %" PRIu32 - ", Duration: %" PRIu32 " ms", - OperationTypeToString(mType), TimeTraceOperationToString(mOperation), mError.AsInteger(), - mStartTime.count(), mEndTime.count(), (mEndTime - mStartTime).count()); - case OperationType::kInstant: - return snprintf(reinterpret_cast(buffer.data()), buffer.size(), - "TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", EventTime: %" PRIu32 "", - OperationTypeToString(mType), TimeTraceOperationToString(mOperation), mError.AsInteger(), - mStartTime.count()); + case OperationType::kBegin: { + int offset = + snprintf(buffer.data(), buffer.size(), + "TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", StartTime: ", OperationTypeToString(mType), + TimeTraceOperationToString(mOperation), mError.AsInteger()); + + MutableCharSpan subSpan; + + if (offset < static_cast(buffer.size())) + subSpan = buffer.SubSpan(static_cast(offset)); + + offset += FormatTimeStamp(mStartTime, subSpan); + return offset; + } + case OperationType::kEnd: { + int offset = snprintf(buffer.data(), buffer.size(), + "TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", Start: ", OperationTypeToString(mType), + TimeTraceOperationToString(mOperation), mError.AsInteger()); + MutableCharSpan subSpan; + + if (offset < static_cast(buffer.size())) + subSpan = buffer.SubSpan(static_cast(offset)); + + offset += FormatTimeStamp(mStartTime, subSpan); + + if (offset < static_cast(buffer.size())) + subSpan = buffer.SubSpan(static_cast(offset)); + + offset += snprintf(subSpan.data(), subSpan.size(), ", End: "); + + if (offset < static_cast(buffer.size())) + subSpan = buffer.SubSpan(static_cast(offset)); + + offset += FormatTimeStamp(mEndTime, subSpan); + + if (offset < static_cast(buffer.size())) + subSpan = buffer.SubSpan(static_cast(offset)); + + offset += snprintf(subSpan.data(), subSpan.size(), ", Duration: "); + + if (offset < static_cast(buffer.size())) + subSpan = buffer.SubSpan(static_cast(offset)); + + offset += FormatTimeStamp(mEndTime - mStartTime, subSpan); + return offset; + } + case OperationType::kInstant: { + int offset = + snprintf(buffer.data(), buffer.size(), + "TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", EventTime: ", OperationTypeToString(mType), + TimeTraceOperationToString(mOperation), mError.AsInteger()); + MutableCharSpan subSpan; + if (offset < static_cast(buffer.size())) + subSpan = buffer.SubSpan(static_cast(offset)); + + offset += FormatTimeStamp(mStartTime, subSpan); + return offset; + } default: - return snprintf(reinterpret_cast(buffer.data()), buffer.size(), "TimeTracker - Unknown operation type"); + return snprintf(buffer.data(), buffer.size(), "TimeTracker - Unknown operation type"); } } @@ -275,8 +336,8 @@ CHIP_ERROR SilabsTracer::OutputTimeTracker(const TimeTracker & tracker) ChipLogError(DeviceLayer, "Invalid tracker")); VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED); // Allocate a buffer to store the trace - uint8_t buffer[kMaxTraceSize]; - MutableByteSpan span(buffer); + char buffer[kMaxTraceSize]; + MutableCharSpan span(buffer); tracker.ToCharArray(span); ChipLogProgress(DeviceLayer, "%s", buffer); // Use format string literal return CHIP_NO_ERROR; @@ -294,7 +355,8 @@ CHIP_ERROR SilabsTracer::OutputTrace(const TimeTracker & tracker) } else if (mBufferedTrackerCount == kMaxBufferedTraces - 1) { - // Save a tracker with TimeTraceOperation::kNumTraces and CHIP_ERROR_BUFFER_TOO_SMALL to indicate that the buffer is full + // Save a tracker with TimeTraceOperation::kNumTraces and CHIP_ERROR_BUFFER_TOO_SMALL to indicate that the + // buffer is full TimeTracker resourceExhaustedTracker = tracker; resourceExhaustedTracker.mStartTime = System::SystemClock().GetMonotonicTimestamp(); resourceExhaustedTracker.mEndTime = resourceExhaustedTracker.mStartTime; @@ -316,7 +378,9 @@ CHIP_ERROR SilabsTracer::OutputTrace(const TimeTracker & tracker) CHIP_ERROR SilabsTracer::OutputWaterMark(TimeTraceOperation aOperation) { VerifyOrReturnError(to_underlying(aOperation) < kNumTraces, CHIP_ERROR_INVALID_ARGUMENT, - ChipLogError(DeviceLayer, "Invalid TimeTraceOperation")); + ChipLogError(DeviceLayer, + "Invalid Watemarks TimeTraceOperation\r\nNote: App specific operations are not " + "supported by Watermarks")); VerifyOrReturnError(isLogInitialized(), CHIP_ERROR_UNINITIALIZED); ChipLogProgress(DeviceLayer, @@ -414,7 +478,7 @@ CHIP_ERROR SilabsTracer::LoadWatermarks() return CHIP_NO_ERROR; } -CHIP_ERROR SilabsTracer::GetTraceByOperation(size_t aOperation, MutableByteSpan & buffer) const +CHIP_ERROR SilabsTracer::GetTraceByOperation(size_t aOperation, MutableCharSpan & buffer) const { auto * current = mTimeTrackerList.head; while (current != nullptr) @@ -442,7 +506,7 @@ CHIP_ERROR SilabsTracer::GetTraceByOperation(size_t aOperation, MutableByteSpan return CHIP_ERROR_NOT_FOUND; } -CHIP_ERROR SilabsTracer::GetTraceByOperation(CharSpan & appOperationKey, MutableByteSpan & buffer) const +CHIP_ERROR SilabsTracer::GetTraceByOperation(CharSpan & appOperationKey, MutableCharSpan & buffer) const { size_t index = 0; ReturnErrorOnFailure(FindAppOperationIndex(appOperationKey, index)); diff --git a/src/platform/silabs/tracing/SilabsTracing.h b/src/platform/silabs/tracing/SilabsTracing.h index fb46cdd901..1683c97ddd 100644 --- a/src/platform/silabs/tracing/SilabsTracing.h +++ b/src/platform/silabs/tracing/SilabsTracing.h @@ -52,14 +52,14 @@ struct TimeTracker * @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; + int ToCharArray(MutableCharSpan & 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; + MutableCharSpan temp; return ToCharArray(temp); } }; @@ -202,8 +202,8 @@ class SilabsTracer Watermark GetWatermark(TimeTraceOperation aOperation) { return mWatermarks[to_underlying(aOperation)]; } size_t GetTimeTracesCount() { return mBufferedTrackerCount; } - CHIP_ERROR GetTraceByOperation(size_t aOperation, MutableByteSpan & buffer) const; - CHIP_ERROR GetTraceByOperation(CharSpan & appOperationKey, MutableByteSpan & buffer) const; + CHIP_ERROR GetTraceByOperation(size_t aOperation, MutableCharSpan & buffer) const; + CHIP_ERROR GetTraceByOperation(CharSpan & appOperationKey, MutableCharSpan & buffer) const; /** @brief Register an App specific time trace operation * This will register an App specific operation to be tracked by the time tracer. The string will be mapped to a diff --git a/src/platform/tests/TestSilabsTracing.cpp b/src/platform/tests/TestSilabsTracing.cpp index 359b072e93..d288b68c4d 100644 --- a/src/platform/tests/TestSilabsTracing.cpp +++ b/src/platform/tests/TestSilabsTracing.cpp @@ -661,25 +661,25 @@ TEST_F(TestSilabsTracing, TestLogs) EXPECT_EQ(traceCount, 4u); // 4 calls: 2 TimeTraceBegin and 2 TimeTraceEnd // Verify the output logs using Operation - uint8_t logBuffer[256]; - MutableByteSpan span(logBuffer); + char logBuffer[256]; + MutableCharSpan span(logBuffer); // Verify OTA log EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kOTA), span), CHIP_NO_ERROR); const char * expectedOTALogFormat = - "TimeTracker - Type: End, Operation: OTA, Status: 0x0, StartTime: 0, EndTime: 100, Duration: 100 ms"; - EXPECT_STREQ(reinterpret_cast(span.data()), expectedOTALogFormat); + "TimeTracker - Type: End, Operation: OTA, Status: 0x0, Start: 00:00:00.000, End: 00:00:00.100, Duration: 00:00:00.100"; + EXPECT_STREQ(span.data(), expectedOTALogFormat); // Verify Bootup log - span = MutableByteSpan(logBuffer); + span = MutableCharSpan(logBuffer); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kBootup), span), CHIP_NO_ERROR); const char * expectedBootupLogFormat = - "TimeTracker - Type: End, Operation: Bootup, Status: 0x0, StartTime: 100, EndTime: 300, Duration: 200 ms"; - EXPECT_STREQ(reinterpret_cast(span.data()), expectedBootupLogFormat); + "TimeTracker - Type: End, Operation: Bootup, Status: 0x0, Start: 00:00:00.100, End: 00:00:00.300, Duration: 00:00:00.200"; + EXPECT_STREQ(span.data(), expectedBootupLogFormat); // Test buffer too small behavior - uint8_t smallBuffer[10]; - MutableByteSpan smallSpan(smallBuffer); + char smallBuffer[10]; + MutableCharSpan smallSpan(smallBuffer); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kOTA), smallSpan), CHIP_ERROR_BUFFER_TOO_SMALL); @@ -689,12 +689,12 @@ TEST_F(TestSilabsTracing, TestLogs) EXPECT_EQ(traceCount, 2u); // Only Bootup traces should remain // Verify Bootup log still exists - span = MutableByteSpan(logBuffer); + span = MutableCharSpan(logBuffer); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kBootup), span), CHIP_NO_ERROR); - EXPECT_STREQ(reinterpret_cast(span.data()), expectedBootupLogFormat); + EXPECT_STREQ(span.data(), expectedBootupLogFormat); // Verify OTA log is removed - span = MutableByteSpan(logBuffer); + span = MutableCharSpan(logBuffer); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kOTA), span), CHIP_ERROR_NOT_FOUND); // Test TraceBufferFlushAll @@ -703,9 +703,9 @@ TEST_F(TestSilabsTracing, TestLogs) EXPECT_EQ(traceCount, 0u); // All traces should be flushed // Verify no logs exist - span = MutableByteSpan(logBuffer); + span = MutableCharSpan(logBuffer); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kBootup), span), CHIP_ERROR_NOT_FOUND); - span = MutableByteSpan(logBuffer); + span = MutableCharSpan(logBuffer); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kOTA), span), CHIP_ERROR_NOT_FOUND); } @@ -731,11 +731,11 @@ TEST_F(TestSilabsTracing, TestBufferBusting) // Verify an overflow operation is added (kBufferFull) EXPECT_EQ(SilabsTracer::kMaxBufferedTraces, SilabsTracer::Instance().GetTimeTracesCount()); - uint8_t logBuffer[256]; - MutableByteSpan logSpan(logBuffer); + char logBuffer[256]; + MutableCharSpan logSpan(logBuffer); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kBufferFull), logSpan), CHIP_NO_ERROR); - const char * expectedNumLogFormat = "TimeTracker - Type: Instant, Operation: BufferFull, Status: 0x19, EventTime: 6200"; - EXPECT_STREQ(reinterpret_cast(logSpan.data()), expectedNumLogFormat); + const char * expectedNumLogFormat = "TimeTracker - Type: Instant, Operation: BufferFull, Status: 0x19, EventTime: 00:00:06.200"; + EXPECT_STREQ(logSpan.data(), expectedNumLogFormat); // Verify the kImageUpload operation was not added EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(to_underlying(TimeTraceOperation::kImageUpload), logSpan), @@ -804,16 +804,18 @@ TEST_F(TestSilabsTracing, TestAppSpecificTraces) EXPECT_EQ(SilabsTracer::Instance().TimeTraceInstant(appSpecificSpan2), CHIP_NO_ERROR); // Verify that the logs match expectation - uint8_t logBuffer[256]; - MutableByteSpan span(logBuffer); + char logBuffer[256]; + MutableCharSpan span(logBuffer); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(appSpecificSpan, span), CHIP_NO_ERROR); - const char * expectedAppSpecificLogFormat = "TimeTracker - Type: Instant, Operation: AppTrace, Status: 0x0, EventTime: 0"; - EXPECT_STREQ(reinterpret_cast(span.data()), expectedAppSpecificLogFormat); + const char * expectedAppSpecificLogFormat = + "TimeTracker - Type: Instant, Operation: AppTrace, Status: 0x0, EventTime: 00:00:00.000"; + EXPECT_STREQ(span.data(), expectedAppSpecificLogFormat); - span = MutableByteSpan(logBuffer); + span = MutableCharSpan(logBuffer); EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(appSpecificSpan2, span), CHIP_NO_ERROR); - const char * expectedAppSpecificLogFormat2 = "TimeTracker - Type: Instant, Operation: AppTrace2, Status: 0x0, EventTime: 0"; - EXPECT_STREQ(reinterpret_cast(span.data()), expectedAppSpecificLogFormat2); + const char * expectedAppSpecificLogFormat2 = + "TimeTracker - Type: Instant, Operation: AppTrace2, Status: 0x0, EventTime: 00:00:00.000"; + EXPECT_STREQ(span.data(), expectedAppSpecificLogFormat2); // Confirm trace count traceCount = SilabsTracer::Instance().GetTimeTracesCount();