diff --git a/src/darwin/Framework/CHIP/MTRCommissionableBrowser.mm b/src/darwin/Framework/CHIP/MTRCommissionableBrowser.mm index 4e7b253fff5831..a0ccfd380a232d 100644 --- a/src/darwin/Framework/CHIP/MTRCommissionableBrowser.mm +++ b/src/darwin/Framework/CHIP/MTRCommissionableBrowser.mm @@ -20,6 +20,8 @@ #import "MTRCommissionableBrowserResult_Internal.h" #import "MTRDeviceController.h" #import "MTRLogging_Internal.h" +#import "MTRMetricKeys.h" +#include #include #include @@ -35,6 +37,8 @@ constexpr char kBleKey[] = "BLE"; +using namespace chip::Tracing::DarwinFramework; + @implementation MTRCommissionableBrowserResultInterfaces @end @@ -70,6 +74,7 @@ CHIP_ERROR Start(id delegate, MTRDeviceControl mController = controller; mDispatchQueue = queue; mDiscoveredResults = [[NSMutableDictionary alloc] init]; + ResetCounters(); #if CONFIG_NETWORK_LAYER_BLE ReturnErrorOnFailure(PlatformMgrImpl().StartBleScan(this)); @@ -100,6 +105,7 @@ CHIP_ERROR Stop() ClearBleDiscoveredDevices(); ClearDnssdDiscoveredDevices(); + ResetCounters(); mDiscoveredResults = nil; #if CONFIG_NETWORK_LAYER_BLE @@ -109,6 +115,12 @@ CHIP_ERROR Stop() return ChipDnssdStopBrowse(this); } + void ResetCounters() + { + mOnNetworkDevicesAdded = mOnNetworkDevicesRemoved = 0; + mBLEDevicesAdded = mBLEDevicesRemoved = 0; + } + void ClearBleDiscoveredDevices() { NSMutableDictionary * discoveredResultsCopy = @ {}.mutableCopy; @@ -197,6 +209,8 @@ void OnBrowseAdd(DnssdService service) override VerifyOrReturn(mController != nil); VerifyOrReturn(mDispatchQueue != nil); + MATTER_LOG_METRIC(kMetricOnNetworkDevicesAdded, ++mOnNetworkDevicesAdded); + auto key = [NSString stringWithUTF8String:service.mName]; if ([mDiscoveredResults objectForKey:key] == nil) { mDiscoveredResults[key] = [[MTRCommissionableBrowserResult alloc] init]; @@ -218,6 +232,8 @@ void OnBrowseRemove(DnssdService service) override VerifyOrReturn(mController != nil); VerifyOrReturn(mDispatchQueue != nil); + MATTER_LOG_METRIC(kMetricOnNetworkDevicesRemoved, ++mOnNetworkDevicesRemoved); + auto key = [NSString stringWithUTF8String:service.mName]; if ([mDiscoveredResults objectForKey:key] == nil) { // It should not happens. @@ -269,6 +285,8 @@ void OnBleScanAdd(BLE_CONNECTION_OBJECT connObj, const ChipBLEDeviceIdentificati result.commissioningMode = YES; result.params = chip::MakeOptional(chip::Controller::SetUpCodePairerParameters(connObj, false /* connected */)); + MATTER_LOG_METRIC(kMetricBLEDevicesAdded, ++mBLEDevicesAdded); + auto key = [NSString stringWithFormat:@"%@", connObj]; mDiscoveredResults[key] = result; @@ -290,6 +308,8 @@ void OnBleScanRemove(BLE_CONNECTION_OBJECT connObj) override auto result = mDiscoveredResults[key]; mDiscoveredResults[key] = nil; + MATTER_LOG_METRIC(kMetricBLEDevicesRemoved, ++mBLEDevicesRemoved); + dispatch_async(mDispatchQueue, ^{ [mDelegate controller:mController didFindCommissionableDevice:result]; }); @@ -301,6 +321,10 @@ void OnBleScanRemove(BLE_CONNECTION_OBJECT connObj) override id mDelegate; MTRDeviceController * mController; NSMutableDictionary * mDiscoveredResults; + int32_t mOnNetworkDevicesAdded; + int32_t mOnNetworkDevicesRemoved; + int32_t mBLEDevicesAdded; + int32_t mBLEDevicesRemoved; }; @interface MTRCommissionableBrowser () diff --git a/src/darwin/Framework/CHIP/MTRDeviceController.mm b/src/darwin/Framework/CHIP/MTRDeviceController.mm index a0eb2dd829d572..789449cb4d9f9f 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceController.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceController.mm @@ -40,6 +40,7 @@ #import "MTRKeypair.h" #import "MTRLogging_Internal.h" #import "MTRMetricKeys.h" +#import "MTRMetricsCollector.h" #import "MTROperationalCredentialsDelegate.h" #import "MTRP256KeypairBridge.h" #import "MTRPersistentStorageDelegateBridge.h" @@ -610,10 +611,18 @@ static inline void emitMetricForSetupPayload(MTRSetupPayload * payload) MATTER_LOG_METRIC(kMetricDeviceProductID, [payload.productID unsignedIntValue]); } +- (void)preparePASESessionMetric:(chip::NodeId)nodeId +{ + self->_deviceControllerDelegateBridge->SetDeviceNodeID(nodeId); + MATTER_LOG_METRIC_BEGIN(kMetricSetupPASESession); +} + - (BOOL)setupCommissioningSessionWithPayload:(MTRSetupPayload *)payload newNodeID:(NSNumber *)newNodeID error:(NSError * __autoreleasing *)error { + [[MTRMetricsCollector sharedInstance] resetMetrics]; + // Track overall commissioning MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning); emitMetricForSetupPayload(payload); @@ -623,7 +632,7 @@ - (BOOL)setupCommissioningSessionWithPayload:(MTRSetupPayload *)payload __block CHIP_ERROR errorCode = CHIP_NO_ERROR; auto block = ^BOOL { - // Track just this portion of overall PASE setup + // Track work until end of scope MATTER_LOG_METRIC_SCOPE(kMetricSetupWithPayload, errorCode); // Try to get a QR code if possible (because it has a better @@ -633,12 +642,17 @@ - (BOOL)setupCommissioningSessionWithPayload:(MTRSetupPayload *)payload pairingCode = [payload manualEntryCode]; } if (pairingCode == nil) { - return ![MTRDeviceController checkForError:CHIP_ERROR_INVALID_ARGUMENT logMsg:kErrorSetupCodeGen error:error]; + errorCode = CHIP_ERROR_INVALID_ARGUMENT; + return ![MTRDeviceController checkForError:errorCode logMsg:kErrorSetupCodeGen error:error]; } chip::NodeId nodeId = [newNodeID unsignedLongLongValue]; self->_operationalCredentialsDelegate->SetDeviceID(nodeId); + + [self preparePASESessionMetric:nodeId]; errorCode = self->_cppCommissioner->EstablishPASEConnection(nodeId, [pairingCode UTF8String]); + VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode)); + return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; @@ -654,6 +668,8 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR newNodeID:(NSNumber *)newNodeID error:(NSError * __autoreleasing *)error { + [[MTRMetricsCollector sharedInstance] resetMetrics]; + // Track overall commissioning MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning); emitMetricForSetupPayload(payload); @@ -663,7 +679,7 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR __block CHIP_ERROR errorCode = CHIP_NO_ERROR; auto block = ^BOOL { - // Track just this portion of overall PASE setup + // Track work until end of scope MATTER_LOG_METRIC_SCOPE(kMetricSetupWithDiscovered, errorCode); chip::NodeId nodeId = [newNodeID unsignedLongLongValue]; @@ -675,7 +691,9 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR auto pinCode = static_cast(payload.setupPasscode.unsignedLongValue); params.Value().SetSetupPINCode(pinCode); + [self preparePASESessionMetric:nodeId]; errorCode = self->_cppCommissioner->EstablishPASEConnection(nodeId, params.Value()); + VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode)); } else { // Try to get a QR code if possible (because it has a better // discriminator, etc), then fall back to manual code if that fails. @@ -684,7 +702,8 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR pairingCode = [payload manualEntryCode]; } if (pairingCode == nil) { - return ![MTRDeviceController checkForError:CHIP_ERROR_INVALID_ARGUMENT logMsg:kErrorSetupCodeGen error:error]; + errorCode = CHIP_ERROR_INVALID_ARGUMENT; + return ![MTRDeviceController checkForError:errorCode logMsg:kErrorSetupCodeGen error:error]; } for (id key in discoveredDevice.interfaces) { @@ -693,9 +712,11 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR continue; } + [self preparePASESessionMetric:nodeId]; errorCode = self->_cppCommissioner->EstablishPASEConnection( nodeId, [pairingCode UTF8String], chip::Controller::DiscoveryType::kDiscoveryNetworkOnly, resolutionData); if (CHIP_NO_ERROR != errorCode) { + MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode); break; } } @@ -1616,6 +1637,8 @@ - (BOOL)pairDevice:(uint64_t)deviceID setupPINCode:(uint32_t)setupPINCode error:(NSError * __autoreleasing *)error { + [[MTRMetricsCollector sharedInstance] resetMetrics]; + // Track overall commissioning MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning); @@ -1624,7 +1647,7 @@ - (BOOL)pairDevice:(uint64_t)deviceID __block CHIP_ERROR errorCode = CHIP_NO_ERROR; auto block = ^BOOL { - // Track just this portion of overall PASE setup + // Track work until end of scope MATTER_LOG_METRIC_SCOPE(kMetricPairDevice, errorCode); std::string manualPairingCode; @@ -1636,7 +1659,11 @@ - (BOOL)pairDevice:(uint64_t)deviceID VerifyOrReturnValue(![MTRDeviceController checkForError:errorCode logMsg:kErrorSetupCodeGen error:error], NO); self->_operationalCredentialsDelegate->SetDeviceID(deviceID); + + [self preparePASESessionMetric:deviceID]; errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, manualPairingCode.c_str()); + VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode)); + return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; @@ -1653,6 +1680,8 @@ - (BOOL)pairDevice:(uint64_t)deviceID setupPINCode:(uint32_t)setupPINCode error:(NSError * __autoreleasing *)error { + [[MTRMetricsCollector sharedInstance] resetMetrics]; + // Track overall commissioning MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning); @@ -1661,7 +1690,7 @@ - (BOOL)pairDevice:(uint64_t)deviceID __block CHIP_ERROR errorCode = CHIP_NO_ERROR; auto block = ^BOOL { - // Track just this portion of overall PASE setup + // Track work until end of scope MATTER_LOG_METRIC_SCOPE(kMetricPairDevice, errorCode); chip::Inet::IPAddress addr; @@ -1671,7 +1700,11 @@ - (BOOL)pairDevice:(uint64_t)deviceID self->_operationalCredentialsDelegate->SetDeviceID(deviceID); auto params = chip::RendezvousParameters().SetSetupPINCode(setupPINCode).SetPeerAddress(peerAddress); + + [self preparePASESessionMetric:deviceID]; errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, params); + VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode)); + return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; @@ -1684,6 +1717,8 @@ - (BOOL)pairDevice:(uint64_t)deviceID - (BOOL)pairDevice:(uint64_t)deviceID onboardingPayload:(NSString *)onboardingPayload error:(NSError * __autoreleasing *)error { + [[MTRMetricsCollector sharedInstance] resetMetrics]; + // Track overall commissioning MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning); emitMetricForSetupPayload([MTRSetupPayload setupPayloadWithOnboardingPayload:onboardingPayload error:nil]); @@ -1693,11 +1728,15 @@ - (BOOL)pairDevice:(uint64_t)deviceID onboardingPayload:(NSString *)onboardingPa __block CHIP_ERROR errorCode = CHIP_NO_ERROR; auto block = ^BOOL { - // Track just this portion of overall PASE setup + // Track work until end of scope MATTER_LOG_METRIC_SCOPE(kMetricPairDevice, errorCode); self->_operationalCredentialsDelegate->SetDeviceID(deviceID); + + [self preparePASESessionMetric:deviceID]; errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, [onboardingPayload UTF8String]); + VerifyOrDo(errorCode != CHIP_NO_ERROR, MATTER_LOG_METRIC_END(kMetricSetupPASESession, errorCode)); + return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; diff --git a/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.h b/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.h index d5b131d21ae8d9..b14425afe0cf42 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.h +++ b/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.h @@ -42,10 +42,13 @@ class MTRDeviceControllerDelegateBridge : public chip::Controller::DevicePairing void OnCommissioningComplete(chip::NodeId deviceId, CHIP_ERROR error) override; + void SetDeviceNodeID(chip::NodeId deviceNodeId); + private: MTRDeviceController * __weak mController; _Nullable id mDelegate; _Nullable dispatch_queue_t mQueue; + chip::NodeId mDeviceNodeId; MTRCommissioningStatus MapStatus(chip::Controller::DevicePairingDelegate::Status status); }; diff --git a/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm b/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm index 842f0019ae81b8..b90921e1924275 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm @@ -64,6 +64,13 @@ { MTR_LOG_DEFAULT("DeviceControllerDelegate status updated: %d", status); + // If pairing failed, PASE failed. However, since OnPairingComplete(failure_code) might not be invoked in all cases, mark + // end of PASE with timeout as assumed failure. If OnPairingComplete is invoked, the right error code will be updated in + // the end event + if (status == chip::Controller::DevicePairingDelegate::Status::SecurePairingFailed) { + MATTER_LOG_METRIC_END(kMetricSetupPASESession, CHIP_ERROR_TIMEOUT); + } + id strongDelegate = mDelegate; MTRDeviceController * strongController = mController; if (strongDelegate && mQueue && strongController) { @@ -73,12 +80,21 @@ [strongDelegate controller:strongController statusUpdate:commissioningStatus]; }); } + + // If PASE session setup fails and the client implements the delegate that accepts metrics, invoke the delegate + // to mark end of commissioning request. + // Since OnPairingComplete(failure_code) might not be invoked in all cases, use this opportunity to inform of failed commissioning + // and default the error to timeout since that is best guess in this layer. + if (status == chip::Controller::DevicePairingDelegate::Status::SecurePairingFailed && [strongDelegate respondsToSelector:@selector(controller:commissioningComplete:nodeID:metrics:)]) { + OnCommissioningComplete(mDeviceNodeId, CHIP_ERROR_TIMEOUT); + } } } void MTRDeviceControllerDelegateBridge::OnPairingComplete(CHIP_ERROR error) { MTR_LOG_DEFAULT("DeviceControllerDelegate Pairing complete. Status %s", chip::ErrorStr(error)); + MATTER_LOG_METRIC_END(kMetricSetupPASESession, error); id strongDelegate = mDelegate; MTRDeviceController * strongController = mController; @@ -129,6 +145,7 @@ // Always collect the metrics to avoid unbounded growth of the stats in the collector MTRMetrics * metrics = [[MTRMetricsCollector sharedInstance] metricSnapshot:TRUE]; + MTR_LOG_INFO("Device commissioning complete with metrics %@", metrics); if ([strongDelegate respondsToSelector:@selector(controller:commissioningComplete:nodeID:)] || [strongDelegate respondsToSelector:@selector(controller:commissioningComplete:nodeID:metrics:)]) { @@ -158,6 +175,11 @@ } } +void MTRDeviceControllerDelegateBridge::SetDeviceNodeID(chip::NodeId deviceNodeId) +{ + mDeviceNodeId = deviceNodeId; +} + @implementation MTRProductIdentity - (instancetype)initWithVendorID:(NSNumber *)vendorID productID:(NSNumber *)productID diff --git a/src/darwin/Framework/CHIP/MTRMetricKeys.h b/src/darwin/Framework/CHIP/MTRMetricKeys.h index 173feebce81746..5ea03da70d9752 100644 --- a/src/darwin/Framework/CHIP/MTRMetricKeys.h +++ b/src/darwin/Framework/CHIP/MTRMetricKeys.h @@ -21,36 +21,66 @@ namespace chip { namespace Tracing { namespace DarwinFramework { +// Tracks overall commissioning via one of the setup APIs constexpr Tracing::MetricKey kMetricDeviceCommissioning = "dwnfw_device_commissioning"; +// Tracks portion related to starting setup with a payload constexpr Tracing::MetricKey kMetricSetupWithPayload = "dwnfw_setup_with_payload"; +// Tracks portion related to legacy setup APIs constexpr Tracing::MetricKey kMetricPairDevice = "dwnfw_pair_device"; +// Tracks portion related to starting setup with a discovered device constexpr Tracing::MetricKey kMetricSetupWithDiscovered = "dwnfw_setup_with_discovered"; +// Tracks PASE session during setup of a device +constexpr Tracing::MetricKey kMetricSetupPASESession = "dwnfw_setup_pase_session"; + +// Marks the request to prewarm for commissioning constexpr Tracing::MetricKey kMetricPreWarmCommissioning = "dwnfw_prewarm_commissioning"; +// Marks the request to start browsing for commissionable devices constexpr Tracing::MetricKey kMetricStartBrowseForCommissionables = "dwnfw_start_browse_commissionables"; +// Marks the request to stop browsing for commissionable devices constexpr Tracing::MetricKey kMetricStopBrowseForCommissionables = "dwnfw_stop_browse_commissionables"; +// Marks the request to cancel commissioning a device constexpr Tracing::MetricKey kMetricCancelCommissioning = "dwnfw_cancel_commissioning"; +// Marks the request to continue or cancel after attestation failure constexpr Tracing::MetricKey kMetricContinueCommissioningAfterAttestation = "dwnfw_commission_post_attestation"; +// Tracks request to commission device with a node ID constexpr Tracing::MetricKey kMetricCommissionNode = "dwnfw_commission_node"; +// Marks the request to get device being commissioned constexpr Tracing::MetricKey kMetricDeviceBeingCommissioned = "dwnfw_dev_being_commissioned"; +// Tracks the request to generate PASE verifier for a given setup code constexpr Tracing::MetricKey kMetricPASEVerifierForSetupCode = "dwnfw_pase_verifier_for_code"; +// Marks the request to open pairing window constexpr Tracing::MetricKey kMetricOpenPairingWindow = "dwnfw_pase_verifier_for_code"; +// Device Vendor ID constexpr Tracing::MetricKey kMetricDeviceVendorID = "dwnfw_device_vendor_id"; +// Device Product ID constexpr Tracing::MetricKey kMetricDeviceProductID = "dwnfw_device_product_id"; +// Counter of number of devices discovered on the network during setup +constexpr Tracing::MetricKey kMetricOnNetworkDevicesAdded = "dwnfw_onnet_devices_added"; + +// Counter of number of devices removed from the network during setup +constexpr Tracing::MetricKey kMetricOnNetworkDevicesRemoved = "dwnfw_onnet_devices_removed"; + +// Counter of number of BLE devices discovered during setup +constexpr Tracing::MetricKey kMetricBLEDevicesAdded = "dwnfw_ble_devices_added"; + +// Counter of number of BLE devices removed during setup +constexpr Tracing::MetricKey kMetricBLEDevicesRemoved = "dwnfw_ble_devices_removed"; + } // namespace DarwinFramework } // namespace Tracing } // namespace chip diff --git a/src/darwin/Framework/CHIP/MTRMetrics.mm b/src/darwin/Framework/CHIP/MTRMetrics.mm index a7301302b8370b..36150b33164853 100644 --- a/src/darwin/Framework/CHIP/MTRMetrics.mm +++ b/src/darwin/Framework/CHIP/MTRMetrics.mm @@ -76,7 +76,7 @@ - (void)removeMetricDataForKey:(NSString *)key - (NSString *)description { - return [_metricsData description]; + return [NSString stringWithFormat:@"", _uniqueIdentifier, [_metricsData description]]; } @end diff --git a/src/darwin/Framework/CHIP/MTRMetricsCollector.h b/src/darwin/Framework/CHIP/MTRMetricsCollector.h index 71d0afc26c039a..04fdf14b4b56a2 100644 --- a/src/darwin/Framework/CHIP/MTRMetricsCollector.h +++ b/src/darwin/Framework/CHIP/MTRMetricsCollector.h @@ -54,6 +54,11 @@ void ShutdownMetricsCollection(); */ - (MTRMetrics *)metricSnapshot:(BOOL)resetCollection; +/** + * @brief This method clears any metrics collected. + */ +- (void)resetMetrics; + @end NS_ASSUME_NONNULL_END diff --git a/src/darwin/Framework/CHIP/MTRMetricsCollector.mm b/src/darwin/Framework/CHIP/MTRMetricsCollector.mm index 0bf5c18a69a5ba..3bde24fa52a527 100644 --- a/src/darwin/Framework/CHIP/MTRMetricsCollector.mm +++ b/src/darwin/Framework/CHIP/MTRMetricsCollector.mm @@ -17,8 +17,8 @@ #import "MTRMetricsCollector.h" #import "MTRLogging_Internal.h" -#include "MTRMetrics_Internal.h" -#include +#import "MTRMetrics.h" +#import "MTRMetrics_Internal.h" #import #include #include @@ -74,16 +74,17 @@ - (instancetype)initWithMetricEvent:(const MetricEvent &)event case ValueType::kUndefined: break; } + MTR_LOG_DEBUG("Initializing metric event data %s, type: %d, with time point %llu", event.key(), _type, _timePoint.count()); return self; } -- (void)setDurationFromMetricDataAndClearCounters:(MTRMetricData *)fromData +- (void)setDurationFromMetricData:(MTRMetricData *)fromData { auto duration = _timePoint - fromData->_timePoint; _duration = [NSNumber numberWithDouble:double(duration.count()) / USEC_PER_SEC]; - // Clear timepoints to minimize history - _timePoint = fromData->_timePoint = chip::System::Clock::Microseconds64(0); + MTR_LOG_DEBUG("Calculating duration for Matter metric with type %d, from type %d, (%llu - %llu) = %llu us (%llu s)", + _type, fromData->_type, _timePoint.count(), fromData->_timePoint.count(), duration.count(), [_duration unsignedLongLongValue]); } - (NSString *)description @@ -184,7 +185,7 @@ - (void)unregisterTracingBackend case MetricEvent::Type::kEndEvent: return @"_end"; case MetricEvent::Type::kInstantEvent: - return @"_instant"; + return @"_event"; } } @@ -200,19 +201,19 @@ - (void)handleMetricEvent:(MetricEvent)event using ValueType = MetricEvent::Value::Type; switch (event.ValueType()) { case ValueType::kInt32: - MTR_LOG_INFO("Received metric event, key: %s, type: %d, value: %d", event.key(), static_cast(event.type()), event.ValueInt32()); + MTR_LOG_DEBUG("Received metric event, key: %s, type: %d, value: %d", event.key(), static_cast(event.type()), event.ValueInt32()); break; case ValueType::kUInt32: - MTR_LOG_INFO("Received metric event, key: %s, type: %d, value: %u", event.key(), static_cast(event.type()), event.ValueUInt32()); + MTR_LOG_DEBUG("Received metric event, key: %s, type: %d, value: %u", event.key(), static_cast(event.type()), event.ValueUInt32()); break; case ValueType::kChipErrorCode: - MTR_LOG_INFO("Received metric event, key: %s, type: %d, error value: %u", event.key(), static_cast(event.type()), event.ValueErrorCode()); + MTR_LOG_DEBUG("Received metric event, key: %s, type: %d, error value: %u", event.key(), static_cast(event.type()), event.ValueErrorCode()); break; case ValueType::kUndefined: - MTR_LOG_INFO("Received metric event, key: %s, type: %d, value: nil", event.key(), static_cast(event.type())); + MTR_LOG_DEBUG("Received metric event, key: %s, type: %d, value: nil", event.key(), static_cast(event.type())); break; default: - MTR_LOG_INFO("Received metric event, key: %s, type: %d, unknown value", event.key(), static_cast(event.type())); + MTR_LOG_DEBUG("Received metric event, key: %s, type: %d, unknown value", event.key(), static_cast(event.type())); return; } @@ -225,16 +226,15 @@ - (void)handleMetricEvent:(MetricEvent)event auto metricsBeginKey = [NSString stringWithFormat:@"%s%@", event.key(), suffixNameForMetricType(MetricEvent::Type::kBeginEvent)]; MTRMetricData * beginMetric = _metricsDataCollection[metricsBeginKey]; if (beginMetric) { - [data setDurationFromMetricDataAndClearCounters:beginMetric]; + [data setDurationFromMetricData:beginMetric]; } else { // Unbalanced end MTR_LOG_ERROR("Unable to find Begin event corresponding to Metric Event: %s", event.key()); } } - // If this is a Begin event, capture only the first instance of it to account for the largest duration - // spent on the event. For the remaining events, capture the the most recent event - if (event.type() != MetricEvent::Type::kBeginEvent || ![_metricsDataCollection valueForKey:metricsKey]) { + // Add to the collection only if it does not exist as yet. + if (![_metricsDataCollection valueForKey:metricsKey]) { [_metricsDataCollection setValue:data forKey:metricsKey]; } } @@ -255,4 +255,10 @@ - (MTRMetrics *)metricSnapshot:(BOOL)resetCollection return metrics; } +- (void)resetMetrics +{ + std::lock_guard lock(_lock); + [_metricsDataCollection removeAllObjects]; +} + @end diff --git a/src/platform/Darwin/BUILD.gn b/src/platform/Darwin/BUILD.gn index 321076da241cb5..8728178735404d 100644 --- a/src/platform/Darwin/BUILD.gn +++ b/src/platform/Darwin/BUILD.gn @@ -71,6 +71,7 @@ static_library("Darwin") { "NetworkCommissioningDriver.h", "PlatformManagerImpl.cpp", "PlatformManagerImpl.h", + "PlatformMetricKeys.h", "PosixConfig.cpp", "PosixConfig.h", "SystemPlatformConfig.h", @@ -101,6 +102,7 @@ static_library("Darwin") { "${chip_root}/src/lib/dnssd:platform_header", "${chip_root}/src/platform/logging:headers", "${chip_root}/src/setup_payload", + "${chip_root}/src/tracing", ] public_deps = [ diff --git a/src/platform/Darwin/BleConnectionDelegateImpl.mm b/src/platform/Darwin/BleConnectionDelegateImpl.mm index 5677c014cc0a2f..8ec68fc35ea8f4 100644 --- a/src/platform/Darwin/BleConnectionDelegateImpl.mm +++ b/src/platform/Darwin/BleConnectionDelegateImpl.mm @@ -35,10 +35,13 @@ #include #include #include +#include +#import "PlatformMetricKeys.h" #import "UUIDHelper.h" using namespace chip::Ble; +using namespace chip::Tracing::DarwinPlatform; constexpr uint64_t kScanningWithDiscriminatorTimeoutInSeconds = 60; constexpr uint64_t kScanningWithoutDelegateTimeoutInSeconds = 120; @@ -222,6 +225,8 @@ - (void)removePeripheralsFromCache; } // namespace chip @interface BleConnection () +@property (nonatomic, readonly) int32_t totalDevicesAdded; +@property (nonatomic, readonly) int32_t totalDevicesRemoved; @end @implementation BleConnection @@ -237,6 +242,7 @@ - (id)initWithQueue:(dispatch_queue_t)queue _found = false; _cachedPeripherals = [[NSMutableDictionary alloc] init]; _currentMode = kUndefined; + [self _resetCounters]; } return self; @@ -330,6 +336,8 @@ - (void)dispatchConnectionComplete:(CBPeripheral *)peripheral - (void)centralManagerDidUpdateState:(CBCentralManager *)central { + MATTER_LOG_METRIC(kMetricBLECentralManagerState, static_cast(central.state)); + switch (central.state) { case CBManagerStatePoweredOn: ChipLogDetail(Ble, "CBManagerState: ON"); @@ -374,6 +382,8 @@ - (void)centralManager:(CBCentralManager *)central } NSNumber * isConnectable = [advertisementData objectForKey:CBAdvertisementDataIsConnectable]; + MATTER_LOG_METRIC_END(kMetricBLEDiscoveredPeripheral, [isConnectable boolValue]); + if ([isConnectable boolValue] == NO) { ChipLogError(Ble, "A device (%p) with a matching Matter UUID has been discovered but it is not connectable.", peripheral); return; @@ -389,6 +399,7 @@ - (void)centralManager:(CBCentralManager *)central "A device (%p) with a matching Matter UUID has been discovered but the service data len does not match our expectation " "(serviceData = %s)", peripheral, [hexString UTF8String]); + MATTER_LOG_METRIC(kMetricBLEBadServiceDataLength, static_cast([serviceData length])); return; } @@ -398,6 +409,7 @@ - (void)centralManager:(CBCentralManager *)central "A device (%p) with a matching Matter UUID has been discovered but the service data opCode not match our expectation " "(opCode = %u).", peripheral, opCode); + MATTER_LOG_METRIC(kMetricBLEBadOpCode, opCode); return; } @@ -409,9 +421,11 @@ - (void)centralManager:(CBCentralManager *)central "A device (%p) with a matching Matter UUID has been discovered but the service data discriminator not match our " "expectation (discriminator = %u).", peripheral, discriminator); + MATTER_LOG_METRIC(kMetricBLEMismatchedDiscriminator); return; } + MATTER_LOG_METRIC_BEGIN(kMetricBLEDiscoveredMatchingPeripheral); ChipLogProgress(Ble, "Connecting to device %p with discriminator: %d", peripheral, discriminator); [self connect:peripheral]; [self stopScanning]; @@ -427,6 +441,8 @@ - (BOOL)checkDiscriminator:(uint16_t)discriminator - (void)centralManager:(CBCentralManager *)central didConnectPeripheral:(CBPeripheral *)peripheral { + MATTER_LOG_METRIC_END(kMetricBLEConnectPeripheral); + MATTER_LOG_METRIC_BEGIN(kMetricBLEDiscoveredServices); [peripheral setDelegate:self]; [peripheral discoverServices:nil]; } @@ -441,8 +457,11 @@ - (void)peripheral:(CBPeripheral *)peripheral didDiscoverServices:(NSError *)err ChipLogError(Ble, "BLE:Error finding Chip Service in the device: [%s]", [error.localizedDescription UTF8String]); } + MATTER_LOG_METRIC_END(kMetricBLEDiscoveredServices, CHIP_ERROR(chip::ChipError::Range::kOS, static_cast(error.code))); + for (CBService * service in peripheral.services) { if ([service.UUID.data isEqualToData:_shortServiceUUID.data] && !self.found) { + MATTER_LOG_METRIC_BEGIN(kMetricBLEDiscoveredCharacteristics); [peripheral discoverCharacteristics:nil forService:service]; self.found = true; break; @@ -451,12 +470,15 @@ - (void)peripheral:(CBPeripheral *)peripheral didDiscoverServices:(NSError *)err if (!self.found || error != nil) { ChipLogError(Ble, "Service not found on the device."); + MATTER_LOG_METRIC(kMetricBLEDiscoveredServices, CHIP_ERROR_INCORRECT_STATE); [self dispatchConnectionError:CHIP_ERROR_INCORRECT_STATE]; } } - (void)peripheral:(CBPeripheral *)peripheral didDiscoverCharacteristicsForService:(CBService *)service error:(NSError *)error { + MATTER_LOG_METRIC_END(kMetricBLEDiscoveredCharacteristics, CHIP_ERROR(chip::ChipError::Range::kOS, static_cast(error.code))); + if (nil != error) { ChipLogError( Ble, "BLE:Error finding Characteristics in Chip service on the device: [%s]", [error.localizedDescription UTF8String]); @@ -481,6 +503,7 @@ - (void)peripheral:(CBPeripheral *)peripheral ChipLogError( Ble, "BLE:Error writing Characteristics in Chip service on the device: [%s]", [error.localizedDescription UTF8String]); dispatch_async(_chipWorkQueue, ^{ + MATTER_LOG_METRIC(kMetricBLEWriteChrValueFailed, BLE_ERROR_GATT_WRITE_FAILED); _mBleLayer->HandleConnectionError((__bridge void *) peripheral, BLE_ERROR_GATT_WRITE_FAILED); }); } @@ -509,10 +532,12 @@ - (void)peripheral:(CBPeripheral *)peripheral [error.localizedDescription UTF8String]); dispatch_async(_chipWorkQueue, ^{ if (isNotifying) { + MATTER_LOG_METRIC(kMetricBLEUpdateNotificationStateForChrFailed, BLE_ERROR_GATT_WRITE_FAILED); // we're still notifying, so we must failed the unsubscription _mBleLayer->HandleConnectionError((__bridge void *) peripheral, BLE_ERROR_GATT_UNSUBSCRIBE_FAILED); } else { // we're not notifying, so we must failed the subscription + MATTER_LOG_METRIC(kMetricBLEUpdateNotificationStateForChrFailed, BLE_ERROR_GATT_SUBSCRIBE_FAILED); _mBleLayer->HandleConnectionError((__bridge void *) peripheral, BLE_ERROR_GATT_SUBSCRIBE_FAILED); } }); @@ -535,17 +560,20 @@ - (void)peripheral:(CBPeripheral *)peripheral if (msgBuf.IsNull()) { ChipLogError(Ble, "Failed at allocating buffer for incoming BLE data"); + MATTER_LOG_METRIC(kMetricBLEUpdateValueForChrFailed, CHIP_ERROR_NO_MEMORY); _mBleLayer->HandleConnectionError((__bridge void *) peripheral, CHIP_ERROR_NO_MEMORY); } else if (!_mBleLayer->HandleIndicationReceived((__bridge void *) peripheral, &svcId, &charId, std::move(msgBuf))) { // since this error comes from device manager core // we assume it would do the right thing, like closing the connection ChipLogError(Ble, "Failed at handling incoming BLE data"); + MATTER_LOG_METRIC(kMetricBLEUpdateValueForChrFailed, CHIP_ERROR_INCORRECT_STATE); } }); } else { ChipLogError( Ble, "BLE:Error receiving indication of Characteristics on the device: [%s]", [error.localizedDescription UTF8String]); dispatch_async(_chipWorkQueue, ^{ + MATTER_LOG_METRIC(kMetricBLEUpdateValueForChrFailed, BLE_ERROR_GATT_INDICATE_FAILED); _mBleLayer->HandleConnectionError((__bridge void *) peripheral, BLE_ERROR_GATT_INDICATE_FAILED); }); } @@ -558,6 +586,7 @@ - (void)start // If a peripheral has already been found, try to connect to it once BLE starts, // otherwise start scanning to find the peripheral to connect to. if (_peripheral != nil) { + MATTER_LOG_METRIC_BEGIN(kMetricBLEDiscoveredMatchingPeripheral); [self connect:_peripheral]; } else { [self startScanning]; @@ -597,12 +626,23 @@ - (void)stop }); } +- (void)_resetCounters +{ + _totalDevicesAdded = 0; + _totalDevicesRemoved = 0; +} + - (void)startScanning { if (!_centralManager) { return; } + MATTER_LOG_METRIC_BEGIN(kMetricBLEScan); + MATTER_LOG_METRIC_BEGIN(kMetricBLEDiscoveredPeripheral); + MATTER_LOG_METRIC_BEGIN(kMetricBLEDiscoveredMatchingPeripheral); + [self _resetCounters]; + auto scanOptions = @{ CBCentralManagerScanOptionAllowDuplicatesKey : @YES }; [_centralManager scanForPeripheralsWithServices:@[ _shortServiceUUID ] options:scanOptions]; } @@ -613,6 +653,9 @@ - (void)stopScanning return; } + MATTER_LOG_METRIC_END(kMetricBLEScan); + [self _resetCounters]; + [self clearTimer]; [_centralManager stopScan]; } @@ -623,6 +666,8 @@ - (void)connect:(CBPeripheral *)peripheral return; } + MATTER_LOG_METRIC_END(kMetricBLEDiscoveredMatchingPeripheral); + MATTER_LOG_METRIC_BEGIN(kMetricBLEConnectPeripheral); _peripheral = peripheral; [_centralManager connectPeripheral:peripheral options:nil]; } @@ -669,6 +714,7 @@ - (void)updateWithDiscriminator:(const chip::SetupDiscriminator &)deviceDiscrimi [self removePeripheralsFromCache]; if (peripheral) { + MATTER_LOG_METRIC_BEGIN(kMetricBLEDiscoveredMatchingPeripheral); ChipLogProgress(Ble, "Connecting to cached device: %p", peripheral); [self connect:peripheral]; [self stopScanning]; @@ -682,6 +728,7 @@ - (void)updateWithPeripheral:(CBPeripheral *)peripheral _scannerDelegate = nil; _currentMode = kConnecting; + MATTER_LOG_METRIC_BEGIN(kMetricBLEDiscoveredMatchingPeripheral); ChipLogProgress(Ble, "Connecting to device: %p", peripheral); [self connect:peripheral]; [self stopScanning]; @@ -713,6 +760,7 @@ - (void)addPeripheralToCache:(CBPeripheral *)peripheral data:(NSData *)data timeoutTimer = dispatch_source_create(DISPATCH_SOURCE_TYPE_TIMER, 0, 0, _workQueue); dispatch_source_set_event_handler(timeoutTimer, ^{ + MATTER_LOG_METRIC(kMetricBLEPeripheralRemoved, ++self->_totalDevicesRemoved); [self removePeripheralFromCache:peripheral]; }); dispatch_resume(timeoutTimer); @@ -721,6 +769,11 @@ - (void)addPeripheralToCache:(CBPeripheral *)peripheral data:(NSData *)data auto timeout = static_cast(kCachePeripheralTimeoutInSeconds * NSEC_PER_SEC); dispatch_source_set_timer(timeoutTimer, dispatch_walltime(nullptr, timeout), DISPATCH_TIME_FOREVER, 5 * NSEC_PER_SEC); + // Add only unique count of devices found + if (!_cachedPeripherals[peripheral]) { + MATTER_LOG_METRIC(kMetricBLEPeripheralAdded, ++_totalDevicesAdded); + } + _cachedPeripherals[peripheral] = @{ @"data" : data, @"timer" : timeoutTimer, diff --git a/src/platform/Darwin/PlatformManagerImpl.cpp b/src/platform/Darwin/PlatformManagerImpl.cpp index 0edc652ed827f2..d0289f7b7e0a18 100644 --- a/src/platform/Darwin/PlatformManagerImpl.cpp +++ b/src/platform/Darwin/PlatformManagerImpl.cpp @@ -23,6 +23,7 @@ */ #include +#include #if !CHIP_DISABLE_PLATFORM_KVS #include @@ -36,6 +37,10 @@ #include #include +#include + +#import "PlatformMetricKeys.h" +using namespace chip::Tracing::DarwinPlatform; namespace chip { namespace DeviceLayer { @@ -188,7 +193,7 @@ bool PlatformManagerImpl::IsWorkQueueCurrentQueue() const CHIP_ERROR PlatformManagerImpl::StartBleScan(BleScannerDelegate * delegate) { #if CONFIG_NETWORK_LAYER_BLE - ReturnErrorOnFailure(Internal::BLEMgrImpl().StartScan(delegate)); + ReturnErrorOnFailureWithMetric(kMetricBLEScan, Internal::BLEMgrImpl().StartScan(delegate)); #endif // CONFIG_NETWORK_LAYER_BLE return CHIP_NO_ERROR; } @@ -196,7 +201,7 @@ CHIP_ERROR PlatformManagerImpl::StartBleScan(BleScannerDelegate * delegate) CHIP_ERROR PlatformManagerImpl::StopBleScan() { #if CONFIG_NETWORK_LAYER_BLE - ReturnErrorOnFailure(Internal::BLEMgrImpl().StopScan()); + ReturnErrorOnFailureWithMetric(kMetricBLEScan, Internal::BLEMgrImpl().StopScan()); #endif // CONFIG_NETWORK_LAYER_BLE return CHIP_NO_ERROR; } @@ -204,7 +209,7 @@ CHIP_ERROR PlatformManagerImpl::StopBleScan() CHIP_ERROR PlatformManagerImpl::PrepareCommissioning() { #if CONFIG_NETWORK_LAYER_BLE - ReturnErrorOnFailure(Internal::BLEMgrImpl().StartScan()); + ReturnErrorOnFailureWithMetric(kMetricBLEStartPreWarmScan, Internal::BLEMgrImpl().StartScan()); #endif // CONFIG_NETWORK_LAYER_BLE return CHIP_NO_ERROR; } diff --git a/src/platform/Darwin/PlatformMetricKeys.h b/src/platform/Darwin/PlatformMetricKeys.h new file mode 100644 index 00000000000000..0493e04ed16ce0 --- /dev/null +++ b/src/platform/Darwin/PlatformMetricKeys.h @@ -0,0 +1,74 @@ +/** + * Copyright (c) 2024 Project CHIP Authors + * + * 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. + */ + +#include +#include + +namespace chip { +namespace Tracing { +namespace DarwinPlatform { + +// BLE Scan duration +constexpr Tracing::MetricKey kMetricBLEScan = "dwnpm_ble_scan"; + +// Number of peripherals added to the cache during a scan operation +constexpr Tracing::MetricKey kMetricBLEPeripheralAdded = "dwnpm_ble_peripheral_added"; + +// Number of peripherals removed from the cache during a scan operation +constexpr Tracing::MetricKey kMetricBLEPeripheralRemoved = "dwnpm_ble_peripheral_removed"; + +// Request to prewarm scan +constexpr Tracing::MetricKey kMetricBLEStartPreWarmScan = "dwnpm_ble_start_prewarm_scan"; + +// Captures the last known state of the BLE Central manager during a commissioning attempt +constexpr Tracing::MetricKey kMetricBLECentralManagerState = "dwnpm_ble_cbmgr_state"; + +// Discovered a peripheral after a request to scan +constexpr Tracing::MetricKey kMetricBLEDiscoveredPeripheral = "dwnpm_ble_discovered_peripheral"; + +// Discovered a peripheral matching scanned from QR Code +constexpr Tracing::MetricKey kMetricBLEDiscoveredMatchingPeripheral = "dwnpm_ble_discovered_matching_peripheral"; + +// Unexpected length of Matter BLE service data +constexpr Tracing::MetricKey kMetricBLEBadServiceDataLength = "dwnpm_ble_bad_service_data"; + +// Unexpected OpCode in Matter BLE service data +constexpr Tracing::MetricKey kMetricBLEBadOpCode = "dwnpm_ble_bad_opcode"; + +// Mismatched discriminator when connecting to a peripheral +constexpr Tracing::MetricKey kMetricBLEMismatchedDiscriminator = "dwnpm_ble_mismatched_discriminator"; + +// Attempt to connect to discovered peripheral +constexpr Tracing::MetricKey kMetricBLEConnectPeripheral = "dwnpm_ble_connect_peripheral"; + +// Discover services on connected peripheral +constexpr Tracing::MetricKey kMetricBLEDiscoveredServices = "dwnpm_ble_discovered_svs"; + +// Discover characteristics on connected peripheral +constexpr Tracing::MetricKey kMetricBLEDiscoveredCharacteristics = "dwnpm_ble_discovered_chrs"; + +// Failed to write charateristic value +constexpr Tracing::MetricKey kMetricBLEWriteChrValueFailed = "dwnpm_ble_write_chr_val_failed"; + +// Failed to update notification state change for charateristic +constexpr Tracing::MetricKey kMetricBLEUpdateNotificationStateForChrFailed = "dwnpm_ble_chr_nfy_state_failed"; + +// Failed to update value for charateristic +constexpr Tracing::MetricKey kMetricBLEUpdateValueForChrFailed = "dwnpm_ble_upd_chr_val_failed"; + +} // namespace DarwinPlatform +} // namespace Tracing +} // namespace chip