From 15cb0a57304bf97f46c767aa2c8d60c2e16528de Mon Sep 17 00:00:00 2001 From: Nora Trapp Date: Mon, 23 Aug 2021 13:11:56 -0700 Subject: [PATCH 1/3] Add benchmarks around various message sending milestones --- .../ConversationCollectionView.swift | 2 -- .../ConversationViewController+CVC.swift | 12 ++++++++++ ...ler+ConversationInputToolbarDelegate.swift | 5 ++-- SignalMessaging/utils/ThreadUtil.swift | 14 +++++++++-- SignalServiceKit/src/Messages/MessageSender.m | 22 +++++++++++++++++ .../src/Network/MessageSenderJobQueue.swift | 6 +++++ SignalServiceKit/src/Util/Bench.swift | 24 ++++++++++++++----- 7 files changed, 72 insertions(+), 13 deletions(-) diff --git a/Signal/src/ViewControllers/ConversationView/ConversationCollectionView.swift b/Signal/src/ViewControllers/ConversationView/ConversationCollectionView.swift index c49f1228ba..cac65d01db 100644 --- a/Signal/src/ViewControllers/ConversationView/ConversationCollectionView.swift +++ b/Signal/src/ViewControllers/ConversationView/ConversationCollectionView.swift @@ -58,8 +58,6 @@ public extension ConversationCollectionView { }, failureBlock: tryFailure) } layout.didPerformBatchUpdates() - - BenchManager.completeEvent(eventId: "message-send") }, failureBlock: tryFailure) } diff --git a/Signal/src/ViewControllers/ConversationView/ConversationViewController+CVC.swift b/Signal/src/ViewControllers/ConversationView/ConversationViewController+CVC.swift index cceabc8b8e..56a64818de 100644 --- a/Signal/src/ViewControllers/ConversationView/ConversationViewController+CVC.swift +++ b/Signal/src/ViewControllers/ConversationView/ConversationViewController+CVC.swift @@ -574,6 +574,8 @@ extension ConversationViewController: CVLoadCoordinatorDelegate { } }() + var benchEventIdsToComplete = [String]() + let batchUpdatesBlock = { AssertIsOnMainThread() @@ -587,6 +589,10 @@ extension ConversationViewController: CVLoadCoordinatorDelegate { let indexPath = IndexPath(row: oldIndex, section: section) self.collectionView.deleteItems(at: [indexPath]) case .insert(let newIndex): + if let outgoingMessage = item.value.interaction as? TSOutgoingMessage, outgoingMessage.messageState == .sending { + benchEventIdsToComplete.append("sendMessageSending-\(outgoingMessage.timestamp)") + } + let indexPath = IndexPath(row: newIndex, section: section) self.collectionView.insertItems(at: [indexPath]) case .move(let oldIndex, let newIndex): @@ -594,6 +600,10 @@ extension ConversationViewController: CVLoadCoordinatorDelegate { let newIndexPath = IndexPath(row: newIndex, section: section) self.collectionView.moveItem(at: oldIndexPath, to: newIndexPath) case .update(let oldIndex, _): + if let outgoingMessage = item.value.interaction as? TSOutgoingMessage, outgoingMessage.messageState != .sending { + benchEventIdsToComplete.append("sendMessagePostNetwork-\(outgoingMessage.timestamp)") + benchEventIdsToComplete.append("sendMessageSent-\(outgoingMessage.timestamp)") + } let indexPath = IndexPath(row: oldIndex, section: section) self.collectionView.reloadItems(at: [indexPath]) } @@ -607,6 +617,8 @@ extension ConversationViewController: CVLoadCoordinatorDelegate { return } + BenchManager.completeEvents(eventIds: benchEventIdsToComplete) + // If the scroll action is not animated, perform it _before_ // updateViewToReflectLoad(). if !scrollAction.isAnimated { diff --git a/Signal/src/ViewControllers/ConversationView/ConversationViewController+ConversationInputToolbarDelegate.swift b/Signal/src/ViewControllers/ConversationView/ConversationViewController+ConversationInputToolbarDelegate.swift index c0a82e9fce..574e42559c 100644 --- a/Signal/src/ViewControllers/ConversationView/ConversationViewController+ConversationInputToolbarDelegate.swift +++ b/Signal/src/ViewControllers/ConversationView/ConversationViewController+ConversationInputToolbarDelegate.swift @@ -34,10 +34,9 @@ extension ConversationViewController: ConversationInputToolbarDelegate { return } - BenchManager.startEvent(title: "Send Message", eventId: "message-send") - BenchManager.startEvent(title: "Send Message milestone: clearTextMessageAnimated completed", + BenchManager.startEvent(title: "Send Message Milestone: clearTextMessageAnimated", eventId: "fromSendUntil_clearTextMessageAnimated") - BenchManager.startEvent(title: "Send Message milestone: toggleDefaultKeyboard completed", + BenchManager.startEvent(title: "Send Message Milestone: toggleDefaultKeyboard", eventId: "fromSendUntil_toggleDefaultKeyboard") tryToSendTextMessage(messageBody, updateKeyboardState: true) diff --git a/SignalMessaging/utils/ThreadUtil.swift b/SignalMessaging/utils/ThreadUtil.swift index 1999ae0aad..dffe3ae902 100644 --- a/SignalMessaging/utils/ThreadUtil.swift +++ b/SignalMessaging/utils/ThreadUtil.swift @@ -39,14 +39,24 @@ public extension ThreadUtil { transaction: readTransaction) let message: TSOutgoingMessage = outgoingMessagePreparer.unpreparedMessage - BenchManager.benchAsync(title: "Saving outgoing message") { benchmarkCompletion in + BenchManager.startEvent( + title: "Send Message Milestone: Sending (\(message.timestamp))", + eventId: "sendMessageSending-\(message.timestamp)" + ) + BenchManager.startEvent( + title: "Send Message Milestone: Sent (\(message.timestamp))", + eventId: "sendMessageSent-\(message.timestamp)" + ) + BenchManager.benchAsync(title: "Send Message Milestone: Enqueue \(message.timestamp)") { benchmarkCompletion in Self.enqueueSendAsyncWrite { writeTransaction in outgoingMessagePreparer.insertMessage(linkPreviewDraft: linkPreviewDraft, transaction: writeTransaction) Self.messageSenderJobQueue.add(message: outgoingMessagePreparer, transaction: writeTransaction) - writeTransaction.addAsyncCompletionOnMain { + writeTransaction.addSyncCompletion { benchmarkCompletion() + } + writeTransaction.addAsyncCompletionOnMain { persistenceCompletion?() } } diff --git a/SignalServiceKit/src/Messages/MessageSender.m b/SignalServiceKit/src/Messages/MessageSender.m index 3f3d87fc73..35f4894e83 100644 --- a/SignalServiceKit/src/Messages/MessageSender.m +++ b/SignalServiceKit/src/Messages/MessageSender.m @@ -257,6 +257,10 @@ NSError *SSKEnsureError(NSError *_Nullable error, OWSErrorCode fallbackCode, NSS if ([latestCopy isKindOfClass:[TSOutgoingMessage class]]) { messageWasRemotelyDeleted = ((TSOutgoingMessage *)latestCopy).wasRemotelyDeleted; } + + [BenchManager + completeEventWithEventId:[NSString stringWithFormat:@"sendMessagePreNetwork-%llu", self.message.timestamp]]; + if ((self.message.shouldBeSaved && latestCopy == nil) || messageWasRemotelyDeleted) { OWSLogInfo(@"aborting message send; message deleted."); NSError *error = [MessageDeletedBeforeSentError asNSError]; @@ -264,22 +268,40 @@ NSError *SSKEnsureError(NSError *_Nullable error, OWSErrorCode fallbackCode, NSS return; } + [BenchManager startEventWithTitle:[NSString stringWithFormat:@"Send Message Milestone: Network (%llu)", + self.message.timestamp] + eventId:[NSString stringWithFormat:@"sendMessageNetwork-%llu", self.message.timestamp]]; + [self.messageSender sendMessageToService:self.message success:^{ [self reportSuccess]; } failure:^(NSError *error) { [self reportError:error]; }]; } +- (void)completeNetworkEvent +{ + [BenchManager + completeEventWithEventId:[NSString stringWithFormat:@"sendMessageNetwork-%llu", self.message.timestamp]]; + [BenchManager + startEventWithTitle:[NSString + stringWithFormat:@"Send Message Milestone: Post-Network (%llu)", self.message.timestamp] + eventId:[NSString stringWithFormat:@"sendMessagePostNetwork-%llu", self.message.timestamp]]; +} + - (void)didSucceed { if (self.message.messageState != TSOutgoingMessageStateSent) { OWSFailDebug(@"Unexpected message status: %@", self.message.statusDescription); } + [self completeNetworkEvent]; + self.successHandler(); } - (void)didFailWithError:(NSError *)error { + [self completeNetworkEvent]; + OWSLogError(@"Failed with error: %@ (isRetryable: %d)", error, error.isRetryable); self.failureHandler(error); } diff --git a/SignalServiceKit/src/Network/MessageSenderJobQueue.swift b/SignalServiceKit/src/Network/MessageSenderJobQueue.swift index baa7f77af1..cc2e98dac9 100644 --- a/SignalServiceKit/src/Network/MessageSenderJobQueue.swift +++ b/SignalServiceKit/src/Network/MessageSenderJobQueue.swift @@ -162,6 +162,12 @@ public class MessageSenderJobQueue: NSObject, JobQueue { if let resolver = resolver { jobResolvers[jobRecord.uniqueId] = resolver } + transaction.addSyncCompletion { + BenchManager.startEvent( + title: "Send Message Milestone: Pre-Network (\(messageRecord.timestamp))", + eventId: "sendMessagePreNetwork-\(messageRecord.timestamp)" + ) + } } catch { message.unpreparedMessage.update(sendingError: error, transaction: transaction) } diff --git a/SignalServiceKit/src/Util/Bench.swift b/SignalServiceKit/src/Util/Bench.swift index 985644bd60..e120bc1b9a 100644 --- a/SignalServiceKit/src/Util/Bench.swift +++ b/SignalServiceKit/src/Util/Bench.swift @@ -134,13 +134,19 @@ public func BenchEventStart(title: String, eventId: BenchmarkEventId) { } public func BenchEventComplete(eventId: BenchmarkEventId) { - eventQueue.sync { - guard let event = runningEvents.removeValue(forKey: eventId) else { - Logger.debug("no active event with id: \(eventId)") - return - } + BenchEventComplete(eventIds: [eventId]) +} - event.completion() +public func BenchEventComplete(eventIds: [BenchmarkEventId]) { + eventQueue.sync { + for eventId in eventIds { + guard let event = runningEvents.removeValue(forKey: eventId) else { + Logger.debug("no active event with id: \(eventId)") + return + } + + event.completion() + } } } @@ -168,6 +174,12 @@ public class BenchManager: NSObject { BenchEventComplete(eventId: eventId) } + @objc + public class func completeEvents(eventIds: [BenchmarkEventId]) { + guard !eventIds.isEmpty else { return } + BenchEventComplete(eventIds: eventIds) + } + @objc public class func benchAsync(title: String, block: (@escaping () -> Void) -> Void) { BenchAsync(title: title, block: block) From ee298b468899b385237ae0fcb9d038e8b279f25e Mon Sep 17 00:00:00 2001 From: Nora Trapp Date: Tue, 24 Aug 2021 14:07:28 -0700 Subject: [PATCH 2/3] Start next job in the same transaction it's created in --- SignalServiceKit/src/Util/JobQueue.swift | 71 +++++++++++++++--------- 1 file changed, 44 insertions(+), 27 deletions(-) diff --git a/SignalServiceKit/src/Util/JobQueue.swift b/SignalServiceKit/src/Util/JobQueue.swift index 20e24100e4..3837d24852 100644 --- a/SignalServiceKit/src/Util/JobQueue.swift +++ b/SignalServiceKit/src/Util/JobQueue.swift @@ -103,6 +103,12 @@ public extension JobQueue { jobRecord.anyInsert(transaction: transaction) + transaction.addTransactionFinalizationBlock( + forKey: "jobQueue.\(jobRecordLabel).startWorkImmediatelyIfAppIsReady" + ) { transaction in + self.startWorkImmediatelyIfAppIsReady(transaction: transaction) + } + transaction.addAsyncCompletion(queue: .global()) { self.startWorkWhenAppIsReady() } @@ -112,6 +118,15 @@ public extension JobQueue { return nil != finder.getNextReady(label: self.jobRecordLabel, transaction: transaction) } + func startWorkImmediatelyIfAppIsReady(transaction: SDSAnyWriteTransaction) { + guard isEnabled else { return } + guard !CurrentAppContext().isRunningTests else { return } + guard AppReadiness.isAppReady else { return } + guard !DebugFlags.suppressBackgroundActivity else { return } + guard isSetup.get() else { return } + workStep(transaction: transaction) + } + func startWorkWhenAppIsReady() { guard isEnabled else { return } @@ -150,44 +165,46 @@ public extension JobQueue { return } - self.databaseStorage.write { transaction in - guard let nextJob: JobRecordType = self.finder.getNextReady(label: self.jobRecordLabel, transaction: transaction) else { - Logger.verbose("nothing left to enqueue") - self.didFlushQueue(transaction: transaction) - return - } + databaseStorage.write { self.workStep(transaction: $0) } + } - do { - try nextJob.saveAsStarted(transaction: transaction) + func workStep(transaction: SDSAnyWriteTransaction) { + guard let nextJob: JobRecordType = self.finder.getNextReady(label: jobRecordLabel, transaction: transaction) else { + Logger.verbose("nothing left to enqueue") + didFlushQueue(transaction: transaction) + return + } - let operationQueue = self.operationQueue(jobRecord: nextJob) - let durableOperation = try self.buildOperation(jobRecord: nextJob, transaction: transaction) + do { + try nextJob.saveAsStarted(transaction: transaction) - durableOperation.durableOperationDelegate = self as? Self.DurableOperationType.DurableOperationDelegateType - owsAssertDebug(durableOperation.durableOperationDelegate != nil) + let operationQueue = operationQueue(jobRecord: nextJob) + let durableOperation = try buildOperation(jobRecord: nextJob, transaction: transaction) - let remainingRetries = self.remainingRetries(durableOperation: durableOperation) - durableOperation.remainingRetries = remainingRetries + durableOperation.durableOperationDelegate = self as? Self.DurableOperationType.DurableOperationDelegateType + owsAssertDebug(durableOperation.durableOperationDelegate != nil) + let remainingRetries = remainingRetries(durableOperation: durableOperation) + durableOperation.remainingRetries = remainingRetries + + transaction.addSyncCompletion { self.runningOperations.append(durableOperation) Logger.debug("adding operation: \(durableOperation) with remainingRetries: \(remainingRetries)") operationQueue.addOperation(durableOperation.operation) - } catch JobError.assertionFailure(let description) { - owsFailDebug("assertion failure: \(description)") - nextJob.saveAsPermanentlyFailed(transaction: transaction) - } catch JobError.obsolete(let description) { - // TODO is this even worthwhile to have obsolete state? Should we just delete the task outright? - Logger.verbose("marking obsolete task as such. description:\(description)") - nextJob.saveAsObsolete(transaction: transaction) - } catch { - owsFailDebug("unexpected error") - } - - DispatchQueue.global().async { - self.workStep() } + } catch JobError.assertionFailure(let description) { + owsFailDebug("assertion failure: \(description)") + nextJob.saveAsPermanentlyFailed(transaction: transaction) + } catch JobError.obsolete(let description) { + // TODO is this even worthwhile to have obsolete state? Should we just delete the task outright? + Logger.verbose("marking obsolete task as such. description:\(description)") + nextJob.saveAsObsolete(transaction: transaction) + } catch { + owsFailDebug("unexpected error") } + + transaction.addAsyncCompletionOffMain { self.workStep() } } func restartOldJobs() { From 64ca34f485711f80725d8fb4058e1204315932b7 Mon Sep 17 00:00:00 2001 From: Nora Trapp Date: Thu, 26 Aug 2021 12:04:55 -0700 Subject: [PATCH 3/3] Eliminate wait on main thread for every network request --- .../src/Messages/MessageSender.swift | 2 +- .../src/Messages/UD/OWSUDManager.swift | 26 +++++++++---------- .../src/Network/WebSockets/OWSWebSocket.h | 2 +- .../src/Network/WebSockets/OWSWebSocket.m | 6 ++--- .../Network/WebSockets/SocketManager.swift | 8 ++---- 5 files changed, 19 insertions(+), 25 deletions(-) diff --git a/SignalServiceKit/src/Messages/MessageSender.swift b/SignalServiceKit/src/Messages/MessageSender.swift index 48626f98ba..937e28e4b0 100644 --- a/SignalServiceKit/src/Messages/MessageSender.swift +++ b/SignalServiceKit/src/Messages/MessageSender.swift @@ -574,7 +574,7 @@ extension MessageSender { // which recipients are unregistered. return firstly(on: .global()) { () -> Promise<[SignalServiceAddress]> in Self.ensureRecipientAddresses(sendInfo.recipients, message: message) - }.map { (validRecipients: [SignalServiceAddress]) in + }.map(on: .global()) { (validRecipients: [SignalServiceAddress]) in // Replace recipients with validRecipients. MessageSendInfo(thread: sendInfo.thread, recipients: validRecipients, diff --git a/SignalServiceKit/src/Messages/UD/OWSUDManager.swift b/SignalServiceKit/src/Messages/UD/OWSUDManager.swift index a6aea942a9..8dedec07bc 100644 --- a/SignalServiceKit/src/Messages/UD/OWSUDManager.swift +++ b/SignalServiceKit/src/Messages/UD/OWSUDManager.swift @@ -584,11 +584,11 @@ public class OWSUDManagerImpl: NSObject, OWSUDManager { public func ensureSenderCertificates(certificateExpirationPolicy: OWSUDCertificateExpirationPolicy, success: @escaping (SenderCertificates) -> Void, failure: @escaping (Error) -> Void) { - firstly { + firstly(on: .global()) { self.ensureSenderCertificates(certificateExpirationPolicy: certificateExpirationPolicy) - }.done { senderCertificates in + }.done(on: .global()) { senderCertificates in success(senderCertificates) - }.catch { error in + }.catch(on: .global()) { error in failure(error) } } @@ -600,7 +600,7 @@ public class OWSUDManagerImpl: NSObject, OWSUDManager { } let defaultPromise = ensureSenderCertificate(uuidOnly: false, certificateExpirationPolicy: certificateExpirationPolicy) let uuidOnlyPromise = ensureSenderCertificate(uuidOnly: true, certificateExpirationPolicy: certificateExpirationPolicy) - return firstly { + return firstly(on: .global()) { when(fulfilled: defaultPromise, uuidOnlyPromise) }.map(on: .global()) { defaultCert, uuidOnlyCert in return SenderCertificates(defaultCert: defaultCert, uuidOnlyCert: uuidOnlyCert) @@ -613,18 +613,18 @@ public class OWSUDManagerImpl: NSObject, OWSUDManager { return Promise.value(certificate) } - return firstly { - requestSenderCertificate(uuidOnly: uuidOnly) - }.map { (certificate: SenderCertificate) in + return firstly(on: .global()) { + self.requestSenderCertificate(uuidOnly: uuidOnly) + }.map(on: .global()) { (certificate: SenderCertificate) in self.setSenderCertificate(uuidOnly: uuidOnly, certificateData: Data(certificate.serialize())) return certificate } } private func requestSenderCertificate(uuidOnly: Bool) -> Promise { - return firstly { + return firstly(on: .global()) { SignalServiceRestClient().requestUDSenderCertificate(uuidOnly: uuidOnly) - }.map { certificateData -> SenderCertificate in + }.map(on: .global()) { certificateData -> SenderCertificate in let certificate = try SenderCertificate(certificateData) guard self.isValidCertificate(certificate) else { @@ -632,7 +632,7 @@ public class OWSUDManagerImpl: NSObject, OWSUDManager { } return certificate - }.recover { error -> Promise in + }.recover(on: .global()) { error -> Promise in throw error } } @@ -707,9 +707,9 @@ public class OWSUDManagerImpl: NSObject, OWSUDManager { } // Try to update the account attributes to reflect this change. - firstly { - tsAccountManager.updateAccountAttributes() - }.catch { error in + firstly(on: .global()) { + Self.tsAccountManager.updateAccountAttributes() + }.catch(on: .global()) { error in Logger.warn("Error: \(error)") } } diff --git a/SignalServiceKit/src/Network/WebSockets/OWSWebSocket.h b/SignalServiceKit/src/Network/WebSockets/OWSWebSocket.h index fc6c720f27..1bcf1248c5 100644 --- a/SignalServiceKit/src/Network/WebSockets/OWSWebSocket.h +++ b/SignalServiceKit/src/Network/WebSockets/OWSWebSocket.h @@ -31,7 +31,7 @@ typedef void (^TSSocketMessageFailure)(OWSHTTPErrorWrapper *failure); // TODO: Port to Swift. @interface OWSWebSocket : NSObject -@property (nonatomic, readonly) OWSWebSocketType webSocketType; +@property (atomic, readonly) OWSWebSocketType webSocketType; @property (nonatomic, readonly) OWSWebSocketState state; @property (nonatomic, readonly) BOOL hasEmptiedInitialQueue; @property (nonatomic, readonly) BOOL shouldSocketBeOpen; diff --git a/SignalServiceKit/src/Network/WebSockets/OWSWebSocket.m b/SignalServiceKit/src/Network/WebSockets/OWSWebSocket.m index b5d53b446f..4947d65174 100644 --- a/SignalServiceKit/src/Network/WebSockets/OWSWebSocket.m +++ b/SignalServiceKit/src/Network/WebSockets/OWSWebSocket.m @@ -91,7 +91,7 @@ NSString *NSStringForOWSWebSocketType(OWSWebSocketType value) // trying to keep the socket open), all three should be clear. // // This represents how long we're trying to keep the socket open. -@property (nonatomic, nullable) NSDate *backgroundKeepAliveUntilDate; +@property (atomic, nullable) NSDate *backgroundKeepAliveUntilDate; // This timer is used to check periodically whether we should // close the socket. @property (nonatomic, nullable) NSTimer *backgroundKeepAliveTimer; @@ -102,7 +102,7 @@ NSString *NSStringForOWSWebSocketType(OWSWebSocketType value) // We cache this value instead of consulting [UIApplication sharedApplication].applicationState, // because UIKit only provides a "will resign active" notification, not a "did resign active" // notification. -@property (nonatomic) BOOL appIsActive; +@property (atomic) BOOL appIsActive; @property (nonatomic) BOOL hasObservedNotifications; @@ -843,8 +843,6 @@ NSString *NSStringForOWSWebSocketType(OWSWebSocketType value) - (BOOL)shouldSocketBeOpen { - OWSAssertIsOnMainThread(); - // Don't open socket in app extensions. if (!CurrentAppContext().isMainApp) { if (SSKFeatureFlags.deprecateREST) { diff --git a/SignalServiceKit/src/Network/WebSockets/SocketManager.swift b/SignalServiceKit/src/Network/WebSockets/SocketManager.swift index b42b8cd726..3572f5c734 100644 --- a/SignalServiceKit/src/Network/WebSockets/SocketManager.swift +++ b/SignalServiceKit/src/Network/WebSockets/SocketManager.swift @@ -42,10 +42,6 @@ public class SocketManager: NSObject { private func waitForSocketToOpen(webSocketType: OWSWebSocketType, waitStartDate: Date = Date()) -> Promise { - // The socket state we consult in this method is not yet thread-safe, - // so we need to do this waiting on the main thread. - AssertIsOnMainThread() - let webSocket = self.webSocket(ofType: webSocketType) if webSocket.canMakeRequests { // The socket is open; proceed. @@ -64,7 +60,7 @@ public class SocketManager: NSObject { } return firstly(on: .global()) { after(seconds: kSecondInterval / 10) - }.then(on: .main) { + }.then(on: .global()) { self.waitForSocketToOpen(webSocketType: webSocketType, waitStartDate: waitStartDate) } @@ -104,7 +100,7 @@ public class SocketManager: NSObject { } } - return firstly(on: .main) { + return firstly(on: .global()) { self.waitForSocketToOpen(webSocketType: webSocketType) }.then(on: .global()) { () -> Promise in let (promise, resolver) = Promise.pending()