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.

Author: bzbarsky-apple

src/darwin/Framework/CHIP/MTRDevice.h

@@ -101,6 +101,14 @@ MTR_AVAILABLE(ios(16.1), macos(13.0), watchos(9.1), tvos(16.1))
  */
 @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.
  *

src/darwin/Framework/CHIP/MTRDevice.mm

@@ -213,6 +213,7 @@ @implementation MTRDeviceClusterData {
 
 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 @@ @implementation MTRDevice {
     //   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 @@ - (void)setDelegate:(id<MTRDeviceDelegate>)delegate queue:(dispatch_queue_t)queu
     }
 
     if (setUpSubscription) {
+        _initialSubscribeStart = [NSDate now];
         if ([self _deviceUsesThread]) {
             [self _scheduleSubscriptionPoolWork:^{
                 std::lock_guard lock(self->_lock);
@@ -954,6 +960,18 @@ - (void)_handleSubscriptionEstablished
     // 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)setPersistedClusterData:(NSDictionary<MTRClusterPath *, MTRDeviceCluster
     }
 }
 
+- (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);

src/darwin/Framework/CHIP/MTRDeviceController.mm

@@ -966,7 +966,7 @@ - (MTRDevice *)_setupDeviceForNodeID:(NSNumber *)nodeID prefetchedClusterData:(N
         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 @@ - (MTRDevice *)_setupDeviceForNodeID:(NSNumber *)nodeID prefetchedClusterData:(N
         }
     }
 
+    // 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;
 }
 

src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.h

@@ -78,6 +78,16 @@ typedef void (^MTRDeviceControllerDataStoreClusterDataHandler)(NSDictionary<NSNu
 - (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

src/darwin/Framework/CHIP/MTRDeviceControllerDataStore.mm

@@ -1020,6 +1020,65 @@ - (void)storeClusterData:(NSDictionary<MTRClusterPath *, MTRDeviceClusterData *>
     });
 }
 
+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

src/darwin/Framework/CHIP/MTRDevice_Internal.h

@@ -86,6 +86,9 @@ MTR_TESTABLE
 //   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

src/darwin/Framework/CHIPTests/MTRPerControllerStorageTests.m

@@ -1362,10 +1362,18 @@ - (void)doDataStoreMTRDeviceTestWithStorageDelegate:(id<MTRDeviceControllerStora
         [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 @@ - (void)doDataStoreMTRDeviceTestWithStorageDelegate:(id<MTRDeviceControllerStora
     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];