Skip to content

Commit 9ac70fe

Browse files
jtung-appleratgr
jtung-apple
authored and
ratgr
committed
[Darwin] Add logging for sync storage duration over a threshold (project-chip#37501)
* [Darwin] Add logging for sync storage duration over a threshold * restyled * Clarify constant name per review comment
1 parent c47254a commit 9ac70fe

File tree

1 file changed

+53
-0
lines changed

1 file changed

+53
-0
lines changed

‎src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm

+53
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,9 @@
2626
#include <lib/support/CodeUtils.h>
2727
#include <lib/support/SafeInt.h>
2828

29+
// Log error each time sync storage takes longer than this threshold
30+
#define SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS (2.0)
31+
2932
// FIXME: Are these good key strings? https://github.com/project-chip/connectedhomeip/issues/28973
3033
static NSString * sResumptionNodeListKey = @"caseResumptionNodeList";
3134
static NSString * sLastLocallyUsedNOCKey = @"lastLocallyUsedControllerNOC";
@@ -134,6 +137,7 @@ - (nullable instancetype)initWithController:(MTRDeviceController *)controller
134137

135138
__block id resumptionNodeList;
136139
__block NSArray<NSNumber *> * nodesWithAttributeInfo;
140+
NSDate * startTime = [NSDate now];
137141
dispatch_sync(_storageDelegateQueue, ^{
138142
@autoreleasepool {
139143
// NOTE: controller, not our weak ref, since we know it's still
@@ -146,6 +150,10 @@ - (nullable instancetype)initWithController:(MTRDeviceController *)controller
146150
nodesWithAttributeInfo = [self _fetchNodeIndex];
147151
}
148152
});
153+
NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow];
154+
if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) {
155+
MTR_LOG_ERROR("MTRDeviceControllerDataStore init took %0.6lf seconds to read from storage", syncDuration);
156+
}
149157
if (resumptionNodeList != nil) {
150158
if (![resumptionNodeList isKindOfClass:[NSArray class]]) {
151159
MTR_LOG_ERROR("List of CASE resumption node IDs is not an array");
@@ -177,11 +185,16 @@ - (void)fetchAttributeDataForAllDevices:(MTRDeviceControllerDataStoreClusterData
177185
MTRDeviceController * controller = _controller;
178186
VerifyOrReturn(controller != nil); // No way to call delegate without controller.
179187

188+
NSDate * startTime = [NSDate now];
180189
dispatch_sync(_storageDelegateQueue, ^{
181190
if ([self->_storageDelegate respondsToSelector:@selector(valuesForController:securityLevel:sharingType:)]) {
182191
dataStoreSecureLocalValues = [self->_storageDelegate valuesForController:controller securityLevel:MTRStorageSecurityLevelSecure sharingType:MTRStorageSharingTypeNotShared];
183192
}
184193
});
194+
NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow];
195+
if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) {
196+
MTR_LOG_ERROR("MTRDeviceControllerDataStore fetchAttributeDataForAllDevices took %0.6lf seconds to read from storage", syncDuration);
197+
}
185198

186199
if (dataStoreSecureLocalValues.count) {
187200
clusterDataHandler([self _getClusterDataFromSecureLocalValues:dataStoreSecureLocalValues]);
@@ -204,6 +217,7 @@ - (void)storeResumptionInfo:(MTRCASESessionResumptionInfo *)resumptionInfo
204217
VerifyOrReturn(controller != nil); // No way to call delegate without controller.
205218

206219
auto * oldInfo = [self findResumptionInfoByNodeID:resumptionInfo.nodeID];
220+
NSDate * startTime = [NSDate now];
207221
dispatch_sync(_storageDelegateQueue, ^{
208222
if (oldInfo != nil) {
209223
// Remove old resumption id key. No need to do that for the
@@ -241,6 +255,10 @@ - (void)storeResumptionInfo:(MTRCASESessionResumptionInfo *)resumptionInfo
241255
securityLevel:MTRStorageSecurityLevelSecure
242256
sharingType:MTRStorageSharingTypeNotShared];
243257
});
258+
NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow];
259+
if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) {
260+
MTR_LOG_ERROR("MTRDeviceControllerDataStore storeResumptionInfo took %0.6lf seconds to store to storage", syncDuration);
261+
}
244262
}
245263

246264
- (void)clearAllResumptionInfo
@@ -274,6 +292,7 @@ - (void)_clearResumptionInfoForNodeID:(NSNumber *)nodeID controller:(MTRDeviceCo
274292
{
275293
auto * oldInfo = [self findResumptionInfoByNodeID:nodeID];
276294
if (oldInfo != nil) {
295+
NSDate * startTime = [NSDate now];
277296
dispatch_sync(_storageDelegateQueue, ^{
278297
[_storageDelegate controller:controller
279298
removeValueForKey:ResumptionByResumptionIDKey(oldInfo.resumptionID)
@@ -284,6 +303,10 @@ - (void)_clearResumptionInfoForNodeID:(NSNumber *)nodeID controller:(MTRDeviceCo
284303
securityLevel:MTRStorageSecurityLevelSecure
285304
sharingType:MTRStorageSharingTypeNotShared];
286305
});
306+
NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow];
307+
if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) {
308+
MTR_LOG_ERROR("MTRDeviceControllerDataStore _clearResumptionInfoForNodeID took %0.6lf seconds to remove from storage", syncDuration);
309+
}
287310
}
288311
}
289312

@@ -293,13 +316,18 @@ - (CHIP_ERROR)storeLastLocallyUsedNOC:(MTRCertificateTLVBytes)noc
293316
VerifyOrReturnError(controller != nil, CHIP_ERROR_PERSISTED_STORAGE_FAILED); // No way to call delegate without controller.
294317

