Skip to content

Commit

Permalink
[SL-ONLY] Feature/silabs tracing logs formating (#114)
Browse files Browse the repository at this point in the history
  • Loading branch information
@lpbeliveau-silabs
lpbeliveau-silabs authored Nov 20, 2024
1 parent a70f40e commit 9bf974a
Show file tree
Hide file tree
Showing 3 changed files with 345 additions and 66 deletions.
161 changes: 133 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,78 @@ namespace chip {
namespace Tracing {
namespace Silabs {

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

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 +114,29 @@ struct TimeTrackerStorage : public TimeTracker, PersistentData<kPersistentTimeTr
// TODO implement the Persistent Array class and use it here for logging the watermark array
};

int TimeTracker::ToCharArray(MutableByteSpan & buffer) const
{
switch (mType)
{
case OperationType::kBegin:
return snprintf(reinterpret_cast<char *>(buffer.data()), buffer.size(),
"TimeTracker - StartTime: %" PRIu32 ", Operation: %s, Type: %s, Error: 0x%" PRIx32, mStartTime.count(),
TimeTraceOperationToString(mOperation), OperationTypeToString(mType), mError.AsInteger());
case OperationType::kEnd:
return snprintf(reinterpret_cast<char *>(buffer.data()), buffer.size(),
"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());
case OperationType::kInstant:
return snprintf(reinterpret_cast<char *>(buffer.data()), buffer.size(),
"TimeTracker - EventTime: %" PRIu32 ", Operation: %s, Type: %s, Error: 0x%" PRIx32, mStartTime.count(),
TimeTraceOperationToString(mOperation), OperationTypeToString(mType), mError.AsInteger());
default:
return snprintf(reinterpret_cast<char *>(buffer.data()), buffer.size(), "TimeTracker - Unknown operation type");
}
}

SilabsTracer SilabsTracer::sInstance;

SilabsTracer::SilabsTracer()
Expand Down Expand Up @@ -78,7 +172,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 +184,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 +221,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
uint8_t buffer[kMaxTraceSize];
MutableByteSpan span(buffer);
tracker.ToCharArray(span);
ChipLogProgress(DeviceLayer, "%s", buffer); // Use format string literal
return CHIP_NO_ERROR;
}

Expand All @@ -168,10 +262,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 +284,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 +368,33 @@ 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, MutableByteSpan & buffer) 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.GetSize();

if (requiredSize < 0)
{
return CHIP_ERROR_INTERNAL;
}

if (static_cast<size_t>(requiredSize) >= buffer.size())
{
return CHIP_ERROR_BUFFER_TOO_SMALL;
}

current->mValue.ToCharArray(buffer);
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
65 changes: 39 additions & 26 deletions src/platform/silabs/tracing/SilabsTracing.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@
#include <lib/core/CHIPError.h>
#include <lib/core/CHIPPersistentStorageDelegate.h>
#include <lib/support/LinkedList.h>
#include <lib/support/Span.h>
#include <stdint.h>
#include <system/SystemClock.h>

Expand Down Expand Up @@ -60,6 +61,7 @@ enum class TimeTraceOperation : uint8_t
kBootup,
kSilabsInit,
kMatterInit,
kBufferFull,
kNumTraces,
};

Expand All @@ -78,6 +80,23 @@ 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 a buffer of size == 0 to get the required buffer size
* @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;

/** @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;
return ToCharArray(temp);
}
};

struct Watermark
Expand All @@ -95,10 +114,11 @@ struct Watermark
//
class SilabsTracer
{
public:
static constexpr size_t kNumTraces = to_underlying(TimeTraceOperation::kNumTraces);
static constexpr size_t kMaxBufferedTraces = 64;
static constexpr size_t kMaxTraceSize = 256;

public:
/** @brief Get the singleton instance of SilabsTracer */
static SilabsTracer & Instance() { return sInstance; }

Expand All @@ -119,24 +139,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 +198,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 +208,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, MutableByteSpan & buffer) const;

private:
struct TimeTrackerList
Expand Down
Loading

0 comments on commit 9bf974a

Please sign in to comment.