Skip to content
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.

Sign up for GitHub

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

Jump to bottom

fix: fix utxo scan edge case when pc awakes from sleep #3160

Merged
merged 1 commit into from
Aug 6, 2021
Merged

fix: fix utxo scan edge case when pc awakes from sleep #3160

merged 1 commit into from
Aug 6, 2021

Conversation

hansieodendaal
Copy link
Contributor

Description

This PR fixes an issue where bottled up tokio interval events are fired successively for the edge case where a computer wakes up from sleep. This was evident in the UTXO scanning service where many UTXO scanning tasks would be started in parallel afterwards instead of only one.

The log extract below shows multiple tokio interval events being fired and negated by the code change. The computer was put to sleep just after a completed scan at 14:23:29 and woken again at ~14:39:47. UTXO scanning interval was set at 30s for this test.

2021-08-04 14:22:59.183379600 [wallet::utxo_scanning] DEBUG UTXO scanning service starting scan for utxos
2021-08-04 14:23:06.024966100 [wallet::utxo_scanning] DEBUG Attempting UTXO sync with seed peer 1 (3e38003060dc53370434610f6d)
2021-08-04 14:23:29.413874600 [wallet::utxo_scanning] DEBUG Scanning UTXO's (start_index = 453682, output_mmr_size = 453683, height = 15284, tip_hash = 063ae608784253c0b320ae0cb019d32d56e448d0c97b2fd829cfb278277350a4)
2021-08-04 14:23:29.413888000 [wallet::utxo_scanning] DEBUG Scanning complete UTXO #453682 in 2.75s
2021-08-04 14:23:29.413899500 [wallet::utxo_scanning] DEBUG Scanned to UTXO #453682
2021-08-04 14:39:47.605332800 [wallet::utxo_scanning] DEBUG UTXO scanning service starting scan for utxos
2021-08-04 14:39:47.605355200 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605369300 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605384000 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605397500 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605411200 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605424600 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605437700 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605450700 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605467300 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605484300 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605498300 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605511200 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605524600 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605538300 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605551900 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605565300 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605578700 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605592100 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605614900 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605628700 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605646300 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605661400 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605673600 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605685200 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605697600 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605708800 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605722400 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605737700 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605751000 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605769200 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605844200 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:39:47.605870300 [wallet::utxo_scanning] DEBUG Attempting UTXO sync with seed peer 1 (3e38003060dc53370434610f6d)
2021-08-04 14:39:49.796532200 [wallet::utxo_scanning] WARN  Failed to scan UTXO's from base node 3e38003060dc53370434610f6d: RpcError: `Handshake error: Remote peer unexpectedly closed the RPC connection`
2021-08-04 14:39:49.796562000 [wallet::utxo_scanning] DEBUG Attempting UTXO sync with seed peer 1 (3e38003060dc53370434610f6d)
2021-08-04 14:39:59.177391000 [wallet::utxo_scanning] DEBUG UTXO scanning work interval event fired too quickly, not running the task
2021-08-04 14:40:05.697376100 [wallet::utxo_scanning] DEBUG Scanning UTXO's (start_index = 453682, output_mmr_size = 453683, height = 15284, tip_hash = 063ae608784253c0b320ae0cb019d32d56e448d0c97b2fd829cfb278277350a4)
2021-08-04 14:40:05.697387800 [wallet::utxo_scanning] DEBUG Scanning complete UTXO #453682 in 6.87s
2021-08-04 14:40:05.697397600 [wallet::utxo_scanning] DEBUG Scanned to UTXO #453682
2021-08-04 14:40:29.177122900 [wallet::utxo_scanning] DEBUG UTXO scanning service starting scan for utxos
2021-08-04 14:40:29.177210000 [wallet::utxo_scanning] DEBUG Attempting UTXO sync with seed peer 1 (3e38003060dc53370434610f6d)
2021-08-04 14:40:34.756283700 [wallet::utxo_scanning] DEBUG Scanning UTXO's (start_index = 453682, output_mmr_size = 453699, height = 15290, tip_hash = db71baa70ee60c78d8cfaec60c842dd502aa8c2d6d92bec24d76480961398baa)
2021-08-04 14:40:34.756316700 [wallet::utxo_scanning] DEBUG Scanning UTXO's from #453682 to #453699 (height 15290)
2021-08-04 14:40:36.548045400 [wallet::utxo_scanning] DEBUG Scanning round completed UTXO #453699 in 5.91s (17 scanned)
2021-08-04 14:40:39.614574400 [wallet::utxo_scanning] DEBUG Scanning UTXO's (start_index = 453698, output_mmr_size = 453699, height = 15290, tip_hash = db71baa70ee60c78d8cfaec60c842dd502aa8c2d6d92bec24d76480961398baa)
2021-08-04 14:40:39.614589700 [wallet::utxo_scanning] DEBUG Scanning complete UTXO #453698 in 8.97s
2021-08-04 14:40:39.614600700 [wallet::utxo_scanning] DEBUG Scanned to UTXO #453698

