diff --git a/Cargo.lock b/Cargo.lock index 09c3d7b25..c12346524 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -497,6 +497,8 @@ dependencies = [ "rusqlite", "tempfile", "test-log", + "tracing", + "tracing-subscriber", ] [[package]] diff --git a/cli/main.rs b/cli/main.rs index a3939fbc5..93344884b 100644 --- a/cli/main.rs +++ b/cli/main.rs @@ -7,7 +7,7 @@ mod opcodes_dictionary; use rustyline::{error::ReadlineError, Config, Editor}; use std::sync::atomic::Ordering; -use tracing_subscriber::{fmt, prelude::*, EnvFilter}; +use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter}; fn rustyline_config() -> Config { Config::builder() @@ -18,7 +18,11 @@ fn rustyline_config() -> Config { fn main() -> anyhow::Result<()> { let mut rl = Editor::with_config(rustyline_config())?; tracing_subscriber::registry() - .with(fmt::layer()) + .with( + tracing_subscriber::fmt::layer() + .with_line_number(true) + .with_thread_ids(true), + ) .with(EnvFilter::from_default_env()) .init(); let mut app = app::Limbo::new(&mut rl)?; diff --git a/core/vdbe/mod.rs b/core/vdbe/mod.rs index d62c4e23f..c00674438 100644 --- a/core/vdbe/mod.rs +++ b/core/vdbe/mod.rs @@ -73,6 +73,7 @@ use std::ffi::c_void; use std::num::NonZero; use std::rc::{Rc, Weak}; use std::sync::{Arc, Mutex}; +use tracing::instrument; #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)] /// Represents a target for a jump instruction. @@ -348,6 +349,7 @@ impl Program { } } + #[instrument(skip_all)] pub fn step(&self, state: &mut ProgramState, pager: Rc) -> Result { loop { if state.is_interrupted() { diff --git a/tests/Cargo.toml b/tests/Cargo.toml index aba2c5529..831860687 100644 --- a/tests/Cargo.toml +++ b/tests/Cargo.toml @@ -27,6 +27,8 @@ rand = "0.9.0" [dev-dependencies] test-log = { version = "0.2.17", features = ["trace"] } +tracing-subscriber = { version = "0.3.19", features = ["env-filter"] } +tracing = "0.1.41" # rexpect does not support windows. [target.'cfg(not(windows))'.dependencies] diff --git a/tests/integration/wal/test_wal.rs b/tests/integration/wal/test_wal.rs index 7ef3f2ae1..9e064d3bc 100644 --- a/tests/integration/wal/test_wal.rs +++ b/tests/integration/wal/test_wal.rs @@ -4,10 +4,14 @@ use std::cell::RefCell; use std::ops::{Add, Deref}; use std::rc::Rc; use std::sync::{Arc, Mutex}; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::util::SubscriberInitExt; +use tracing_subscriber::EnvFilter; #[allow(clippy::arc_with_non_send_sync)] -#[test_log::test] +#[test] fn test_wal_checkpoint_result() -> Result<()> { + setup_tracing(); let tmp_db = TempDatabase::new("test_wal.db"); let conn = tmp_db.connect_limbo(); conn.execute("CREATE TABLE t1 (id text);")?; @@ -31,87 +35,6 @@ fn test_wal_checkpoint_result() -> Result<()> { Ok(()) } -#[test] -#[ignore = "Multi threaded seems to not work but this tests proves the point for later fiixes"] -fn test_wal_1_writer_1_reader() -> Result<()> { - let tmp_db = Arc::new(Mutex::new(TempDatabase::new("test_wal.db"))); - let db = tmp_db.lock().unwrap().limbo_database(); - - { - let conn = db.connect().unwrap(); - match conn.query("CREATE TABLE t (id)")? { - Some(ref mut rows) => loop { - match rows.step().unwrap() { - StepResult::Row => {} - StepResult::IO => { - tmp_db.lock().unwrap().io.run_once().unwrap(); - } - StepResult::Interrupt => break, - StepResult::Done => break, - StepResult::Busy => unreachable!(), - } - }, - None => todo!(), - } - do_flush(&conn, tmp_db.lock().unwrap().deref()).unwrap(); - } - let rows = Arc::new(std::sync::Mutex::new(0)); - let rows_ = rows.clone(); - const ROWS_WRITE: usize = 1000; - let tmp_db_w = db.clone(); - let writer_thread = std::thread::spawn(move || { - let conn = tmp_db_w.connect().unwrap(); - for i in 0..ROWS_WRITE { - println!("adding {}", i); - conn.execute(format!("INSERT INTO t values({})", i).as_str()) - .unwrap(); - let _ = rows_.lock().unwrap().add(1); - } - }); - let rows_ = rows.clone(); - let reader_thread = std::thread::spawn(move || { - let conn = db.connect().unwrap(); - loop { - let rows = *rows_.lock().unwrap(); - let mut i = 0; - // println!("reading {}", rows); - match conn.query("SELECT * FROM t") { - Ok(Some(ref mut rows)) => loop { - match rows.step().unwrap() { - StepResult::Row => { - let row = rows.row().unwrap(); - let first_value = row.get_value(0); - let id = match first_value { - limbo_core::OwnedValue::Integer(i) => *i as i32, - _ => unreachable!(), - }; - assert_eq!(id, i); - i += 1; - } - StepResult::IO => { - tmp_db.lock().unwrap().io.run_once().unwrap(); - } - StepResult::Interrupt => break, - StepResult::Done => break, - StepResult::Busy => unreachable!(), - } - }, - Ok(None) => {} - Err(err) => { - eprintln!("{}", err); - } - } - if rows == ROWS_WRITE { - break; - } - } - }); - - writer_thread.join().unwrap(); - reader_thread.join().unwrap(); - Ok(()) -} - /// Execute a statement and get strings result pub(crate) fn execute_and_get_strings( tmp_db: &TempDatabase,