From be7a8e6e908b1777b2043ba724a11fce712b8bff Mon Sep 17 00:00:00 2001 From: Lev Date: Tue, 5 Dec 2023 01:45:37 -0800 Subject: [PATCH 1/3] Revert "Reset wait times when checked out successfully (#656)" This reverts commit ec3920d60f7ad26a2b71820b3e3076e8f8ec5978. --- src/stats/client.rs | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/stats/client.rs b/src/stats/client.rs index c3a636d0..0079fbad 100644 --- a/src/stats/client.rs +++ b/src/stats/client.rs @@ -109,7 +109,6 @@ 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 @@ -125,7 +124,6 @@ impl ClientStats { /// 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 From 7d33df3f594b1c71e4fedfcf0ef8c8116207d537 Mon Sep 17 00:00:00 2001 From: Lev Date: Tue, 5 Dec 2023 01:45:48 -0800 Subject: [PATCH 2/3] Revert "Not sure how this sneaked past CI" This reverts commit 4c5498b915edbaa51b392bf3dd4078d325b7b082. --- src/admin.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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(), From cf3ac05a39185c8b80d7c92e79961f134438234d Mon Sep 17 00:00:00 2001 From: Lev Date: Tue, 5 Dec 2023 01:45:57 -0800 Subject: [PATCH 3/3] Revert "only report wait times from clients currently waiting to match behavior of pgbouncer (#655)" This reverts commit 0e8064b049adaca18a0c1fbed4bae884265e23de. --- src/stats/client.rs | 15 +++++---------- src/stats/pool.rs | 14 +++----------- tests/ruby/stats_spec.rb | 16 ++++------------ 3 files changed, 12 insertions(+), 33 deletions(-) diff --git a/src/stats/client.rs b/src/stats/client.rs index 0079fbad..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)), @@ -113,11 +111,6 @@ impl ClientStats { /// 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); } @@ -141,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