Motivation and Context

The code should behave in a predicted manner when waking from sleep.

How Has This Been Tested?

System-level testing with a base node and a console wallet.

Checklist:

  • I'm merging against the development branch.
  • I have squashed my commits into a single commit.

stringhandler
stringhandler previously approved these changes Aug 4, 2021
View reviewed changes
Copy link
Collaborator

@stringhandler stringhandler left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks fine. Could have also been done in fewer lines using a delay that you set each time instead of an interval, but doesn't really matter

base_layer/wallet/src/utxo_scanner_service/utxo_scanning.rs
@@ -709,21 +709,34 @@ where TBackend: WalletBackend + 'static
let mut shutdown = self.shutdown_signal.clone();
let start_at = Instant::now() + Duration::from_secs(1);
let mut work_interval = time::interval_at(start_at.into(), self.scan_for_utxo_interval).fuse();
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
let mut work_interval = time::interval_at(start_at.into(), self.scan_for_utxo_interval).fuse();
let mut work_interval = time::delay_for(self.scan_for_utxo_interval);

base_layer/wallet/src/utxo_scanner_service/utxo_scanning.rs
}
previous = Instant::now();
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
previous = Instant::now();
work_interval = time::delay_for(self.scan_for_utxo_interval);

base_layer/wallet/src/utxo_scanner_service/utxo_scanning.rs
// This bit of code prevents bottled up tokio interval events to be fired successively for the edge
// case where a computer wakes up from sleep.
if start_at.elapsed() > self.scan_for_utxo_interval &&
previous.elapsed() < self.scan_for_utxo_interval.mul_f32(0.9)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: The strictly less than probably is good enough without the mul_f32

@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 4, 2021

PR queued successfully. Your position in queue is: 8

@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 4, 2021

PR is on top of the queue now

@aviator-app aviator-app bot added the mq-failed label Aug 4, 2021
@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 4, 2021

PR failed to merge with reason: Some CI status(es) failed
Failed CI(s): ci/circleci: run-integration-tests

@hansieodendaal
Fix UTXO scan edge case when PC awakes from sleep
4d09eae 
This PR fixes an issue where bottled up tokio interval events are fired
successively for the edge case where a computer wakes up from sleep. This
was evident in the UTXO scanning service where many many UTXO scanning tasks
would be started in parallel afterwards instead of only one.
@hansieodendaal hansieodendaal force-pushed the ho_fix_wake_from_sleep_for_utxo_scanning branch from c920337 to 4d09eae Compare August 6, 2021 09:18
@aviator-app aviator-app bot removed the mq-failed label Aug 6, 2021
@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 6, 2021

PR queued successfully. Your position in queue is: 1

@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 6, 2021

PR failed to merge with reason: Failed due to unknown reason

@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 6, 2021

PR queued successfully. Your position in queue is: 1

@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 6, 2021

PR failed to merge with reason: Failed due to unknown reason

@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 6, 2021

PR queued successfully. Your position in queue is: 1

@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 6, 2021

PR failed to merge with reason: Failed due to unknown reason

@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 6, 2021

PR queued successfully. Your position in queue is: 1

@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 6, 2021

PR failed to merge with reason: Failed due to unknown reason

@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 6, 2021

PR queued successfully. Your position in queue is: 1

@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 6, 2021

PR failed to merge with reason: Failed due to unknown reason

@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 6, 2021

PR queued successfully. Your position in queue is: 1

@aviator-app aviator-app bot added the mq-failed label Aug 6, 2021
@aviator-app
Copy link
Contributor

aviator-app bot commented Aug 6, 2021

PR failed to merge with reason: Ready label was manually removed

@stringhandler stringhandler merged commit 5bdc9f3 into tari-project:development Aug 6, 2021
@hansieodendaal hansieodendaal deleted the ho_fix_wake_from_sleep_for_utxo_scanning branch August 6, 2021 12:25
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@stringhandler stringhandler stringhandler approved these changes

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@hansieodendaal @stringhandler