[#1108] Instrument rust backend tracing (#1109)

* [#1108] Instrument rust backend tracing

This adds a parameter to the `Initializer` constructor that allows
developers to turn on performance trancing tooling on the Rust
backend. It can't be disabled on the fly. It's either OFF or ON
all the life-span for the Synchronizer.

Closes #1108

Update ffi framework commit hash

* update resolved filed

Example/ZcashLightClientSample/ZcashLightClientSample.xcodeproj/project.xcworkspace/xcshareddata/swiftpm/Package.resolved

@@ -158,8 +158,7 @@
       "kind" : "remoteSourceControl",
       "location" : "https://github.com/zcash-hackworks/zcash-light-client-ffi",
       "state" : {
-        "revision" : "75821e2b859600707318e4a788abbe27e6615833",
-        "version" : "0.3.1"
+        "revision" : "cdbc06f10b2d7cbe0d6362b30f68167825942e86"
       }
     }
   ],

Example/ZcashLightClientSample/ZcashLightClientSample/AppDelegate.swift

@@ -51,7 +51,8 @@ class AppDelegate: UIResponder, UIApplicationDelegate {
                 network: kZcashNetwork,
                 spendParamsURL: try! spendParamsURLHelper(),
                 outputParamsURL: try! outputParamsURLHelper(),
-                saplingParamsSourceURL: SaplingParamsSourceURL.default
+                saplingParamsSourceURL: SaplingParamsSourceURL.default,
+                enableBackendTracing: true
             )
            
             self.wallet = wallet

Example/ZcashLightClientSample/ZcashLightClientSample/Sync Blocks/SyncBlocksListViewController.swift

@@ -111,7 +111,8 @@ class SyncBlocksListViewController: UIViewController {
             outputParamsURL: try! outputParamsURLHelper(),
             saplingParamsSourceURL: SaplingParamsSourceURL.default,
             alias: data.alias,
-            loggingPolicy: .default(.debug)
+            loggingPolicy: .default(.debug),
+            enableBackendTracing: true
         )
 
         return SDKSynchronizer(initializer: initializer)

Example/ZcashLightClientSample/ZcashLightClientSample/Sync Blocks/SyncBlocksViewController.swift

