From 4ac2fb21a32b4a506f5faf371740ddec6297ae49 Mon Sep 17 00:00:00 2001 From: Hansie Odendaal <39146854+hansieodendaal@users.noreply.github.com> Date: Wed, 22 Sep 2021 16:43:18 +0200 Subject: [PATCH] fix: fix debouncer delay bug (#3376) 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 --- .../src/ui/state/debouncer.rs | 17 +++++++++-------- 1 file changed, 9 insertions(+), 8 deletions(-) diff --git a/applications/tari_console_wallet/src/ui/state/debouncer.rs b/applications/tari_console_wallet/src/ui/state/debouncer.rs index 1869779af7..b274cabb9b 100644 --- a/applications/tari_console_wallet/src/ui/state/debouncer.rs +++ b/applications/tari_console_wallet/src/ui/state/debouncer.rs @@ -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"; @@ -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 { @@ -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) => { @@ -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,