Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[SL-ONLY] Bugfix/tracing log format #180

Merged
merged 2 commits into from
Dec 16, 2024
Merged

[SL-ONLY] Bugfix/tracing log format #180

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
5dde547
Formatted the logs timestamps to HH:mm:ss.SSS and fixed crash when no…
lpbeliveau-silabs Dec 13, 2024
97961d4
Removed requirement for string header, improved memory usage by reduc…
lpbeliveau-silabs Dec 16, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 12 additions & 1 deletion examples/platform/silabs/shell/tracing/TracingShellCommands.cpp
View file
Open in desktop
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
Open in desktop
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
lpbeliveau-silabs marked this conversation as resolved.
Show resolved Hide resolved

#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();
lpbeliveau-silabs marked this conversation as resolved.
Show resolved Hide resolved
auto s = ms / 1000;
ms %= 1000;
auto m = s / 60;
s %= 60;
auto h = m / 60;
m %= 60;
lpbeliveau-silabs marked this conversation as resolved.
Show resolved Hide resolved

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
Open in desktop
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
Loading