diff --git a/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm b/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm index 8a0057ca1ed9f2..7baa49060dd282 100644 --- a/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm +++ b/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm @@ -26,6 +26,9 @@ #include #include +// Log error each time sync storage takes longer than this threshold +#define SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS (2.0) + // FIXME: Are these good key strings? https://github.com/project-chip/connectedhomeip/issues/28973 static NSString * sResumptionNodeListKey = @"caseResumptionNodeList"; static NSString * sLastLocallyUsedNOCKey = @"lastLocallyUsedControllerNOC"; @@ -134,6 +137,7 @@ - (nullable instancetype)initWithController:(MTRDeviceController *)controller __block id resumptionNodeList; __block NSArray * nodesWithAttributeInfo; + NSDate * startTime = [NSDate now]; dispatch_sync(_storageDelegateQueue, ^{ @autoreleasepool { // NOTE: controller, not our weak ref, since we know it's still @@ -146,6 +150,10 @@ - (nullable instancetype)initWithController:(MTRDeviceController *)controller nodesWithAttributeInfo = [self _fetchNodeIndex]; } }); + NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow]; + if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) { + MTR_LOG_ERROR("MTRDeviceControllerDataStore init took %0.6lf seconds to read from storage", syncDuration); + } if (resumptionNodeList != nil) { if (![resumptionNodeList isKindOfClass:[NSArray class]]) { MTR_LOG_ERROR("List of CASE resumption node IDs is not an array"); @@ -177,11 +185,16 @@ - (void)fetchAttributeDataForAllDevices:(MTRDeviceControllerDataStoreClusterData MTRDeviceController * controller = _controller; VerifyOrReturn(controller != nil); // No way to call delegate without controller. + NSDate * startTime = [NSDate now]; dispatch_sync(_storageDelegateQueue, ^{ if ([self->_storageDelegate respondsToSelector:@selector(valuesForController:securityLevel:sharingType:)]) { dataStoreSecureLocalValues = [self->_storageDelegate valuesForController:controller securityLevel:MTRStorageSecurityLevelSecure sharingType:MTRStorageSharingTypeNotShared]; } }); + NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow]; + if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) { + MTR_LOG_ERROR("MTRDeviceControllerDataStore fetchAttributeDataForAllDevices took %0.6lf seconds to read from storage", syncDuration); + } if (dataStoreSecureLocalValues.count) { clusterDataHandler([self _getClusterDataFromSecureLocalValues:dataStoreSecureLocalValues]); @@ -204,6 +217,7 @@ - (void)storeResumptionInfo:(MTRCASESessionResumptionInfo *)resumptionInfo VerifyOrReturn(controller != nil); // No way to call delegate without controller. auto * oldInfo = [self findResumptionInfoByNodeID:resumptionInfo.nodeID]; + NSDate * startTime = [NSDate now]; dispatch_sync(_storageDelegateQueue, ^{ if (oldInfo != nil) { // Remove old resumption id key. No need to do that for the @@ -241,6 +255,10 @@ - (void)storeResumptionInfo:(MTRCASESessionResumptionInfo *)resumptionInfo securityLevel:MTRStorageSecurityLevelSecure sharingType:MTRStorageSharingTypeNotShared]; }); + NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow]; + if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) { + MTR_LOG_ERROR("MTRDeviceControllerDataStore storeResumptionInfo took %0.6lf seconds to store to storage", syncDuration); + } } - (void)clearAllResumptionInfo @@ -274,6 +292,7 @@ - (void)_clearResumptionInfoForNodeID:(NSNumber *)nodeID controller:(MTRDeviceCo { auto * oldInfo = [self findResumptionInfoByNodeID:nodeID]; if (oldInfo != nil) { + NSDate * startTime = [NSDate now]; dispatch_sync(_storageDelegateQueue, ^{ [_storageDelegate controller:controller removeValueForKey:ResumptionByResumptionIDKey(oldInfo.resumptionID) @@ -284,6 +303,10 @@ - (void)_clearResumptionInfoForNodeID:(NSNumber *)nodeID controller:(MTRDeviceCo securityLevel:MTRStorageSecurityLevelSecure sharingType:MTRStorageSharingTypeNotShared]; }); + NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow]; + if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) { + MTR_LOG_ERROR("MTRDeviceControllerDataStore _clearResumptionInfoForNodeID took %0.6lf seconds to remove from storage", syncDuration); + } } } @@ -293,6 +316,7 @@ - (CHIP_ERROR)storeLastLocallyUsedNOC:(MTRCertificateTLVBytes)noc VerifyOrReturnError(controller != nil, CHIP_ERROR_PERSISTED_STORAGE_FAILED); // No way to call delegate without controller. __block BOOL ok; + NSDate * startTime = [NSDate now]; dispatch_sync(_storageDelegateQueue, ^{ ok = [_storageDelegate controller:controller storeValue:noc @@ -300,6 +324,10 @@ - (CHIP_ERROR)storeLastLocallyUsedNOC:(MTRCertificateTLVBytes)noc securityLevel:MTRStorageSecurityLevelSecure sharingType:MTRStorageSharingTypeNotShared]; }); + NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow]; + if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) { + MTR_LOG_ERROR("MTRDeviceControllerDataStore storeLastLocallyUsedNOC took %0.6lf seconds to store to storage", syncDuration); + } return ok ? CHIP_NO_ERROR : CHIP_ERROR_PERSISTED_STORAGE_FAILED; } @@ -309,6 +337,7 @@ - (MTRCertificateTLVBytes _Nullable)fetchLastLocallyUsedNOC VerifyOrReturnValue(controller != nil, nil); // No way to call delegate without controller. __block id data; + NSDate * startTime = [NSDate now]; dispatch_sync(_storageDelegateQueue, ^{ @autoreleasepool { data = [_storageDelegate controller:controller @@ -317,6 +346,10 @@ - (MTRCertificateTLVBytes _Nullable)fetchLastLocallyUsedNOC sharingType:MTRStorageSharingTypeNotShared]; } }); + NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow]; + if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) { + MTR_LOG_ERROR("MTRDeviceControllerDataStore fetchLastLocallyUsedNOC took %0.6lf seconds to read from storage", syncDuration); + } if (data == nil) { return nil; @@ -340,6 +373,7 @@ - (nullable MTRCASESessionResumptionInfo *)_findResumptionInfoWithKey:(nullable } __block id resumptionInfo; + NSDate * startTime = [NSDate now]; dispatch_sync(_storageDelegateQueue, ^{ @autoreleasepool { resumptionInfo = [_storageDelegate controller:controller @@ -348,6 +382,10 @@ - (nullable MTRCASESessionResumptionInfo *)_findResumptionInfoWithKey:(nullable sharingType:MTRStorageSharingTypeNotShared]; } }); + NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow]; + if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) { + MTR_LOG_ERROR("MTRDeviceControllerDataStore _findResumptionInfoWithKey took %0.6lf seconds to read from storage", syncDuration); + } if (resumptionInfo == nil) { return nil; @@ -866,6 +904,7 @@ - (void)clearAllStoredClusterData } __block NSMutableDictionary * clusterDataToReturn = nil; + NSDate * startTime = [NSDate now]; dispatch_sync(_storageDelegateQueue, ^{ std::lock_guard lock(self->_nodeArrayLock); @@ -924,6 +963,10 @@ - (void)clearAllStoredClusterData } } }); + NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow]; + if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) { + MTR_LOG_ERROR("MTRDeviceControllerDataStore getStoredClusterDataForNodeID took %0.6lf seconds to read from storage", syncDuration); + } return clusterDataToReturn; } @@ -934,9 +977,14 @@ - (nullable MTRDeviceClusterData *)getStoredClusterDataForNodeID:(NSNumber *)nod // when the consumer knows that we're supposed to have data for this cluster // path. __block MTRDeviceClusterData * clusterDataToReturn = nil; + NSDate * startTime = [NSDate now]; dispatch_sync(_storageDelegateQueue, ^{ clusterDataToReturn = [self _fetchClusterDataForNodeID:nodeID endpointID:endpointID clusterID:clusterID]; }); + NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow]; + if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) { + MTR_LOG_ERROR("MTRDeviceControllerDataStore getStoredClusterDataForNodeID took %0.6lf seconds to read from storage", syncDuration); + } return clusterDataToReturn; } @@ -1173,6 +1221,7 @@ - (NSString *)_deviceDataKeyForNodeID:(NSNumber *)nodeID - (nullable NSDictionary *)getStoredDeviceDataForNodeID:(NSNumber *)nodeID { __block NSDictionary * deviceData = nil; + NSDate * startTime = [NSDate now]; dispatch_sync(_storageDelegateQueue, ^{ MTRDeviceController * controller = self->_controller; VerifyOrReturn(controller != nil); // No way to call delegate without controller. @@ -1204,6 +1253,10 @@ - (NSString *)_deviceDataKeyForNodeID:(NSNumber *)nodeID // to do that. deviceData = dictionary; }); + NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow]; + if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) { + MTR_LOG_ERROR("MTRDeviceControllerDataStore getStoredDeviceDataForNodeID took %0.6lf seconds to read from storage", syncDuration); + } return deviceData; }