Skip to content

Commit

Permalink
Moved metric keys to separate header
Browse files Browse the repository at this point in the history
Reworked metric_event names for more clarity
  • Loading branch information
anush-apple committed Feb 20, 2024
1 parent c7c7042 commit 80d1e32
Show file tree
Hide file tree
Showing 7 changed files with 116 additions and 70 deletions.
16 changes: 11 additions & 5 deletions src/darwin/Framework/CHIP/MTRMetricsCollector.mm
Original file line number Diff line number Diff line change
Expand Up @@ -49,11 +49,11 @@ - (instancetype)initWithMetricEvent:(const MetricEvent&) event
return nil;
}

if (event.value.type == MetricEvent::Value::ValueType::SignedValue) {
_value = [NSNumber numberWithInteger:event.value.store.svalue];
if (event.value.type == MetricEvent::Value::Type::Signed32Type) {
_value = [NSNumber numberWithInteger:event.value.store.int32_value];
}
else {
_value = [NSNumber numberWithUnsignedInteger:event.value.store.uvalue];
_value = [NSNumber numberWithUnsignedInteger:event.value.store.uint32_value];
}
_timePoint = event.timePoint;
_duration = chip::System::Clock::Microseconds64(0);
Expand Down Expand Up @@ -132,7 +132,7 @@ - (instancetype)init
return self;
}

static NSString * suffixNameForMetricTag(MetricEvent::Tag tag)
static inline NSString * suffixNameForMetricTag(MetricEvent::Tag tag)
{
switch (tag) {
case MetricEvent::Tag::Begin: return @"-begin";
Expand All @@ -148,9 +148,14 @@ - (instancetype)init

- (void)handleMetricEvent:(MetricEvent)event
{
MTR_LOG_INFO("Received metric event, type: %s, value: %u", event.key, event.value.store.uvalue);
MTR_LOG_INFO("Received metric event, key: %s, type: %hhu value: %d",
event.key,
event.value.type,
(event.value.type == MetricEvent::Value::Type::Signed32Type) ? event.value.store.int32_value : event.value.store.uint32_value);

std::lock_guard lock(_lock);

// Create the new metric key based event type
auto metricsKey = [NSString stringWithFormat:@"%s%@", event.key, suffixNameForMetricTag(event)];
MTRMetricsData *data = [[MTRMetricsData alloc] initWithMetricEvent:event];

Expand All @@ -162,6 +167,7 @@ - (void)handleMetricEvent:(MetricEvent)event
[data setDurationFromMetricData:beginMetric];
}
else {
// Unbalanced end
MTR_LOG_ERROR("Unable to find Begin event corresponding to Metric Event: %s", event.key);
}
}
Expand Down
14 changes: 7 additions & 7 deletions src/platform/Darwin/Tracing.h
Original file line number Diff line number Diff line change
Expand Up @@ -20,16 +20,16 @@
#include <os/signpost.h>
#include <tracing/backend.h>

#define MATTER_TRACE_BEGIN(label,group) os_signpost_interval_begin(_DARWIN_MATTER_SIGNPOST_LOGGER, OS_SIGNPOST_ID_EXCLUSIVE, group "-" label)
#define MATTER_TRACE_END(label,group) os_signpost_interval_end(_DARWIN_MATTER_SIGNPOST_LOGGER, OS_SIGNPOST_ID_EXCLUSIVE, group "-" label)
#define MATTER_TRACE_INSTANT(label,group) os_signpost_event_emit(_DARWIN_MATTER_SIGNPOST_LOGGER, OS_SIGNPOST_ID_EXCLUSIVE, group "-" label)
#define MATTER_TRACE_BEGIN(label,group) os_signpost_interval_begin(__DARWIN_MATTER_SIGNPOST_LOGGER(), OS_SIGNPOST_ID_EXCLUSIVE, group "-" label)
#define MATTER_TRACE_END(label,group) os_signpost_interval_end(__DARWIN_MATTER_SIGNPOST_LOGGER(), OS_SIGNPOST_ID_EXCLUSIVE, group "-" label)
#define MATTER_TRACE_INSTANT(label,group) os_signpost_event_emit(__DARWIN_MATTER_SIGNPOST_LOGGER(), OS_SIGNPOST_ID_EXCLUSIVE, group "-" label)
#define MATTER_TRACE_METRIC(label, value) ::chip::Tracing::Internal::Metric(label, value)

#define MATTER_TRACE_COUNTER(label) \
do \
{ \
static unsigned int count##_label = 0; \
os_signpost_event_emit(_DARWIN_MATTER_SIGNPOST_LOGGER, OS_SIGNPOST_ID_EXCLUSIVE, label, "%u", ++count##_label); \
os_signpost_event_emit(__DARWIN_MATTER_SIGNPOST_LOGGER(), OS_SIGNPOST_ID_EXCLUSIVE, label, "%u", ++count##_label); \
} while (0)

#define _CONCAT_IMPL(a, b) a##b
Expand All @@ -38,7 +38,7 @@
#define MATTER_TRACE_SCOPE(label, group) ::chip::Tracing::signposts::Scoped _MACRO_CONCAT(_trace_scope, __COUNTER__)(label, group)

#define MATTER_SDK_SIGNPOST_NAME "com.csa.matter.signpost"
#define _DARWIN_MATTER_SIGNPOST_LOGGER chip::Tracing::signposts::GetMatterSignpostLogger()
#define __DARWIN_MATTER_SIGNPOST_LOGGER() chip::Tracing::signposts::GetMatterSignpostLogger()

namespace chip {
namespace Tracing {
Expand All @@ -49,8 +49,8 @@ os_log_t GetMatterSignpostLogger();
class Scoped
{
public:
inline Scoped(const char * label, const char * group) : mLabel(label), mGroup(group) { os_signpost_interval_begin(_DARWIN_MATTER_SIGNPOST_LOGGER, OS_SIGNPOST_ID_EXCLUSIVE, MATTER_SDK_SIGNPOST_NAME, "%s-%s", group, label); }
inline ~Scoped() { os_signpost_interval_end(_DARWIN_MATTER_SIGNPOST_LOGGER, OS_SIGNPOST_ID_EXCLUSIVE, MATTER_SDK_SIGNPOST_NAME, "%s-%s", mGroup, mLabel); }
inline Scoped(const char * label, const char * group) : mLabel(label), mGroup(group) { os_signpost_interval_begin(__DARWIN_MATTER_SIGNPOST_LOGGER(), OS_SIGNPOST_ID_EXCLUSIVE, MATTER_SDK_SIGNPOST_NAME, "%s-%s", group, label); }
inline ~Scoped() { os_signpost_interval_end(__DARWIN_MATTER_SIGNPOST_LOGGER(), OS_SIGNPOST_ID_EXCLUSIVE, MATTER_SDK_SIGNPOST_NAME, "%s-%s", mGroup, mLabel); }

private:
const char * mLabel;
Expand Down
4 changes: 1 addition & 3 deletions src/platform/Darwin/Tracing.mm
Original file line number Diff line number Diff line change
Expand Up @@ -42,10 +42,8 @@ os_log_t GetMatterSignpostLogger()

void DarwinTracingBackend::LogEvent(MetricEvent & event)
{
ChipLogProgress(DeviceLayer, "Receive scalar event, type: %s, value: %u",
event.key, event.value.store.uvalue);
// Pass along to the client to handle the event
if (mClientCallback) {
ChipLogProgress(DeviceLayer, "Invoking client callback %p", mClientCallback);
mClientCallback(event);
}
}
Expand Down
1 change: 1 addition & 0 deletions src/tracing/BUILD.gn
Original file line number Diff line number Diff line change
Expand Up @@ -51,6 +51,7 @@ source_set("metrics") {
sources = [
"metric_event.h",
"metric_macros.h",
"metric_keys.h",
]

public_deps = [
Expand Down
65 changes: 27 additions & 38 deletions src/tracing/metric_event.h
Original file line number Diff line number Diff line change
Expand Up @@ -23,29 +23,11 @@

#include <lib/core/CHIPError.h>
#include <system/SystemClock.h>
#include <tracing/metric_keys.h>

namespace chip {
namespace Tracing {

/**
* Defines the key type use to identity a specific metric
*/
typedef const char* MetricKey;

/**
* List of supported metric keys
*/
constexpr MetricKey kMetricDiscoveryOverBLE = "disc-over-ble";
constexpr MetricKey kMetricDiscoveryOnNetwork = "disc-on-nw";
constexpr MetricKey kMetricPASESession = "pase-session";
constexpr MetricKey kMetricPASESessionPair = "pase-session-pair";
constexpr MetricKey kMetricPASESessionBLE = "pase-session-ble";
constexpr MetricKey kMetricAttestationResult = "attestation-result";
constexpr MetricKey kMetricAttestationOverridden = "attestation-overridden";
constexpr MetricKey kMetricCASESession = "case-session";
constexpr MetricKey kMetricCASESessionEstState = "case-conn-est";
constexpr MetricKey kMetricWiFiRSSI = "wifi-rssi";

/**
* Define a metric that can be logged. A metric consists of a key-value pair. The value is
* currently limited to simple scalar values. The value is interpreted based on the key type.
Expand All @@ -64,37 +46,41 @@ struct MetricEvent

// Value for the metric
struct Value {
enum class ValueType {
SignedValue,
UnsignedValue,
ErrorValue
enum class Type : uint8_t {
Signed32Type, // int32_t
Unsigned32Type, // uint32_t
ChipErrorType // chip::ChipError
};

union ValueStore {
uint32_t uvalue;
int32_t svalue;
ValueStore(uint32_t v) : uvalue(v) {}
ValueStore(int32_t v) : svalue(v) {}
} store;
ValueType type;
union Store {
int32_t int32_value;
uint32_t uint32_value;

Value(uint32_t value) : store(value), type(ValueType::UnsignedValue) {}
Store(int32_t v) : int32_value(v) {}

Value(int32_t value) : store(value), type(ValueType::SignedValue) {}
Store(uint32_t v) : uint32_value(v) {}
};

Value(const ChipError & err) : store(err.AsInteger()), type(ValueType::ErrorValue) {}
Store store;
Type type;

Value(uint32_t value) : store(value), type(Type::Unsigned32Type) {}

Value(int32_t value) : store(value), type(Type::Signed32Type) {}

Value(const ChipError & err) : store(err.AsInteger()), type(Type::ChipErrorType) {}
};

Tag tag;
MetricKey key;
Value value;
System::Clock::Microseconds64 timePoint;

MetricEvent(Tag tg, MetricKey k, uint32_t val = 0)
MetricEvent(Tag tg, MetricKey k, int32_t val = 0)
: tag(tg), key(k), value(val), timePoint(System::SystemClock().GetMonotonicMicroseconds64())
{}

MetricEvent(Tag tg, MetricKey k, int32_t val)
MetricEvent(Tag tg, MetricKey k, uint32_t val)
: tag(tg), key(k), value(val), timePoint(System::SystemClock().GetMonotonicMicroseconds64())
{}

Expand All @@ -108,14 +94,17 @@ namespace Internal {
void LogEvent(::chip::Tracing::MetricEvent & event);

} // namespace Internal
//

namespace utils {

/**
* Utility to emit an instant metric if the error is not a success. Used in SuccessOrExit macro
* to allow emitting the event before jumping to the exit label.
*/
inline bool logMetricIfError(const ::chip::ChipError& err, MetricKey metricKey)
{
bool success = ::chip::ChipError::IsSuccess(err);
if (!success)
{
if (!success) {
using Tag = chip::Tracing::MetricEvent::Tag;
::chip::Tracing::MetricEvent _metric_event(Tag::Instant, metricKey, err);
::chip::Tracing::Internal::LogEvent(_metric_event);
Expand Down
47 changes: 47 additions & 0 deletions src/tracing/metric_keys.h
Original file line number Diff line number Diff line change
@@ -0,0 +1,47 @@
/*
* Copyright (c) 2024 Project CHIP Authors
* All rights reserved.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
#pragma once

#include <matter/tracing/build_config.h>

#if MATTER_TRACING_ENABLED

namespace chip {
namespace Tracing {

/**
* Defines the key type use to identity a specific metric
*/
typedef const char* MetricKey;

/**
* List of supported metric keys
*/
constexpr MetricKey kMetricDiscoveryOverBLE = "disc-over-ble";
constexpr MetricKey kMetricDiscoveryOnNetwork = "disc-on-nw";
constexpr MetricKey kMetricPASESession = "pase-session";
constexpr MetricKey kMetricPASESessionPair = "pase-session-pair";
constexpr MetricKey kMetricPASESessionBLE = "pase-session-ble";
constexpr MetricKey kMetricAttestationResult = "attestation-result";
constexpr MetricKey kMetricAttestationOverridden = "attestation-overridden";
constexpr MetricKey kMetricCASESession = "case-session";
constexpr MetricKey kMetricCASESessionEstState = "case-conn-est";

} // namespace Tracing
} // namespace chip

#endif // MATTER_TRACING_ENABLED
39 changes: 22 additions & 17 deletions src/tracing/metric_macros.h
Original file line number Diff line number Diff line change
Expand Up @@ -22,51 +22,51 @@

#if MATTER_TRACING_ENABLED


// Always return the 3rd argument from macro parameters
// Utility to always return the 3rd argument from macro parameters
#define __GET_3RD_ARGUMENT(_a1,_a2,_a3,...) _a3

// Macro to select the verify or exit macro with the correct signature based on the invoked macro
// Utility macro to select the VerifyOrExit macro with the correct signature based on the invoked macro
#define __SELECT_MACRO_FOR_VERIFY_ACTION(...) __GET_3RD_ARGUMENT(__VA_ARGS__, \
__VERIFY_ACTION_2ARGS, \
__VERIFY_ACTION_1ARGS, )

// Wrapper to capture all arguments and invoke the real wrapper for VerifyOrExit's third argument
#define __LOG_METRIC_FOR_VERIFY_ACTION(...) __SELECT_MACRO_FOR_VERIFY_ACTION(__VA_ARGS__)(__VA_ARGS__)

// Macro that takes the action wraps it to emit the metric in a Verify macro, when a metric key is specified
// Utility macro that takes the action wraps it to emit the metric in a Verify macro, when a metric key is specified
#define __VERIFY_ACTION_2ARGS(anAction, metricKey) MATTER_LOG_METRIC(metricKey, anAction)

// Macro that takes the action in a Verify macro when a metric key is not specified
#define __VERIFY_ACTION_1ARGS(anAction) anAction

// Macro used by VerifyOrExit macro to handle a third optional metric key and emit an event, if specified
// Utility macro used by VerifyOrExit macro to handle an optional third metric key argument and emit an event, if specified
#define LOG_METRIC_FOR_VERIFY_OR_EXIT_ACTION(anAction,...) __LOG_METRIC_FOR_VERIFY_ACTION(anAction,##__VA_ARGS__)


// Macro to select the success or exit macro with the correct signature based on the invoked macro
// Utility macro to select the SuccessOrExit macro with the correct signature based on the invoked macro
#define __SELECT_MACRO_FOR_SUCCESS_OR_EXIT(...) __GET_3RD_ARGUMENT(__VA_ARGS__, \
__SUCCESS_OR_EXIT_2ARGS, \
__SUCCESS_OR_EXIT_1ARGS, )

// Wrapper to capture all arguments and invoke the real wrapper for SuccessOrExit's second argument
#define __LOG_METRIC_FOR_SUCCESS_OR_EXIT(...) __SELECT_MACRO_FOR_SUCCESS_OR_EXIT(__VA_ARGS__)(__VA_ARGS__)

// Macro that takes the status and wraps it to emit the metric in a SuccessOrExit macro, when a metric key is specified
// Utility macro that takes the status and wraps it to emit the metric in a SuccessOrExit macro, when a metric key is specified
#define __SUCCESS_OR_EXIT_2ARGS(aStatus, metricKey) chip::Tracing::utils::logMetricIfError(aStatus, chip::Tracing::kMetric##metricKey)

// Macro that just evaluates the status when no metric key is specified
// Utility macro that just evaluates the status when no metric key is specified
#define __SUCCESS_OR_EXIT_1ARGS(aStatus) ::chip::ChipError::IsSuccess((aStatus))

// Utility macro used by SuccessOrExit macro to handle an optional second metric key argument and emit an event, if specified
#define LOG_METRIC_FOR_SUCCESS_OR_EXIT(aStatus,...) __LOG_METRIC_FOR_SUCCESS_OR_EXIT(aStatus,##__VA_ARGS__)


////////////////////// Metric LOGGING

// Always return the 4th argument from macro parameters
// Utility to always return the 4th argument from macro parameters
#define __GET_4TH_ARG(_a1,_a2,_a3,_a4,...) _a4

// Macro to select the macro with the correct signature based on the invoked MATTER_LOG_METRIC_XYZ macro
// Utility macro to select the macro with the correct signature based on the invoked MATTER_LOG_METRIC_XYZ macro
#define __SELECT_MACRO_FOR_EVENT_METRIC(...) __GET_4TH_ARG(__VA_ARGS__, \
__MATTER_LOG_METRIC_3ARGS, \
__MATTER_LOG_METRIC_2ARGS, \
Expand Down Expand Up @@ -164,17 +164,22 @@
*/
#define MATTER_LOG_METRIC_END(key, ...) __MATTER_LOG_METRIC(Tag::End, key, ##__VA_ARGS__)

#else
#else // Tracing is disabled

#define __MATTER_LOG_METRIC_DISABLE(...) \
do \
{ \
} while (false)

// Noop if tracing is disabled
#define MATTER_LOG_METRIC(...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
#define MATTER_LOG_METRIC_BEGIN(key, ...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
#define MATTER_LOG_METRIC_END(key, ...) _MATTER_TRACE_DISABLE(__VA_ARGS__)
// Noop for logging metrics
#define MATTER_LOG_METRIC(...) __MATTER_LOG_METRIC_DISABLE(__VA_ARGS__)
#define MATTER_LOG_METRIC_BEGIN(key, ...) __MATTER_LOG_METRIC_DISABLE(__VA_ARGS__)
#define MATTER_LOG_METRIC_END(key, ...) __MATTER_LOG_METRIC_DISABLE(__VA_ARGS__)

// Default behavior when tracing is disabled is to just execute the action
// Default behavior is to just execute the action
#define LOG_METRIC_FOR_VERIFY_OR_EXIT_ACTION(anAction,...) anAction

// Default behavior when tracing is disabled is to just evaluate the status
// Default behavior is to just evaluate the status
#define LOG_METRIC_FOR_SUCCESS_OR_EXIT(aStatus,...) ::chip::ChipError::IsSuccess((aStatus))

#endif // MATTER_TRACING_ENABLED

0 comments on commit 80d1e32

Please sign in to comment.