diff --git a/src/darwin/Framework/CHIP/MTRMetricsCollector.mm b/src/darwin/Framework/CHIP/MTRMetricsCollector.mm index ee28974f23fa58..dd989a117a2d22 100644 --- a/src/darwin/Framework/CHIP/MTRMetricsCollector.mm +++ b/src/darwin/Framework/CHIP/MTRMetricsCollector.mm @@ -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); @@ -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"; @@ -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]; @@ -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); } } diff --git a/src/platform/Darwin/Tracing.h b/src/platform/Darwin/Tracing.h index cae1ac727a022f..45a450061816d4 100644 --- a/src/platform/Darwin/Tracing.h +++ b/src/platform/Darwin/Tracing.h @@ -20,16 +20,16 @@ #include #include -#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 @@ -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 { @@ -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; diff --git a/src/platform/Darwin/Tracing.mm b/src/platform/Darwin/Tracing.mm index 4e961dc5a70c73..13ed7655d7a28a 100644 --- a/src/platform/Darwin/Tracing.mm +++ b/src/platform/Darwin/Tracing.mm @@ -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); } } diff --git a/src/tracing/BUILD.gn b/src/tracing/BUILD.gn index c408a733708f25..ef2fdd512fae79 100644 --- a/src/tracing/BUILD.gn +++ b/src/tracing/BUILD.gn @@ -51,6 +51,7 @@ source_set("metrics") { sources = [ "metric_event.h", "metric_macros.h", + "metric_keys.h", ] public_deps = [ diff --git a/src/tracing/metric_event.h b/src/tracing/metric_event.h index d6663f340c2b29..52e419ec5dfac9 100644 --- a/src/tracing/metric_event.h +++ b/src/tracing/metric_event.h @@ -23,29 +23,11 @@ #include #include +#include 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. @@ -64,25 +46,29 @@ 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; @@ -90,11 +76,11 @@ struct MetricEvent 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()) {} @@ -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); diff --git a/src/tracing/metric_keys.h b/src/tracing/metric_keys.h new file mode 100644 index 00000000000000..79786d17b95daf --- /dev/null +++ b/src/tracing/metric_keys.h @@ -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 + +#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 diff --git a/src/tracing/metric_macros.h b/src/tracing/metric_macros.h index 4100f28321c894..24cea21b83608d 100644 --- a/src/tracing/metric_macros.h +++ b/src/tracing/metric_macros.h @@ -22,11 +22,10 @@ #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, ) @@ -34,17 +33,17 @@ // 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, ) @@ -52,21 +51,22 @@ // 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, \ @@ -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