From ed30b15fdadfcc2fdc70a33f8c7e83e5d5753272 Mon Sep 17 00:00:00 2001 From: Matthew Chen Date: Wed, 6 Feb 2019 14:55:34 -0500 Subject: [PATCH 1/2] Add call setup time logging. --- Signal/src/call/CallService.swift | 27 ++++++++++++++++++++++----- 1 file changed, 22 insertions(+), 5 deletions(-) diff --git a/Signal/src/call/CallService.swift b/Signal/src/call/CallService.swift index b79b3d4a5..8de9dc8f8 100644 --- a/Signal/src/call/CallService.swift +++ b/Signal/src/call/CallService.swift @@ -106,6 +106,9 @@ protocol SignalCallDataDelegate: class { // Gather all per-call state in one place. private class SignalCallData: NSObject { + + let startTime: UInt64 + fileprivate weak var delegate: SignalCallDataDelegate? public let call: SignalCall @@ -154,8 +157,9 @@ private class SignalCallData: NSObject { } } - required init(call: SignalCall, delegate: SignalCallDataDelegate) { + required init(call: SignalCall, startTime: UInt64, delegate: SignalCallDataDelegate) { self.call = call + self.startTime = startTime self.delegate = delegate let (callConnectedPromise, callConnectedResolver) = Promise.pending() @@ -438,6 +442,8 @@ private class SignalCallData: NSObject { func handleOutgoingCall(_ call: SignalCall) -> Promise { AssertIsOnMainThread() + let startTime = NSDate.ows_millisecondTimeStamp() + guard self.call == nil else { let errorDescription = "call was unexpectedly already set." Logger.error(errorDescription) @@ -446,7 +452,7 @@ private class SignalCallData: NSObject { return Promise(error: CallError.assertionError(description: errorDescription)) } - let callData = SignalCallData(call: call, delegate: self) + let callData = SignalCallData(call: call, startTime: startTime, delegate: self) self.callData = callData // MJK TODO remove this timestamp param @@ -677,6 +683,8 @@ private class SignalCallData: NSObject { public func handleReceivedOffer(thread: TSContactThread, callId: UInt64, sessionDescription callerSessionDescription: String) { AssertIsOnMainThread() + let startTime = NSDate.ows_millisecondTimeStamp() + let newCall = SignalCall.incomingCall(localId: UUID(), remotePhoneNumber: thread.contactIdentifier(), signalingId: callId) Logger.info("receivedCallOffer: \(newCall.identifiersForLogs)") @@ -747,7 +755,7 @@ private class SignalCallData: NSObject { Logger.info("starting new call: \(newCall.identifiersForLogs)") - let callData = SignalCallData(call: newCall, delegate: self) + let callData = SignalCallData(call: newCall, startTime: startTime, delegate: self) self.callData = callData var backgroundTask: OWSBackgroundTask? = OWSBackgroundTask(label: "\(#function)", completionBlock: { [weak self] status in @@ -972,20 +980,29 @@ private class SignalCallData: NSObject { private func handleIceConnected() { AssertIsOnMainThread() - guard let call = self.call else { + guard let callData = self.callData else { // This will only be called for the current peerConnectionClient, so // fail the current call. OWSProdError(OWSAnalyticsEvents.callServiceCallMissing(), file: #file, function: #function, line: #line) handleFailedCurrentCall(error: CallError.assertionError(description: "ignoring \(#function) since there is no current call.")) return } + let call = callData.call - Logger.info("\(call.identifiersForLogs).") + Logger.info("\(call.identifiersForLogs)") switch call.state { case .dialing: + if call.state != .remoteRinging { + let connectedTime = NSDate.ows_millisecondTimeStamp() + Logger.info("Connected in: \(connectedTime - callData.startTime)") + } call.state = .remoteRinging case .answering: + if call.state != .localRinging { + let connectedTime = NSDate.ows_millisecondTimeStamp() + Logger.info("Connected in: \(connectedTime - callData.startTime)") + } call.state = .localRinging self.callUIAdapter.reportIncomingCall(call, thread: call.thread) case .remoteRinging: From d62fa19cb521f40a46ba54ef45f6176d81010161 Mon Sep 17 00:00:00 2001 From: Matthew Chen Date: Tue, 12 Feb 2019 09:34:24 -0500 Subject: [PATCH 2/2] Respond to CR. --- Signal/src/call/CallService.swift | 21 +++++++++------------ 1 file changed, 9 insertions(+), 12 deletions(-) diff --git a/Signal/src/call/CallService.swift b/Signal/src/call/CallService.swift index 8de9dc8f8..197561c7c 100644 --- a/Signal/src/call/CallService.swift +++ b/Signal/src/call/CallService.swift @@ -107,8 +107,6 @@ protocol SignalCallDataDelegate: class { // Gather all per-call state in one place. private class SignalCallData: NSObject { - let startTime: UInt64 - fileprivate weak var delegate: SignalCallDataDelegate? public let call: SignalCall @@ -157,9 +155,8 @@ private class SignalCallData: NSObject { } } - required init(call: SignalCall, startTime: UInt64, delegate: SignalCallDataDelegate) { + required init(call: SignalCall, delegate: SignalCallDataDelegate) { self.call = call - self.startTime = startTime self.delegate = delegate let (callConnectedPromise, callConnectedResolver) = Promise.pending() @@ -442,7 +439,8 @@ private class SignalCallData: NSObject { func handleOutgoingCall(_ call: SignalCall) -> Promise { AssertIsOnMainThread() - let startTime = NSDate.ows_millisecondTimeStamp() + let callId = call.signalingId + BenchEventStart(title: "Outgoing Call Connection", eventId: "call-\(callId)") guard self.call == nil else { let errorDescription = "call was unexpectedly already set." @@ -452,7 +450,7 @@ private class SignalCallData: NSObject { return Promise(error: CallError.assertionError(description: errorDescription)) } - let callData = SignalCallData(call: call, startTime: startTime, delegate: self) + let callData = SignalCallData(call: call, delegate: self) self.callData = callData // MJK TODO remove this timestamp param @@ -683,7 +681,7 @@ private class SignalCallData: NSObject { public func handleReceivedOffer(thread: TSContactThread, callId: UInt64, sessionDescription callerSessionDescription: String) { AssertIsOnMainThread() - let startTime = NSDate.ows_millisecondTimeStamp() + BenchEventStart(title: "Incoming Call Connection", eventId: "call-\(callId)") let newCall = SignalCall.incomingCall(localId: UUID(), remotePhoneNumber: thread.contactIdentifier(), signalingId: callId) @@ -755,7 +753,7 @@ private class SignalCallData: NSObject { Logger.info("starting new call: \(newCall.identifiersForLogs)") - let callData = SignalCallData(call: newCall, startTime: startTime, delegate: self) + let callData = SignalCallData(call: newCall, delegate: self) self.callData = callData var backgroundTask: OWSBackgroundTask? = OWSBackgroundTask(label: "\(#function)", completionBlock: { [weak self] status in @@ -988,20 +986,19 @@ private class SignalCallData: NSObject { return } let call = callData.call + let callId = call.signalingId Logger.info("\(call.identifiersForLogs)") switch call.state { case .dialing: if call.state != .remoteRinging { - let connectedTime = NSDate.ows_millisecondTimeStamp() - Logger.info("Connected in: \(connectedTime - callData.startTime)") + BenchEventComplete(eventId: "call-\(callId)") } call.state = .remoteRinging case .answering: if call.state != .localRinging { - let connectedTime = NSDate.ows_millisecondTimeStamp() - Logger.info("Connected in: \(connectedTime - callData.startTime)") + BenchEventComplete(eventId: "call-\(callId)") } call.state = .localRinging self.callUIAdapter.reportIncomingCall(call, thread: call.thread)