Merge 'Simulator improvements' from Pekka Enberg

Reviewed-by: Jussi Saurio <jussi.saurio@gmail.com>

Closes #683

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();

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

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();
 
@@ -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<ResultSet>,
 ) -> Result<()> {
-    log::info!("executing: {}", interaction);
+    log::trace!("executing: {}", interaction);
     match interaction {
         generation::plan::Interaction::Query(_) => {
             let conn = match &mut env.connections[connection_index] {
@@ -326,3 +326,11 @@ fn compare_equal_rows(a: &[Vec<Value>], b: &[Vec<Value>]) {
         }
     }
 }
+
+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();
+}

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(

simulator/runner/file.rs

@@ -4,11 +4,22 @@ use limbo_core::{File, Result};
 pub(crate) struct SimulatorFile {
     pub(crate) inner: Rc<dyn File>,
     pub(crate) fault: RefCell<bool>,
+
+    /// Number of `pread` function calls (both success and failures).
+    pub(crate) nr_pread_calls: RefCell<usize>,
+
+    /// Number of `pread` function calls with injected fault.
     pub(crate) nr_pread_faults: RefCell<usize>,
+
+    /// Number of `pwrite` function calls (both success and failures).
+    pub(crate) nr_pwrite_calls: RefCell<usize>,
+
+    /// Number of `pwrite` function calls with injected fault.
     pub(crate) nr_pwrite_faults: RefCell<usize>,
-    pub(crate) writes: RefCell<usize>,
-    pub(crate) reads: RefCell<usize>,
-    pub(crate) syncs: RefCell<usize>,
+
+    /// Number of `sync` function calls (both success and failures).
+    pub(crate) nr_sync_calls: RefCell<usize>,
+
     pub(crate) page_size: usize,
 }
 
@@ -18,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(),
-            *self.reads.borrow(),
-            *self.writes.borrow(),
-            *self.syncs.borrow(),
+            "pread     {:8} {:8}",
+            *self.nr_pread_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);
     }
 }
 
@@ -49,13 +75,13 @@ impl limbo_core::File for SimulatorFile {
     }
 
     fn pread(&self, pos: usize, c: Rc<limbo_core::Completion>) -> 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 +91,18 @@ impl limbo_core::File for SimulatorFile {
         buffer: Rc<std::cell::RefCell<limbo_core::Buffer>>,
         c: Rc<limbo_core::Completion>,
     ) -> 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<limbo_core::Completion>) -> Result<()> {
-        *self.syncs.borrow_mut() += 1;
+        *self.nr_sync_calls.borrow_mut() += 1;
         self.inner.sync(c)
     }
 

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!();
         }
     }
 }
@@ -60,9 +63,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());