improvement: log filter in a reusable format for slow queries

This commit is contained in:
Greg Heartsfield 2023-01-31 18:09:43 -06:00
parent 111eb4a10c
commit 6d57adef73
2 changed files with 25 additions and 10 deletions

View File

@ -347,7 +347,7 @@ impl NostrRepo for SqliteRepo {
let start = Instant::now(); let start = Instant::now();
let mut row_count: usize = 0; let mut row_count: usize = 0;
// cutoff for displaying slow queries // cutoff for displaying slow queries
let slow_cutoff = Duration::from_millis(2000); let slow_cutoff = Duration::from_millis(1000);
let mut filter_count = 0; let mut filter_count = 0;
for filter in sub.filters.iter() { for filter in sub.filters.iter() {
let filter_start = Instant::now(); let filter_start = Instant::now();
@ -356,7 +356,7 @@ impl NostrRepo for SqliteRepo {
let sql_gen_elapsed = start.elapsed(); let sql_gen_elapsed = start.elapsed();
if sql_gen_elapsed > Duration::from_millis(10) { if sql_gen_elapsed > Duration::from_millis(10) {
debug!("SQL (slow) generated in {:?}", start.elapsed()); debug!("SQL (slow) generated in {:?}", filter_start.elapsed());
} }
// any client that doesn't cause us to generate new rows in 5 // any client that doesn't cause us to generate new rows in 5
// seconds gets dropped. // seconds gets dropped.
@ -379,16 +379,16 @@ impl NostrRepo for SqliteRepo {
"first result in {:?} (cid: {}, sub: {:?}, filter: {}) [used index: {:?}]", "first result in {:?} (cid: {}, sub: {:?}, filter: {}) [used index: {:?}]",
first_event_elapsed, client_id, sub.id, filter_count, idx first_event_elapsed, client_id, sub.id, filter_count, idx
); );
// logging for slow queries; show filter and SQL.
// to reduce logging; only show 1/16th of clients (leading 0)
if slow_first_event && client_id.starts_with('0') {
debug!(
"filter first result (slow): {} (cid: {}, sub: {:?})",
serde_json::to_string(&filter)?, client_id, sub.id
);
}
first_result = false; first_result = false;
} }
// logging for slow queries; show sub and SQL.
// to reduce logging; only show 1/16th of clients (leading 0)
if row_count == 0 && slow_first_event && client_id.starts_with('0') {
debug!(
"query filter req (slow): {:?} (cid: {}, sub: {:?})",
filter, client_id, sub.id
);
}
// check if a checkpoint is trying to run, and abort // check if a checkpoint is trying to run, and abort
if row_count % 100 == 0 { if row_count % 100 == 0 {
{ {
@ -447,6 +447,14 @@ impl NostrRepo for SqliteRepo {
} else { } else {
warn!("Could not get a database connection for querying"); warn!("Could not get a database connection for querying");
} }
// if the filter took more than 1 second of db_time, print out the JSON.
if start.elapsed() > slow_cutoff && client_id.starts_with('0') {
debug!(
"query filter req (slow): {} (cid: {}, sub: {:?})",
serde_json::to_string(&filter)?, client_id, sub.id
);
}
} }
drop(sem); // new query can begin drop(sem); // new query can begin
debug!( debug!(

View File

@ -22,16 +22,22 @@ pub struct Subscription {
#[derive(Serialize, PartialEq, Eq, Debug, Clone)] #[derive(Serialize, PartialEq, Eq, Debug, Clone)]
pub struct ReqFilter { pub struct ReqFilter {
/// Event hashes /// Event hashes
#[serde(skip_serializing_if="Option::is_none")]
pub ids: Option<Vec<String>>, pub ids: Option<Vec<String>>,
/// Event kinds /// Event kinds
#[serde(skip_serializing_if="Option::is_none")]
pub kinds: Option<Vec<u64>>, pub kinds: Option<Vec<u64>>,
/// Events published after this time /// Events published after this time
#[serde(skip_serializing_if="Option::is_none")]
pub since: Option<u64>, pub since: Option<u64>,
/// Events published before this time /// Events published before this time
#[serde(skip_serializing_if="Option::is_none")]
pub until: Option<u64>, pub until: Option<u64>,
/// List of author public keys /// List of author public keys
#[serde(skip_serializing_if="Option::is_none")]
pub authors: Option<Vec<String>>, pub authors: Option<Vec<String>>,
/// Limit number of results /// Limit number of results
#[serde(skip_serializing_if="Option::is_none")]
pub limit: Option<u64>, pub limit: Option<u64>,
/// Set of tags /// Set of tags
#[serde(skip)] #[serde(skip)]
@ -40,6 +46,7 @@ pub struct ReqFilter {
// we can't represent it in the req filter, so we don't want to // we can't represent it in the req filter, so we don't want to
// erroneously match. This basically indicates the req tried to // erroneously match. This basically indicates the req tried to
// do something invalid. // do something invalid.
#[serde(skip)]
pub force_no_match: bool, pub force_no_match: bool,
} }