Merge pull request #1327 from LukasKorba/1325-Log-metrics

the logger has been extended to log the level as well there is only partial match of levels between SDK logger levels, OSLogEntryLogLevel and OSLogType so only debug, info, error are fully matched this is a base for the exporter on client's side Scan & Enhance logs added checkpoints updated every CBP action is measured separately and collects the data, when the sync is done it dumps overview of the run to the logger next run clears out the previous data and starts to collect fresh reports for the run
Electric-Coin-Company · Dec 12, 2023 · ad6ac80 · ad6ac80
2 parents 5644f89 + 3e263f0
commit ad6ac80
Show file tree

Hide file tree

Showing 60 changed files with 600 additions and 556 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -4,6 +4,35 @@ All notable changes to this library will be documented in this file.
 The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 and this library adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
+# Unreleased
+
+## Changed
+The `SDKMetrics` logs data using os_log. The public API `enableMetrics()` and `disableMetrics()` no longer exist. All metrics are automatically logged for every sync run. Extraction of the metrics is up to the client/dev - done by using `OSLogStore`. 
+
+## Added
+
+### [#1325] Log metrics
+The sync process is measured and detailed metrics are logged for every sync run. The data are logged using os_log so any client can export it. Verbose logs are under `sdkLogs_default` category, `default` level. Sync specific logs use `error` level. 
+
+## Checkpoints
+
+Mainnet
+
+````
+Sources/ZcashLightClientKit/Resources/checkpoints/mainnet/2270000.json
+...
+Sources/ZcashLightClientKit/Resources/checkpoints/mainnet/2327500.json
+````
+
+
+Testnet
+
+````
+Sources/ZcashLightClientKit/Resources/checkpoints/testnet/2560000.json
+...
+Sources/ZcashLightClientKit/Resources/checkpoints/testnet/2620000.json
+````
+
 # 2.0.3 - 2023-10-20
 
 ## Fixed

