Skip to content

Commit

Permalink
Formatted the logs timestamps to HH:mm:ss.SSS and fixed crash when no…
Browse files Browse the repository at this point in the history 
…t specifying operation for watermarks or flush commands
  • Loading branch information
@lpbeliveau-silabs
lpbeliveau-silabs committed Dec 13, 2024
1 parent f96399a commit 5dde547
Show file tree
Hide file tree
Showing 3 changed files with 47 additions and 15 deletions.
13 changes: 12 additions & 1 deletion examples/platform/silabs/shell/tracing/TracingShellCommands.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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 <TimeTraceOperation>\r\n");
return CHIP_ERROR_INVALID_ARGUMENT;
}

if (strcmp(argv[0], "all") == 0)
{
error = SilabsTracer::Instance().OutputAllWaterMarks();
Expand All @@ -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 <TimeTraceOperation>\r\n");
return CHIP_ERROR_INVALID_ARGUMENT;
}

CharSpan opKey(argv[0], sizeof(argv[0]));
if (strcmp(argv[0], "all") == 0)
{
Expand Down
37 changes: 28 additions & 9 deletions src/platform/silabs/tracing/SilabsTracing.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -15,9 +15,11 @@
*
******************************************************************************/
#include "SilabsTracing.h"
#include <cstdio> // Include the necessary header for snprintf
#include <cstring>
#include <lib/support/CodeUtils.h>
#include <lib/support/PersistentData.h>
#include <string> // Include the necessary header for std::string

#if !CONFIG_BUILD_FOR_HOST_UNIT_TEST
#include <platform/silabs/Logging.h> // for isLogInitialized
Expand Down Expand Up @@ -122,6 +124,22 @@ const char * OperationTypeToString(OperationType type)
}
}

std::string FormatTimeStamp(std::chrono::milliseconds time)
{
auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(time).count();
auto s = ms / 1000;
ms %= 1000;
auto m = s / 60;
s %= 60;
auto h = m / 60;
m %= 60;

char buffer[32];
snprintf(buffer, sizeof(buffer), "%02d:%02d:%02d.%03d", static_cast<int>(h), static_cast<int>(m), static_cast<int>(s),
static_cast<int>(ms));
return std::string(buffer);
}

namespace {
constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES;
} // namespace
Expand All @@ -136,20 +154,19 @@ int TimeTracker::ToCharArray(MutableByteSpan & buffer) const
{
case OperationType::kBegin:
return snprintf(reinterpret_cast<char *>(buffer.data()), buffer.size(),
"TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", StartTime: %" PRIu32 "",
"TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", StartTime: %s",
OperationTypeToString(mType), TimeTraceOperationToString(mOperation), mError.AsInteger(),
mStartTime.count());
FormatTimeStamp(mStartTime).c_str());
case OperationType::kEnd:
return snprintf(reinterpret_cast<char *>(buffer.data()), buffer.size(),
"TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", StartTime: %" PRIu32 ", EndTime: %" PRIu32
", Duration: %" PRIu32 " ms",
"TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", Start: %s, End: %s, Duration: %s",
OperationTypeToString(mType), TimeTraceOperationToString(mOperation), mError.AsInteger(),
mStartTime.count(), mEndTime.count(), (mEndTime - mStartTime).count());
FormatTimeStamp(mStartTime).c_str(), FormatTimeStamp(mEndTime).c_str(),
FormatTimeStamp(mEndTime - mStartTime).c_str());
case OperationType::kInstant:
return snprintf(reinterpret_cast<char *>(buffer.data()), buffer.size(),
"TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", EventTime: %" PRIu32 "",
OperationTypeToString(mType), TimeTraceOperationToString(mOperation), mError.AsInteger(),
mStartTime.count());
"TimeTracker - Type: %s, Operation: %s, Status: 0x%" PRIx32 ", EventTime: %s", OperationTypeToString(mType),
TimeTraceOperationToString(mOperation), mError.AsInteger(), FormatTimeStamp(mStartTime).c_str());
default:
return snprintf(reinterpret_cast<char *>(buffer.data()), buffer.size(), "TimeTracker - Unknown operation type");
}
Expand Down Expand Up @@ -316,7 +333,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,
Expand Down
12 changes: 7 additions & 5 deletions src/platform/tests/TestSilabsTracing.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -667,14 +667,14 @@ TEST_F(TestSilabsTracing, TestLogs)
// 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";
"TimeTracker - Type: End, Operation: OTA, Status: 0x0, Start: 00:00:00.000, End: 00:00:00.100, Duration: 00:00:00.100";
EXPECT_STREQ(reinterpret_cast<const char *>(span.data()), expectedOTALogFormat);

// Verify Bootup log
span = MutableByteSpan(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";
"TimeTracker - Type: End, Operation: Bootup, Status: 0x0, Start: 00:00:00.100, End: 00:00:00.300, Duration: 00:00:00.200";
EXPECT_STREQ(reinterpret_cast<const char *>(span.data()), expectedBootupLogFormat);

// Test buffer too small behavior
Expand Down Expand Up @@ -734,7 +734,7 @@ TEST_F(TestSilabsTracing, TestBufferBusting)
uint8_t logBuffer[256];
MutableByteSpan 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";
const char * expectedNumLogFormat = "TimeTracker - Type: Instant, Operation: BufferFull, Status: 0x19, EventTime: 00:00:06.200";
EXPECT_STREQ(reinterpret_cast<const char *>(logSpan.data()), expectedNumLogFormat);

// Verify the kImageUpload operation was not added
Expand Down Expand Up @@ -807,12 +807,14 @@ TEST_F(TestSilabsTracing, TestAppSpecificTraces)
uint8_t logBuffer[256];
MutableByteSpan span(logBuffer);
EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(appSpecificSpan, span), CHIP_NO_ERROR);
const char * expectedAppSpecificLogFormat = "TimeTracker - Type: Instant, Operation: AppTrace, Status: 0x0, EventTime: 0";
const char * expectedAppSpecificLogFormat =
"TimeTracker - Type: Instant, Operation: AppTrace, Status: 0x0, EventTime: 00:00:00.000";
EXPECT_STREQ(reinterpret_cast<const char *>(span.data()), expectedAppSpecificLogFormat);

span = MutableByteSpan(logBuffer);
EXPECT_EQ(SilabsTracer::Instance().GetTraceByOperation(appSpecificSpan2, span), CHIP_NO_ERROR);
const char * expectedAppSpecificLogFormat2 = "TimeTracker - Type: Instant, Operation: AppTrace2, Status: 0x0, EventTime: 0";
const char * expectedAppSpecificLogFormat2 =
"TimeTracker - Type: Instant, Operation: AppTrace2, Status: 0x0, EventTime: 00:00:00.000";
EXPECT_STREQ(reinterpret_cast<const char *>(span.data()), expectedAppSpecificLogFormat2);

// Confirm trace count
Expand Down

0 comments on commit 5dde547

Please sign in to comment.