nostr/nostr-rs-relay
1
0
Fork 0
mirror of https://github.com/scsibug/nostr-rs-relay.git synced 2024-11-22 00:59:07 -05:00
Code Issues Packages Projects Releases Wiki Activity

improvement: log slow requests that return zero results

Browse Source
This commit is contained in:
Greg Heartsfield 2022-12-18 13:42:31 -06:00
parent b24d2f9aaa
commit 677b7d39e9
1 changed files with 32 additions and 27 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

59
src/db.rs
View File

@ -636,9 +636,11 @@ pub async fn db_query(
query_tx: tokio::sync::mpsc::Sender<QueryResult>, query_tx: tokio::sync::mpsc::Sender<QueryResult>,
mut abandon_query_rx: tokio::sync::oneshot::Receiver<()>, mut abandon_query_rx: tokio::sync::oneshot::Receiver<()>,
) { ) {
let start = Instant::now();
task::spawn_blocking(move || { task::spawn_blocking(move || {
let mut row_count: usize = 0; debug!("moved DB query to thread in {:?}", start.elapsed());
let start = Instant::now(); let start = Instant::now();
let mut row_count: usize = 0;
// generate SQL query // generate SQL query
let (q, p) = query_from_sub(&sub); let (q, p) = query_from_sub(&sub);
debug!("SQL generated in {:?}", start.elapsed()); debug!("SQL generated in {:?}", start.elapsed());
@ -647,44 +649,47 @@ pub async fn db_query(
// 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();
let mut slow_first_event;
if let Ok(conn) = pool.get() { if let Ok(conn) = pool.get() {
// execute the query. Don't cache, since queries vary so much. // execute the query. Don't cache, since queries vary so much.
let mut stmt = conn.prepare(&q)?; let mut stmt = conn.prepare(&q)?;
let mut event_rows = stmt.query(rusqlite::params_from_iter(p))?; let mut event_rows = stmt.query(rusqlite::params_from_iter(p))?;
let mut first_result = true; let mut first_result = true;
while let Some(row) = event_rows.next()? { while let Some(row) = event_rows.next()? {
let first_event_elapsed = start.elapsed();
slow_first_event = first_event_elapsed >= slow_cutoff;
if first_result { if first_result {
let first_result_elapsed = start.elapsed();
// logging for slow queries; show sub and SQL
if first_result_elapsed >= slow_cutoff {
info!(
"query req (slow): {:?} (cid: {}, sub: {:?})",
sub, client_id, sub.id
);
info!(
"query string (slow): {} (cid: {}, sub: {:?})",
q, client_id, sub.id
);
} else {
trace!(
"query req: {:?} (cid: {}, sub: {:?})",
sub,
client_id,
sub.id
);
trace!(
"query string: {} (cid: {}, sub: {:?})",
q,
client_id,
sub.id
);
}
debug!( debug!(
"first result in {:?} (cid: {}, sub: {:?})", "first result in {:?} (cid: {}, sub: {:?})",
first_result_elapsed, client_id, sub.id first_event_elapsed, client_id, sub.id
); );
first_result = false; first_result = false;
} }
// logging for slow queries; show sub and SQL
//
if slow_first_event {
info!(
"query req (slow): {:?} (cid: {}, sub: {:?})",
sub, client_id, sub.id
);
info!(
"query string (slow): {} (cid: {}, sub: {:?})",
q, client_id, sub.id
);
} else {
trace!(
"query req: {:?} (cid: {}, sub: {:?})",
sub,
client_id,
sub.id
);
trace!(
"query string: {} (cid: {}, sub: {:?})",
q,
client_id,
sub.id
);
}
// check if this is still active // check if this is still active
// TODO: check every N rows // TODO: check every N rows
if abandon_query_rx.try_recv().is_ok() { if abandon_query_rx.try_recv().is_ok() {