@@ -151,11 +151,16 @@ class SyncBlocksViewController: UIViewController {
             do {
                 if syncStatus == .unprepared {
                     // swiftlint:disable:next force_try
-                    _ = try! await synchronizer.prepare(
+                    do {
+                        _ = try await synchronizer.prepare(
                             with: DemoAppConfig.defaultSeed,
                             viewingKeys: [AppDelegate.shared.sharedViewingKey],
                             walletBirthday: DemoAppConfig.defaultBirthdayHeight
                         )
+                    } catch {
+                        loggerProxy.error(error.toZcashError().message)
+                        fatalError(error.toZcashError().message)
+                    }
                 }
 
                 synchronizer.metrics.enableMetrics()

Package.resolved

@@ -104,8 +104,7 @@
       "kind" : "remoteSourceControl",
       "location" : "https://github.com/zcash-hackworks/zcash-light-client-ffi",
       "state" : {
-        "revision" : "75821e2b859600707318e4a788abbe27e6615833",
-        "version" : "0.3.1"
+        "revision" : "cdbc06f10b2d7cbe0d6362b30f68167825942e86"
       }
     }
   ],

Package.swift

@@ -16,7 +16,7 @@ let package = Package(
     dependencies: [
         .package(url: "https://github.com/grpc/grpc-swift.git", from: "1.14.0"),
         .package(url: "https://github.com/stephencelis/SQLite.swift.git", from: "0.14.1"),
-        .package(url: "https://github.com/zcash-hackworks/zcash-light-client-ffi", from: "0.3.1")
+        .package(url: "https://github.com/zcash-hackworks/zcash-light-client-ffi", revision: "cdbc06f10b2d7cbe0d6362b30f68167825942e86")
     ],
     targets: [
         .target(

Sources/ZcashLightClientKit/Initializer.swift

@@ -146,6 +146,8 @@ public class Initializer {
     ///  - endpoint: the endpoint representing the lightwalletd instance you want to point to
     ///  - spendParamsURL: location of the spend parameters
     ///  - outputParamsURL: location of the output parameters
+    ///  - loggingPolicy: the `LoggingPolicy` for the logger
+    ///  - enableBackendTracing: this enables tracing for super detailed debugging. it will slow down everything 10 or 100x.
     convenience public init(
         cacheDbURL: URL?,
         fsBlockDbRoot: URL,
@@ -156,7 +158,8 @@ public class Initializer {
         outputParamsURL: URL,
         saplingParamsSourceURL: SaplingParamsSourceURL,
         alias: ZcashSynchronizerAlias = .default,
-        loggingPolicy: LoggingPolicy = .default(.debug)
+        loggingPolicy: LoggingPolicy = .default(.debug),
+        enableBackendTracing: Bool = false
     ) {
         let container = DIContainer()
         
@@ -173,7 +176,8 @@ public class Initializer {
             outputParamsURL: outputParamsURL,
             saplingParamsSourceURL: saplingParamsSourceURL,
             alias: alias,
-            loggingPolicy: loggingPolicy
+            loggingPolicy: loggingPolicy,
+            enableBackendTracing: enableBackendTracing
         )
         
         self.init(
@@ -201,7 +205,8 @@ public class Initializer {
         outputParamsURL: URL,
         saplingParamsSourceURL: SaplingParamsSourceURL,
         alias: ZcashSynchronizerAlias = .default,
-        loggingPolicy: LoggingPolicy = .default(.debug)
+        loggingPolicy: LoggingPolicy = .default(.debug),
+        enableBackendTracing: Bool = false
     ) {
         // It's not possible to fail from constructor. Technically it's possible but it can be pain for the client apps to handle errors thrown
         // from constructor. So `parsingError` is just stored in initializer and `SDKSynchronizer.prepare()` throw this error if it exists.
@@ -216,7 +221,8 @@ public class Initializer {
             outputParamsURL: outputParamsURL,
             saplingParamsSourceURL: saplingParamsSourceURL,
             alias: alias,
-            loggingPolicy: loggingPolicy
+            loggingPolicy: loggingPolicy,
+            enableBackendTracing: enableBackendTracing
         )
 
         self.init(
@@ -285,7 +291,8 @@ public class Initializer {
         outputParamsURL: URL,
         saplingParamsSourceURL: SaplingParamsSourceURL,
         alias: ZcashSynchronizerAlias,
-        loggingPolicy: LoggingPolicy = .default(.debug)
+        loggingPolicy: LoggingPolicy = .default(.debug),
+        enableBackendTracing: Bool = false
     ) -> (URLs, ZcashError?) {
         let urls = URLs(
             fsBlockDbRoot: fsBlockDbRoot,
@@ -304,7 +311,8 @@ public class Initializer {
             alias: alias,
             networkType: network.networkType,
             endpoint: endpoint,
-            loggingPolicy: loggingPolicy
+            loggingPolicy: loggingPolicy,
+            enableBackendTracing: enableBackendTracing
         )
         
         return (updatedURLs, parsingError)

Sources/ZcashLightClientKit/Rust/ZcashRustBackend.swift

@@ -21,6 +21,7 @@ actor ZcashRustBackend: ZcashRustBackendWelding {
 
     nonisolated let networkType: NetworkType
 
+    static var tracingEnabled = false
     /// Creates instance of `ZcashRustBackend`.
     /// - Parameters:
     ///   - dbData: `URL` pointing to file where data database will be.
@@ -30,13 +31,20 @@ actor ZcashRustBackend: ZcashRustBackendWelding {
     ///   - spendParamsPath: `URL` pointing to spend parameters file.
     ///   - outputParamsPath: `URL` pointing to output parameters file.
     ///   - networkType: Network type to use.
-    init(dbData: URL, fsBlockDbRoot: URL, spendParamsPath: URL, outputParamsPath: URL, networkType: NetworkType) {
+    ///   - enableTracing: this sets up whether the tracing system will dump logs onto the OSLogger system or not.
+    ///   **Important note:** this will enable the tracing **for all instances** of ZcashRustBackend, not only for this one.
+    init(dbData: URL, fsBlockDbRoot: URL, spendParamsPath: URL, outputParamsPath: URL, networkType: NetworkType, enableTracing: Bool = false) {
         self.dbData = dbData.osStr()
         self.fsBlockDbRoot = fsBlockDbRoot.osPathStr()
         self.spendParamsPath = spendParamsPath.osPathStr()
         self.outputParamsPath = outputParamsPath.osPathStr()
         self.networkType = networkType
         self.keyDeriving = ZcashKeyDerivationBackend(networkType: networkType)
+
+        if enableTracing && !Self.tracingEnabled {
+            Self.tracingEnabled = true
+            Self.enableTracing()
+        }
     }
 
     func createAccount(seed: [UInt8]) async throws -> UnifiedSpendingKey {
@@ -562,6 +570,12 @@ actor ZcashRustBackend: ZcashRustBackendWelding {
     }
 }
 
+private extension ZcashRustBackend {
+    static func enableTracing() {
+        zcashlc_init_on_load()
+    }
+}
+
 private extension ZcashRustBackend {
     nonisolated func lastErrorMessage(fallback: String) -> String {
         let errorLen = zcashlc_last_error_length()

Sources/ZcashLightClientKit/Synchronizer/Dependencies.swift

@@ -14,7 +14,8 @@ enum Dependencies {
         alias: ZcashSynchronizerAlias,
         networkType: NetworkType,
         endpoint: LightWalletEndpoint,
-        loggingPolicy: Initializer.LoggingPolicy = .default(.debug)
+        loggingPolicy: Initializer.LoggingPolicy = .default(.debug),
+        enableBackendTracing: Bool = false
     ) {
         container.register(type: Logger.self, isSingleton: true) { _ in
             let logger: Logger
@@ -36,7 +37,8 @@ enum Dependencies {
                 fsBlockDbRoot: urls.fsBlockDbRoot,
                 spendParamsPath: urls.spendParamsURL,
                 outputParamsPath: urls.outputParamsURL,
-                networkType: networkType
+                networkType: networkType,
+                enableTracing: enableBackendTracing
             )
         }
 

docs/testing/Performance.md

@@ -1,4 +1,6 @@
 # Performance Testing
+
+## Using `SDKMetrics`
 ### Intro
 Benchmarking the SDK is one of the key focuses of `SDKMetrics` API. The most important operation of the SDK is the ability to synchronize blocks in order to see transactions, right balances and to send & receive funds. In short, be in sync with the mainnet blockchain. Synchronization consists of several sub-operations like downloading the blocks, validating & scanning, etc.
 
@@ -114,3 +116,26 @@ totalSyncTimes: min: 7.222689986228943 max: 10.718868017196655 avg: 8.9970629364
 
 ### Performance tests
 We encourage you to visit `Tests/PerformanceTests/` folder and check `SynchronizerTests` where we do exactly what is mentioned in this doc. We run synchronization for specific range of 100 blocks 5 times, measure every run separately and merge results together in the end. The `SDKMetrics` and `SynchronizerTests` lay down foundations for the future automatization of performance testing.
+
+## Fine-grained tunning with `os_signpost` from `zcashlc`
+
+Besides `SDKMetrics`, developers can also check specific `os_signpost` calls enabled inside the 
+rust backend. 
+
+**Note:** This might degrade overall app performance a bit but will bring up exact numbers on what's going on
+while scanning blocks under the hood. 
+
+### Enabling tracing
+To achieve this the SDK must initialized passing `true` to Initializer's `enableBackendTracing` parameter.
+
+### Disabling tracing
+At the moment tracing can't be disabled in runtime. It's either ON or OFF. Synchronizer must be started with the tracing 
+argument defined as `false`.
+
+### viewing metrics
+
+Tracing leverages `OSSignpost` APIs and `OSLogger`. Those can be viewed on Instruments by using the
+"os_signpost" instrument.
+
+We added a profiling templates into the `Tools/` folder called `Zcash-SyncTime-Profiler` for our
+convenience, but you are free to use whatever you choose.