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 a70f40e commit 4846604
Show file tree
Hide file tree
Showing 3 changed files with 341 additions and 66 deletions.
163 changes: 135 additions & 28 deletions src/platform/silabs/tracing/SilabsTracing.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -34,7 +34,80 @@ namespace chip {
namespace Tracing {
namespace Silabs {

// TODO add string mapping to log the operation names and types
// 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";
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";
}
}

namespace {
constexpr size_t kPersistentTimeTrackerBufferMax = SERIALIZED_TIME_TRACKERS_SIZE_BYTES;
} // namespace
Expand All @@ -43,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 @@ -78,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 @@ -90,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 @@ -127,28 +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);
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());
// 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 @@ -168,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 All @@ -189,10 +285,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 +369,34 @@ 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, size_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)
{
// Check if the buffer is large enough
auto requiredSize = current->mValue.ToCharArray(nullptr, 0);

if (requiredSize < 0)
{
return CHIP_ERROR_INTERNAL;
}

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

current->mValue.ToCharArray(buffer, size);
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
54 changes: 28 additions & 26 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 @@ -175,18 +187,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 +197,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)]; }
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 4846604

Please sign in to comment.