[Electric-Coin-Company#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 [Electric-Coin-Company#1325] Log metrics - typos fixed [Electric-Coin-Company#1325] Log metrics - scan metric logs added [Electric-Coin-Company#1325] Log metrics - Scan & Enhance logs [Electric-Coin-Company#1325] Log metrics - 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#1325] Log metrics (Electric-Coin-Company#1327) - changelog update [Electric-Coin-Company#1325] Log metrics (Electric-Coin-Company#1327) - SDKMetrics updated to be mockable - unit test updated
LukasKorba · Dec 12, 2023 · 1c2c9a5 · 1c2c9a5
1 parent 5644f89
commit 1c2c9a5
Show file tree

Hide file tree

Showing 57 changed files with 599 additions and 380 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()