Skip to content

Commit

Permalink
Code Review Suggestions:
Browse files Browse the repository at this point in the history
1. Metric Macros take full string constants and no longer use
   preprocessor to prefix. Allows free flowing strings
2. Reworked MetricEvent class and documented
3. Handled LogEventMetric for Darwin, ESP32, Perfetto, JSON to account
   for all types
4. Removed timePoint from MetricEvent class. Timestamps and duration
   calculation is now responsibility for the handlers of the event
5. Reverted BUILD.gn in system to not break out SystemClock.h
  • Loading branch information
anush-apple committed Feb 24, 2024
1 parent a4a892a commit ad11da8
Show file tree
Hide file tree
Showing 19 changed files with 223 additions and 119 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,7 @@
#include <platform/DiagnosticDataProvider.h>
#include <tracing/macros.h>
#include <tracing/metric_event.h>
#include <tracing/metric_keys.h>

using namespace chip;
using namespace chip::app;
Expand Down Expand Up @@ -164,7 +165,7 @@ CHIP_ERROR WiFiDiagosticsAttrAccess::ReadWiFiRssi(AttributeValueEncoder & aEncod
{
rssi.SetNonNull(value);
ChipLogProgress(Zcl, "The current RSSI of the Node’s Wi-Fi radio in dB: %d", value);
MATTER_LOG_METRIC(WiFiRSSI, value);
MATTER_LOG_METRIC(chip::Tracing::kMetricWiFiRSSI, value);
}
else
{
Expand Down
17 changes: 9 additions & 8 deletions src/controller/CHIPDeviceController.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,7 @@

#ifndef __STDC_LIMIT_MACROS
#define __STDC_LIMIT_MACROS
#include <tracing/metric_keys.h>
#endif
#ifndef __STDC_FORMAT_MACROS
#define __STDC_FORMAT_MACROS
Expand Down Expand Up @@ -630,7 +631,7 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, co
CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, RendezvousParameters & params)
{
MATTER_TRACE_SCOPE("EstablishPASEConnection", "DeviceCommissioner");
MATTER_LOG_METRIC_BEGIN(PASESession);
MATTER_LOG_METRIC_BEGIN(chip::Tracing::kMetricPASESession);

CHIP_ERROR err = CHIP_NO_ERROR;
CommissioneeDeviceProxy * device = nullptr;
Expand Down Expand Up @@ -709,7 +710,7 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, Re
{
if (params.HasConnectionObject())
{
SuccessOrExit(err = mSystemState->BleLayer()->NewBleConnectionByObject(params.GetConnectionObject()), PASESessionBLE);
SuccessOrExit(err = mSystemState->BleLayer()->NewBleConnectionByObject(params.GetConnectionObject()), chip::Tracing::kMetricPASESessionBLE);
}
else if (params.HasDiscoveredObject())
{
Expand All @@ -718,7 +719,7 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, Re
mRendezvousParametersForDeviceDiscoveredOverBle = params;
SuccessOrExit(err = mSystemState->BleLayer()->NewBleConnectionByObject(
params.GetDiscoveredObject(), this, OnDiscoveredDeviceOverBleSuccess, OnDiscoveredDeviceOverBleError),
PASESessionBLE);
chip::Tracing::kMetricPASESessionBLE);
ExitNow(CHIP_NO_ERROR);
}
else if (params.HasDiscriminator())
Expand All @@ -731,7 +732,7 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, Re
discriminator.SetLongValue(params.GetDiscriminator());
SuccessOrExit(err = mSystemState->BleLayer()->NewBleConnectionByDiscriminator(
discriminator, this, OnDiscoveredDeviceOverBleSuccess, OnDiscoveredDeviceOverBleError),
PASESessionBLE);
chip::Tracing::kMetricPASESessionBLE);
ExitNow(CHIP_NO_ERROR);
}
else
Expand All @@ -741,7 +742,7 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, Re
}
#endif
session = mSystemState->SessionMgr()->CreateUnauthenticatedSession(params.GetPeerAddress(), params.GetMRPConfig());
VerifyOrExit(session.HasValue(), err = CHIP_ERROR_NO_MEMORY, PASESessionPair);
VerifyOrExit(session.HasValue(), err = CHIP_ERROR_NO_MEMORY, chip::Tracing::kMetricPASESessionPair);

