diff --git a/src/admin.rs b/src/admin.rs index f7be8665..22bbb0af 100644 --- a/src/admin.rs +++ b/src/admin.rs @@ -699,7 +699,7 @@ where res.put(row_description(&columns)); for (_, client) in new_map { - let max_wait = client.wait_start.load(Ordering::Relaxed); + let max_wait = client.max_wait_time.load(Ordering::Relaxed); let row = vec![ format!("{:#010X}", client.client_id()), client.pool_name(), diff --git a/src/stats/client.rs b/src/stats/client.rs index c3a636d0..6a30ec15 100644 --- a/src/stats/client.rs +++ b/src/stats/client.rs @@ -38,10 +38,8 @@ pub struct ClientStats { /// Total time spent waiting for a connection from pool, measures in microseconds pub total_wait_time: Arc, - /// When this client started waiting. - /// Stored as microseconds since connect_time so it can fit in an AtomicU64 instead - /// of us using an "AtomicInstant" - pub wait_start: Arc, + /// Maximum time spent waiting for a connection from pool, measures in microseconds + pub max_wait_time: Arc, /// Current state of the client pub state: Arc, @@ -65,7 +63,7 @@ impl Default for ClientStats { username: String::new(), pool_name: String::new(), total_wait_time: Arc::new(AtomicU64::new(0)), - wait_start: Arc::new(AtomicU64::new(0)), + max_wait_time: Arc::new(AtomicU64::new(0)), state: Arc::new(AtomicClientState::new(ClientState::Idle)), transaction_count: Arc::new(AtomicU64::new(0)), query_count: Arc::new(AtomicU64::new(0)), @@ -109,23 +107,16 @@ impl ClientStats { /// Reports a client is done querying the server and is no longer assigned a server connection pub fn idle(&self) { self.state.store(ClientState::Idle, Ordering::Relaxed); - self.wait_start.store(0, Ordering::Relaxed); } /// Reports a client is waiting for a connection pub fn waiting(&self) { - // safe to truncate, we only lose info if duration is greater than ~585,000 years - self.wait_start.store( - Instant::now().duration_since(self.connect_time).as_micros() as u64, - Ordering::Relaxed, - ); self.state.store(ClientState::Waiting, Ordering::Relaxed); } /// Reports a client is done waiting for a connection and is about to query the server. pub fn active(&self) { self.state.store(ClientState::Active, Ordering::Relaxed); - self.wait_start.store(0, Ordering::Relaxed); } /// Reports a client has failed to obtain a connection from a connection pool @@ -143,6 +134,8 @@ impl ClientStats { pub fn checkout_time(&self, microseconds: u64) { self.total_wait_time .fetch_add(microseconds, Ordering::Relaxed); + self.max_wait_time + .fetch_max(microseconds, Ordering::Relaxed); } /// Report a query executed by a client against a server diff --git a/src/stats/pool.rs b/src/stats/pool.rs index a3724bdd..46c74632 100644 --- a/src/stats/pool.rs +++ b/src/stats/pool.rs @@ -4,7 +4,6 @@ use super::{ClientState, ServerState}; use crate::{config::PoolMode, messages::DataType, pool::PoolIdentifier}; use std::collections::HashMap; use std::sync::atomic::*; -use tokio::time::Instant; use crate::pool::get_all_pools; @@ -54,7 +53,6 @@ impl PoolStats { ); } - let now = Instant::now(); for client in client_map.values() { match map.get_mut(&PoolIdentifier { db: client.pool_name(), @@ -64,16 +62,10 @@ impl PoolStats { match client.state.load(Ordering::Relaxed) { ClientState::Active => pool_stats.cl_active += 1, ClientState::Idle => pool_stats.cl_idle += 1, - ClientState::Waiting => { - pool_stats.cl_waiting += 1; - // wait_start is measured as microseconds since connect_time - // so compute wait_time as (now() - connect_time) - (wait_start - connect_time) - let duration_since_connect = now.duration_since(client.connect_time()); - let wait_time = (duration_since_connect.as_micros() as u64) - - client.wait_start.load(Ordering::Relaxed); - pool_stats.maxwait = std::cmp::max(pool_stats.maxwait, wait_time); - } + ClientState::Waiting => pool_stats.cl_waiting += 1, } + let max_wait = client.max_wait_time.load(Ordering::Relaxed); + pool_stats.maxwait = std::cmp::max(pool_stats.maxwait, max_wait); } None => debug!("Client from an obselete pool"), } diff --git a/tests/ruby/stats_spec.rb b/tests/ruby/stats_spec.rb index 2d635f0a..ddf63cd3 100644 --- a/tests/ruby/stats_spec.rb +++ b/tests/ruby/stats_spec.rb @@ -233,7 +233,7 @@ sleep(1.1) # Allow time for stats to update admin_conn = PG::connect(processes.pgcat.admin_connection_string) results = admin_conn.async_exec("SHOW POOLS")[0] - %w[cl_idle cl_cancel_req sv_idle sv_used sv_tested sv_login].each do |s| + %w[cl_idle cl_cancel_req sv_idle sv_used sv_tested sv_login maxwait].each do |s| raise StandardError, "Field #{s} was expected to be 0 but found to be #{results[s]}" if results[s] != "0" end @@ -260,20 +260,12 @@ threads << Thread.new { c.async_exec("SELECT pg_sleep(1.5)") rescue nil } end - admin_conn = PG::connect(processes.pgcat.admin_connection_string) - - # two connections waiting => they report wait time - sleep(1.1) # Allow time for stats to update - results = admin_conn.async_exec("SHOW POOLS")[0] - expect(results["maxwait"]).to eq("1") - expect(results["maxwait_us"].to_i).to be_within(200_000).of(100_000) - sleep(2.5) # Allow time for stats to update + admin_conn = PG::connect(processes.pgcat.admin_connection_string) results = admin_conn.async_exec("SHOW POOLS")[0] - # no connections waiting => no reported wait time - expect(results["maxwait"]).to eq("0") - expect(results["maxwait_us"]).to eq("0") + expect(results["maxwait"]).to eq("1") + expect(results["maxwait_us"].to_i).to be_within(200_000).of(500_000) connections.map(&:close) sleep(4.5) # Allow time for stats to update