Added methods for tracking call durations.

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 = "<group>"; };
 		183E023327E4A73C00903BED /* MemberDetailsProviderProtocol.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = MemberDetailsProviderProtocol.swift; sourceTree = "<group>"; };
 		183E023527E4A79D00903BED /* RoomTimelineProviderProtocol.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = RoomTimelineProviderProtocol.swift; sourceTree = "<group>"; };
+		184858EA27FAF6D300B8AC7B /* Benchmark.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = Benchmark.swift; sourceTree = "<group>"; };
 		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 = "<group>"; };
@@ -186,6 +188,7 @@
 		18ADC80427EB1ED100A8C953 /* UIFont+AttributedStringBuilder.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = "UIFont+AttributedStringBuilder.m"; sourceTree = "<group>"; };
 		18ADC80527EB1ED100A8C953 /* UIFont+AttributedStringBuilder.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = "UIFont+AttributedStringBuilder.h"; sourceTree = "<group>"; };
 		18ADC80727EB1EE200A8C953 /* ElementX-Bridging-Header.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = "ElementX-Bridging-Header.h"; sourceTree = "<group>"; };
+		18BB170627FB74B30074CBD6 /* matrix-rust-components-swift */ = {isa = PBXFileReference; lastKnownFileType = wrapper; name = "matrix-rust-components-swift"; path = "../matrix-rust-components-swift"; sourceTree = "<group>"; };
 		18C5744827E1D84000D70937 /* RoomProxyProtocol.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = RoomProxyProtocol.swift; sourceTree = "<group>"; };
 		18C5744A27E1D84000D70937 /* RoomProxy.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = RoomProxy.swift; sourceTree = "<group>"; };
 		18C5744B27E1D84000D70937 /* MockRoomProxy.swift */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.swift; path = MockRoomProxy.swift; sourceTree = "<group>"; };
@@ -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 */,

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() {

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
+    }
+}

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 = ""

ElementX/Sources/Services/Authentication/AuthenticationCoordinator.swift

@@ -123,6 +123,7 @@ class AuthenticationCoordinator: Coordinator {
     }
     
     private func login(username: String, password: String, completion: @escaping (Result<Void, AuthenticationCoordinatorError>) -> 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, AuthenticationCoordinatorError>) -> 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()

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
             }

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()