Skip to content

Commit

Permalink
Implemented formating for Trace logs, added test for logging as well …
Browse files Browse the repository at this point in the history 
…as reworks to get logging working
  • Loading branch information
@lpbeliveau-silabs
lpbeliveau-silabs committed Nov 19, 2024
1 parent cbdbd28 commit d045a78
Show file tree
Hide file tree
Showing 3 changed files with 150 additions and 49 deletions.
94 changes: 59 additions & 35 deletions src/platform/silabs/tracing/SilabsTracing.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -85,12 +85,29 @@ const char * TimeTraceOperationToString(TimeTraceOperation operation)
return "MatterInit";
case TimeTraceOperation::kNumTraces:
return "NumTraces";
case TimeTraceOperation::kBufferFull:
return "BufferFull";
default:
return "Unknown";
}
}

// String mapping for OperationType
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";
}
}

// TODO add string mapping to log the operation names and types
namespace {
constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES;
} // namespace
Expand All @@ -99,6 +116,28 @@ struct TimeTrackerStorage : public TimeTracker, PersistentData<kPersistentTimeTr
// TODO implement the Persistent Array class and use it here for logging the watermark array
};

int TimeTracker::ToCharArray(char * buffer, size_t bufferSize) const
{
if (mType == OperationType::kBegin)
{
return snprintf(buffer, bufferSize, "TimeTracker - StartTime: %" PRIu32 ", Operation: %s, Type: %s, Error: 0x%" PRIx32,
mStartTime.count(), TimeTraceOperationToString(mOperation), OperationTypeToString(mType),
mError.AsInteger());
}
else if (mType == OperationType::kEnd)
{
return snprintf(buffer, bufferSize,
"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());
}

// Instant operation
return snprintf(buffer, bufferSize, "TimeTracker - EventTime: %" PRIu32 ", Operation: %s, Type: %s, Error: 0x%" PRIx32,
mStartTime.count(), TimeTraceOperationToString(mOperation), OperationTypeToString(mType), mError.AsInteger());
}

SilabsTracer SilabsTracer::sInstance;

SilabsTracer::SilabsTracer()
Expand Down Expand Up @@ -134,7 +173,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<size_t>(aOperation)];
Expand All @@ -146,10 +185,10 @@ void SilabsTracer::TimeTraceBegin(TimeTraceOperation aOperation)
auto & watermark = mWatermarks[static_cast<size_t>(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<size_t>(aOperation)];
tracker.mEndTime = System::SystemClock().GetMonotonicTimestamp();
Expand Down Expand Up @@ -183,29 +222,28 @@ 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();
tracker.mEndTime = tracker.mStartTime;
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);
auto duration = tracker.mEndTime - tracker.mStartTime;
ChipLogProgress(DeviceLayer,
"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());
// Allocate a buffer to store the trace
char buffer[256];
auto bufferSize = sizeof(buffer);
tracker.ToCharArray(buffer, bufferSize);
ChipLogProgress(DeviceLayer, "%s", buffer); // Use format string literal
return CHIP_NO_ERROR;
}

Expand All @@ -225,10 +263,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
Expand Down Expand Up @@ -330,43 +369,28 @@ CHIP_ERROR SilabsTracer::LoadWatermarks()
return CHIP_NO_ERROR;
}

size_t SilabsTracer::GetTraceCount()
{
return mBufferedTrackerCount;
}

CHIP_ERROR SilabsTracer::GetTraceByOperation(TimeTraceOperation aOperation, char * buffer, uint16_t & size) const
CHIP_ERROR SilabsTracer::GetTraceByOperation(TimeTraceOperation aOperation, char * buffer, size_t & size) const
{
auto * current = mTimeTrackerList.head;
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());
// Check if the buffer is large enough
auto requiredSize = current->mValue.ToCharArray(nullptr, 0);

if (requiredSize < 0)
{
return CHIP_ERROR_INTERNAL;
}

if (requiredSize >= size)
if (static_cast<size_t>(requiredSize) >= size)
{
size = requiredSize + 1; // Include null terminator
size = static_cast<size_t>(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());
current->mValue.ToCharArray(buffer, size);
return CHIP_NO_ERROR;
}
current = current->mpNext;
Expand Down
24 changes: 18 additions & 6 deletions src/platform/silabs/tracing/SilabsTracing.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -60,6 +60,7 @@ enum class TimeTraceOperation : uint8_t
kBootup,
kSilabsInit,
kMatterInit,
kBufferFull,
kNumTraces,
};

Expand All @@ -78,6 +79,14 @@ 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 nullptr and 0 to get the required buffer size
* @param buffer The buffer to write the string to
* @param bufferSize The size of the buffer
*/
int ToCharArray(char * buffer, size_t bufferSize) const;
};

struct Watermark
Expand All @@ -95,10 +104,10 @@ struct Watermark
//
class SilabsTracer
{
public:
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; }

Expand All @@ -119,24 +128,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.
Expand Down Expand Up @@ -198,8 +210,8 @@ class SilabsTracer
* @return Watermark, the watermark for the operation
*/
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;
size_t GetTimeTracesCount() { return mBufferedTrackerCount; }
CHIP_ERROR GetTraceByOperation(TimeTraceOperation aOperation, char * buffer, size_t & size) const;

private:
struct TimeTrackerList
Expand Down
Loading

0 comments on commit d045a78

Please sign in to comment.