From 332258837e6b533778e9f8c40902bc6db0980e21 Mon Sep 17 00:00:00 2001 From: Karsten Sperling <113487422+ksperling-apple@users.noreply.github.com> Date: Wed, 11 Oct 2023 16:47:58 +1300 Subject: [PATCH] Darwin: Improve MTRAsyncWorkQueue logging by tracking unique item ids (#29568) * Darwin: Improve MTRAsyncWorkQueue logging by tracking unique item ids Also return more information from the batching handler so we can log both partial and full batching from the queue itself. * Avoid unused variable warning / error * Include work item id in various log messages as per review * Tweaks from review * restyle --- src/darwin/Framework/CHIP/MTRAsyncWorkQueue.h | 33 ++++- .../Framework/CHIP/MTRAsyncWorkQueue.mm | 135 ++++++++++++++---- .../Framework/CHIP/MTRDefines_Internal.h | 10 ++ src/darwin/Framework/CHIP/MTRDevice.mm | 87 +++++------ .../CHIPTests/MTRAsyncWorkQueueTests.m | 25 ++-- 5 files changed, 193 insertions(+), 97 deletions(-) diff --git a/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.h b/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.h index 5bc302c6e39714..b584e30738740c 100644 --- a/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.h +++ b/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.h @@ -30,6 +30,12 @@ typedef NS_ENUM(NSInteger, MTRAsyncWorkOutcome) { /// being cancelled). typedef BOOL (^MTRAsyncWorkCompletionBlock)(MTRAsyncWorkOutcome outcome); +typedef NS_ENUM(NSInteger, MTRBatchingOutcome) { + MTRNotBatched = 0, + MTRBatchedPartially, // some work was batched but the source item has work remaining + MTRBatchedFully, // the source item is now empty and can be dropped from the queue +}; + /// An optional handler that controls batching of MTRAsyncWorkItem. /// /// When a work item is dequeued to run, if it is of a type that can be @@ -47,15 +53,16 @@ typedef BOOL (^MTRAsyncWorkCompletionBlock)(MTRAsyncWorkOutcome outcome); /// `opaqueDataNext` is the data for the next item. The `fullyMerged` parameter /// will be initialized to NO by the caller. /// -/// The handler is expected to mutate the data as needed to achieve batching. -/// -/// If after the data mutations opaqueDataNext no longer requires any work, the -/// handler should set `fullyMerged` to YES to indicate that the next item can -/// be dropped from the queue. In this case, the handler may be called again to -/// possibly also batch the work item after the one that was dropped. +/// The handler is expected to mutate the data as needed to achieve batching, +/// and return an `MTRBatchingOutcome` to indicate if any or all of the work +/// from the next item was merged into the current item. A return value of +/// `MTRBatchedFully` indicates that `opaqueDataNext` no longer requires any +/// work and should be dropped from the queue. In this case, the handler may be +/// called again to possibly also batch the work item after the one that was +/// dropped. /// /// @see MTRAsyncWorkItem -typedef void (^MTRAsyncWorkBatchingHandler)(id opaqueDataCurrent, id opaqueDataNext, BOOL * fullyMerged); +typedef MTRBatchingOutcome (^MTRAsyncWorkBatchingHandler)(id opaqueDataCurrent, id opaqueDataNext); /// An optional handler than enables duplicate checking for MTRAsyncWorkItem. /// @@ -100,6 +107,10 @@ MTR_TESTABLE /// Creates a work item that will run on the specified dispatch queue. - (instancetype)initWithQueue:(dispatch_queue_t)queue; +/// A unique (modulo overflow) ID automatically assigned to each work item for +/// the purpose of correlating log messages from the work queue. +@property (readonly, nonatomic) uint64_t uniqueID; + /// Called by the work queue to start this work item. /// /// Will be called on the dispatch queue associated with this item. @@ -188,6 +199,14 @@ MTR_TESTABLE /// re-used. - (void)enqueueWorkItem:(MTRAsyncWorkItem *)item; +/// Same as `enqueueWorkItem:` but includes the description in queue logging. +- (void)enqueueWorkItem:(MTRAsyncWorkItem *)item + description:(nullable NSString *)description; + +/// Convenience for `enqueueWorkItem:description:` with a formatted string. +- (void)enqueueWorkItem:(MTRAsyncWorkItem *)item + descriptionWithFormat:(NSString *)format, ... NS_FORMAT_FUNCTION(2, 3); + /// Checks whether the queue already contains a work item matching the provided /// details. A client may call this method to avoid enqueueing duplicate work. /// diff --git a/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm b/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm index 4de523ec0cd889..ff7242c3582377 100644 --- a/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm +++ b/src/darwin/Framework/CHIP/MTRAsyncWorkQueue.mm @@ -19,8 +19,11 @@ #import "MTRDefines_Internal.h" #import "MTRLogging_Internal.h" +#import #import +NS_ASSUME_NONNULL_BEGIN + typedef NS_ENUM(NSInteger, MTRAsyncWorkItemState) { MTRAsyncWorkItemMutable, MTRAsyncWorkItemComplete, @@ -29,6 +32,20 @@ typedef NS_ENUM(NSInteger, MTRAsyncWorkItemState) { MTRAsyncWorkItemRetryCountBase = MTRAsyncWorkItemRunning, // values >= MTRAsyncWorkItemRunning encode retryCount }; +// A helper struct that facilitates access to _context while +// - only reading the _context weak reference once and retaining a strong +// reference for the duration of a particular queue method call +// - avoiding calls to `[context description]` under our lock +struct ContextSnapshot { + id _Nullable reference; + NSString * _Nullable description; + ContextSnapshot(id _Nullable context) + { + reference = context; + description = [context description]; + } +}; + MTR_DIRECT_MEMBERS @implementation MTRAsyncWorkItem { dispatch_queue_t _queue; @@ -41,19 +58,21 @@ - (instancetype)initWithQueue:(dispatch_queue_t)queue { NSParameterAssert(queue); if (self = [super init]) { + static std::atomic nextUniqueID(1); + _uniqueID = nextUniqueID++; _queue = queue; _state = MTRAsyncWorkItemMutable; } return self; } -- (void)setReadyHandler:(void (^)(id context, NSInteger retryCount, MTRAsyncWorkCompletionBlock completion))readyHandler +- (void)setReadyHandler:(nullable void (^)(id context, NSInteger retryCount, MTRAsyncWorkCompletionBlock completion))readyHandler { [self assertMutable]; _readyHandler = readyHandler; } -- (void)setCancelHandler:(void (^)(void))cancelHandler +- (void)setCancelHandler:(nullable void (^)(void))cancelHandler { [self assertMutable]; _cancelHandler = cancelHandler; @@ -103,7 +122,6 @@ - (NSInteger)retryCount - (void)callReadyHandlerWithContext:(id)context completion:(MTRAsyncWorkCompletionBlock)completion { - // NSAssert(_state >= MTRAsyncWorkItemEnqueued, @"work item is not enqueued (%ld)", (long) _state); NSInteger retryCount = 0; if (_state == MTRAsyncWorkItemEnqueued) { @@ -117,8 +135,14 @@ - (void)callReadyHandlerWithContext:(id)context completion:(MTRAsyncWorkCompleti // Always dispatch even if there is no readyHandler as this avoids synchronously // re-entering the MTRAsyncWorkQueueCode, simplifying the implementation. + auto uniqueID = _uniqueID; auto readyHandler = _readyHandler; dispatch_async(_queue, ^{ + if (!retryCount) { + MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> executing work item [%llu]", context, uniqueID); + } else { + MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> executing work item [%llu] (retry %zd)", context, uniqueID, retryCount); + } if (readyHandler) { readyHandler(context, retryCount, completion); } else { @@ -160,6 +184,25 @@ - (void)markComplete _duplicateCheckHandler = nil; } +- (NSString *)description +{ + NSString * state; + switch (_state) { + case MTRAsyncWorkItemMutable: + state = @"mutable"; + break; + case MTRAsyncWorkItemComplete: + state = @"complete"; + break; + case MTRAsyncWorkItemEnqueued: + state = @"enqueued"; + break; + default: + return [NSString stringWithFormat:@"<%@ %llu running retry: %tu>", self.class, _uniqueID, self.retryCount]; + } + return [NSString stringWithFormat:@"<%@ %llu %@>", self.class, _uniqueID, state]; +} + @end MTR_DIRECT_MEMBERS @@ -182,29 +225,56 @@ - (instancetype)initWithContext:(id)context - (NSString *)description { + NSUInteger itemsCount; os_unfair_lock_lock(&_lock); - auto * result = [NSString stringWithFormat:@"<%@ context: %@ items count: %tu>", self.class, _context, _items.count]; + itemsCount = _items.count; os_unfair_lock_unlock(&_lock); - return result; + return [NSString stringWithFormat:@"<%@ context: %@ items count: %tu>", self.class, _context, itemsCount]; +} + +- (void)enqueueWorkItem:(MTRAsyncWorkItem *)item +{ + [self enqueueWorkItem:item description:nil]; +} + +- (void)enqueueWorkItem:(MTRAsyncWorkItem *)item descriptionWithFormat:(NSString *)format, ... +{ + va_list args; + va_start(args, format); + NSString * description = [[NSString alloc] initWithFormat:format arguments:args]; + va_end(args); + [self enqueueWorkItem:item description:description]; } - (void)enqueueWorkItem:(MTRAsyncWorkItem *)item + description:(nullable NSString *)description { NSParameterAssert(item); - NSAssert(_context, @"context has been lost"); + ContextSnapshot context(_context); // outside of lock + NSAssert(context.reference, @"context has been lost"); os_unfair_lock_lock(&_lock); [item markEnqueued]; [_items addObject:item]; - [self _callNextReadyWorkItem]; + + if (description) { + // Logging the description once is enough because other log messages + // related to the work item (execution, completion etc) can easily be + // correlated using the unique id. + MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> enqueued work item [%llu]: %@", context.description, item.uniqueID, description); + } else { + MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> enqueued work item [%llu]", context.description, item.uniqueID); + } + + [self _callNextReadyWorkItemWithContext:context]; os_unfair_lock_unlock(&_lock); } - (void)invalidate { - NSString * contextDescription = [_context description]; // outside of lock + ContextSnapshot context(_context); // outside of lock os_unfair_lock_lock(&_lock); - MTR_LOG_INFO("MTRAsyncWorkQueue<%@> invalidate %tu items", contextDescription, _items.count); + MTR_LOG_INFO("MTRAsyncWorkQueue<%@> invalidate %tu items", context.description, _items.count); for (MTRAsyncWorkItem * item in _items) { [item cancel]; } @@ -212,7 +282,9 @@ - (void)invalidate os_unfair_lock_unlock(&_lock); } -- (void)_postProcessWorkItem:(MTRAsyncWorkItem *)workItem retry:(BOOL)retry +- (void)_postProcessWorkItem:(MTRAsyncWorkItem *)workItem + context:(ContextSnapshot const &)context + retry:(BOOL)retry { os_unfair_lock_assert_owner(&_lock); @@ -222,18 +294,20 @@ - (void)_postProcessWorkItem:(MTRAsyncWorkItem *)workItem retry:(BOOL)retry return; } - // if work item is done (no need to retry), remove from queue and call ready on the next item - if (!retry) { + if (retry) { + MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> retry needed for work item [%llu]", context.description, workItem.uniqueID); + } else { [workItem markComplete]; [_items removeObjectAtIndex:0]; + MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> completed work item [%llu]", context.description, workItem.uniqueID); } // when "concurrency width" is implemented this will be decremented instead _runningWorkItemCount = 0; - [self _callNextReadyWorkItem]; + [self _callNextReadyWorkItemWithContext:context]; } -- (void)_callNextReadyWorkItem +- (void)_callNextReadyWorkItemWithContext:(ContextSnapshot const &)context { os_unfair_lock_assert_owner(&_lock); @@ -246,9 +320,8 @@ - (void)_callNextReadyWorkItem return; // nothing to run } - id context = _context; - if (!context) { - MTR_LOG_ERROR("MTRAsyncWorkQueue context has been lost, dropping queued work items"); + if (!context.reference) { + MTR_LOG_ERROR("MTRAsyncWorkQueue<%@> context has been lost, dropping queued work items", (id) nil); [_items removeAllObjects]; return; } @@ -264,27 +337,35 @@ - (void)_callNextReadyWorkItem while (_items.count >= 2) { MTRAsyncWorkItem * nextWorkItem = _items[1]; if (!nextWorkItem.batchingHandler || nextWorkItem.batchingID != workItem.batchingID) { - break; // next item is not eligible to merge with this one + goto done; // next item is not eligible to merge with this one } - BOOL fullyMerged = NO; - batchingHandler(workItem.batchableData, nextWorkItem.batchableData, &fullyMerged); - if (!fullyMerged) { - break; // not removing the next item, so we can't merge anything else + switch (batchingHandler(workItem.batchableData, nextWorkItem.batchableData)) { + case MTRNotBatched: + goto done; // can't merge anything else + case MTRBatchedPartially: + MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> partially merged work item [%llu] into %llu", + context.description, nextWorkItem.uniqueID, workItem.uniqueID); + goto done; // can't merge anything else + case MTRBatchedFully: + MTR_LOG_DEFAULT("MTRAsyncWorkQueue<%@> fully merged work item [%llu] into %llu", + context.description, nextWorkItem.uniqueID, workItem.uniqueID); + [_items removeObjectAtIndex:1]; + continue; // try to batch the next item (if any) } - - [_items removeObjectAtIndex:1]; } + done:; } mtr_weakify(self); - [workItem callReadyHandlerWithContext:context completion:^(MTRAsyncWorkOutcome outcome) { + [workItem callReadyHandlerWithContext:context.reference completion:^(MTRAsyncWorkOutcome outcome) { mtr_strongify(self); BOOL handled = NO; if (self) { + ContextSnapshot context(self->_context); // re-acquire a new snapshot os_unfair_lock_lock(&self->_lock); if (!workItem.isComplete) { - [self _postProcessWorkItem:workItem retry:(outcome == MTRAsyncWorkNeedsRetry)]; + [self _postProcessWorkItem:workItem context:context retry:(outcome == MTRAsyncWorkNeedsRetry)]; handled = YES; } os_unfair_lock_unlock(&self->_lock); @@ -315,3 +396,5 @@ - (BOOL)hasDuplicateForTypeID:(NSUInteger)opaqueDuplicateTypeID workItemData:(id } @end + +NS_ASSUME_NONNULL_END diff --git a/src/darwin/Framework/CHIP/MTRDefines_Internal.h b/src/darwin/Framework/CHIP/MTRDefines_Internal.h index d5d7040a927681..b4e73c8f97e044 100644 --- a/src/darwin/Framework/CHIP/MTRDefines_Internal.h +++ b/src/darwin/Framework/CHIP/MTRDefines_Internal.h @@ -46,4 +46,14 @@ _Pragma("clang diagnostic ignored \"-Wshadow\"") \ __strong typeof(local) _Nullable local = _mtr_weak_##local \ _Pragma("clang diagnostic pop") + +/// Declares an unused local of unspecified type, to prevent accidental +/// references to a shadowed variable of the same name. Note that hiding +/// `self` does not prevent implicit references to self due to ivar access. +#define mtr_hide(local) \ + _Pragma("clang diagnostic push") \ + _Pragma("clang diagnostic ignored \"-Wshadow\"") \ + __attribute__((unused)) variable_hidden_by_mtr_hide local; \ + _Pragma("clang diagnostic pop") +typedef struct {} variable_hidden_by_mtr_hide; // clang-format on diff --git a/src/darwin/Framework/CHIP/MTRDevice.mm b/src/darwin/Framework/CHIP/MTRDevice.mm index 28874a560b287f..26f52986e8d239 100644 --- a/src/darwin/Framework/CHIP/MTRDevice.mm +++ b/src/darwin/Framework/CHIP/MTRDevice.mm @@ -857,7 +857,6 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath) attributeID:(NSNumber *)attributeID params:(MTRReadParams *)params { - NSString * logPrefix = [NSString stringWithFormat:@"%@ read %@ %@ %@", self, endpointID, clusterID, attributeID]; MTRAttributePath * attributePath = [MTRAttributePath attributePathWithEndpointID:endpointID clusterID:clusterID attributeID:attributeID]; @@ -894,46 +893,43 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath) // Create work item, set ready handler to perform task, then enqueue the work MTRAsyncWorkItem * workItem = [[MTRAsyncWorkItem alloc] initWithQueue:self.queue]; - [workItem setBatchingID:MTRDeviceWorkItemBatchingReadID data:readRequests handler:^(id opaqueDataCurrent, id opaqueDataNext, BOOL * fullyMerged) { + uint64_t workItemID = workItem.uniqueID; // capture only the ID, not the work item + [workItem setBatchingID:MTRDeviceWorkItemBatchingReadID data:readRequests handler:^(id opaqueDataCurrent, id opaqueDataNext) { + mtr_hide(self); // don't capture self accidentally NSMutableArray * readRequestsCurrent = opaqueDataCurrent; NSMutableArray * readRequestsNext = opaqueDataNext; - // Can only read up to 9 paths at a time, per spec - if (readRequestsCurrent.count >= 9) { - MTR_LOG_DEFAULT("%@ batching cannot add more", logPrefix); - return; - } - + MTRBatchingOutcome outcome = MTRNotBatched; while (readRequestsNext.count) { + // Can only read up to 9 paths at a time, per spec + if (readRequestsCurrent.count >= 9) { + MTR_LOG_INFO("Batching read attribute work item [%llu]: cannot add more work, item is full", workItemID); + return outcome; + } + // if params don't match then they cannot be merged if (![readRequestsNext[0][MTRDeviceReadRequestFieldParamsIndex] isEqual:readRequestsCurrent[0][MTRDeviceReadRequestFieldParamsIndex]]) { - MTR_LOG_DEFAULT("%@ batching merged all possible items", logPrefix); - return; + MTR_LOG_INFO("Batching read attribute work item [%llu]: cannot add more work, parameter mismatch", workItemID); + return outcome; } // merge the next item's first request into the current item's list - [readRequestsCurrent addObject:readRequestsNext[0]]; - MTR_LOG_INFO("%@ batching merging %@ => %lu total", logPrefix, readRequestsNext[0], - (unsigned long) readRequestsCurrent.count); + auto readItem = readRequestsNext.firstObject; [readRequestsNext removeObjectAtIndex:0]; - - // Can only read up to 9 paths at a time, per spec - if (readRequestsCurrent.count == 9) { - MTR_LOG_DEFAULT("%@ batching to max paths allowed", logPrefix); - break; - } - } - - if (readRequestsNext.count == 0) { - MTR_LOG_DEFAULT("%@ batching - fully merged next item", logPrefix); - *fullyMerged = YES; + [readRequestsCurrent addObject:readItem]; + MTR_LOG_INFO("Batching read attribute work item [%llu]: added %@ (now %tu requests total)", + workItemID, readItem, readRequestsCurrent.count); + outcome = MTRBatchedPartially; } + NSCAssert(readRequestsNext.count == 0, @"should have batched everything or returned early"); + return MTRBatchedFully; }]; [workItem setDuplicateTypeID:MTRDeviceWorkItemDuplicateReadTypeID handler:^(id opaqueItemData, BOOL * isDuplicate, BOOL * stop) { + mtr_hide(self); // don't capture self accidentally for (NSArray * readItem in readRequests) { if ([readItem isEqual:opaqueItemData]) { - MTR_LOG_DEFAULT("%@ duplicate check found %@ - report duplicate", logPrefix, readItem); + MTR_LOG_DEFAULT("Read attribute work item [%llu] report duplicate %@", workItemID, readItem); *isDuplicate = YES; *stop = YES; return; @@ -941,12 +937,10 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath) } *stop = NO; }]; - [workItem setReadyHandler:^(MTRDevice * device, NSInteger retryCount, MTRAsyncWorkCompletionBlock completion) { - MTR_LOG_DEFAULT("%@ dequeueWorkItem %@", logPrefix, self->_asyncWorkQueue); - + [workItem setReadyHandler:^(MTRDevice * self, NSInteger retryCount, MTRAsyncWorkCompletionBlock completion) { // Sanity check if (readRequests.count == 0) { - MTR_LOG_ERROR("%@ dequeueWorkItem no read requests", logPrefix); + MTR_LOG_ERROR("Read attribute work item [%llu] contained no read requests", workItemID); completion(MTRAsyncWorkComplete); return; } @@ -954,12 +948,7 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath) // Build the attribute paths from the read requests NSMutableArray * attributePaths = [NSMutableArray array]; for (NSArray * readItem in readRequests) { - // Sanity check - if (readItem.count < 2) { - MTR_LOG_ERROR("%@ dequeueWorkItem read item missing info %@", logPrefix, readItem); - completion(MTRAsyncWorkComplete); - return; - } + NSAssert(readItem.count == 2, @"invalid read attribute item"); [attributePaths addObject:readItem[MTRDeviceReadRequestFieldPathIndex]]; } // If param is the NSNull stand-in, then just use nil @@ -976,22 +965,21 @@ static BOOL AttributeHasChangesOmittedQuality(MTRAttributePath * attributePath) if (values) { // Since the format is the same data-value dictionary, this looks like an // attribute report - MTR_LOG_INFO("%@ completion values %@", logPrefix, values); + MTR_LOG_INFO("Read attribute work item [%llu] result: %@", workItemID, values); [self _handleAttributeReport:values]; } // TODO: better retry logic if (error && (retryCount < 2)) { - MTR_LOG_ERROR("%@ completion error %@ retryWork %lu", logPrefix, error, (unsigned long) retryCount); + MTR_LOG_ERROR("Read attribute work item [%llu] failed (will retry): %@", workItemID, error); completion(MTRAsyncWorkNeedsRetry); } else { - MTR_LOG_DEFAULT("%@ completion error %@ endWork", logPrefix, error); + MTR_LOG_DEFAULT("Read attribute work item [%llu] failed (giving up): %@", workItemID, error); completion(MTRAsyncWorkComplete); } }]; }]; - MTR_LOG_DEFAULT("%@ enqueueWorkItem %@", logPrefix, _asyncWorkQueue); - [_asyncWorkQueue enqueueWorkItem:workItem]; + [_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"read %@ %@ %@", endpointID, clusterID, attributeID]; } return attributeValueToReturn; @@ -1004,7 +992,6 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID expectedValueInterval:(NSNumber *)expectedValueInterval timedWriteTimeout:(NSNumber * _Nullable)timeout { - NSString * logPrefix = [NSString stringWithFormat:@"%@ write %@ %@ %@", self, endpointID, clusterID, attributeID]; if (timeout) { timeout = MTRClampedNumber(timeout, @(1), @(UINT16_MAX)); } @@ -1020,14 +1007,14 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID expectedValueID:&expectedValueID]; MTRAsyncWorkItem * workItem = [[MTRAsyncWorkItem alloc] initWithQueue:self.queue]; + uint64_t workItemID = workItem.uniqueID; // capture only the ID, not the work item // The write operation will install a duplicate check handler, to return NO for "isDuplicate". Since a write operation may // change values, only read requests after this should be considered for duplicate requests. [workItem setDuplicateTypeID:MTRDeviceWorkItemDuplicateReadTypeID handler:^(id opaqueItemData, BOOL * isDuplicate, BOOL * stop) { *isDuplicate = NO; *stop = YES; }]; - [workItem setReadyHandler:^(MTRDevice * device, NSInteger retryCount, MTRAsyncWorkCompletionBlock completion) { - MTR_LOG_DEFAULT("%@ dequeueWorkItem %@", logPrefix, self->_asyncWorkQueue); + [workItem setReadyHandler:^(MTRDevice * self, NSInteger retryCount, MTRAsyncWorkCompletionBlock completion) { MTRBaseDevice * baseDevice = [self newBaseDevice]; [baseDevice writeAttributeWithEndpointID:endpointID @@ -1037,15 +1024,14 @@ - (void)writeAttributeWithEndpointID:(NSNumber *)endpointID timedWriteTimeout:timeout queue:self.queue completion:^(NSArray *> * _Nullable values, NSError * _Nullable error) { - MTR_LOG_DEFAULT("%@ completion error %@ endWork", logPrefix, error); if (error) { + MTR_LOG_ERROR("Write attribute work item [%llu] failed: %@", workItemID, error); [self removeExpectedValueForAttributePath:attributePath expectedValueID:expectedValueID]; } completion(MTRAsyncWorkComplete); }]; }]; - MTR_LOG_DEFAULT("%@ enqueueWorkItem %@", logPrefix, _asyncWorkQueue); - [_asyncWorkQueue enqueueWorkItem:workItem]; + [_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"write %@ %@ %@", endpointID, clusterID, attributeID]; } - (void)invokeCommandWithEndpointID:(NSNumber *)endpointID @@ -1085,7 +1071,6 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID queue:(dispatch_queue_t)queue completion:(MTRDeviceResponseHandler)completion { - NSString * logPrefix = [NSString stringWithFormat:@"%@ command %@ %@ %@", self, endpointID, clusterID, commandID]; if (!expectedValueInterval || ([expectedValueInterval compare:@(0)] == NSOrderedAscending)) { expectedValues = nil; } else { @@ -1105,6 +1090,7 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID } } MTRAsyncWorkItem * workItem = [[MTRAsyncWorkItem alloc] initWithQueue:self.queue]; + uint64_t workItemID = workItem.uniqueID; // capture only the ID, not the work item // The command operation will install a duplicate check handler, to return NO for "isDuplicate". Since a command operation may // change values, only read requests after this should be considered for duplicate requests. [workItem setDuplicateTypeID:MTRDeviceWorkItemDuplicateReadTypeID handler:^(id opaqueItemData, BOOL * isDuplicate, BOOL * stop) { @@ -1112,7 +1098,6 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID *stop = YES; }]; [workItem setReadyHandler:^(MTRDevice * device, NSInteger retryCount, MTRAsyncWorkCompletionBlock workCompletion) { - MTR_LOG_DEFAULT("%@ dequeueWorkItem %@", logPrefix, self->_asyncWorkQueue); MTRBaseDevice * baseDevice = [self newBaseDevice]; [baseDevice _invokeCommandWithEndpointID:endpointID @@ -1125,19 +1110,17 @@ - (void)_invokeCommandWithEndpointID:(NSNumber *)endpointID completion:^(NSArray *> * _Nullable values, NSError * _Nullable error) { // Log the data at the INFO level (not usually persisted permanently), // but make sure we log the work completion at the DEFAULT level. - MTR_LOG_INFO("%@ received response: %@ error: %@", logPrefix, values, error); + MTR_LOG_INFO("Invoke work item [%llu] received command response: %@ error: %@", workItemID, values, error); dispatch_async(queue, ^{ completion(values, error); }); if (error && expectedValues) { [self removeExpectedValuesForAttributePaths:attributePaths expectedValueID:expectedValueID]; } - MTR_LOG_DEFAULT("%@ endWork", logPrefix); workCompletion(MTRAsyncWorkComplete); }]; }]; - MTR_LOG_DEFAULT("%@ enqueueWorkItem %@", logPrefix, _asyncWorkQueue); - [_asyncWorkQueue enqueueWorkItem:workItem]; + [_asyncWorkQueue enqueueWorkItem:workItem descriptionWithFormat:@"invoke %@ %@ %@", endpointID, clusterID, commandID]; } - (void)_invokeKnownCommandWithEndpointID:(NSNumber *)endpointID diff --git a/src/darwin/Framework/CHIPTests/MTRAsyncWorkQueueTests.m b/src/darwin/Framework/CHIPTests/MTRAsyncWorkQueueTests.m index d7154afe996d77..031c45380496f0 100644 --- a/src/darwin/Framework/CHIPTests/MTRAsyncWorkQueueTests.m +++ b/src/darwin/Framework/CHIPTests/MTRAsyncWorkQueueTests.m @@ -50,7 +50,7 @@ - (void)testRunItem counter++; [expectation fulfill]; }; - [workQueue enqueueWorkItem:workItem1]; + [workQueue enqueueWorkItem:workItem1 description:@"work item 1"]; // Check for leaks. MTRAsyncWorkItem * __weak weakItem = workItem1; @@ -77,7 +77,7 @@ - (void)testRunItemsSerialized counter++; completion(MTRAsyncWorkComplete); }; - [workQueue enqueueWorkItem:workItem1]; + [workQueue enqueueWorkItem:workItem1 descriptionWithFormat:@"work item %d", 1]; MTRAsyncWorkItem * workItem2 = [[MTRAsyncWorkItem alloc] initWithQueue:dispatch_get_global_queue(QOS_CLASS_DEFAULT, 0)]; workItem2.readyHandler = ^(id context, NSInteger retryCount, MTRAsyncWorkCompletionBlock completion) { @@ -87,7 +87,7 @@ - (void)testRunItemsSerialized } completion(MTRAsyncWorkComplete); }; - [workQueue enqueueWorkItem:workItem2]; + [workQueue enqueueWorkItem:workItem2 description:@"work item 2"]; [self waitForExpectationsWithTimeout:2 handler:nil]; @@ -114,7 +114,7 @@ - (void)testRunItemsRetry completion(MTRAsyncWorkNeedsRetry); } }; - [workQueue enqueueWorkItem:workItem1]; + [workQueue enqueueWorkItem:workItem1 description:@"needs a retry"]; MTRAsyncWorkItem * workItem2 = [[MTRAsyncWorkItem alloc] initWithQueue:dispatch_get_global_queue(QOS_CLASS_DEFAULT, 0)]; workItem2.readyHandler = ^(id context, NSInteger retryCount, MTRAsyncWorkCompletionBlock completion) { @@ -144,7 +144,7 @@ - (void)testRunItemsAfterDrain completion(MTRAsyncWorkComplete); [expectation1 fulfill]; }; - [workQueue enqueueWorkItem:workItem1]; + [workQueue enqueueWorkItem:workItem1 description:@"workItem1"]; [self waitForExpectations:@[ expectation1 ] timeout:2]; @@ -153,7 +153,7 @@ - (void)testRunItemsAfterDrain [expectation2 fulfill]; completion(MTRAsyncWorkComplete); }; - [workQueue enqueueWorkItem:workItem2]; + [workQueue enqueueWorkItem:workItem2 description:@"workItem2"]; [self waitForExpectationsWithTimeout:2 handler:nil]; } @@ -243,12 +243,12 @@ - (void)testBatching }]; [workItem1 setBatchingID:1 data:@(1) - handler:^(id _Nonnull opaqueDataFirst, id _Nonnull opaqueDataSecond, BOOL * _Nonnull fullyMerged) { + handler:^(id _Nonnull opaqueDataFirst, id _Nonnull opaqueDataSecond) { XCTAssertEqualObjects(opaqueDataFirst, @(1)); XCTAssertEqualObjects(opaqueDataSecond, @(2)); - *fullyMerged = YES; + return MTRBatchedFully; }]; - [workQueue enqueueWorkItem:workItem1]; + [workQueue enqueueWorkItem:workItem1 description:@"workItem1"]; MTRAsyncWorkItem * workItem2 = [[MTRAsyncWorkItem alloc] initWithQueue:dispatch_get_global_queue(QOS_CLASS_DEFAULT, 0)]; [workItem2 setReadyHandler:^(id context, NSInteger retryCount, MTRAsyncWorkCompletionBlock completion) { @@ -257,17 +257,18 @@ - (void)testBatching }]; [workItem2 setBatchingID:1 data:@(2) - handler:^(id _Nonnull opaqueDataFirst, id _Nonnull opaqueDataSecond, BOOL * _Nonnull fullyMerged) { + handler:^(id _Nonnull opaqueDataFirst, id _Nonnull opaqueDataSecond) { workItem2BatchingCalled = YES; + return MTRBatchedPartially; }]; - [workQueue enqueueWorkItem:workItem2]; + [workQueue enqueueWorkItem:workItem2 description:@"workItem2"]; MTRAsyncWorkItem * workItem3 = [[MTRAsyncWorkItem alloc] initWithQueue:dispatch_get_global_queue(QOS_CLASS_DEFAULT, 0)]; [workItem3 setReadyHandler:^(id context, NSInteger retryCount, MTRAsyncWorkCompletionBlock completion) { [workItem3ReadyExpectation fulfill]; completion(MTRAsyncWorkComplete); }]; - [workQueue enqueueWorkItem:workItem3]; + [workQueue enqueueWorkItem:workItem3 description:@"workItem3"]; completion(MTRAsyncWorkComplete); };