Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Darwin] Add logging for sync storage duration over a threshold #37501

Merged
merged 3 commits into from
Feb 11, 2025
Merged

[Darwin] Add logging for sync storage duration over a threshold #37501

Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
bed5f6d
[Darwin] Add logging for sync storage duration over a threshold
jtung-apple Feb 10, 2025
30e8c8f
restyled
jtung-apple Feb 11, 2025
5b87a95
Clarify constant name per review comment
jtung-apple Feb 11, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
53 changes: 53 additions & 0 deletions src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,9 @@
#include <lib/support/CodeUtils.h>
#include <lib/support/SafeInt.h>

// 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";
Expand Down Expand Up @@ -134,6 +137,7 @@ - (nullable instancetype)initWithController:(MTRDeviceController *)controller

__block id resumptionNodeList;
__block NSArray<NSNumber *> * nodesWithAttributeInfo;
NSDate * startTime = [NSDate now];
dispatch_sync(_storageDelegateQueue, ^{
@autoreleasepool {
// NOTE: controller, not our weak ref, since we know it's still
Expand All @@ -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");
Expand Down Expand Up @@ -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]);
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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)
Expand All @@ -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);
}
}
}

Expand All @@ -293,13 +316,18 @@ - (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
forKey:sLastLocallyUsedNOCKey
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;
}

Expand All @@ -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
Expand All @@ -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;
Expand All @@ -340,6 +373,7 @@ - (nullable MTRCASESessionResumptionInfo *)_findResumptionInfoWithKey:(nullable
}

__block id resumptionInfo;
NSDate * startTime = [NSDate now];
dispatch_sync(_storageDelegateQueue, ^{
@autoreleasepool {
resumptionInfo = [_storageDelegate controller:controller
Expand All @@ -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;
Expand Down Expand Up @@ -866,6 +904,7 @@ - (void)clearAllStoredClusterData
}

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

Expand Down Expand Up @@ -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;
}
Expand All @@ -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;
}

Expand Down Expand Up @@ -1173,6 +1221,7 @@ - (NSString *)_deviceDataKeyForNodeID:(NSNumber *)nodeID
- (nullable NSDictionary<NSString *, id> *)getStoredDeviceDataForNodeID:(NSNumber *)nodeID
{
__block NSDictionary<NSString *, id> * deviceData = nil;
NSDate * startTime = [NSDate now];
dispatch_sync(_storageDelegateQueue, ^{
MTRDeviceController * controller = self->_controller;
VerifyOrReturn(controller != nil); // No way to call delegate without controller.
Expand Down Expand Up @@ -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;
}

Expand Down
Loading