From 5b4c7ec7f5c7c04bb15731086a55cf5d0d56c256 Mon Sep 17 00:00:00 2001 From: Pekka Enberg Date: Tue, 14 Jan 2025 17:24:14 +0200 Subject: [PATCH 1/7] simulator: Rename stats in SimulatorFile --- simulator/runner/file.rs | 29 ++++++++++++++++++++--------- simulator/runner/io.rs | 6 +++--- 2 files changed, 23 insertions(+), 12 deletions(-) diff --git a/simulator/runner/file.rs b/simulator/runner/file.rs index e0153f2b3..bc23eff89 100644 --- a/simulator/runner/file.rs +++ b/simulator/runner/file.rs @@ -4,11 +4,22 @@ use limbo_core::{File, Result}; pub(crate) struct SimulatorFile { pub(crate) inner: Rc, pub(crate) fault: RefCell, + + /// Number of `pread` function calls (both success and failures). + pub(crate) nr_pread_calls: RefCell, + + /// Number of `pread` function calls with injected fault. pub(crate) nr_pread_faults: RefCell, + + /// Number of `pwrite` function calls (both success and failures). + pub(crate) nr_pwrite_calls: RefCell, + + /// Number of `pwrite` function calls with injected fault. pub(crate) nr_pwrite_faults: RefCell, - pub(crate) writes: RefCell, - pub(crate) reads: RefCell, - pub(crate) syncs: RefCell, + + /// Number of `sync` function calls (both success and failures). + pub(crate) nr_sync_calls: RefCell, + pub(crate) page_size: usize, } @@ -22,9 +33,9 @@ impl SimulatorFile { "pread faults: {}, pwrite faults: {}, reads: {}, writes: {}, syncs: {}", *self.nr_pread_faults.borrow(), *self.nr_pwrite_faults.borrow(), - *self.reads.borrow(), - *self.writes.borrow(), - *self.syncs.borrow(), + *self.nr_pread_calls.borrow(), + *self.nr_pwrite_calls.borrow(), + *self.nr_sync_calls.borrow(), ); } } @@ -49,13 +60,13 @@ impl limbo_core::File for SimulatorFile { } fn pread(&self, pos: usize, c: Rc) -> Result<()> { + *self.nr_pread_calls.borrow_mut() += 1; if *self.fault.borrow() { *self.nr_pread_faults.borrow_mut() += 1; return Err(limbo_core::LimboError::InternalError( "Injected fault".into(), )); } - *self.reads.borrow_mut() += 1; self.inner.pread(pos, c) } @@ -65,18 +76,18 @@ impl limbo_core::File for SimulatorFile { buffer: Rc>, c: Rc, ) -> Result<()> { + *self.nr_pwrite_calls.borrow_mut() += 1; if *self.fault.borrow() { *self.nr_pwrite_faults.borrow_mut() += 1; return Err(limbo_core::LimboError::InternalError( "Injected fault".into(), )); } - *self.writes.borrow_mut() += 1; self.inner.pwrite(pos, buffer, c) } fn sync(&self, c: Rc) -> Result<()> { - *self.syncs.borrow_mut() += 1; + *self.nr_sync_calls.borrow_mut() += 1; self.inner.sync(c) } diff --git a/simulator/runner/io.rs b/simulator/runner/io.rs index c039764b0..ce4f45231 100644 --- a/simulator/runner/io.rs +++ b/simulator/runner/io.rs @@ -60,9 +60,9 @@ impl IO for SimulatorIO { fault: RefCell::new(false), nr_pread_faults: RefCell::new(0), nr_pwrite_faults: RefCell::new(0), - reads: RefCell::new(0), - writes: RefCell::new(0), - syncs: RefCell::new(0), + nr_pread_calls: RefCell::new(0), + nr_pwrite_calls: RefCell::new(0), + nr_sync_calls: RefCell::new(0), page_size: self.page_size, }); self.files.borrow_mut().push(file.clone()); From 14ec057a3414dd6fdc790ac30528e6af1f35f47c Mon Sep 17 00:00:00 2001 From: Pekka Enberg Date: Tue, 14 Jan 2025 17:30:11 +0200 Subject: [PATCH 2/7] simulator: Make stats printout prettier ``` op calls faults --------- -------- -------- pread 3 0 pwrite 1 0 sync 0 0 --------- -------- -------- total 4 0 ``` --- simulator/runner/file.rs | 25 ++++++++++++++++++++----- simulator/runner/io.rs | 3 +++ 2 files changed, 23 insertions(+), 5 deletions(-) diff --git a/simulator/runner/file.rs b/simulator/runner/file.rs index bc23eff89..685a60af2 100644 --- a/simulator/runner/file.rs +++ b/simulator/runner/file.rs @@ -29,14 +29,29 @@ impl SimulatorFile { } pub(crate) fn print_stats(&self) { + println!("op calls faults"); + println!("--------- -------- --------"); println!( - "pread faults: {}, pwrite faults: {}, reads: {}, writes: {}, syncs: {}", - *self.nr_pread_faults.borrow(), - *self.nr_pwrite_faults.borrow(), + "pread {:8} {:8}", *self.nr_pread_calls.borrow(), - *self.nr_pwrite_calls.borrow(), - *self.nr_sync_calls.borrow(), + *self.nr_pread_faults.borrow() ); + println!( + "pwrite {:8} {:8}", + *self.nr_pwrite_calls.borrow(), + *self.nr_pwrite_faults.borrow() + ); + println!( + "sync {:8} {:8}", + *self.nr_sync_calls.borrow(), + 0 // No fault counter for sync + ); + println!("--------- -------- --------"); + let sum_calls = *self.nr_pread_calls.borrow() + + *self.nr_pwrite_calls.borrow() + + *self.nr_sync_calls.borrow(); + let sum_faults = *self.nr_pread_faults.borrow() + *self.nr_pwrite_faults.borrow(); + println!("total {:8} {:8}", sum_calls, sum_faults); } } diff --git a/simulator/runner/io.rs b/simulator/runner/io.rs index ce4f45231..e7802b40f 100644 --- a/simulator/runner/io.rs +++ b/simulator/runner/io.rs @@ -42,7 +42,10 @@ impl SimulatorIO { pub(crate) fn print_stats(&self) { println!("run_once faults: {}", self.nr_run_once_faults.borrow()); for file in self.files.borrow().iter() { + println!(); + println!("==========================="); file.print_stats(); + println!(); } } } From e1f5fa875ea6339ec3a8c7723299d56bb3a1b37f Mon Sep 17 00:00:00 2001 From: Pekka Enberg Date: Tue, 14 Jan 2025 17:37:53 +0200 Subject: [PATCH 3/7] simulator: Make simulator runs longer by default --- simulator/runner/cli.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/simulator/runner/cli.rs b/simulator/runner/cli.rs index 8ad42c8b3..71923a92e 100644 --- a/simulator/runner/cli.rs +++ b/simulator/runner/cli.rs @@ -18,14 +18,14 @@ pub struct SimulatorCLI { short = 'n', long, help = "change the maximum size of the randomly generated sequence of interactions", - default_value_t = 1024 + default_value_t = 20000 )] pub maximum_size: usize, #[clap( short = 'k', long, help = "change the minimum size of the randomly generated sequence of interactions", - default_value_t = 1 + default_value_t = 10000 )] pub minimum_size: usize, #[clap( From 3c6c6041ffa7c7e0c41676c322f753cce0268701 Mon Sep 17 00:00:00 2001 From: Pekka Enberg Date: Tue, 14 Jan 2025 17:41:07 +0200 Subject: [PATCH 4/7] simulator: Log query errors with debug level ...it is totally fine for a SQL query to fail as part of the simulation. For example, if we attempt to create a table that already exists, the expectation is that the query fails. No need to spam the logs. --- simulator/generation/plan.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/simulator/generation/plan.rs b/simulator/generation/plan.rs index dbf6dd7f6..367a18c02 100644 --- a/simulator/generation/plan.rs +++ b/simulator/generation/plan.rs @@ -209,7 +209,7 @@ impl Interaction { let rows = conn.query(&query_str); if rows.is_err() { let err = rows.err(); - log::error!( + log::debug!( "Error running query '{}': {:?}", &query_str[0..query_str.len().min(4096)], err From d355ce785cac40e1a88ebf084014a7198ac43773 Mon Sep 17 00:00:00 2001 From: Pekka Enberg Date: Tue, 14 Jan 2025 17:54:17 +0200 Subject: [PATCH 5/7] core/storage: Remove debug printout --- core/storage/sqlite3_ondisk.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/core/storage/sqlite3_ondisk.rs b/core/storage/sqlite3_ondisk.rs index 8dbda073b..5b54be756 100644 --- a/core/storage/sqlite3_ondisk.rs +++ b/core/storage/sqlite3_ondisk.rs @@ -1245,7 +1245,6 @@ pub fn begin_write_wal_frame( *write_counter.borrow_mut() += 1; let write_complete = { let buf_copy = buffer.clone(); - log::info!("finished"); Box::new(move |bytes_written: i32| { let buf_copy = buf_copy.clone(); let buf_len = buf_copy.borrow().len(); From 30a380cab137083d8f5a2260794aa86507a1954e Mon Sep 17 00:00:00 2001 From: Pekka Enberg Date: Tue, 14 Jan 2025 17:54:29 +0200 Subject: [PATCH 6/7] simulator: Move more logging under trace level --- simulator/main.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/simulator/main.rs b/simulator/main.rs index 52c33d5ec..504adf50b 100644 --- a/simulator/main.rs +++ b/simulator/main.rs @@ -269,7 +269,7 @@ fn execute_plan( let interaction = &plan.plan[plan.interaction_pointer]; if let SimConnection::Disconnected = connection { - log::info!("connecting {}", connection_index); + log::trace!("connecting {}", connection_index); env.connections[connection_index] = SimConnection::Connected(env.db.connect()); } else { match execute_interaction(env, connection_index, interaction, &mut plan.stack) { @@ -293,7 +293,7 @@ fn execute_interaction( interaction: &Interaction, stack: &mut Vec, ) -> Result<()> { - log::info!("executing: {}", interaction); + log::trace!("executing: {}", interaction); match interaction { generation::plan::Interaction::Query(_) => { let conn = match &mut env.connections[connection_index] { From 0c7ebd4df5eaa20b964c862e01e33a57e4e041b5 Mon Sep 17 00:00:00 2001 From: Pekka Enberg Date: Tue, 14 Jan 2025 17:54:39 +0200 Subject: [PATCH 7/7] simulator: Enable info-level logging by default --- simulator/main.rs | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/simulator/main.rs b/simulator/main.rs index 504adf50b..3d9752b77 100644 --- a/simulator/main.rs +++ b/simulator/main.rs @@ -20,7 +20,7 @@ mod model; mod runner; fn main() { - let _ = env_logger::try_init(); + init_logger(); let cli_opts = SimulatorCLI::parse(); @@ -326,3 +326,11 @@ fn compare_equal_rows(a: &[Vec], b: &[Vec]) { } } } + +fn init_logger() { + env_logger::Builder::from_env(env_logger::Env::default().filter_or("RUST_LOG", "info")) + .format_timestamp(None) + .format_module_path(false) + .format_target(false) + .init(); +}