Modified metric object to have begin, end and instant qualities

src/controller/CHIPDeviceController.cpp

@@ -630,6 +630,8 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, co
 CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, RendezvousParameters & params)
 {
     MATTER_TRACE_SCOPE("EstablishPASEConnection", "DeviceCommissioner");
+    MATTER_LOG_METRIC_BEGIN(PASEConnectionEstablished); // Emit start of event (-begin), Emit Signpost
+    MATTER_LOG_METRIC_INSTANT(PASEConnectionEstablished); // Emit event (-event), Emit Signpost
 
     CHIP_ERROR err                     = CHIP_NO_ERROR;
     CommissioneeDeviceProxy * device   = nullptr;
@@ -748,7 +750,8 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, Re
     // exchange context right before calling Pair ensures that if allocation
     // succeeds, PASESession has taken ownership.
     exchangeCtxt = mSystemState->ExchangeMgr()->NewContext(session.Value(), &device->GetPairing());
-    VerifyOrExit(exchangeCtxt != nullptr, MATTER_LOG_METRIC_EVENT(PASEConnectionFailed, err = CHIP_ERROR_INTERNAL));
+    //VerifyOrExit(exchangeCtxt != nullptr, MATTER_LOG_METRIC_EVENT(PASEConnectionFailed, err = CHIP_ERROR_INTERNAL));
+    VerifyOrExit(exchangeCtxt != nullptr, err = CHIP_ERROR_INTERNAL);
 
     err = device->GetPairing().Pair(*mSystemState->SessionMgr(), params.GetSetupPINCode(), GetLocalMRPConfig(), exchangeCtxt, this);
     SuccessOrExit(err);
@@ -762,7 +765,10 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, Re
         }
     }
 
-    MATTER_LOG_METRIC_EVENT(PASEConnectionEstablished, CHIP_NO_ERROR);
+    MATTER_LOG_METRIC_INSTANT(PASEConnectionEstablished, 2); // Emit event (-event)
+    MATTER_LOG_METRIC_INSTANT(PASEConnectionEstablished); // Emit event (-event)
+    MATTER_LOG_METRIC_END(PASEConnectionEstablished, err); // Emit end of event with duration (-duration), Emit event (-end), Emit event error separately (-error), Emit Signpost
+    MATTER_LOG_METRIC_END(PASEConnectionEstablished); // Emit end of event with duration (-duration), Emit event (-end), Emit Signpost
     return err;
 }
 

src/darwin/Framework/CHIP/MTRMetricsCollector.mm

