Provide an estimate of subscription latency in MTRDevice. (#33490)
The idea is to track how long subscriptions took in the past and surface an
estimate based on that to the API consumer.
diff --git a/src/darwin/Framework/CHIP/MTRDevice.h b/src/darwin/Framework/CHIP/MTRDevice.h
index a8fc45a..d9555a9 100644
--- a/src/darwin/Framework/CHIP/MTRDevice.h
+++ b/src/darwin/Framework/CHIP/MTRDevice.h
@@ -102,6 +102,14 @@
@property (nonatomic, readonly, copy) NSNumber * nodeID NS_REFINED_FOR_SWIFT MTR_AVAILABLE(ios(17.4), macos(14.4), watchos(10.4), tvos(17.4));
/**
+ * An estimate of how much time is likely to elapse between setDelegate being
+ * called and the current device state (attributes, stored events) being known.
+ *
+ * nil if no such estimate is available. Otherwise, the NSNumber stores an NSTimeInterval.
+ */
+@property (nonatomic, readonly, nullable, copy) NSNumber * estimatedSubscriptionLatency MTR_NEWLY_AVAILABLE;
+
+/**
* Set the delegate to receive asynchronous callbacks about the device.
*
* The delegate will be called on the provided queue, for attribute reports, event reports, and device state changes.
diff --git a/src/darwin/Framework/CHIP/MTRDevice.mm b/src/darwin/Framework/CHIP/MTRDevice.mm
index 8801355..ff2187c 100644
--- a/src/darwin/Framework/CHIP/MTRDevice.mm
+++ b/src/darwin/Framework/CHIP/MTRDevice.mm
@@ -213,6 +213,7 @@
static NSString * const sDataVersionKey = @"dataVersion";
static NSString * const sAttributesKey = @"attributes";
+static NSString * const sLastInitialSubscribeLatencyKey = @"lastInitialSubscribeLatency";
- (void)storeValue:(MTRDeviceDataValueDictionary _Nullable)value forAttribute:(NSNumber *)attribute
{
@@ -414,6 +415,10 @@
// 2. OnResubscriptionNeeded is called
// 3. Subscription reset (including when getSessionForNode fails)
MTRAsyncWorkCompletionBlock _subscriptionPoolWorkCompletionBlock;
+
+ // Tracking of initial subscribe latency. When _initialSubscribeStart is
+ // nil, we are not tracking the latency.
+ NSDate * _Nullable _initialSubscribeStart;
}
- (instancetype)initWithNodeID:(NSNumber *)nodeID controller:(MTRDeviceController *)controller
@@ -705,6 +710,7 @@
}
if (setUpSubscription) {
+ _initialSubscribeStart = [NSDate now];
if ([self _deviceUsesThread]) {
[self _scheduleSubscriptionPoolWork:^{
std::lock_guard lock(self->_lock);
@@ -954,6 +960,18 @@
// No need to monitor connectivity after subscription establishment
[self _stopConnectivityMonitoring];
+ auto initialSubscribeStart = _initialSubscribeStart;
+ // We no longer need to track subscribe latency for this device.
+ _initialSubscribeStart = nil;
+
+ if (initialSubscribeStart != nil) {
+ // We want time interval from initialSubscribeStart to now, not the other
+ // way around.
+ NSTimeInterval subscriptionLatency = -[initialSubscribeStart timeIntervalSinceNow];
+ _estimatedSubscriptionLatency = @(subscriptionLatency);
+ [self _storePersistedDeviceData];
+ }
+
os_unfair_lock_unlock(&self->_lock);
os_unfair_lock_lock(&self->_timeSyncLock);
@@ -2884,6 +2902,50 @@
}
}
+- (void)_setLastInitialSubscribeLatency:(id)latency
+{
+ os_unfair_lock_assert_owner(&self->_lock);
+
+ if (![latency isKindOfClass:NSNumber.class]) {
+ // Unexpected value of some sort; just ignore it.
+ return;
+ }
+
+ _estimatedSubscriptionLatency = latency;
+}
+
+- (void)setPersistedDeviceData:(NSDictionary<NSString *, id> *)data
+{
+ MTR_LOG_INFO("%@ setPersistedDeviceData: %@", self, data);
+
+ std::lock_guard lock(_lock);
+
+ // For now the only data we care about is our initial subscribe latency.
+ id initialSubscribeLatency = data[sLastInitialSubscribeLatencyKey];
+ if (initialSubscribeLatency != nil) {
+ [self _setLastInitialSubscribeLatency:initialSubscribeLatency];
+ }
+}
+
+- (void)_storePersistedDeviceData
+{
+ os_unfair_lock_assert_owner(&self->_lock);
+
+ auto datastore = _deviceController.controllerDataStore;
+ if (datastore == nil) {
+ // No way to store.
+ return;
+ }
+
+ // For now the only data we have is our initial subscribe latency.
+ NSMutableDictionary<NSString *, id> * data = [NSMutableDictionary dictionary];
+ if (_estimatedSubscriptionLatency != nil) {
+ data[sLastInitialSubscribeLatencyKey] = _estimatedSubscriptionLatency;
+ }
+
+ [datastore storeDeviceData:[data copy] forNodeID:self.nodeID];
+}
+
- (BOOL)deviceCachePrimed
{
std::lock_guard lock(_lock);
diff --git a/src/darwin/Framework/CHIP/MTRDeviceController.mm b/src/darwin/Framework/CHIP/MTRDeviceController.mm
index 278ccdf..9c4b0a4 100644
--- a/src/darwin/Framework/CHIP/MTRDeviceController.mm
+++ b/src/darwin/Framework/CHIP/MTRDeviceController.mm
@@ -966,7 +966,7 @@
if (prefetchedClusterData.count) {
[deviceToReturn setPersistedClusterData:prefetchedClusterData];
}
- } else {
+ } else if (_controllerDataStore) {
// Load persisted cluster data if they exist.
NSDictionary * clusterData = [_controllerDataStore getStoredClusterDataForNodeID:nodeID];
MTR_LOG_INFO("Loaded %lu cluster data from storage for %@", static_cast<unsigned long>(clusterData.count), deviceToReturn);
@@ -975,6 +975,14 @@
}
}
+ // TODO: Figure out how to get the device data as part of our bulk-read bits.
+ if (_controllerDataStore) {
+ auto * deviceData = [_controllerDataStore getStoredDeviceDataForNodeID:nodeID];
+ if (deviceData.count) {
+ [deviceToReturn setPersistedDeviceData:deviceData];
+ }
+ }
+
return deviceToReturn;
}
diff --git a/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.h b/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.h
index dd9da5c..e0cf9d0 100644
--- a/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.h
+++ b/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.h
@@ -78,6 +78,16 @@
- (void)clearStoredClusterDataForNodeID:(NSNumber *)nodeID;
- (void)clearAllStoredClusterData;
+/**
+ * Storage for miscellaneous MTRDevice data that only needs to be stored
+ * locally.
+ *
+ * storeDeviceData uses data and nodeID async without copying, so callers should
+ * not modify the passed-in dictionary or nodeID.
+ */
+- (nullable NSDictionary<NSString *, id> *)getStoredDeviceDataForNodeID:(NSNumber *)nodeID;
+- (void)storeDeviceData:(NSDictionary<NSString *, id> *)data forNodeID:(NSNumber *)nodeID;
+
@end
NS_ASSUME_NONNULL_END
diff --git a/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm b/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm
index 1f515f2..7b65f8e 100644
--- a/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm
+++ b/src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm
@@ -1020,6 +1020,65 @@
});
}
+static NSString * sDeviceDataKeyPrefix = @"deviceData";
+
+- (NSString *)_deviceDataKeyForNodeID:(NSNumber *)nodeID
+{
+ return [sDeviceDataKeyPrefix stringByAppendingFormat:@":0x%016llX", nodeID.unsignedLongLongValue];
+}
+
+- (nullable NSDictionary<NSString *, id> *)getStoredDeviceDataForNodeID:(NSNumber *)nodeID
+{
+ __block NSDictionary<NSString *, id> * deviceData = nil;
+ dispatch_sync(_storageDelegateQueue, ^{
+ MTRDeviceController * controller = self->_controller;
+ VerifyOrReturn(controller != nil); // No way to call delegate without controller.
+
+ id data;
+ @autoreleasepool {
+ data = [self->_storageDelegate controller:controller
+ valueForKey:[self _deviceDataKeyForNodeID:nodeID]
+ securityLevel:MTRStorageSecurityLevelSecure
+ sharingType:MTRStorageSharingTypeNotShared];
+ }
+ if (data == nil) {
+ return;
+ }
+
+ if (![data isKindOfClass:NSDictionary.class]) {
+ return;
+ }
+
+ // Check that all the keys are in fact strings.
+ NSDictionary * dictionary = data;
+ for (id key in dictionary) {
+ if (![key isKindOfClass:NSString.class]) {
+ return;
+ }
+ }
+
+ // We can't do value type verification; our API consumer will need
+ // to do that.
+ deviceData = dictionary;
+ });
+ return deviceData;
+}
+
+- (void)storeDeviceData:(NSDictionary<NSString *, id> *)data forNodeID:(NSNumber *)nodeID
+{
+ dispatch_async(_storageDelegateQueue, ^{
+ MTRDeviceController * controller = self->_controller;
+ VerifyOrReturn(controller != nil); // No way to call delegate without controller.
+
+ // Ignore store failures, since they are not actionable for us here.
+ [self->_storageDelegate controller:controller
+ storeValue:data
+ forKey:[self _deviceDataKeyForNodeID:nodeID]
+ securityLevel:MTRStorageSecurityLevelSecure
+ sharingType:MTRStorageSharingTypeNotShared];
+ });
+}
+
@end
@implementation MTRCASESessionResumptionInfo
diff --git a/src/darwin/Framework/CHIP/MTRDevice_Internal.h b/src/darwin/Framework/CHIP/MTRDevice_Internal.h
index 7302a5b..04313a6 100644
--- a/src/darwin/Framework/CHIP/MTRDevice_Internal.h
+++ b/src/darwin/Framework/CHIP/MTRDevice_Internal.h
@@ -86,6 +86,9 @@
// Contains data version information and attribute values.
- (void)setPersistedClusterData:(NSDictionary<MTRClusterPath *, MTRDeviceClusterData *> *)clusterData;
+// Method to insert persisted data that pertains to the whole device.
+- (void)setPersistedDeviceData:(NSDictionary<NSString *, id> *)data;
+
#ifdef DEBUG
- (NSUInteger)unitTestAttributeCount;
#endif
diff --git a/src/darwin/Framework/CHIPTests/MTRPerControllerStorageTests.m b/src/darwin/Framework/CHIPTests/MTRPerControllerStorageTests.m
index 49679dc..1940372 100644
--- a/src/darwin/Framework/CHIPTests/MTRPerControllerStorageTests.m
+++ b/src/darwin/Framework/CHIPTests/MTRPerControllerStorageTests.m
@@ -1362,10 +1362,18 @@
[subscriptionExpectation fulfill];
};
+ // Verify that initially (before we have ever subscribed while using this
+ // datastore) the device has no estimate for subscription latency.
+ XCTAssertNil(device.estimatedSubscriptionLatency);
+
+ __auto_type * beforeSetDelegate = [NSDate now];
+
[device setDelegate:delegate queue:queue];
[self waitForExpectations:@[ subscriptionExpectation ] timeout:60];
+ __auto_type * afterInitialSubscription = [NSDate now];
+
NSUInteger dataStoreValuesCount = 0;
NSDictionary<MTRClusterPath *, MTRDeviceClusterData *> * dataStoreClusterData = [controller.controllerDataStore getStoredClusterDataForNodeID:deviceID];
for (MTRClusterPath * path in dataStoreClusterData) {
@@ -1400,6 +1408,21 @@
double storedAttributeDifferFromMTRDevicePercentage = storedAttributeDifferFromMTRDeviceCount * 100.0 / dataStoreValuesCount;
XCTAssertTrue(storedAttributeDifferFromMTRDevicePercentage < 10.0);
+ // Check that the new device has an estimated subscription latency.
+ XCTAssertNotNil(device.estimatedSubscriptionLatency);
+
+ // Check that this estimate is positive, since subscribing must have taken
+ // some time.
+ XCTAssertGreaterThan(device.estimatedSubscriptionLatency.doubleValue, 0);
+
+ // Check that this estimate is no larger than the measured latency observed
+ // above. Unfortunately, We measure our observed latency to report end, not
+ // to the immediately following internal subscription established
+ // notification, so in fact our measured value can end up shorter than the
+ // estimated latency the device has. Add some slop to handle that.
+ const NSTimeInterval timingSlopInSeconds = 0.1;
+ XCTAssertLessThanOrEqual(device.estimatedSubscriptionLatency.doubleValue, [afterInitialSubscription timeIntervalSinceDate:beforeSetDelegate] + timingSlopInSeconds);
+
// Now set up new delegate for the new device and verify that once subscription reestablishes, the data version filter loaded from storage will work
__auto_type * newDelegate = [[MTRDeviceTestDelegate alloc] init];
