Skip to content

Commit

Permalink
Browse files Browse the repository at this point in the history
- 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
  • Loading branch information
LukasKorba committed Dec 11, 2023
1 parent 5644f89 commit b7039fc
Show file tree
Hide file tree
Showing 42 changed files with 496 additions and 17 deletions.
26 changes: 26 additions & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,32 @@ 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

## 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
Expand Down
2 changes: 2 additions & 0 deletions Sources/ZcashLightClientKit/Block/Actions/EnhanceAction.swift
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -11,11 +11,13 @@ 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)
}
}

Expand All @@ -26,7 +28,14 @@ extension ProcessSuggestedScanRangesAction: Action {
logger.info("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

Expand Down
3 changes: 2 additions & 1 deletion Sources/ZcashLightClientKit/Block/Actions/ScanAction.swift
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
3 changes: 3 additions & 0 deletions Sources/ZcashLightClientKit/Block/CompactBlockProcessor.swift
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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
}

Expand Down Expand Up @@ -134,9 +135,14 @@ extension BlockEnhancerImpl: BlockEnhancer {
}
}

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)

metrics.pushProgressReport(
start: startTime,
end: Date(),
end: endTime,
batchSize: range.count,
operation: .enhancement
)
Expand Down
1 change: 1 addition & 0 deletions Sources/ZcashLightClientKit/Block/Scan/BlockScanner.swift
Original file line number Diff line number Diff line change
Expand Up @@ -79,6 +79,7 @@ extension BlockScannerImpl: BlockScanner {
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()
Expand Down
121 changes: 121 additions & 0 deletions Sources/ZcashLightClientKit/Metrics/SDKMetrics.swift
Original file line number Diff line number Diff line change
Expand Up @@ -50,12 +50,31 @@ public class SDKMetrics {
public let endTime: TimeInterval
public var duration: TimeInterval { endTime - startTime }
}

public struct CBPStateMetricReport: Equatable {
static let zero = Self(runs: 0, startTime: 0, cummulativeTime: 0, maxTime: 0, avgTime: 0)

var runs: Int
var startTime: TimeInterval
var cummulativeTime: TimeInterval
var minTime: TimeInterval = .infinity
var maxTime: TimeInterval
var avgTime: TimeInterval

var details: [String] = []
}

public var cumulativeSummaries: [CumulativeSummary] = []
public var syncReport: SyncReport?
var isEnabled = false
var reports: [Operation: [BlockMetricReport]] = [:]

// Compact Block Processor Metrics
var syncs = 0
var cbpStartTime: TimeInterval = 0
var cbpOverview: [CBPState: CBPStateMetricReport] = [:]
var lastActionInRun: CBPState?

public init() { }

/// `SDKMetrics` is disabled by default. Any pushed data are simply ignored until `enableMetrics()` is called.
Expand Down Expand Up @@ -256,3 +275,105 @@ extension SDKMetrics {
return ReportSummary(minTime: min, maxTime: max, avgTime: avg)
}
}

// MARK: - Compact Block Processor State Machine Overview

