Skip to content

Commit

Permalink
fix: fix debouncer delay bug (#3376)
Browse files Browse the repository at this point in the history
Description
---
Fixed a bug in the console wallet's debouncer where the tokio delay did not perform as expected. This was replaced with a tokio interval with missed tick behaviour set to `MissedTickBehavior::Delay`.

_**Note:** I know this is totally different from the approach in #3375, but it fixes a bug to present a working alternative._

Motivation and Context
---
The debouncing cooldown period was not honoured by the tokio delay in the select loop. Compounded to this the event fired consecutively if the system got busy.

Sampled time measurements of the change this PR brought measuring events `_ = interval.tick() => {` below with a user-configured debouncing cooldown period of 60s. The lags represent balance update requests that were ignored from the beginning of the time interval with the balance update only occurring at the end of the interval. The wallet in question started receiving 250 transactions during this period, therefore the high balance update request rate.
``` rust
2021-09-21 17:36:06.556792200 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (60008 ms): Err(Lagged(2))
2021-09-21 17:36:59.404245700 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (15075 ms): Ok(())
2021-09-21 17:37:44.332807100 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (43347 ms): Err(Lagged(5))
2021-09-21 17:38:44.335269600 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (59129 ms): Ok(())
2021-09-21 17:40:10.003133300 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (84774 ms): Ok(())
2021-09-21 17:43:10.060240200 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (25690 ms): Ok(())
2021-09-21 17:45:12.709112500 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (28316 ms): Ok(())
2021-09-21 17:45:44.393584900 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (30605 ms): Err(Lagged(65))
2021-09-21 17:46:44.395335600 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (58222 ms): Err(Lagged(260))
2021-09-21 17:47:44.392690700 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (55383 ms): Err(Lagged(347))
2021-09-21 17:48:44.393535800 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (47611 ms): Err(Lagged(485))
2021-09-21 17:49:44.396478100 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (53356 ms): Err(Lagged(348))
2021-09-21 17:50:44.403330700 [wallet::console_wallet::debouncer] TRACE tokio::select! delay (53906 ms): Err(Lagged(1))
```

The balance refresh query time from before the 250 transactions was sent till after is shown below:

![image](https://user-images.githubusercontent.com/39146854/134289525-a140fd31-8fb7-44a0-9931-6569a0b827a8.png)


How Has This Been Tested?
---
System-level testing
  • Loading branch information
hansieodendaal committed Sep 22, 2021
1 parent dd23808 commit 4ac2fb2
Showing 1 changed file with 9 additions and 8 deletions.
17 changes: 9 additions & 8 deletions applications/tari_console_wallet/src/ui/state/debouncer.rs
Expand Up @@ -30,6 +30,7 @@ use tari_wallet::output_manager_service::handle::OutputManagerHandle;
use tokio::{
sync::{broadcast, RwLock},
time,
time::MissedTickBehavior,
};

const LOG_TARGET: &str = "wallet::console_wallet::debouncer";
Expand Down Expand Up @@ -61,8 +62,9 @@ impl BalanceEnquiryDebouncer {
pub async fn run(mut self) {
let balance_enquiry_events = &mut self.tx.subscribe();
let mut shutdown_signal = self.app_state_inner.read().await.get_shutdown_signal();
let delay = time::sleep(self.balance_enquiry_cooldown_period);
tokio::pin!(delay);
let mut interval = time::interval(self.balance_enquiry_cooldown_period);
interval.set_missed_tick_behavior(MissedTickBehavior::Delay);
tokio::pin!(interval);

debug!(target: LOG_TARGET, "Balance enquiry debouncer starting");
if let Ok(balance) = self.output_manager_service.get_balance().await {
Expand All @@ -80,13 +82,16 @@ impl BalanceEnquiryDebouncer {
}
loop {
tokio::select! {
_ = &mut delay => {
_ = interval.tick() => {
if let Ok(result) = time::timeout(
self.balance_enquiry_cooldown_period,
balance_enquiry_events.recv()
).await {
if let Err(broadcast::error::RecvError::Lagged(n)) = result {
trace!(target: LOG_TARGET, "Balance enquiry debouncer lagged {} update requests", n);
}
match result {
Ok(_) => {
Ok(_) | Err(broadcast::error::RecvError::Lagged(_)) => {
let start_time = Instant::now();
match self.output_manager_service.get_balance().await {
Ok(balance) => {
Expand All @@ -108,10 +113,6 @@ impl BalanceEnquiryDebouncer {
}
}
}
Err(broadcast::error::RecvError::Lagged(n)) => {
trace!(target: LOG_TARGET, "Balance enquiry debouncer lagged {} update requests", n);
continue;
}
Err(broadcast::error::RecvError::Closed) => {
info!(
target: LOG_TARGET,
Expand Down

0 comments on commit 4ac2fb2

Please sign in to comment.