diff --git a/.../ZcashLightClientSample/ZcashLightClientSample/Sync Blocks/SyncBlocksViewController.swift b/.../ZcashLightClientSample/ZcashLightClientSample/Sync Blocks/SyncBlocksViewController.swift
@@ -24,16 +24,6 @@ class SyncBlocksViewController: UIViewController {
     private var queue = DispatchQueue(label: "metrics.queue", qos: .default)
     private var enhancingStarted = false
     private var accumulatedMetrics: ProcessorMetrics = .initial
-    private var currentMetric: SDKMetrics.Operation?
-    private var currentMetricName: String {
-        guard let currentMetric else { return "" }
-        switch currentMetric {
-        case .downloadBlocks: return "download: "
-        case .scanBlocks: return "scan: "
-        case .enhancement: return "enhancement: "
-        case .fetchUTXOs: return "fetchUTXOs: "
-        }
-    }
 
     var cancellables: [AnyCancellable] = []
     let dateFormatter = DateFormatter()
@@ -88,50 +78,14 @@ class SyncBlocksViewController: UIViewController {
             """
             progressDataLabel.text = progressText
 
-            if let currentMetric {
-                let report = synchronizer.metrics.popBlock(operation: currentMetric)?.last
-                metricLabel.text = currentMetricName + report.debugDescription
-            }
-
         case .upToDate, .stopped:
-            accumulateMetrics()
             summaryLabel.text = "enhancement: \(accumulatedMetrics.debugDescription)"
-            overallSummary()
 
         case .error:
             break
         }
     }
 
-    func accumulateMetrics() {
-        guard let currentMetric else { return }
-        if let reports = synchronizer.metrics.popBlock(operation: currentMetric) {
-            for report in reports {
-                accumulatedMetrics = .accumulate(accumulatedMetrics, current: report)
-            }
-        }
-    }
-
-    func overallSummary() {
-        let cumulativeSummary = synchronizer.metrics.cumulativeSummary()
-
-        let downloadedBlocksReport = cumulativeSummary.downloadedBlocksReport ?? SDKMetrics.ReportSummary.zero
-        let scannedBlocksReport = cumulativeSummary.scannedBlocksReport ?? SDKMetrics.ReportSummary.zero
-        let enhancementReport = cumulativeSummary.enhancementReport ?? SDKMetrics.ReportSummary.zero
-        let fetchUTXOsReport = cumulativeSummary.fetchUTXOsReport ?? SDKMetrics.ReportSummary.zero
-        let totalSyncReport = cumulativeSummary.totalSyncReport ?? SDKMetrics.ReportSummary.zero
-
-        metricLabel.text =
-            """
-            Summary:
-                downloadedBlocks: min: \(downloadedBlocksReport.minTime) max: \(downloadedBlocksReport.maxTime) avg: \(downloadedBlocksReport.avgTime)
-                scannedBlocks: min: \(scannedBlocksReport.minTime) max: \(scannedBlocksReport.maxTime) avg: \(scannedBlocksReport.avgTime)
-                enhancement: min: \(enhancementReport.minTime) max: \(enhancementReport.maxTime) avg: \(enhancementReport.avgTime)
-                fetchUTXOs: min: \(fetchUTXOsReport.minTime) max: \(fetchUTXOsReport.maxTime) avg: \(fetchUTXOsReport.avgTime)
-                totalSync: min: \(totalSyncReport.minTime) max: \(totalSyncReport.maxTime) avg: \(totalSyncReport.avgTime)
-            """
-    }
-
     @IBAction func startStop() {
         Task { @MainActor in
             await doStartStop()
@@ -156,7 +110,6 @@ class SyncBlocksViewController: UIViewController {
                     }
                 }
 
-                synchronizer.metrics.enableMetrics()
                 try await synchronizer.start()
                 updateUI()
             } catch {
@@ -165,7 +118,6 @@ class SyncBlocksViewController: UIViewController {
             }
         default:
             synchronizer.stop()
-            synchronizer.metrics.disableMetrics()
             updateUI()
         }
 
@@ -253,17 +205,6 @@ struct ProcessorMetrics {
         measuredCount: 0
     )
 
-    static func accumulate(_ prev: ProcessorMetrics, current: SDKMetrics.BlockMetricReport) -> Self {
-        .init(
-            minHeight: prev.minHeight,
-            maxHeight: prev.maxHeight,
-            maxDuration: prev.maxDuration,
-            minDuration: prev.minDuration,
-            cumulativeDuration: prev.cumulativeDuration + current.duration,
-            measuredCount: prev.measuredCount + 1
-        )
-    }
-
     static func compareDuration(
         _ prev: (TimeInterval, CompactBlockRange),
         _ current: (TimeInterval, CompactBlockRange),
@@ -300,16 +241,6 @@ extension CompactBlockRange {
     }
 }
 
-extension SDKMetrics.BlockMetricReport: CustomDebugStringConvertible {
-    public var debugDescription: String {
-        """
-        BlockMetric:
-            batchSize: \(self.batchSize)
-            duration: \(self.duration)
-        """
-    }
-}
-
 // MARK: Wipe
 
 extension SyncBlocksViewController {

diff --git a/Sources/ZcashLightClientKit/Block/Actions/EnhanceAction.swift b/Sources/ZcashLightClientKit/Block/Actions/EnhanceAction.swift
@@ -88,6 +88,8 @@ extension EnhanceAction: Action {
             if let transactions {
                 await didUpdate(.foundTransactions(transactions, enhanceRange))
             }
+        } else {
+            logger.sync("Action called but skipped for not enough blocks scanned from the last time.")
         }
 
         return await decideWhatToDoNext(context: context, lastScannedHeight: lastScannedHeight)

diff --git a/Sources/ZcashLightClientKit/Block/Actions/ProcessSuggestedScanRangesAction.swift b/Sources/ZcashLightClientKit/Block/Actions/ProcessSuggestedScanRangesAction.swift
@@ -11,22 +11,31 @@ final class ProcessSuggestedScanRangesAction {
     let rustBackend: ZcashRustBackendWelding
     let service: LightWalletService
     let logger: Logger
+    let metrics: SDKMetrics
 
     init(container: DIContainer) {
         service = container.resolve(LightWalletService.self)
         rustBackend = container.resolve(ZcashRustBackendWelding.self)
         logger = container.resolve(Logger.self)
+        metrics = container.resolve(SDKMetrics.self)
     }
 }
 
 extension ProcessSuggestedScanRangesAction: Action {
     var removeBlocksCacheWhenFailed: Bool { false }
 
     func run(with context: ActionContext, didUpdate: @escaping (CompactBlockProcessor.Event) async -> Void) async throws -> ActionContext {
-        logger.info("Getting the suggested scan ranges from the wallet database.")
+        logger.debug("Getting the suggested scan ranges from the wallet database.")
         let scanRanges = try await rustBackend.suggestScanRanges()
 
+        logger.sync("CALL suggestScanRanges \(scanRanges)")
+
+        for scanRange in scanRanges {
+            metrics.actionDetail("range \(scanRange.priority) \(scanRange.range)", for: .processSuggestedScanRanges)
+        }
+
         if let firstRange = scanRanges.first {
+            logger.sync("PROCESSING range \(firstRange.priority) \(firstRange.range)")
             let rangeStartExclusive = firstRange.range.lowerBound - 1
             let rangeEndInclusive = firstRange.range.upperBound - 1
 

diff --git a/Sources/ZcashLightClientKit/Block/Actions/ScanAction.swift b/Sources/ZcashLightClientKit/Block/Actions/ScanAction.swift
@@ -50,7 +50,8 @@ extension ScanAction: Action {
         let batchRange = batchRangeStart...batchRangeEnd
 
         logger.debug("Starting scan blocks with range: \(batchRange.lowerBound)...\(batchRange.upperBound)")
-
+        logger.sync("Starting scan blocks with range \(batchRange.lowerBound)...\(batchRange.upperBound)")
+
         do {
             try await blockScanner.scanBlocks(at: batchRange) { [weak self] lastScannedHeight, increment in
                 let processedHeight = await context.processedHeight

diff --git a/Sources/ZcashLightClientKit/Block/Actions/UpdateChainTipAction.swift b/Sources/ZcashLightClientKit/Block/Actions/UpdateChainTipAction.swift
@@ -25,7 +25,7 @@ final class UpdateChainTipAction {
     func updateChainTip(_ context: ActionContext, time: TimeInterval) async throws {
         let latestBlockHeight = try await service.latestBlockHeight()
 
-        logger.info("Latest block height is \(latestBlockHeight)")
+        logger.debug("Latest block height is \(latestBlockHeight)")
         try await rustBackend.updateChainTip(height: Int32(latestBlockHeight))
         await context.update(lastChainTipUpdateTime: time)
         await latestBlocksDataProvider.update(latestBlockHeight)

diff --git a/Sources/ZcashLightClientKit/Block/Actions/UpdateSubtreeRootsAction.swift b/Sources/ZcashLightClientKit/Block/Actions/UpdateSubtreeRootsAction.swift
@@ -28,7 +28,7 @@ extension UpdateSubtreeRootsAction: Action {
         var request = GetSubtreeRootsArg()
         request.shieldedProtocol = .sapling
 
-        logger.info("Attempt to get subtree roots, this may fail because lightwalletd may not support Spend before Sync.")
+        logger.debug("Attempt to get subtree roots, this may fail because lightwalletd may not support Spend before Sync.")
         let stream = service.getSubtreeRoots(request)
 
         var roots: [SubtreeRoot] = []
@@ -41,7 +41,7 @@ extension UpdateSubtreeRootsAction: Action {
             throw ZcashError.serviceSubtreeRootsStreamFailed(LightWalletServiceError.timeOut)
         }
 
-        logger.info("Sapling tree has \(roots.count) subtrees")
+        logger.debug("Sapling tree has \(roots.count) subtrees")
         do {
             try await rustBackend.putSaplingSubtreeRoots(startIndex: UInt64(request.startIndex), roots: roots)
 

diff --git a/Sources/ZcashLightClientKit/Block/CompactBlockProcessor.swift b/Sources/ZcashLightClientKit/Block/CompactBlockProcessor.swift
@@ -478,6 +478,7 @@ extension CompactBlockProcessor {
     // swiftlint:disable:next cyclomatic_complexity
     private func run() async {
         logger.debug("Starting run")
+        metrics.cbpStart()
         await resetContext()
 
         while true {
@@ -513,6 +514,7 @@ extension CompactBlockProcessor {
                 try Task.checkCancellation()
 
                 // Execute action.
+                metrics.actionStart(state)
                 context = try await action.run(with: context) { [weak self] event in
                     await self?.send(event: event)
                     if let progressChanged = await self?.compactBlockProgress.hasProgressUpdated(event), progressChanged {
@@ -633,6 +635,7 @@ extension CompactBlockProcessor {
 
     private func syncFinished() async -> Bool {
         logger.debug("Sync finished")
+        metrics.logCBPOverviewReport(logger)
         let latestBlockHeightWhenSyncing = await context.syncControlData.latestBlockHeight
         let latestBlockHeight = await latestBlocksDataProvider.latestBlockHeight
         // If `latestBlockHeightWhenSyncing` is 0 then it means that there was nothing to sync in last sync process.

diff --git a/Sources/ZcashLightClientKit/Block/Download/BlockDownloader.swift b/Sources/ZcashLightClientKit/Block/Download/BlockDownloader.swift
@@ -196,23 +196,12 @@ actor BlockDownloaderImpl {
         logger.debug("Downloading blocks in range: \(range.lowerBound)...\(range.upperBound)")
 
         var startTime = Date()
-        var counter = 0
         var lastDownloadedBlockHeight = -1
 
-        let pushMetrics: (BlockHeight, Date, Date) -> Void = { [metrics] _, startTime, finishTime in
-            metrics.pushProgressReport(
-                start: startTime,
-                end: finishTime,
-                batchSize: maxBlockBufferSize,
-                operation: .downloadBlocks
-            )
-        }
-
         for _ in stride(from: range.lowerBound, to: range.upperBound + 1, by: 1) {
             try Task.checkCancellation()
             guard let block = try await stream.nextBlock() else { break }
 
-            counter += 1
             lastDownloadedBlockHeight = block.height
 
             buffer.append(block)
@@ -222,17 +211,10 @@ actor BlockDownloaderImpl {
                 try await blocksBufferWritten(buffer)
                 buffer.removeAll(keepingCapacity: true)
 
-                pushMetrics(block.height, startTime, finishTime)
-
-                counter = 0
                 startTime = finishTime
             }
         }
 
-        if counter > 0 {
-            pushMetrics(lastDownloadedBlockHeight, startTime, Date())
-        }
-
         try await storage.write(blocks: buffer)
         try await blocksBufferWritten(buffer)
     }

diff --git a/Sources/ZcashLightClientKit/Block/Enhance/BlockEnhancer.swift b/Sources/ZcashLightClientKit/Block/Enhance/BlockEnhancer.swift
@@ -96,6 +96,7 @@ extension BlockEnhancerImpl: BlockEnhancer {
 
             guard !transactions.isEmpty else {
                 logger.debug("no transactions detected on range: \(range.lowerBound)...\(range.upperBound)")
+                logger.sync("No transactions detected on range: \(range.lowerBound)...\(range.upperBound)")
                 return nil
             }
 
@@ -134,12 +135,10 @@ extension BlockEnhancerImpl: BlockEnhancer {
                 }
             }
 
-            metrics.pushProgressReport(
-                start: startTime,
-                end: Date(),
-                batchSize: range.count,
-                operation: .enhancement
-            )
+            let endTime = Date()
+            let logMsg = "Enhanced \(transactions.count) transaction(s) in \(endTime.timeIntervalSince1970 - startTime.timeIntervalSince1970) for range \(range.lowerBound)...\(range.upperBound)"
+            logger.sync(logMsg)
+            metrics.actionDetail(logMsg, for: .enhance)
         } catch {
             logger.error("error enhancing transactions! \(error)")
             throw error

diff --git a/Sources/ZcashLightClientKit/Block/FetchUnspentTxOutputs/UTXOFetcher.swift b/Sources/ZcashLightClientKit/Block/FetchUnspentTxOutputs/UTXOFetcher.swift
@@ -85,13 +85,6 @@ extension UTXOFetcherImpl: UTXOFetcher {
             }
         }
 
-        metrics.pushProgressReport(
-            start: startTime,
-            end: Date(),
-            batchSize: 1,
-            operation: .fetchUTXOs
-        )
-
         let result = (inserted: refreshed, skipped: skipped)
 
         if Task.isCancelled {

diff --git a/Sources/ZcashLightClientKit/Block/Scan/BlockScanner.swift b/Sources/ZcashLightClientKit/Block/Scan/BlockScanner.swift
@@ -69,16 +69,10 @@ extension BlockScannerImpl: BlockScanner {
             if scannedNewBlocks {
                 try await didScan(lastScannedHeight, batchSize)
 
-                metrics.pushProgressReport(
-                    start: scanStartTime,
-                    end: scanFinishTime,
-                    batchSize: Int(batchSize),
-                    operation: .scanBlocks
-                )
-
                 let heightCount = lastScannedHeight - previousScannedHeight
                 let seconds = scanFinishTime.timeIntervalSinceReferenceDate - scanStartTime.timeIntervalSinceReferenceDate
                 logger.debug("Scanned \(heightCount) blocks in \(seconds) seconds")
+                logger.sync("Scanned \(heightCount) blocks in \(seconds) seconds")
             }
 
             await Task.yield()