extension SDKMetrics {
func cbpStart() {
syncs += 1
cbpStartTime = Date().timeIntervalSince1970

// reset of previous values
cbpOverview.removeAll()
}

func actionStart(_ action: CBPState) {
actionStop()

lastActionInRun = action

var report = CBPStateMetricReport.zero

if let reportFound = cbpOverview[action] {
report = reportFound
}

report.runs += 1
report.startTime = Date().timeIntervalSince1970

cbpOverview[action] = report
}

func actionDetail(_ detail: String, `for` action: CBPState) {
guard var report = cbpOverview[action] else {
return
}

report.details.append(detail)

cbpOverview[action] = report
}

func actionStop() {
guard let lastActionInRun else {
return
}

guard var report = cbpOverview[lastActionInRun] else {
return
}

let endTime = Date().timeIntervalSince1970
let runTime = endTime - report.startTime

report.cummulativeTime += runTime

if runTime < report.minTime {
report.minTime = runTime
}

if runTime > report.maxTime {
report.maxTime = runTime
}

if report.runs > 0 {
report.avgTime = report.cummulativeTime / Double(report.runs)
}

cbpOverview[lastActionInRun] = report
}

// swiftlint:disable string_concatenation
public func logCBPOverviewReport(_ logger: Logger) {
actionStop()

var resText = "SYNC (\(syncs)) REPORT\n"

resText += "finished in: \(Date().timeIntervalSince1970 - cbpStartTime)\n\n"

for action in cbpOverview {
let report = action.value

resText += """
action: \(action.key)
runs: \(report.runs)
cummulativeTime: \(report.cummulativeTime)
minTime: \(report.minTime)
maxTime: \(report.maxTime)
avgTime: \(report.avgTime)
"""

if !report.details.isEmpty {
resText += "\ndetails:\n"

for detail in report.details {
resText += "\t\(detail)\n"
}
}

resText += "\n\n"
}

logger.sync(resText)
}
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,8 @@
{
"network": "main",
"height": "2270000",
"hash": "0000000000c4314de2a15c56249dfe277ff51e1d6a179a5ae3c01e709d80f07d",
"time": 1697958631,
"saplingTree": "014c6ab9468d295866f051ee781d91aca0e7542e143680c89f8cb5c9e72a9838720158af6691c73faa4c3afd7efcbbffa362384f1f3f9eef160de6a9c8ac8bd81d391a0000012731c443460effc12a99483ac5d5c9540cf6edc9932bdee163f331df76218c5b000001adfa0efcad0c23520a4e2a6865ecf1fbdae3851d2019340a1caa84c854fa3e0f01229b6ab4de80a3843c039bd50b9687460b5c04c29b4c5d9baef2742bdb816a0c013b67cbdd09009cd311022460c802b77cce63c5e661b4dcd5543ed98cbdccb8660113ea747404c27dbf347dc87f56796d7a7654455cc9f81db36a1da7b2b063661401d9025bc766e91070f70716c15fb3a8f85525c5b082a0bc9ec77cd667e7b07d38015cc47e57f3c7a46b570ec6f664d5e39e67c73bdaee1e006dc32f9d6fbbf2eb2c01090b969f4a6c25a0bcf22b976c7c7a1145320eb0620ff4da3ac1cc6627b2720301f71ed6dee66571dddf2e1cbc239b50cbd1867ac519ccbc491b3a1284f05b860401ca2ef102fb828472bb323b8e334a3f7dd188b4bd043df1f9e5b525b654bf27200001ffdd1a0628296bf274daa5ea13fb57818d678957d49f91ccd69efae0bac249340182ac7ebe2f7e9d8084a38aa8be56b1bd86292babf05f98882a6959cf9d318c110001d8ccea507421a590ed38116b834189cdc22421b4764179fa4e364803dfa66d56018cf6f5034a55fed59d1d832620916a43c756d2379e50ef9440fc4c3e7a29aa2300011619f99023a69bb647eab2d2aa1a73c3673c74bb033c3c4930eacda19e6fd93b0000000160272b134ca494b602137d89e528c751c06d3ef4a87a45f33af343c15060cc1e",
"orchardTree": "01b2c39d0a9083b615af23168684321b83b0ffaa65a242f168ffca783520910a34001f01c76b3e598049fe3a88fafc213451d6c6bc4758a52c5620300b9482ebf67caa3201034d2240ab404d03f6231989d1aec297566daafe798a3ce71e61cb6de526aa1200019db5c0c598c9db3e4bf851e29ce058878840d7dad804713a251cf8d8e9d8c50601d4962b21d6711214c867706a8e50b07616e92ee8c867ab3fae5912b86a71c7380001d078599b76eba7ce4b38db395b4ca6c289afb1e139ba0ca4281d33fdc5c23d2701acbca7b28d294abc7cec56fe1ad4e653578e188012d70361700803254f0a8934000001ed0b8645ba722e2aeef2cfff7374a7dba95d92a6438276ddca7c76f6f2a3ae1600012ffae608e1b4d4de4f5ac38068b613d9761ba34d95430e5ec8d058848cc9c0250001dd3e61f3e1d497d923486bd000737ea0ffac885fa481316727d0d8f7fc2138100001cf3bf92f69798e68555548afcce1648add1fb2548d64fa9a1ec22a3e26e7890101e637281deb58dff0c44ba13149b784a95da1b493005efd057e6f4ac20ef5d81d000001cc2dcaa338b312112db04b435a706d63244dd435238f0aa1e9e1598d35470810012dcc4273c8a0ed2337ecf7879380a07e7d427c7f9d82e538002bd1442978402c01daf63debf5b40df902dae98dadc029f281474d190cddecef1b10653248a234150001e2bca6a8d987d668defba89dc082196a922634ed88e065c669e526bb8815ee1b000000000000"
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,8 @@
{
"network": "main",
"height": "2272500",
"hash": "000000000101df774d2a45008af97d1cbc62117ce8a2635e8be8432de50c18cd",
"time": 1698147530,
"saplingTree": "018f896dbdedae2e50c0cce982c8204141730b196f745175a82830ca9a47fedf48017a8a234509e3c64c49b5229d8b6589f6389832dfd7ee95696008442827f5116f1a01f16748b8fa01f368a968b5d6f45aa499540bb566314328d4337ea9bad0d69719000001c698abd29732e8d765df5aa15db8652a347aa6dd9e1592f200d3e5bfe66ad26200000129cee479373bc283fdf83c02b3a019178bfa1f8a34a868092a75022cdf43db3a01095b14c824594a5311d7f29406e99dea20cf53b90a27a12df4bdf8b1281fb5080001b099b710de3efd37a880d4372c44c7388d14fdf4a34ca2d97a6ac1acf33d6817000195690f105db42ae533ed2406bd24155128007fb2fbc80676b4e59a05d7aec52100000143d0958ed592bc13ecf47b2664d9087554b43c69f01d23247d1323006a4d750601ffdd1a0628296bf274daa5ea13fb57818d678957d49f91ccd69efae0bac249340182ac7ebe2f7e9d8084a38aa8be56b1bd86292babf05f98882a6959cf9d318c110001d8ccea507421a590ed38116b834189cdc22421b4764179fa4e364803dfa66d56018cf6f5034a55fed59d1d832620916a43c756d2379e50ef9440fc4c3e7a29aa2300011619f99023a69bb647eab2d2aa1a73c3673c74bb033c3c4930eacda19e6fd93b0000000160272b134ca494b602137d89e528c751c06d3ef4a87a45f33af343c15060cc1e",
"orchardTree": "01cdcfa81709e09b8ddbbef40c2953d9222f79a7fd490bb0270fb5182ca3f7ba01001f0199ce56729f4c6e25622d23e77c8f8edbb89e1e65bc042d7b08e0b720d2e3fc1800011eb748c95af57b028618c39fc1ef4d2491578c1a91040224fedc95ec3f6a8f2d018422698954742926542754dc904a3e5b8cb7a1b9411df69fa549496be51e4a1700000000000189a2e7029abe265a7acf4227791eae37c48bb19e21cb2f95d9a87e8914f56e3901ed0b8645ba722e2aeef2cfff7374a7dba95d92a6438276ddca7c76f6f2a3ae1600012ffae608e1b4d4de4f5ac38068b613d9761ba34d95430e5ec8d058848cc9c0250001dd3e61f3e1d497d923486bd000737ea0ffac885fa481316727d0d8f7fc2138100001cf3bf92f69798e68555548afcce1648add1fb2548d64fa9a1ec22a3e26e7890101e637281deb58dff0c44ba13149b784a95da1b493005efd057e6f4ac20ef5d81d000001cc2dcaa338b312112db04b435a706d63244dd435238f0aa1e9e1598d35470810012dcc4273c8a0ed2337ecf7879380a07e7d427c7f9d82e538002bd1442978402c01daf63debf5b40df902dae98dadc029f281474d190cddecef1b10653248a234150001e2bca6a8d987d668defba89dc082196a922634ed88e065c669e526bb8815ee1b000000000000"
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,8 @@
{
"network": "main",
"height": "2275000",
"hash": "0000000001a1d06d7297d87f0f7e0e49383b0f10dbe3e22e7a66ab1ba9cebf66",
"time": 1698335616,
"saplingTree": "015d9ff1fd129cb09cfb3322c4eb284bbb44a30b4027edf52ca5500a18da76382e01251130dcfbc8dbca704428db2fc252d1b63bfe9d8fa9a3a3ff5ad18fec0c266e1a000170b1341313ab46627dce9b636268c1aa457eea90b5ebcf7f0f0a3b8224d32b630000000001435c8a879c5799d05b4467d5de64193196e1793295cb85464e04aec99ef4b77101e508516f5c55360490aabf7dc59642c75dfa08a6a6532e7deb59a427b792360101b09f2068c37a8e89d92735a8672559c77aa4cb5d15d5a84f7c40d30b248dc15c00013bae7327f0e7b60dd2c09cd29e34da76f79da4f1b7593f611e2cc6cb45dcfc090001602f25e80946cd987a4d570593152f72bfe10b054be88436e82bfd9cbbf0cf06000143d0958ed592bc13ecf47b2664d9087554b43c69f01d23247d1323006a4d750601ffdd1a0628296bf274daa5ea13fb57818d678957d49f91ccd69efae0bac249340182ac7ebe2f7e9d8084a38aa8be56b1bd86292babf05f98882a6959cf9d318c110001d8ccea507421a590ed38116b834189cdc22421b4764179fa4e364803dfa66d56018cf6f5034a55fed59d1d832620916a43c756d2379e50ef9440fc4c3e7a29aa2300011619f99023a69bb647eab2d2aa1a73c3673c74bb033c3c4930eacda19e6fd93b0000000160272b134ca494b602137d89e528c751c06d3ef4a87a45f33af343c15060cc1e",
"orchardTree": "010d092947e75a832b868d3dc43cd3d6556e5f3647da76165ac9506fb004930830001f015cc156677f54dc339ddd846e6f94232771f460e8e73e90abec57bd5c7f7cfe34000001f536aced4e2e37cf02ed4b6aa6ac8fb7fa6610f0370020e6d1ac10995d2f8928000001cb1efaf88c34aabae5756dfaaf3d03856d70889efbab49b38496c10987a40a3e0001c13878d4402edfd680750b5cf58e79190819928dc7a553e75d8f14763894ca3d0189a2e7029abe265a7acf4227791eae37c48bb19e21cb2f95d9a87e8914f56e3901ed0b8645ba722e2aeef2cfff7374a7dba95d92a6438276ddca7c76f6f2a3ae1600012ffae608e1b4d4de4f5ac38068b613d9761ba34d95430e5ec8d058848cc9c0250001dd3e61f3e1d497d923486bd000737ea0ffac885fa481316727d0d8f7fc2138100001cf3bf92f69798e68555548afcce1648add1fb2548d64fa9a1ec22a3e26e7890101e637281deb58dff0c44ba13149b784a95da1b493005efd057e6f4ac20ef5d81d000001cc2dcaa338b312112db04b435a706d63244dd435238f0aa1e9e1598d35470810012dcc4273c8a0ed2337ecf7879380a07e7d427c7f9d82e538002bd1442978402c01daf63debf5b40df902dae98dadc029f281474d190cddecef1b10653248a234150001e2bca6a8d987d668defba89dc082196a922634ed88e065c669e526bb8815ee1b000000000000"
}
Original file line number Diff line number Diff line change
@@ -0,0 +1,8 @@
{
"network": "main",
"height": "2277500",
"hash": "0000000000a4dd1adf30d25e02984056504ff96d76fae62f7085458695a411a2",
"time": 1698524343,
"saplingTree": "01fc5d5e38cffb57e9dbb61e285b960a1e63f005dc8e7e709fc22014c36088ef3f001a0001de0ed3aa986e08d4e303387490dce97cb7c99e54e02d16256446718935ccb62b000001da1e0dd9a0db7d398862c6cc76b3743b7c33b5a032f3e96644102508c20e473801ad5fef9438eae8dd617eabaa220a1865d6284ae46488b667abe397753c4cd2200000000000000001fb99b6df98e30fbb8d0b50b4d4af9777346c943d2c2718a5df0c531667e6ba530143d0958ed592bc13ecf47b2664d9087554b43c69f01d23247d1323006a4d750601ffdd1a0628296bf274daa5ea13fb57818d678957d49f91ccd69efae0bac249340182ac7ebe2f7e9d8084a38aa8be56b1bd86292babf05f98882a6959cf9d318c110001d8ccea507421a590ed38116b834189cdc22421b4764179fa4e364803dfa66d56018cf6f5034a55fed59d1d832620916a43c756d2379e50ef9440fc4c3e7a29aa2300011619f99023a69bb647eab2d2aa1a73c3673c74bb033c3c4930eacda19e6fd93b0000000160272b134ca494b602137d89e528c751c06d3ef4a87a45f33af343c15060cc1e",
"orchardTree": "012d9d285babba1461ab28ef71eb6fc228124379fcc5eeece62a00007c676396150122ef493fe98e3fd2afd981a1c596e1b02837036ef50703860847eb1854bed8351f0000015e25ce67f68c5a9f167148a80d46d897c6ccc05dff8ad80f9f7eb429ff0a3d2b01e2e14918c25cd079460a5088418de57cf996e0b7cee619d1c639ee9ef41c671301cdfa1c1b946fc22d67e3a1a9b0485597625481268119937f4c5816d8eb8fe2390187685cddc66dce2bd8e05e6bb26cbb4dbc57e6d06055012ee17af7956caf132b01ba45e35cc7c794e859b2723b5467389966ed6d2b50d6e487d961d10f8786f41300000000014f4953491ea4a29604f7f1935e3fde4d40851918267a9340aa73d3375b86ed3a012ffae608e1b4d4de4f5ac38068b613d9761ba34d95430e5ec8d058848cc9c0250001dd3e61f3e1d497d923486bd000737ea0ffac885fa481316727d0d8f7fc2138100001cf3bf92f69798e68555548afcce1648add1fb2548d64fa9a1ec22a3e26e7890101e637281deb58dff0c44ba13149b784a95da1b493005efd057e6f4ac20ef5d81d000001cc2dcaa338b312112db04b435a706d63244dd435238f0aa1e9e1598d35470810012dcc4273c8a0ed2337ecf7879380a07e7d427c7f9d82e538002bd1442978402c01daf63debf5b40df902dae98dadc029f281474d190cddecef1b10653248a234150001e2bca6a8d987d668defba89dc082196a922634ed88e065c669e526bb8815ee1b000000000000"
}
Loading

0 comments on commit b7039fc

Please sign in to comment.