295318
__block BOOL ok;
319+
NSDate * startTime = [NSDate now];
296320
dispatch_sync(_storageDelegateQueue, ^{
297321
ok = [_storageDelegate controller:controller
298322
storeValue:noc
299323
forKey:sLastLocallyUsedNOCKey
300324
securityLevel:MTRStorageSecurityLevelSecure
301325
sharingType:MTRStorageSharingTypeNotShared];
302326
});
327+
NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow];
328+
if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) {
329+
MTR_LOG_ERROR("MTRDeviceControllerDataStore storeLastLocallyUsedNOC took %0.6lf seconds to store to storage", syncDuration);
330+
}
303331
return ok ? CHIP_NO_ERROR : CHIP_ERROR_PERSISTED_STORAGE_FAILED;
304332
}
305333

@@ -309,6 +337,7 @@ - (MTRCertificateTLVBytes _Nullable)fetchLastLocallyUsedNOC
309337
VerifyOrReturnValue(controller != nil, nil); // No way to call delegate without controller.
310338

311339
__block id data;
340+
NSDate * startTime = [NSDate now];
312341
dispatch_sync(_storageDelegateQueue, ^{
313342
@autoreleasepool {
314343
data = [_storageDelegate controller:controller
@@ -317,6 +346,10 @@ - (MTRCertificateTLVBytes _Nullable)fetchLastLocallyUsedNOC
317346
sharingType:MTRStorageSharingTypeNotShared];
318347
}
319348
});
349+
NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow];
350+
if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) {
351+
MTR_LOG_ERROR("MTRDeviceControllerDataStore fetchLastLocallyUsedNOC took %0.6lf seconds to read from storage", syncDuration);
352+
}
320353

321354
if (data == nil) {
322355
return nil;
@@ -340,6 +373,7 @@ - (nullable MTRCASESessionResumptionInfo *)_findResumptionInfoWithKey:(nullable
340373
}
341374

342375
__block id resumptionInfo;
376+
NSDate * startTime = [NSDate now];
343377
dispatch_sync(_storageDelegateQueue, ^{
344378
@autoreleasepool {
345379
resumptionInfo = [_storageDelegate controller:controller
@@ -348,6 +382,10 @@ - (nullable MTRCASESessionResumptionInfo *)_findResumptionInfoWithKey:(nullable
348382
sharingType:MTRStorageSharingTypeNotShared];
349383
}
350384
});
385+
NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow];
386+
if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) {
387+
MTR_LOG_ERROR("MTRDeviceControllerDataStore _findResumptionInfoWithKey took %0.6lf seconds to read from storage", syncDuration);
388+
}
351389

352390
if (resumptionInfo == nil) {
353391
return nil;
@@ -866,6 +904,7 @@ - (void)clearAllStoredClusterData
866904
}
867905

868906
__block NSMutableDictionary<MTRClusterPath *, MTRDeviceClusterData *> * clusterDataToReturn = nil;
907+
NSDate * startTime = [NSDate now];
869908
dispatch_sync(_storageDelegateQueue, ^{
870909
std::lock_guard lock(self->_nodeArrayLock);
871910

@@ -924,6 +963,10 @@ - (void)clearAllStoredClusterData
924963
}
925964
}
926965
});
966+
NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow];
967+
if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) {
968+
MTR_LOG_ERROR("MTRDeviceControllerDataStore getStoredClusterDataForNodeID took %0.6lf seconds to read from storage", syncDuration);
969+
}
927970

928971
return clusterDataToReturn;
929972
}
@@ -934,9 +977,14 @@ - (nullable MTRDeviceClusterData *)getStoredClusterDataForNodeID:(NSNumber *)nod
934977
// when the consumer knows that we're supposed to have data for this cluster
935978
// path.
936979
__block MTRDeviceClusterData * clusterDataToReturn = nil;
980+
NSDate * startTime = [NSDate now];
937981
dispatch_sync(_storageDelegateQueue, ^{
938982
clusterDataToReturn = [self _fetchClusterDataForNodeID:nodeID endpointID:endpointID clusterID:clusterID];
939983
});
984+
NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow];
985+
if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) {
986+
MTR_LOG_ERROR("MTRDeviceControllerDataStore getStoredClusterDataForNodeID took %0.6lf seconds to read from storage", syncDuration);
987+
}
940988
return clusterDataToReturn;
941989
}
942990

@@ -1173,6 +1221,7 @@ - (NSString *)_deviceDataKeyForNodeID:(NSNumber *)nodeID
11731221
- (nullable NSDictionary<NSString *, id> *)getStoredDeviceDataForNodeID:(NSNumber *)nodeID
11741222
{
11751223
__block NSDictionary<NSString *, id> * deviceData = nil;
1224+
NSDate * startTime = [NSDate now];
11761225
dispatch_sync(_storageDelegateQueue, ^{
11771226
MTRDeviceController * controller = self->_controller;
11781227
VerifyOrReturn(controller != nil); // No way to call delegate without controller.
@@ -1204,6 +1253,10 @@ - (NSString *)_deviceDataKeyForNodeID:(NSNumber *)nodeID
12041253
// to do that.
12051254
deviceData = dictionary;
12061255
});
1256+
NSTimeInterval syncDuration = -[startTime timeIntervalSinceNow];
1257+
if (syncDuration > SYNC_OPERATION_DURATION_LOG_THRESHOLD_SECONDS) {
1258+
MTR_LOG_ERROR("MTRDeviceControllerDataStore getStoredDeviceDataForNodeID took %0.6lf seconds to read from storage", syncDuration);
1259+
}
12071260
return deviceData;
12081261
}
12091262

0 commit comments

Comments
 (0)