// Allocate the exchange immediately before calling PASESession::Pair.
//
Expand All @@ -750,10 +751,10 @@ 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, err = CHIP_ERROR_INTERNAL, PASESessionPair);
VerifyOrExit(exchangeCtxt != nullptr, err = CHIP_ERROR_INTERNAL, chip::Tracing::kMetricPASESessionPair);

err = device->GetPairing().Pair(*mSystemState->SessionMgr(), params.GetSetupPINCode(), GetLocalMRPConfig(), exchangeCtxt, this);
SuccessOrExit(err, PASESessionPair);
SuccessOrExit(err, chip::Tracing::kMetricPASESessionPair);

exit:
if (err != CHIP_NO_ERROR)
Expand All @@ -764,7 +765,7 @@ CHIP_ERROR DeviceCommissioner::EstablishPASEConnection(NodeId remoteDeviceId, Re
}
}

MATTER_LOG_METRIC_END(PASESession, err);
MATTER_LOG_METRIC_END(chip::Tracing::kMetricPASESession);
return err;
}

Expand Down
71 changes: 45 additions & 26 deletions src/darwin/Framework/CHIP/MTRMetricsCollector.mm
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@
#include <platform/Darwin/Tracing.h>
#include <tracing/metric_event.h>
#include <tracing/registry.h>
#include <system/SystemClock.h>

using MetricEvent = chip::Tracing::MetricEvent;

Expand All @@ -47,12 +48,20 @@ - (instancetype)initWithMetricEvent:(const MetricEvent &)event
return nil;
}

if (event.value.type == MetricEvent::Value::Type::Signed32Type) {
_value = [NSNumber numberWithInteger:event.value.store.int32_value];
} else {
_value = [NSNumber numberWithUnsignedInteger:event.value.store.uint32_value];
using ValueType = MetricEvent::Value::Type;
switch (event.value().type) {
case ValueType::kInt32:
_value = [NSNumber numberWithInteger:event.ValueInt32()];
break;
case ValueType::kUInt32:
_value = [NSNumber numberWithInteger:event.ValueUInt32()];
break;
case ValueType::kChipErrorCode:
_value = [NSNumber numberWithInteger:event.ValueUInt32()];
break;
}
_timePoint = event.timePoint;

_timePoint = chip::System::SystemClock().GetMonotonicMicroseconds64();
_duration = chip::System::Clock::Microseconds64(0);
return self;
}
Expand Down Expand Up @@ -129,56 +138,66 @@ - (instancetype)init
return self;
}