@@ -70,14 +70,14 @@ - (instancetype)init
 
 - (void)handleMetricEvent:(chip::Tracing::MetricEvent)event
 {
-    MTR_LOG_INFO("Received metric event, type: %s, value: %u", event.key, event.value.uvalue);
+    MTR_LOG_INFO("Received metric event, type: %s, value: %u", event.key, event.value.store.uvalue);
     std::lock_guard lock(_lock);
-    if (event.isSigned) {
-        [_metricsData setValue:[NSNumber numberWithInteger:event.value.svalue]
+    if (event.value.type == ::chip::Tracing::MetricEvent::Value::ValueType::SignedValue) {
+        [_metricsData setValue:[NSNumber numberWithInteger:event.value.store.svalue]
                         forKey:[NSString stringWithCString:event.key encoding:NSUTF8StringEncoding]];
     }
     else {
-        [_metricsData setValue:[NSNumber numberWithUnsignedInteger:event.value.uvalue]
+        [_metricsData setValue:[NSNumber numberWithUnsignedInteger:event.value.store.uvalue]
                         forKey:[NSString stringWithCString:event.key encoding:NSUTF8StringEncoding]];
     }
 }

src/platform/Darwin/Tracing.mm

@@ -43,7 +43,7 @@ os_log_t GetMatterSignpostLogger()
     void DarwinTracingBackend::LogEvent(MetricEvent & event)
     {
         ChipLogProgress(DeviceLayer, "Receive scalar event, type: %s, value: %u",
-                        event.key, event.value.uvalue);
+                        event.key, event.value.store.uvalue);
         if (mClientCallback) {
             ChipLogProgress(DeviceLayer, "Invoking client callback %p", mClientCallback);
             mClientCallback(event);

src/tracing/macros.h

@@ -75,13 +75,47 @@
         ::chip::Tracing::Internal::LogNodeDiscoveryFailed(_trace_data);                                                            \
     } while (false)
 
-#define MATTER_LOG_METRIC_EVENT(key,value)                                                                              \
+////////////////////// Metric LOGGING
+
+#define __GET_4TH_ARG(_a1,_a2,_a3,_a4,...) _a4
+
+#define __SELECT_MACRO_FOR_EVENT_METRIC(...) __GET_4TH_ARG(__VA_ARGS__,                                                            \
+        __MATTER_LOG_METRIC_3ARGS,                                                                                                 \
+        __MATTER_LOG_METRIC_2ARGS,                                                                                                 \
+        __MATTER_LOG_METRIC_1ARGS, )
+
+#define __MATTER_LOG_METRIC(...) __SELECT_MACRO_FOR_EVENT_METRIC(__VA_ARGS__)(__VA_ARGS__)
+
+#define __MATTER_LOG_METRIC_1ARGS(key)                                                                                             \
+    do                                                                                                                             \
+    {                                                                                                                              \
+        using Tag = chip::Tracing::MetricEvent::Tag;                                                                               \
+        ::chip::Tracing::MetricEvent _metric_event(Tag::Instant, chip::Tracing::kMetric##key);                                     \
+        ::chip::Tracing::Internal::LogEvent(_metric_event);                                                                        \
+    } while (false)
+
+#define __MATTER_LOG_METRIC_2ARGS(tag,key)                                                                                         \
+    do                                                                                                                             \
+    {                                                                                                                              \
+        using Tag = chip::Tracing::MetricEvent::Tag;                                                                               \
+        ::chip::Tracing::MetricEvent _metric_event(tag, chip::Tracing::kMetric##key);                                              \
+        ::chip::Tracing::Internal::LogEvent(_metric_event);                                                                        \
+    } while (false)
+
+#define __MATTER_LOG_METRIC_3ARGS(tag,key,value)                                                                                   \
     do                                                                                                                             \
     {                                                                                                                              \
-        ::chip::Tracing::MetricEvent _metric_event(chip::Tracing::kMetric##key,value);                                                                 \
+        using Tag = chip::Tracing::MetricEvent::Tag;                                                                               \
+        ::chip::Tracing::MetricEvent _metric_event(tag, chip::Tracing::kMetric##key,value);                                        \
         ::chip::Tracing::Internal::LogEvent(_metric_event);                                                                        \
     } while (false)
 
+
+// Format for the args the metric macros: MATTER_LOG_METRIC_XYZ(key, [optional value])
+#define MATTER_LOG_METRIC_INSTANT(...) __MATTER_LOG_METRIC(Tag::Instant, __VA_ARGS__)
+#define MATTER_LOG_METRIC_BEGIN(...) __MATTER_LOG_METRIC(Tag::Begin, __VA_ARGS__)
+#define MATTER_LOG_METRIC_END(...) __MATTER_LOG_METRIC(Tag::End, __VA_ARGS__)
+
 #else // MATTER_TRACING_ENABLED
 
 #define _MATTER_TRACE_DISABLE(...)                                                                                                 \

src/tracing/metric_event.h

@@ -16,14 +16,25 @@
  */
 #pragma once
 
+#include <matter/tracing/build_config.h>
+
+#if MATTER_TRACING_ENABLED
+
 #include <lib/core/CHIPError.h>
 #include <stdint.h>
+#include <chrono>
 
 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 = "discovery-over-ble";
 constexpr MetricKey kMetricDiscoveryOnNetwork = "discovery-on-nw";
 constexpr MetricKey kMetricPASEConnectionEstablished = "pase-conn-est";
@@ -34,21 +45,64 @@ constexpr MetricKey kMetricCASEConnectionEstablished = "case-conn-est";
 constexpr MetricKey kMetricCASEConnectionFailed = "case-conn-failed";
 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.
+ *
+ * Additionally a metric is tagged as either an instant type or marked with a begin and end 
+ * for the event. When the latter is used, a duration can be associated between the two events.
+ */
 struct MetricEvent
 {
+    // Metric tag type
+    enum class Tag {
+        Begin,    // Implies a duration
+        End,      // Implies a duration
+        Instant   // No duration
+    };
+
+    // Value for the metric
+    struct Value {
+        enum class ValueType {
+            SignedValue,
+            UnsignedValue,
+            ErrorValue
+        };
+
+        union ValueStore {
+            uint32_t uvalue;
+            int32_t svalue;
+            ValueStore(uint32_t v) : uvalue(v) {}
+            ValueStore(int32_t v) : svalue(v) {}
+        } store;
+        ValueType type;
+
+        Value(uint32_t value) : store(value), type(ValueType::UnsignedValue) {}
+
+        Value(int32_t value) : store(value), type(ValueType::SignedValue) {}
+
+        Value(const ChipError & err) : store(err.AsInteger()), type(ValueType::ErrorValue) {}
+    };
+
+    Tag tag;
     MetricKey key;
-    union Value {
-        uint32_t uvalue;
-        int32_t svalue;
-        Value(uint32_t v) : uvalue(v) {}
-        Value(int32_t v) : svalue(v) {}
-    } value;
-    bool isSigned;
-
-    MetricEvent(MetricKey k, uint32_t val = 0) : key(k), value(val), isSigned(false) {}
-    MetricEvent(MetricKey k, int32_t val = 0) : key(k), value(val), isSigned(true) {}
-    MetricEvent(MetricKey k, ChipError err) : key(k), value(err.AsInteger()), isSigned(false) {}
+    Value value;
+    std::chrono::steady_clock::time_point timePoint;
+
+    MetricEvent(Tag tg, MetricKey k, uint32_t val = 0)
+        : tag(tg), key(k), value(val), timePoint(std::chrono::steady_clock::now())
+    {}
+
+    MetricEvent(Tag tg, MetricKey k, int32_t val)
+        : tag(tg), key(k), value(val), timePoint(std::chrono::steady_clock::now())
+    {}
+
+    MetricEvent(Tag tg, MetricKey k, const ChipError & err)
+        : tag(tg), key(k), value(err.AsInteger()), timePoint(std::chrono::steady_clock::now())
+    {}
 };
 
 } // namespace Tracing
 } // namespace chip
+
+#endif // MATTER_TRACING_ENABLED