diff --git a/src/darwin/Framework/CHIP/MTRBaseDevice.mm b/src/darwin/Framework/CHIP/MTRBaseDevice.mm index 2a981cdd860fff..56a49f9859e288 100644 --- a/src/darwin/Framework/CHIP/MTRBaseDevice.mm +++ b/src/darwin/Framework/CHIP/MTRBaseDevice.mm @@ -29,6 +29,7 @@ #import "MTREventTLVValueDecoder_Internal.h" #import "MTRFramework.h" #import "MTRLogging_Internal.h" +#import "MTRMetricKeys.h" #import "MTRSetupPayload_Internal.h" #import "NSDataSpanConversion.h" #import "NSStringSpanConversion.h" @@ -61,6 +62,7 @@ using chip::Optional; using chip::SessionHandle; using chip::Messaging::ExchangeManager; +using namespace chip::Tracing::DarwinFramework; NSString * const MTRAttributePathKey = @"attributePath"; NSString * const MTRCommandPathKey = @"commandPath"; @@ -1861,9 +1863,12 @@ - (void)_openCommissioningWindowWithSetupPasscode:(nullable NSNumber *)setupPass queue:(dispatch_queue_t)queue completion:(MTRDeviceOpenCommissioningWindowHandler)completion { + MATTER_LOG_METRIC_BEGIN(kMetricOpenPairingWindow); + if (self.isPASEDevice) { MTR_LOG_ERROR("Can't open a commissioning window over PASE"); dispatch_async(queue, ^{ + MATTER_LOG_METRIC_END(kMetricOpenPairingWindow, CHIP_ERROR_INCORRECT_STATE); completion(nil, [MTRError errorForCHIPErrorCode:CHIP_ERROR_INCORRECT_STATE]); }); return; @@ -1873,6 +1878,7 @@ - (void)_openCommissioningWindowWithSetupPasscode:(nullable NSNumber *)setupPass if (!CanCastTo(durationVal)) { MTR_LOG_ERROR("Error: Duration %llu is too large.", durationVal); dispatch_async(queue, ^{ + MATTER_LOG_METRIC_END(kMetricOpenPairingWindow, CHIP_ERROR_INVALID_INTEGER_VALUE); completion(nil, [MTRError errorForCHIPErrorCode:CHIP_ERROR_INVALID_INTEGER_VALUE]); }); return; @@ -1883,6 +1889,7 @@ - (void)_openCommissioningWindowWithSetupPasscode:(nullable NSNumber *)setupPass if (discriminatorVal > 0xFFF) { MTR_LOG_ERROR("Error: Discriminator %llu is too large. Max value %d", discriminatorVal, 0xFFF); dispatch_async(queue, ^{ + MATTER_LOG_METRIC_END(kMetricOpenPairingWindow, CHIP_ERROR_INVALID_INTEGER_VALUE); completion(nil, [MTRError errorForCHIPErrorCode:CHIP_ERROR_INVALID_INTEGER_VALUE]); }); return; @@ -1894,6 +1901,7 @@ - (void)_openCommissioningWindowWithSetupPasscode:(nullable NSNumber *)setupPass if (!CanCastTo(passcodeVal) || !SetupPayload::IsValidSetupPIN(static_cast(passcodeVal))) { MTR_LOG_ERROR("Error: Setup passcode %llu is not valid", passcodeVal); dispatch_async(queue, ^{ + MATTER_LOG_METRIC_END(kMetricOpenPairingWindow, CHIP_ERROR_INVALID_INTEGER_VALUE); completion(nil, [MTRError errorForCHIPErrorCode:CHIP_ERROR_INVALID_INTEGER_VALUE]); }); return; @@ -1906,6 +1914,7 @@ - (void)_openCommissioningWindowWithSetupPasscode:(nullable NSNumber *)setupPass auto resultCallback = ^(CHIP_ERROR status, const SetupPayload & payload) { if (status != CHIP_NO_ERROR) { dispatch_async(queue, ^{ + MATTER_LOG_METRIC_END(kMetricOpenPairingWindow, status); completion(nil, [MTRError errorForCHIPErrorCode:status]); }); return; @@ -1913,12 +1922,14 @@ - (void)_openCommissioningWindowWithSetupPasscode:(nullable NSNumber *)setupPass auto * payloadObj = [[MTRSetupPayload alloc] initWithSetupPayload:payload]; if (payloadObj == nil) { dispatch_async(queue, ^{ + MATTER_LOG_METRIC_END(kMetricOpenPairingWindow, CHIP_ERROR_NO_MEMORY); completion(nil, [MTRError errorForCHIPErrorCode:CHIP_ERROR_NO_MEMORY]); }); return; } dispatch_async(queue, ^{ + MATTER_LOG_METRIC_END(kMetricOpenPairingWindow, CHIP_NO_ERROR); completion(payloadObj, nil); }); }; @@ -1930,6 +1941,7 @@ - (void)_openCommissioningWindowWithSetupPasscode:(nullable NSNumber *)setupPass if (errorCode != CHIP_NO_ERROR) { dispatch_async(queue, ^{ + MATTER_LOG_METRIC_END(kMetricOpenPairingWindow, errorCode); completion(nil, [MTRError errorForCHIPErrorCode:errorCode]); }); return; @@ -1939,6 +1951,7 @@ - (void)_openCommissioningWindowWithSetupPasscode:(nullable NSNumber *)setupPass } errorHandler:^(NSError * error) { dispatch_async(queue, ^{ + MATTER_LOG_METRIC_END(kMetricOpenPairingWindow, [MTRError errorToCHIPErrorCode:error]); completion(nil, error); }); }]; diff --git a/src/darwin/Framework/CHIP/MTRDeviceController.mm b/src/darwin/Framework/CHIP/MTRDeviceController.mm index d40e269a753d96..7b7fd457447590 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceController.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceController.mm @@ -39,6 +39,7 @@ #import "MTRError_Internal.h" #import "MTRKeypair.h" #import "MTRLogging_Internal.h" +#import "MTRMetricKeys.h" #import "MTROperationalCredentialsDelegate.h" #import "MTRP256KeypairBridge.h" #import "MTRPersistentStorageDelegateBridge.h" @@ -107,6 +108,8 @@ typedef id (^SyncWorkQueueBlockWithReturnValue)(void); typedef BOOL (^SyncWorkQueueBlockWithBoolReturnValue)(void); +using namespace chip::Tracing::DarwinFramework; + @implementation MTRDeviceController { // Atomic because it can be touched from multiple threads. std::atomic _storedFabricIndex; @@ -603,11 +606,28 @@ - (NSNumber *)controllerNodeID return nodeID; } +static inline void emitMetricForSetupPayload(MTRSetupPayload * payload) +{ + MATTER_LOG_METRIC(kMetricDeviceVendorID, [payload.vendorID unsignedIntValue]); + MATTER_LOG_METRIC(kMetricDeviceProductID, [payload.productID unsignedIntValue]); +} + - (BOOL)setupCommissioningSessionWithPayload:(MTRSetupPayload *)payload newNodeID:(NSNumber *)newNodeID error:(NSError * __autoreleasing *)error { + // Track overall commissioning + MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning); + emitMetricForSetupPayload(payload); + + // Capture in a block variable to avoid losing granularity for metrics, + // when translating CHIP_ERROR to NSError + __block CHIP_ERROR errorCode = CHIP_NO_ERROR; + auto block = ^BOOL { + // Track just this portion of overall PASE setup + MATTER_LOG_METRIC_SCOPE(kMetricSetupWithPayload, errorCode); + // Try to get a QR code if possible (because it has a better // discriminator, etc), then fall back to manual code if that fails. NSString * pairingCode = [payload qrCodeString:nil]; @@ -620,11 +640,15 @@ - (BOOL)setupCommissioningSessionWithPayload:(MTRSetupPayload *)payload chip::NodeId nodeId = [newNodeID unsignedLongLongValue]; self->_operationalCredentialsDelegate->SetDeviceID(nodeId); - auto errorCode = self->_cppCommissioner->EstablishPASEConnection(nodeId, [pairingCode UTF8String]); + errorCode = self->_cppCommissioner->EstablishPASEConnection(nodeId, [pairingCode UTF8String]); return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; - return [self syncRunOnWorkQueueWithBoolReturnValue:block error:error]; + auto success = [self syncRunOnWorkQueueWithBoolReturnValue:block error:error]; + if (!success) { + MATTER_LOG_METRIC_END(kMetricDeviceCommissioning, errorCode); + } + return success; } - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserResult *)discoveredDevice @@ -632,11 +656,22 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR newNodeID:(NSNumber *)newNodeID error:(NSError * __autoreleasing *)error { + // Track overall commissioning + MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning); + emitMetricForSetupPayload(payload); + + // Capture in a block variable to avoid losing granularity for metrics, + // when translating CHIP_ERROR to NSError + __block CHIP_ERROR errorCode = CHIP_NO_ERROR; + auto block = ^BOOL { + // Track just this portion of overall PASE setup + MATTER_LOG_METRIC_SCOPE(kMetricSetupWithDiscovered, errorCode); + chip::NodeId nodeId = [newNodeID unsignedLongLongValue]; self->_operationalCredentialsDelegate->SetDeviceID(nodeId); - auto errorCode = CHIP_ERROR_INVALID_ARGUMENT; + errorCode = CHIP_ERROR_INVALID_ARGUMENT; chip::Optional params = discoveredDevice.params; if (params.HasValue()) { auto pinCode = static_cast(payload.setupPasscode.unsignedLongValue); @@ -671,7 +706,11 @@ - (BOOL)setupCommissioningSessionWithDiscoveredDevice:(MTRCommissionableBrowserR return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; - return [self syncRunOnWorkQueueWithBoolReturnValue:block error:error]; + auto success = [self syncRunOnWorkQueueWithBoolReturnValue:block error:error]; + if (!success) { + MATTER_LOG_METRIC_END(kMetricDeviceCommissioning, errorCode); + } + return success; } - (BOOL)commissionNodeWithID:(NSNumber *)nodeID @@ -770,6 +809,7 @@ - (BOOL)commissionNodeWithID:(NSNumber *)nodeID chip::NodeId deviceId = [nodeID unsignedLongLongValue]; self->_operationalCredentialsDelegate->SetDeviceID(deviceId); auto errorCode = self->_cppCommissioner->Commission(deviceId, params); + MATTER_LOG_METRIC(kMetricCommissionNode, errorCode); return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; @@ -788,6 +828,8 @@ - (BOOL)continueCommissioningDevice:(void *)device auto deviceProxy = static_cast(device); auto errorCode = self->_cppCommissioner->ContinueCommissioningAfterDeviceAttestation(deviceProxy, ignoreAttestationFailure ? chip::Credentials::AttestationVerificationResult::kSuccess : lastAttestationResult); + // Emit metric on stage after continuing post attestation + MATTER_LOG_METRIC(kMetricContinueCommissioningAfterAttestation, errorCode); return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; @@ -799,6 +841,8 @@ - (BOOL)cancelCommissioningForNodeID:(NSNumber *)nodeID error:(NSError * __autor auto block = ^BOOL { self->_operationalCredentialsDelegate->ResetDeviceID(); auto errorCode = self->_cppCommissioner->StopPairing([nodeID unsignedLongLongValue]); + // Emit metric on status of cancel + MATTER_LOG_METRIC(kMetricCancelCommissioning, errorCode); return ![MTRDeviceController checkForError:errorCode logMsg:kErrorStopPairing error:error]; }; @@ -808,10 +852,10 @@ - (BOOL)cancelCommissioningForNodeID:(NSNumber *)nodeID error:(NSError * __autor - (BOOL)startBrowseForCommissionables:(id)delegate queue:(dispatch_queue_t)queue { auto block = ^BOOL { - VerifyOrReturnValue(self->_commissionableBrowser == nil, NO); + VerifyOrReturnValueWithMetric(kMetricStartBrowseForCommissionables, self->_commissionableBrowser == nil, NO); auto commissionableBrowser = [[MTRCommissionableBrowser alloc] initWithDelegate:delegate controller:self queue:queue]; - VerifyOrReturnValue([commissionableBrowser start], NO); + VerifyOrReturnValueWithMetric(kMetricStartBrowseForCommissionables, [commissionableBrowser start], NO); self->_commissionableBrowser = commissionableBrowser; return YES; @@ -823,10 +867,10 @@ - (BOOL)startBrowseForCommissionables:(id)dele - (BOOL)stopBrowseForCommissionables { auto block = ^BOOL { - VerifyOrReturnValue(self->_commissionableBrowser != nil, NO); + VerifyOrReturnValueWithMetric(kMetricStopBrowseForCommissionables, self->_commissionableBrowser != nil, NO); auto commissionableBrowser = self->_commissionableBrowser; - VerifyOrReturnValue([commissionableBrowser stop], NO); + VerifyOrReturnValueWithMetric(kMetricStopBrowseForCommissionables, [commissionableBrowser stop], NO); self->_commissionableBrowser = nil; return YES; @@ -839,6 +883,8 @@ - (void)preWarmCommissioningSession { auto block = ^{ auto errorCode = chip::DeviceLayer::PlatformMgrImpl().PrepareCommissioning(); + MATTER_LOG_METRIC(kMetricPreWarmCommissioning, errorCode); + // The checkForError is just so it logs [MTRDeviceController checkForError:errorCode logMsg:kErrorPreWarmCommissioning error:nil]; }; @@ -853,6 +899,8 @@ - (MTRBaseDevice *)deviceBeingCommissionedWithNodeID:(NSNumber *)nodeID error:(N chip::CommissioneeDeviceProxy * deviceProxy; auto errorCode = self->_cppCommissioner->GetDeviceBeingCommissioned(nodeID.unsignedLongLongValue, &deviceProxy); + MATTER_LOG_METRIC(kMetricDeviceBeingCommissioned, errorCode); + VerifyOrReturnValue(![MTRDeviceController checkForError:errorCode logMsg:kErrorGetCommissionee error:error], nil); return [[MTRBaseDevice alloc] initWithPASEDevice:deviceProxy controller:self]; @@ -948,6 +996,9 @@ + (nullable NSData *)computePASEVerifierForSetupPasscode:(NSNumber *)setupPassco { chip::Spake2pVerifier verifier; CHIP_ERROR err = verifier.Generate(iterations.unsignedIntValue, AsByteSpan(salt), setupPasscode.unsignedIntValue); + + MATTER_LOG_METRIC_SCOPE(kMetricPASEVerifierForSetupCode, err); + if ([MTRDeviceController checkForError:err logMsg:kErrorSpake2pVerifierGenerationFailed error:error]) { return nil; } @@ -967,7 +1018,11 @@ - (NSData * _Nullable)attestationChallengeForDeviceID:(NSNumber *)deviceID auto block = ^NSData * { chip::CommissioneeDeviceProxy * deviceProxy; - auto errorCode = self->_cppCommissioner->GetDeviceBeingCommissioned([deviceID unsignedLongLongValue], &deviceProxy); + + auto errorCode = CHIP_NO_ERROR; + MATTER_LOG_METRIC_SCOPE(kMetricPASEVerifierForSetupCode, errorCode); + + errorCode = self->_cppCommissioner->GetDeviceBeingCommissioned([deviceID unsignedLongLongValue], &deviceProxy); VerifyOrReturnValue(![MTRDeviceController checkForError:errorCode logMsg:kErrorGetCommissionee error:nil], nil); uint8_t challengeBuffer[chip::Crypto::kAES_CCM128_Key_Length]; @@ -1557,13 +1612,23 @@ - (BOOL)pairDevice:(uint64_t)deviceID setupPINCode:(uint32_t)setupPINCode error:(NSError * __autoreleasing *)error { + // Track overall commissioning + MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning); + + // Capture in a block variable to avoid losing granularity for metrics, + // when translating CHIP_ERROR to NSError + __block CHIP_ERROR errorCode = CHIP_NO_ERROR; + auto block = ^BOOL { + // Track just this portion of overall PASE setup + MATTER_LOG_METRIC_SCOPE(kMetricPairDevice, errorCode); + std::string manualPairingCode; chip::SetupPayload payload; payload.discriminator.SetLongValue(discriminator); payload.setUpPINCode = setupPINCode; - auto errorCode = chip::ManualSetupPayloadGenerator(payload).payloadDecimalStringRepresentation(manualPairingCode); + errorCode = chip::ManualSetupPayloadGenerator(payload).payloadDecimalStringRepresentation(manualPairingCode); VerifyOrReturnValue(![MTRDeviceController checkForError:errorCode logMsg:kErrorSetupCodeGen error:error], NO); self->_operationalCredentialsDelegate->SetDeviceID(deviceID); @@ -1571,7 +1636,11 @@ - (BOOL)pairDevice:(uint64_t)deviceID return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; - return [self syncRunOnWorkQueueWithBoolReturnValue:block error:error]; + auto success = [self syncRunOnWorkQueueWithBoolReturnValue:block error:error]; + if (!success) { + MATTER_LOG_METRIC_END(kMetricDeviceCommissioning, errorCode); + } + return success; } - (BOOL)pairDevice:(uint64_t)deviceID @@ -1580,7 +1649,17 @@ - (BOOL)pairDevice:(uint64_t)deviceID setupPINCode:(uint32_t)setupPINCode error:(NSError * __autoreleasing *)error { + // Track overall commissioning + MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning); + + // Capture in a block variable to avoid losing granularity for metrics, + // when translating CHIP_ERROR to NSError + __block CHIP_ERROR errorCode = CHIP_NO_ERROR; + auto block = ^BOOL { + // Track just this portion of overall PASE setup + MATTER_LOG_METRIC_SCOPE(kMetricPairDevice, errorCode); + chip::Inet::IPAddress addr; chip::Inet::IPAddress::FromString([address UTF8String], addr); chip::Transport::PeerAddress peerAddress = chip::Transport::PeerAddress::UDP(addr, port); @@ -1588,22 +1667,41 @@ - (BOOL)pairDevice:(uint64_t)deviceID self->_operationalCredentialsDelegate->SetDeviceID(deviceID); auto params = chip::RendezvousParameters().SetSetupPINCode(setupPINCode).SetPeerAddress(peerAddress); - auto errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, params); + errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, params); return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; - return [self syncRunOnWorkQueueWithBoolReturnValue:block error:error]; + auto success = [self syncRunOnWorkQueueWithBoolReturnValue:block error:error]; + if (!success) { + MATTER_LOG_METRIC_END(kMetricDeviceCommissioning, errorCode); + } + return success; } - (BOOL)pairDevice:(uint64_t)deviceID onboardingPayload:(NSString *)onboardingPayload error:(NSError * __autoreleasing *)error { + // Track overall commissioning + MATTER_LOG_METRIC_BEGIN(kMetricDeviceCommissioning); + emitMetricForSetupPayload([MTRSetupPayload setupPayloadWithOnboardingPayload:onboardingPayload error:nil]); + + // Capture in a block variable to avoid losing granularity for metrics, + // when translating CHIP_ERROR to NSError + __block CHIP_ERROR errorCode = CHIP_NO_ERROR; + auto block = ^BOOL { + // Track just this portion of overall PASE setup + MATTER_LOG_METRIC_SCOPE(kMetricPairDevice, errorCode); + self->_operationalCredentialsDelegate->SetDeviceID(deviceID); - auto errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, [onboardingPayload UTF8String]); + errorCode = self->_cppCommissioner->EstablishPASEConnection(deviceID, [onboardingPayload UTF8String]); return ![MTRDeviceController checkForError:errorCode logMsg:kErrorPairDevice error:error]; }; - return [self syncRunOnWorkQueueWithBoolReturnValue:block error:error]; + auto success = [self syncRunOnWorkQueueWithBoolReturnValue:block error:error]; + if (!success) { + MATTER_LOG_METRIC_END(kMetricDeviceCommissioning, errorCode); + } + return success; } - (BOOL)commissionDevice:(uint64_t)deviceID @@ -1633,8 +1731,11 @@ - (BOOL)openPairingWindow:(uint64_t)deviceID duration:(NSUInteger)duration error return NO; } + __block CHIP_ERROR errorCode = CHIP_NO_ERROR; + MATTER_LOG_METRIC_SCOPE(kMetricOpenPairingWindow, errorCode); + auto block = ^BOOL { - auto errorCode = chip::Controller::AutoCommissioningWindowOpener::OpenBasicCommissioningWindow( + errorCode = chip::Controller::AutoCommissioningWindowOpener::OpenBasicCommissioningWindow( self->_cppCommissioner, deviceID, chip::System::Clock::Seconds16(static_cast(duration))); return ![MTRDeviceController checkForError:errorCode logMsg:kErrorOpenPairingWindow error:error]; }; @@ -1664,10 +1765,14 @@ - (NSString *)openPairingWindowWithPIN:(uint64_t)deviceID return nil; } + __block CHIP_ERROR errorCode = CHIP_NO_ERROR; + MATTER_LOG_METRIC_SCOPE(kMetricOpenPairingWindow, errorCode); + if (!chip::CanCastTo(setupPIN) || !chip::SetupPayload::IsValidSetupPIN(static_cast(setupPIN))) { MTR_LOG_ERROR("Error: Setup pin %lu is not valid", static_cast(setupPIN)); + errorCode = CHIP_ERROR_INVALID_INTEGER_VALUE; if (error) { - *error = [MTRError errorForCHIPErrorCode:CHIP_ERROR_INVALID_INTEGER_VALUE]; + *error = [MTRError errorForCHIPErrorCode:errorCode]; } return nil; } @@ -1675,7 +1780,7 @@ - (NSString *)openPairingWindowWithPIN:(uint64_t)deviceID auto block = ^NSString * { chip::SetupPayload setupPayload; - auto errorCode = chip::Controller::AutoCommissioningWindowOpener::OpenCommissioningWindow(self->_cppCommissioner, deviceID, + errorCode = chip::Controller::AutoCommissioningWindowOpener::OpenCommissioningWindow(self->_cppCommissioner, deviceID, chip::System::Clock::Seconds16(static_cast(duration)), chip::Crypto::kSpake2p_Min_PBKDF_Iterations, static_cast(discriminator), chip::MakeOptional(static_cast(setupPIN)), chip::NullOptional, setupPayload); @@ -1685,7 +1790,7 @@ - (NSString *)openPairingWindowWithPIN:(uint64_t)deviceID chip::ManualSetupPayloadGenerator generator(setupPayload); std::string outCode; - if (CHIP_NO_ERROR != generator.payloadDecimalStringRepresentation(outCode)) { + if (CHIP_NO_ERROR != (errorCode = generator.payloadDecimalStringRepresentation(outCode))) { MTR_LOG_ERROR("Failed to get decimal setup code"); return nil; } diff --git a/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm b/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm index c5d47b4309a096..842f0019ae81b8 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceControllerDelegateBridge.mm @@ -20,8 +20,11 @@ #import "MTRDeviceController_Internal.h" #import "MTRError_Internal.h" #import "MTRLogging_Internal.h" +#import "MTRMetricKeys.h" #import "MTRMetricsCollector.h" +using namespace chip::Tracing::DarwinFramework; + MTRDeviceControllerDelegateBridge::MTRDeviceControllerDelegateBridge(void) : mDelegate(nil) { @@ -118,6 +121,7 @@ void MTRDeviceControllerDelegateBridge::OnCommissioningComplete(chip::NodeId nodeId, CHIP_ERROR error) { MTR_LOG_DEFAULT("DeviceControllerDelegate Commissioning complete. NodeId %llu Status %s", nodeId, chip::ErrorStr(error)); + MATTER_LOG_METRIC_END(kMetricDeviceCommissioning, error); id strongDelegate = mDelegate; MTRDeviceController * strongController = mController; diff --git a/src/darwin/Framework/CHIP/MTRMetricKeys.h b/src/darwin/Framework/CHIP/MTRMetricKeys.h new file mode 100644 index 00000000000000..173feebce81746 --- /dev/null +++ b/src/darwin/Framework/CHIP/MTRMetricKeys.h @@ -0,0 +1,56 @@ +/** + * 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 DarwinFramework { + +constexpr Tracing::MetricKey kMetricDeviceCommissioning = "dwnfw_device_commissioning"; + +constexpr Tracing::MetricKey kMetricSetupWithPayload = "dwnfw_setup_with_payload"; + +constexpr Tracing::MetricKey kMetricPairDevice = "dwnfw_pair_device"; + +constexpr Tracing::MetricKey kMetricSetupWithDiscovered = "dwnfw_setup_with_discovered"; + +constexpr Tracing::MetricKey kMetricPreWarmCommissioning = "dwnfw_prewarm_commissioning"; + +constexpr Tracing::MetricKey kMetricStartBrowseForCommissionables = "dwnfw_start_browse_commissionables"; + +constexpr Tracing::MetricKey kMetricStopBrowseForCommissionables = "dwnfw_stop_browse_commissionables"; + +constexpr Tracing::MetricKey kMetricCancelCommissioning = "dwnfw_cancel_commissioning"; + +constexpr Tracing::MetricKey kMetricContinueCommissioningAfterAttestation = "dwnfw_commission_post_attestation"; + +constexpr Tracing::MetricKey kMetricCommissionNode = "dwnfw_commission_node"; + +constexpr Tracing::MetricKey kMetricDeviceBeingCommissioned = "dwnfw_dev_being_commissioned"; + +constexpr Tracing::MetricKey kMetricPASEVerifierForSetupCode = "dwnfw_pase_verifier_for_code"; + +constexpr Tracing::MetricKey kMetricOpenPairingWindow = "dwnfw_pase_verifier_for_code"; + +constexpr Tracing::MetricKey kMetricDeviceVendorID = "dwnfw_device_vendor_id"; + +constexpr Tracing::MetricKey kMetricDeviceProductID = "dwnfw_device_product_id"; + +} // namespace DarwinFramework +} // namespace Tracing +} // namespace chip diff --git a/src/darwin/Framework/CHIP/MTRMetrics.h b/src/darwin/Framework/CHIP/MTRMetrics.h index 62234308e29987..a0d2d2c96b1f89 100644 --- a/src/darwin/Framework/CHIP/MTRMetrics.h +++ b/src/darwin/Framework/CHIP/MTRMetrics.h @@ -55,6 +55,11 @@ MTR_NEWLY_AVAILABLE - (instancetype)init NS_UNAVAILABLE; + (instancetype)new NS_UNAVAILABLE; +/** + * @brief Returns a unique identifier for the object + */ +@property (nonatomic, readonly, copy) NSUUID * uniqueIdentifier; + /** * @brief Returns the names of all the metrics data items collected. */ diff --git a/src/darwin/Framework/CHIP/MTRMetrics.mm b/src/darwin/Framework/CHIP/MTRMetrics.mm index a430c6c8d89714..a7301302b8370b 100644 --- a/src/darwin/Framework/CHIP/MTRMetrics.mm +++ b/src/darwin/Framework/CHIP/MTRMetrics.mm @@ -34,6 +34,7 @@ - (instancetype)initWithCapacity:(NSUInteger)numItems { if (self = [super init]) { _metricsData = [NSMutableDictionary dictionaryWithCapacity:numItems]; + _uniqueIdentifier = [NSUUID UUID]; } return self; } @@ -42,6 +43,7 @@ - (instancetype)initWithCapacity:(NSUInteger)numItems { return [_metricsData allKeys]; } + - (nullable MTRMetricData *)metricDataForKey:(NSString *)key { if (!key) { diff --git a/src/darwin/Framework/CHIP/MTRMetricsCollector.mm b/src/darwin/Framework/CHIP/MTRMetricsCollector.mm index bf4664514a50c5..0bf5c18a69a5ba 100644 --- a/src/darwin/Framework/CHIP/MTRMetricsCollector.mm +++ b/src/darwin/Framework/CHIP/MTRMetricsCollector.mm @@ -232,13 +232,9 @@ - (void)handleMetricEvent:(MetricEvent)event } } - [_metricsDataCollection setValue:data forKey:metricsKey]; - - // If the event is a begin or end event, implicitly emit a corresponding instant event - if (event.type() == MetricEvent::Type::kBeginEvent || event.type() == MetricEvent::Type::kEndEvent) { - MetricEvent instantEvent(MetricEvent::Type::kInstantEvent, event.key()); - data = [[MTRMetricData alloc] initWithMetricEvent:instantEvent]; - metricsKey = [NSString stringWithFormat:@"%s%@", event.key(), suffixNameForMetric(instantEvent)]; + // 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]) { [_metricsDataCollection setValue:data forKey:metricsKey]; } } diff --git a/src/darwin/Framework/CHIPTests/MTRMetricsTests.m b/src/darwin/Framework/CHIPTests/MTRMetricsTests.m index d4bbcc33cc5d2a..fdc3734ea8dbfb 100644 --- a/src/darwin/Framework/CHIPTests/MTRMetricsTests.m +++ b/src/darwin/Framework/CHIPTests/MTRMetricsTests.m @@ -128,4 +128,13 @@ - (void)test005_TestValueRemoval XCTAssertTrue([keys count] == 0); } +- (void)test006_TestUniqueIdentifier +{ + MTRMetrics * metrics1 = [[MTRMetrics alloc] initWithCapacity:1]; + MTRMetrics * metrics2 = [[MTRMetrics alloc] initWithCapacity:1]; + XCTAssertNotNil(metrics1.uniqueIdentifier); + XCTAssertNotNil(metrics2.uniqueIdentifier); + XCTAssertNotEqualObjects(metrics1.uniqueIdentifier, metrics2.uniqueIdentifier); +} + @end diff --git a/src/darwin/Framework/Matter.xcodeproj/project.pbxproj b/src/darwin/Framework/Matter.xcodeproj/project.pbxproj index 305be3271b0372..09b9082a63e1fd 100644 --- a/src/darwin/Framework/Matter.xcodeproj/project.pbxproj +++ b/src/darwin/Framework/Matter.xcodeproj/project.pbxproj @@ -266,6 +266,7 @@ 75B765C12A1D71BC0014719B /* MTRAttributeSpecifiedCheck.h in Headers */ = {isa = PBXBuildFile; fileRef = 75B765C02A1D71BC0014719B /* MTRAttributeSpecifiedCheck.h */; }; 75B765C32A1D82D30014719B /* MTRAttributeSpecifiedCheck.mm in Sources */ = {isa = PBXBuildFile; fileRef = 75B765C22A1D82D30014719B /* MTRAttributeSpecifiedCheck.mm */; }; 8874C1322B69C7060084BEFD /* MTRMetricsTests.m in Sources */ = {isa = PBXBuildFile; fileRef = 8874C1312B69C7060084BEFD /* MTRMetricsTests.m */; }; + 88E07D612B9A89A4005FD53E /* MTRMetricKeys.h in Headers */ = {isa = PBXBuildFile; fileRef = 88E07D602B9A89A4005FD53E /* MTRMetricKeys.h */; }; 88E6C9462B6334ED001A1FE0 /* MTRMetrics.h in Headers */ = {isa = PBXBuildFile; fileRef = 88E6C9432B6334ED001A1FE0 /* MTRMetrics.h */; settings = {ATTRIBUTES = (Public, ); }; }; 88E6C9472B6334ED001A1FE0 /* MTRMetrics_Internal.h in Headers */ = {isa = PBXBuildFile; fileRef = 88E6C9442B6334ED001A1FE0 /* MTRMetrics_Internal.h */; }; 88E6C9482B6334ED001A1FE0 /* MTRMetrics.mm in Sources */ = {isa = PBXBuildFile; fileRef = 88E6C9452B6334ED001A1FE0 /* MTRMetrics.mm */; }; @@ -674,6 +675,7 @@ 75B765C02A1D71BC0014719B /* MTRAttributeSpecifiedCheck.h */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.c.h; path = MTRAttributeSpecifiedCheck.h; sourceTree = ""; }; 75B765C22A1D82D30014719B /* MTRAttributeSpecifiedCheck.mm */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.cpp.objcpp; path = MTRAttributeSpecifiedCheck.mm; sourceTree = ""; }; 8874C1312B69C7060084BEFD /* MTRMetricsTests.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = MTRMetricsTests.m; sourceTree = ""; }; + 88E07D602B9A89A4005FD53E /* MTRMetricKeys.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = MTRMetricKeys.h; sourceTree = ""; }; 88E6C9432B6334ED001A1FE0 /* MTRMetrics.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = MTRMetrics.h; sourceTree = ""; }; 88E6C9442B6334ED001A1FE0 /* MTRMetrics_Internal.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = MTRMetrics_Internal.h; sourceTree = ""; }; 88E6C9452B6334ED001A1FE0 /* MTRMetrics.mm */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.cpp.objcpp; path = MTRMetrics.mm; sourceTree = ""; }; @@ -1190,6 +1192,7 @@ B202528F2459E34F00F97062 /* CHIP */ = { isa = PBXGroup; children = ( + 88E07D602B9A89A4005FD53E /* MTRMetricKeys.h */, 88FA798B2B7B257100CD4B6F /* MTRMetricsCollector.h */, 88FA798C2B7B257100CD4B6F /* MTRMetricsCollector.mm */, 88E6C9442B6334ED001A1FE0 /* MTRMetrics_Internal.h */, @@ -1567,6 +1570,7 @@ 3CF134AB289D8DF70017A19E /* MTRDeviceAttestationInfo.h in Headers */, B2E0D7B2245B0B5C003C5B48 /* MTRManualSetupPayloadParser.h in Headers */, 3CF134A7289D8ADA0017A19E /* MTRCSRInfo.h in Headers */, + 88E07D612B9A89A4005FD53E /* MTRMetricKeys.h in Headers */, B2E0D7B1245B0B5C003C5B48 /* Matter.h in Headers */, 7596A84428762729004DAE0E /* MTRDevice.h in Headers */, B2E0D7B8245B0B5C003C5B48 /* MTRSetupPayload.h in Headers */,