static inline NSString * suffixNameForMetricTag(MetricEvent::Tag tag)
static inline NSString * suffixNameForMetricType(MetricEvent::Type type)
{
switch (tag) {
case MetricEvent::Tag::Begin:
switch (type) {
case MetricEvent::Type::kBeginEvent:
return @"-begin";
case MetricEvent::Tag::End:
case MetricEvent::Type::kEndEvent:
return @"-end";
case MetricEvent::Tag::Instant:
case MetricEvent::Type::kInstantEvent:
return @"-instant";
}
}

static inline NSString * suffixNameForMetricTag(const MetricEvent & event)
static inline NSString * suffixNameForMetric(const MetricEvent & event)
{
return suffixNameForMetricTag(event.tag);
return suffixNameForMetricType(event.type());
}

- (void)handleMetricEvent:(MetricEvent)event
{
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);

using ValueType = MetricEvent::Value::Type;
switch (event.value().type) {
case ValueType::kInt32:
MTR_LOG_INFO("Received metric event, key: %s, type: %d, value: %d", event.key(), event.type(), event.ValueInt32());
break;
case ValueType::kUInt32:
MTR_LOG_INFO("Received metric event, key: %s, type: %d, value: %u", event.key(), event.type(), event.ValueUInt32());
break;
case ValueType::kChipErrorCode:
MTR_LOG_INFO("Received metric event, key: %s, type: %d, error value: %u", event.key(), event.type(), event.ValueUInt32());
break;
default:
MTR_LOG_INFO("Received metric event, key: %s, type: %d, unknown value", event.key(), event.type());
return;
}

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

// If End event, compute its duration using the Begin event
if (event.tag == MetricEvent::Tag::End) {
auto metricsBeginKey = [NSString stringWithFormat:@"%s%@", event.key, suffixNameForMetricTag(MetricEvent::Tag::Begin)];
if (event.type() == MetricEvent::Type::kEndEvent) {
auto metricsBeginKey = [NSString stringWithFormat:@"%s%@", event.key(), suffixNameForMetricType(MetricEvent::Type::kBeginEvent)];
MTRMetricsData * beginMetric = _metricsDataCollection[metricsBeginKey];
if (beginMetric) {
[data setDurationFromMetricData:beginMetric];
} else {
// Unbalanced end
MTR_LOG_ERROR("Unable to find Begin event corresponding to Metric Event: %s", event.key);
MTR_LOG_ERROR("Unable to find Begin event corresponding to Metric Event: %s", event.key());
}
}

[_metricsDataCollection setValue:data forKey:metricsKey];

// If the event is a being or end event, implicitly emit a corresponding instant event
if (event.tag == MetricEvent::Tag::Begin || event.tag == MetricEvent::Tag::End) {
MetricEvent instantEvent(event);
instantEvent.tag = MetricEvent::Tag::Instant;
data = [[MTRMetricsData alloc] initWithMetricEvent:event];
metricsKey = [NSString stringWithFormat:@"%s%@", event.key, suffixNameForMetricTag(MetricEvent::Tag::Instant)];
if (event.type() == MetricEvent::Type::kBeginEvent || event.type() == MetricEvent::Type::kEndEvent) {
MetricEvent instantEvent(MetricEvent::Type::kInstantEvent, event.key(), event.value());
data = [[MTRMetricsData alloc] initWithMetricEvent:instantEvent];
metricsKey = [NSString stringWithFormat:@"%s%@", event.key(), suffixNameForMetric(instantEvent)];
[_metricsDataCollection setValue:data forKey:metricsKey];
}
}
Expand Down
2 changes: 1 addition & 1 deletion src/platform/Darwin/Tracing.h
Original file line number Diff line number Diff line change
Expand Up @@ -66,7 +66,7 @@ namespace Tracing {
typedef void (^MetricEventHandler)(MetricEvent event);

void SetMetricEventHandler(MetricEventHandler callback);
void LogMetricEvent(MetricEvent & event) override;
void LogMetricEvent(const MetricEvent & event) override;

private:
MetricEventHandler mClientCallback;
Expand Down
2 changes: 1 addition & 1 deletion src/platform/Darwin/Tracing.mm
Original file line number Diff line number Diff line change
Expand Up @@ -42,7 +42,7 @@ os_log_t GetMatterSignpostLogger()
mClientCallback = callback;
}

void DarwinTracingBackend::LogMetricEvent(MetricEvent & event)
void DarwinTracingBackend::LogMetricEvent(const MetricEvent & event)
{
// Pass along to the client to handle the event
if (mClientCallback) {
Expand Down
6 changes: 1 addition & 5 deletions src/system/BUILD.gn
Original file line number Diff line number Diff line change
Expand Up @@ -212,16 +212,13 @@ source_set("system_config_header") {
}
}

source_set("system_clock") {
sources = [ "SystemClock.h" ]
}

static_library("system") {
output_name = "libSystemLayer"

sources = [
"PlatformEventSupport.h",
"SystemAlignSize.h",
"SystemClock.h",
"SystemClock.cpp",
"SystemError.cpp",
"SystemError.h",
Expand Down Expand Up @@ -261,7 +258,6 @@ static_library("system") {
cflags = [ "-Wconversion" ]

public_deps = [
":system_clock",
":system_config_header",
"${chip_root}/src/lib/core:error",
"${chip_root}/src/lib/support",
Expand Down
1 change: 0 additions & 1 deletion src/tracing/BUILD.gn
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,6 @@ source_set("metrics") {
public_deps = [
":tracing_buildconfig",
"${chip_root}/src/lib/core:error",
"${chip_root}/src/system:system_clock",
]
}

Expand Down
2 changes: 1 addition & 1 deletion src/tracing/backend.h
Original file line number Diff line number Diff line change
Expand Up @@ -70,7 +70,7 @@ class Backend : public ::chip::IntrusiveListNodeBase<>
virtual void LogNodeLookup(NodeLookupInfo &) { TraceInstant("Lookup", "DNSSD"); }
virtual void LogNodeDiscovered(NodeDiscoveredInfo &) { TraceInstant("Node Discovered", "DNSSD"); }
virtual void LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo &) { TraceInstant("Discovery Failed", "DNSSD"); }
virtual void LogMetricEvent(MetricEvent &) { TraceInstant("Metric Event", "Metric"); }
virtual void LogMetricEvent(const MetricEvent &) { TraceInstant("Metric Event", "Metric"); }
};

} // namespace Tracing
Expand Down
27 changes: 22 additions & 5 deletions src/tracing/esp32_trace/esp32_tracing.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -155,17 +155,34 @@ void ESP32Backend::TraceCounter(const char * label)
::Insights::ESPInsightsCounter::GetInstance(label)->ReportMetrics();
}

void ESP32Backend::LogMetricEvent(MetricEvent & event)
void ESP32Backend::LogMetricEvent(const MetricEvent & event)
{
if (!mRegistered)
{
esp_diag_metrics_register("SYS_MTR" /*Tag of metrics */, event.key /* Unique key 8 */,
event.key /* label displayed on dashboard */, "insights.mtr" /* hierarchical path */,
esp_diag_metrics_register("SYS_MTR" /*Tag of metrics */, event.key() /* Unique key 8 */,
event.key() /* label displayed on dashboard */, "insights.mtr" /* hierarchical path */,
ESP_DIAG_DATA_TYPE_INT /* data_type */);
mRegistered = true;
}
ESP_LOGI("mtr", "The value of %s is %ld ", event.key, event.value.store.int32_value);
esp_diag_metrics_add_int(event.key, event.value.store.int32_value);

using ValueType = MetricEvent::Value::Type;
switch (event.value().type) {
case ValueType::kInt32:
ESP_LOGI("mtr", "The value of %s is %ld ", event.key(), event.ValueInt32());
esp_diag_metrics_add_int(event.key(), event.ValueInt32());
break;
case ValueType::kUInt32:
ESP_LOGI("mtr", "The value of %s is %lu ", event.key(), event.ValueUInt32());
esp_diag_metrics_add_uint(event.key(), event.ValueUInt32());
break;
case ValueType::kChipErrorCode:
ESP_LOGI("mtr", "The value of %s is error with code %lu ", event.key(), event.ValueUInt32());
esp_diag_metrics_add_uint(event.key(), event.ValueUInt32());
break;
default:
ESP_LOGI("mtr", "The value of %s is of an UNKNOWN TYPE", event.key());
break;
}
}

void ESP32Backend::TraceBegin(const char * label, const char * group)
Expand Down
2 changes: 1 addition & 1 deletion src/tracing/esp32_trace/esp32_tracing.h
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,7 @@ class ESP32Backend : public ::chip::Tracing::Backend
void LogNodeLookup(NodeLookupInfo &) override;
void LogNodeDiscovered(NodeDiscoveredInfo &) override;
void LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo &) override;
void LogMetricEvent(MetricEvent &) override;
void LogMetricEvent(const MetricEvent &) override;

private:
bool mRegistered = false;
Expand Down
22 changes: 19 additions & 3 deletions src/tracing/json/json_tracing.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -296,11 +296,27 @@ void JsonBackend::TraceCounter(const char * label)
OutputValue(value);
}

void JsonBackend::LogMetricEvent(MetricEvent & event)
void JsonBackend::LogMetricEvent(const MetricEvent & event)
{
::Json::Value value;
value["label"] = event.key;
value["value"] = event.value.store.int32_value;

value["label"] = event.key();

using ValueType = MetricEvent::Value::Type;
switch (event.value().type) {
case ValueType::kInt32:
value["value"] = event.ValueInt32();
break;
case ValueType::kUInt32:
value["value"] = event.ValueUInt32();
break;
case ValueType::kChipErrorCode:
value["value"] = event.ValueErrorCode();
break;
default:
value["value"] = "UNKNOWN";
break;
}

OutputValue(value);
}
Expand Down
2 changes: 1 addition & 1 deletion src/tracing/json/json_tracing.h
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,7 @@ class JsonBackend : public ::chip::Tracing::Backend
void LogNodeLookup(NodeLookupInfo &) override;
void LogNodeDiscovered(NodeDiscoveredInfo &) override;
void LogNodeDiscoveryFailed(NodeDiscoveryFailedInfo &) override;
void LogMetricEvent(MetricEvent &) override;
void LogMetricEvent(const MetricEvent &) override;
void Close() override { CloseFile(); }

private:
Expand Down
2 changes: 1 addition & 1 deletion src/tracing/log_declares.h
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,7 @@ struct MessageReceivedInfo;
struct NodeLookupInfo;
struct NodeDiscoveredInfo;
struct NodeDiscoveryFailedInfo;
struct MetricEvent;
class MetricEvent;

} // namespace Tracing
} // namespace chip
Loading

0 comments on commit ad11da8

Please sign in to comment.