improvement: DB pool logging shows used connections directly

This commit is contained in:
Greg Heartsfield 2022-12-16 17:01:49 -06:00
parent 838aafd079
commit 7ca9c864f2
2 changed files with 17 additions and 5 deletions

View File

@ -597,6 +597,15 @@ fn query_from_sub(sub: &Subscription) -> (String, Vec<Box<dyn ToSql>>) {
(query, params) (query, params)
} }
fn log_pool_stats(pool: &SqlitePool) {
let state: r2d2::State = pool.state();
let in_use_cxns = state.connections - state.idle_connections;
debug!(
"DB pool usage (in_use: {}, available: {})",
in_use_cxns, state.connections
);
}
/// Perform a database query using a subscription. /// Perform a database query using a subscription.
/// ///
/// The [`Subscription`] is converted into a SQL query. Each result /// The [`Subscription`] is converted into a SQL query. Each result
@ -617,7 +626,7 @@ pub async fn db_query(
let (q, p) = query_from_sub(&sub); let (q, p) = query_from_sub(&sub);
trace!("SQL generated in {:?}", start.elapsed()); trace!("SQL generated in {:?}", start.elapsed());
// show pool stats // show pool stats
debug!("DB pool stats: {:?}", pool.state()); log_pool_stats(&pool);
// cutoff for displaying slow queries // cutoff for displaying slow queries
let slow_cutoff = Duration::from_millis(1000); let slow_cutoff = Duration::from_millis(1000);
let start = Instant::now(); let start = Instant::now();

View File

@ -311,6 +311,7 @@ pub fn start_server(settings: Settings, shutdown_rx: MpscReceiver<()>) -> Result
controlled_shutdown.send(()).ok(); controlled_shutdown.send(()).ok();
} }
Err(std::sync::mpsc::RecvError) => { Err(std::sync::mpsc::RecvError) => {
// FIXME: spurious error on startup?
debug!("shutdown requestor is disconnected"); debug!("shutdown requestor is disconnected");
} }
}; };
@ -431,6 +432,8 @@ async fn nostr_server(
event_tx: mpsc::Sender<SubmittedEvent>, event_tx: mpsc::Sender<SubmittedEvent>,
mut shutdown: Receiver<()>, mut shutdown: Receiver<()>,
) { ) {
// the time this websocket nostr server started
let orig_start = Instant::now();
// get a broadcast channel for clients to communicate on // get a broadcast channel for clients to communicate on
let mut bcast_rx = broadcast.subscribe(); let mut bcast_rx = broadcast.subscribe();
// Track internal client state // Track internal client state
@ -461,7 +464,6 @@ async fn nostr_server(
let mut running_queries: HashMap<String, oneshot::Sender<()>> = HashMap::new(); let mut running_queries: HashMap<String, oneshot::Sender<()>> = HashMap::new();
// keep track of the subscriptions we have // keep track of the subscriptions we have
let mut current_subs: Vec<Subscription> = Vec::new(); let mut current_subs: Vec<Subscription> = Vec::new();
// for stats, keep track of how many events the client published, // for stats, keep track of how many events the client published,
// and how many it received from queries. // and how many it received from queries.
let mut client_published_event_count: usize = 0; let mut client_published_event_count: usize = 0;
@ -473,7 +475,7 @@ async fn nostr_server(
loop { loop {
tokio::select! { tokio::select! {
_ = shutdown.recv() => { _ = shutdown.recv() => {
info!("Close connection down due to shutdown, client: {}, ip: {:?}", cid, conn.ip()); info!("Close connection down due to shutdown, client: {}, ip: {:?}, connected: {:?}", cid, conn.ip(), orig_start.elapsed());
// server shutting down, exit loop // server shutting down, exit loop
break; break;
}, },
@ -676,10 +678,11 @@ async fn nostr_server(
stop_tx.send(()).ok(); stop_tx.send(()).ok();
} }
info!( info!(
"stopping client connection (cid: {}, ip: {:?}, sent: {} events, recv: {} events)", "stopping client connection (cid: {}, ip: {:?}, sent: {} events, recv: {} events, connected: {:?})",
cid, cid,
conn.ip(), conn.ip(),
client_published_event_count, client_published_event_count,
client_received_event_count client_received_event_count,
orig_start.elapsed()
); );
} }