-
Notifications
You must be signed in to change notification settings - Fork 15
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
chore: log sync phases in legacy code and new code - WPB-15289 #2373
base: develop
Are you sure you want to change the base?
Conversation
WireDomain/Sources/WireDomain/Synchronization/SyncTimeTracker.swift
Outdated
Show resolved
Hide resolved
Test Results2 723 tests 2 721 ✅ 4m 11s ⏱️ Results for commit 9b0d2d1. ♻️ This comment has been updated with latest results. |
Datadog ReportBranch report: ✅ 0 Failed, 2589 Passed, 2 Skipped, 2m 45.87s Total Time |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
logic looks good, but data must be in attributes in order to use it in datadog, see comments
let message = "Completed \(syncType) phase \(phase) in \(duration)" | ||
WireLogger.sync.info(message, attributes: .safePublic) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
let message = "Completed \(syncType) phase \(phase) in \(duration)" | |
WireLogger.sync.info(message, attributes: .safePublic) | |
let message = "SyncPhase completed" | |
WireLogger.sync.info(message, attributes: [.duration: \(duration), .syncType: syncType, .phase: phase], .safePublic) |
better to move the info inside attributes so in datadog we can extract it directly.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
done in aaa6638
let message = "Completed \(syncType) in \(syncTimeTracker.totalSyncDuration())" | ||
WireLogger.sync.info(message, attributes: .safePublic) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
let message = "Completed \(syncType) in \(syncTimeTracker.totalSyncDuration())" | |
WireLogger.sync.info(message, attributes: .safePublic) | |
let message = "Completed \(syncType)" | |
WireLogger.sync.info(message, attributes: [.sync_duration: syncTimeTracker.totalSyncDuration(), .syncType: syncType], .safePublic) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
done in aaa6638
let syncType = isSlowSyncing ? "slow sync" : "quick sync" | ||
WireLogger.sync.info("Started \(syncType) phase \(currentSyncPhase)", attributes: .safePublic) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
maybe add an attribute syncSystem: "legacy" or syncSystem: "new" to distinguish which system is running. it should contain same attributes as in new system
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
done in aaa6638
Un-assigning myself as this PR already has a couple of active reviewers. @jullianm Feel free to add me back if you would like. |
Co-authored-by: François Benaiteau <[email protected]>
Co-authored-by: François Benaiteau <[email protected]>
Co-authored-by: François Benaiteau <[email protected]>
I've noticed a funny duration number for the first slow sync phase in legacy code. Probably the time we trigger the timer for this first event should be set later on. I suspect the time we determine the initial sync phase is not the time we actually start to perform the fetch. |
So, the weird duration value for the first slow sync phase would only occur when we run into the case where we have too many devices: we determine the first slow sync phase and start the slow sync but the app is kind of in an idle state where the first phase is not being actually executed until we removed a device (issue was that the timer would've already started). Solution is to start the timer only when the first slow sync phase is actually executed, commit b54bbc1 |
Issue
This PR adds logs for the duration of a sync phase as well as the full duration of a sync to complete (quick or slow sync).
Added to both legacy code and new code in WireDomain.
It will help us analyze and compare the duration between the old sync mechanism and the new one on Datadog.
Testing
N/A
Checklist
[WPB-XXX]
.Logs would look as follows: