From efe8b73c76d623595c5e7c0e64fd914e2b6a207c Mon Sep 17 00:00:00 2001 From: Stefan Ceriu Date: Tue, 5 Apr 2022 10:01:16 +0300 Subject: [PATCH] Added methods for tracking call durations. --- ElementX.xcodeproj/project.pbxproj | 6 ++ ElementX/Sources/AppCoordinator.swift | 6 ++ ElementX/Sources/Other/Benchmark.swift | 64 +++++++++++++++++++ ElementX/Sources/Other/MXLog.swift | 2 +- .../AuthenticationCoordinator.swift | 3 + .../Services/Authentication/UserSession.swift | 9 +++ .../Sources/Services/Room/RoomProxy.swift | 6 +- 7 files changed, 94 insertions(+), 2 deletions(-) create mode 100644 ElementX/Sources/Other/Benchmark.swift diff --git a/ElementX.xcodeproj/project.pbxproj b/ElementX.xcodeproj/project.pbxproj index 2ce10d515..b62f015ad 100644 --- a/ElementX.xcodeproj/project.pbxproj +++ b/ElementX.xcodeproj/project.pbxproj @@ -16,6 +16,7 @@ 182BC48127C4EBBB00A30C33 /* Kingfisher in Frameworks */ = {isa = PBXBuildFile; productRef = 182BC48027C4EBBB00A30C33 /* Kingfisher */; }; 183E023427E4A73C00903BED /* MemberDetailsProviderProtocol.swift in Sources */ = {isa = PBXBuildFile; fileRef = 183E023327E4A73C00903BED /* MemberDetailsProviderProtocol.swift */; }; 183E023627E4A79D00903BED /* RoomTimelineProviderProtocol.swift in Sources */ = {isa = PBXBuildFile; fileRef = 183E023527E4A79D00903BED /* RoomTimelineProviderProtocol.swift */; }; + 184858EB27FAF6D300B8AC7B /* Benchmark.swift in Sources */ = {isa = PBXBuildFile; fileRef = 184858EA27FAF6D300B8AC7B /* Benchmark.swift */; }; 184B31DF27D898960075A669 /* Introspect in Frameworks */ = {isa = PBXBuildFile; productRef = 184B31DE27D898960075A669 /* Introspect */; }; 1850253F27B6918D002E6B18 /* ElementXTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 1850253E27B6918D002E6B18 /* ElementXTests.swift */; }; 1850254927B6918D002E6B18 /* ElementXUITests.swift in Sources */ = {isa = PBXBuildFile; fileRef = 1850254827B6918D002E6B18 /* ElementXUITests.swift */; }; @@ -156,6 +157,7 @@ 181A317E27F70CCA00B8305B /* EventBriefFactoryProtocol.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = EventBriefFactoryProtocol.swift; sourceTree = ""; }; 183E023327E4A73C00903BED /* MemberDetailsProviderProtocol.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = MemberDetailsProviderProtocol.swift; sourceTree = ""; }; 183E023527E4A79D00903BED /* RoomTimelineProviderProtocol.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = RoomTimelineProviderProtocol.swift; sourceTree = ""; }; + 184858EA27FAF6D300B8AC7B /* Benchmark.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = Benchmark.swift; sourceTree = ""; }; 1850252427B6918C002E6B18 /* ElementX.app */ = {isa = PBXFileReference; explicitFileType = wrapper.application; includeInIndex = 0; path = ElementX.app; sourceTree = BUILT_PRODUCTS_DIR; }; 1850253A27B6918D002E6B18 /* ElementXTests.xctest */ = {isa = PBXFileReference; explicitFileType = wrapper.cfbundle; includeInIndex = 0; path = ElementXTests.xctest; sourceTree = BUILT_PRODUCTS_DIR; }; 1850253E27B6918D002E6B18 /* ElementXTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = ElementXTests.swift; sourceTree = ""; }; @@ -186,6 +188,7 @@ 18ADC80427EB1ED100A8C953 /* UIFont+AttributedStringBuilder.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = "UIFont+AttributedStringBuilder.m"; sourceTree = ""; }; 18ADC80527EB1ED100A8C953 /* UIFont+AttributedStringBuilder.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = "UIFont+AttributedStringBuilder.h"; sourceTree = ""; }; 18ADC80727EB1EE200A8C953 /* ElementX-Bridging-Header.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = "ElementX-Bridging-Header.h"; sourceTree = ""; }; + 18BB170627FB74B30074CBD6 /* matrix-rust-components-swift */ = {isa = PBXFileReference; lastKnownFileType = wrapper; name = "matrix-rust-components-swift"; path = "../matrix-rust-components-swift"; sourceTree = ""; }; 18C5744827E1D84000D70937 /* RoomProxyProtocol.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = RoomProxyProtocol.swift; sourceTree = ""; }; 18C5744A27E1D84000D70937 /* RoomProxy.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = RoomProxy.swift; sourceTree = ""; }; 18C5744B27E1D84000D70937 /* MockRoomProxy.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = MockRoomProxy.swift; sourceTree = ""; }; @@ -318,6 +321,7 @@ 1850251B27B6918C002E6B18 = { isa = PBXGroup; children = ( + 18BB170627FB74B30074CBD6 /* matrix-rust-components-swift */, 1850252627B6918C002E6B18 /* ElementX */, 1850253D27B6918D002E6B18 /* ElementXTests */, 1850254727B6918D002E6B18 /* ElementXUITests */, @@ -532,6 +536,7 @@ 18F2BA7D27D25B4000DD1988 /* Other */ = { isa = PBXGroup; children = ( + 184858EA27FAF6D300B8AC7B /* Benchmark.swift */, 18920C1827F3222E00A717B5 /* Colors.swift */, 18F2BA9A27D25B4000DD1988 /* Coordinator.swift */, 18DDB72D27EF936D000F1ABF /* MatrixEntitityRegex.swift */, @@ -999,6 +1004,7 @@ 181A317927F703E300B8305B /* MockRoomSummary.swift in Sources */, 1850256F27B6A135002E6B18 /* AppDelegate.swift in Sources */, 18F2BAE627D25B4000DD1988 /* NavigationRouterType.swift in Sources */, + 184858EB27FAF6D300B8AC7B /* Benchmark.swift in Sources */, 18F2BAE927D25B4000DD1988 /* ActivityPresentable.swift in Sources */, 18DDB72727EC78B8000F1ABF /* AttributedStringBuilderProtocol.swift in Sources */, 18DF7C4327E4670600291672 /* RoomTimelineItemProtocol.swift in Sources */, diff --git a/ElementX/Sources/AppCoordinator.swift b/ElementX/Sources/AppCoordinator.swift index d2563ed69..490a54690 100644 --- a/ElementX/Sources/AppCoordinator.swift +++ b/ElementX/Sources/AppCoordinator.swift @@ -43,6 +43,12 @@ class AppCoordinator: AuthenticationCoordinatorDelegate, Coordinator { authenticationCoordinator = AuthenticationCoordinator(keychainController: keychainController, navigationRouter: navigationRouter) authenticationCoordinator.delegate = self + + let loggerConfiguration = MXLogConfiguration() + loggerConfiguration.logLevel = .verbose + MXLog.configure(loggerConfiguration) + + // Benchmark.trackingEnabled = true } func start() { diff --git a/ElementX/Sources/Other/Benchmark.swift b/ElementX/Sources/Other/Benchmark.swift new file mode 100644 index 000000000..37ebdf93d --- /dev/null +++ b/ElementX/Sources/Other/Benchmark.swift @@ -0,0 +1,64 @@ +// +// Benchmark.swift +// ElementX +// +// Created by Stefan Ceriu on 04/04/2022. +// Copyright © 2022 Element. All rights reserved. +// + +import Foundation + +struct Benchmark { + static private var trackingIdentifiers = [String: CFAbsoluteTime]() + + static public var trackingEnabled = false + + static func startTrackingForIdentifier(_ identifier: String, message: String? = nil) { + guard trackingEnabled else { + return + } + + let startTime = CFAbsoluteTimeGetCurrent() + trackingIdentifiers[identifier] = startTime + + if let message = message { + MXLog.verbose("⏰ Tracking \(identifier). \(message).") + } else { + MXLog.verbose("⏰ Tracking \(identifier).") + } + } + + static func logElapsedDurationForIdentifier(_ identifier: String, message: String? = nil) { + guard trackingEnabled else { + return + } + + guard let start = trackingIdentifiers[identifier] else { + assertionFailure("⏰ Invalid tracking identifier") + return + } + + let elapsedTime = CFAbsoluteTimeGetCurrent() - start + if let message = message { + MXLog.verbose("⏰ Tracking \(identifier). \(message). Elapsed time: \(elapsedTime.round(to: 4)) seconds.") + } else { + MXLog.verbose("⏰ Tracking \(identifier). Elapsed time: \(elapsedTime.round(to: 4)) seconds.") + } + } + + static func endTrackingForIdentifier(_ identifier: String, message: String? = nil) { + guard trackingEnabled else { + return + } + + logElapsedDurationForIdentifier(identifier, message: message) + trackingIdentifiers[identifier] = nil + } +} + +private extension Double { + func round(to places: Int) -> Double { + let divisor = pow(10.0, Double(places)) + return (self * divisor).rounded() / divisor + } +} diff --git a/ElementX/Sources/Other/MXLog.swift b/ElementX/Sources/Other/MXLog.swift index 0afea7e62..d9921e12c 100644 --- a/ElementX/Sources/Other/MXLog.swift +++ b/ElementX/Sources/Other/MXLog.swift @@ -151,7 +151,7 @@ private var logger: SwiftyBeaver.Type = { let consoleDestination = ConsoleDestination() consoleDestination.useNSLog = true consoleDestination.asynchronously = false - consoleDestination.format = "$C $N.$F():$l $M" + consoleDestination.format = "$N.$F:$l $M" consoleDestination.levelColor.verbose = "" consoleDestination.levelColor.debug = "" consoleDestination.levelColor.info = "" diff --git a/ElementX/Sources/Services/Authentication/AuthenticationCoordinator.swift b/ElementX/Sources/Services/Authentication/AuthenticationCoordinator.swift index ed0c58bd1..cdfe69832 100644 --- a/ElementX/Sources/Services/Authentication/AuthenticationCoordinator.swift +++ b/ElementX/Sources/Services/Authentication/AuthenticationCoordinator.swift @@ -123,6 +123,7 @@ class AuthenticationCoordinator: Coordinator { } private func login(username: String, password: String, completion: @escaping (Result) -> Void) { + Benchmark.startTrackingForIdentifier("Login", message: "Started new login") delegate?.authenticationCoordinatorDidStartLoading(self) @@ -148,6 +149,7 @@ class AuthenticationCoordinator: Coordinator { } private func restorePreviousLogin(_ usernameTokenTuple: (username: String, token: String), completion: @escaping (Result) -> Void) { + Benchmark.startTrackingForIdentifier("Login", message: "Started restoring previous login") delegate?.authenticationCoordinatorDidStartLoading(self) @@ -172,6 +174,7 @@ class AuthenticationCoordinator: Coordinator { } private func setupUserSessionForClient(_ client: Client) { + Benchmark.endTrackingForIdentifier("Login", message: "Finished login") do { let restoreToken = try client.restoreToken() diff --git a/ElementX/Sources/Services/Authentication/UserSession.swift b/ElementX/Sources/Services/Authentication/UserSession.swift index 34c3702cb..0e85cefae 100644 --- a/ElementX/Sources/Services/Authentication/UserSession.swift +++ b/ElementX/Sources/Services/Authentication/UserSession.swift @@ -54,6 +54,8 @@ class UserSession: ClientDelegate { self.mediaProvider = MediaProvider(client: client, imageCache: ImageCache.default) client.setDelegate(delegate: WeakUserSessionWrapper(userSession: self)) + + Benchmark.startTrackingForIdentifier("ClientSync", message: "Started sync.") client.startSync() updateRooms() @@ -89,6 +91,7 @@ class UserSession: ClientDelegate { // MARK: ClientDelegate func didReceiveSyncUpdate() { + Benchmark.logElapsedDurationForIdentifier("ClientSync", message: "Received sync update") updateRooms() } @@ -101,7 +104,11 @@ class UserSession: ClientDelegate { return } + Benchmark.startTrackingForIdentifier("ClientRooms", message: "Fetching available rooms") let sdkRooms = self.client.rooms() + Benchmark.endTrackingForIdentifier("ClientRooms", message: "Retrieved \(sdkRooms.count) rooms") + + Benchmark.startTrackingForIdentifier("ProcessingRooms", message: "Started processing \(sdkRooms.count) rooms") let diff = sdkRooms.map({ $0.id()}).difference(from: currentRooms.map({ $0.id })) for change in diff { @@ -117,6 +124,8 @@ class UserSession: ClientDelegate { } } + Benchmark.endTrackingForIdentifier("ProcessingRooms", message: "Finished processing \(sdkRooms.count) rooms") + DispatchQueue.main.async { self.rooms = currentRooms } diff --git a/ElementX/Sources/Services/Room/RoomProxy.swift b/ElementX/Sources/Services/Room/RoomProxy.swift index 8f5cbeb73..f63dc6f64 100644 --- a/ElementX/Sources/Services/Room/RoomProxy.swift +++ b/ElementX/Sources/Services/Room/RoomProxy.swift @@ -150,7 +150,11 @@ class RoomProxy: RoomProxyProtocol { return } - let messages = backwardStream.paginateBackwards(count: UInt64(count)).map { message in + Benchmark.startTrackingForIdentifier("BackPagination \(self.id)", message: "Backpaginating \(count) message(s) in room \(self.id)") + let sdkMessages = backwardStream.paginateBackwards(count: UInt64(count)) + Benchmark.endTrackingForIdentifier("BackPagination \(self.id)", message: "Finished backpaginating \(count) message(s) in room \(self.id)") + + let messages = sdkMessages.map { message in self.messageFactory.buildRoomMessageFrom(message) }.reversed()