From 9a01e32c019800b6ddeb4dc9f04a633acbce71e9 Mon Sep 17 00:00:00 2001 From: Pere Diaz Bou Date: Wed, 5 Mar 2025 12:43:26 +0100 Subject: [PATCH 1/4] add tracing_subscriber and test_log::test I don't know when and why we dropped log::* in favor of tracing but when it was done, it made relevant logs not appear any more while debugging so... I added test_log::test which helps by automatically adding info logs from trace package. --- Cargo.lock | 148 ++++++++++++++++++++++++++++-- cli/Cargo.toml | 10 +- cli/main.rs | 6 +- core/Cargo.toml | 9 +- core/storage/btree.rs | 7 +- tests/Cargo.toml | 3 + tests/integration/wal/test_wal.rs | 2 +- 7 files changed, 167 insertions(+), 18 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index ee0f3efd4..09c3d7b25 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -249,7 +249,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "531a9155a481e2ee699d4f98f43c0ca4ff8ee1bfd55c31e9e98fb29d2b176fe0" dependencies = [ "memchr", - "regex-automata", + "regex-automata 0.4.9", "serde", ] @@ -496,6 +496,7 @@ dependencies = [ "rexpect", "rusqlite", "tempfile", + "test-log", ] [[package]] @@ -1613,6 +1614,8 @@ dependencies = [ "limbo_core", "miette", "rustyline", + "tracing", + "tracing-subscriber", ] [[package]] @@ -1665,7 +1668,7 @@ dependencies = [ "rand 0.8.5", "rand_chacha 0.9.0", "regex", - "regex-syntax", + "regex-syntax 0.8.5", "rstest", "rusqlite", "rustix", @@ -1673,6 +1676,7 @@ dependencies = [ "serde", "strum", "tempfile", + "test-log", "thiserror 1.0.69", "tracing", ] @@ -1764,7 +1768,7 @@ dependencies = [ "rand 0.8.5", "rand_chacha 0.3.1", "regex", - "regex-syntax", + "regex-syntax 0.8.5", "rusqlite", "serde", "serde_json", @@ -1881,6 +1885,15 @@ version = "0.4.25" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "04cbf5b083de1c7e0222a7a51dbfdba1cbe1c6ab0b15e29fff3f6c077fd9cd9f" +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata 0.1.10", +] + [[package]] name = "md5" version = "0.7.0" @@ -2056,6 +2069,16 @@ version = "2.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "5e0826a989adedc2a244799e823aece04662b66609d96af8dff7ac6df9a8925d" +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num-format" version = "0.4.4" @@ -2111,6 +2134,12 @@ dependencies = [ "num-traits", ] +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "owo-colors" version = "4.1.0" @@ -2599,8 +2628,17 @@ checksum = "b544ef1b4eac5dc2db33ea63606ae9ffcfac26c1416a2806ae0bf5f56b201191" dependencies = [ "aho-corasick", "memchr", - "regex-automata", - "regex-syntax", + "regex-automata 0.4.9", + "regex-syntax 0.8.5", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", ] [[package]] @@ -2611,9 +2649,15 @@ checksum = "809e8dc61f6de73b46c85f4c96486310fe304c434cfa43669d7b40f711150908" dependencies = [ "aho-corasick", "memchr", - "regex-syntax", + "regex-syntax 0.8.5", ] +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + [[package]] name = "regex-syntax" version = "0.8.5" @@ -2855,6 +2899,15 @@ dependencies = [ "digest", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.3.0" @@ -3069,6 +3122,28 @@ version = "0.5.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "8f50febec83f5ee1df3015341d8bd429f2d1cc62bcba7ea2076759d315084683" +[[package]] +name = "test-log" +version = "0.2.17" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e7f46083d221181166e5b6f6b1e5f1d499f3a76888826e6cb1d057554157cd0f" +dependencies = [ + "env_logger 0.11.6", + "test-log-macros", + "tracing-subscriber", +] + +[[package]] +name = "test-log-macros" +version = "0.2.17" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "888d0c3c6db53c0fdab160d2ed5e12ba745383d3e85813f2ea0f2b1475ab553f" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.96", +] + [[package]] name = "textwrap" version = "0.16.1" @@ -3119,6 +3194,16 @@ dependencies = [ "syn 2.0.96", ] +[[package]] +name = "thread_local" +version = "1.1.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8b9ef9bad013ada3808854ceac7b46812a6465ba368859a37e2100283d2d719c" +dependencies = [ + "cfg-if", + "once_cell", +] + [[package]] name = "tinystr" version = "0.7.6" @@ -3175,14 +3260,59 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0" dependencies = [ "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "395ae124c09f9e6918a2310af6038fba074bcf474ac352496d5910dd59a2226d" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.96", +] + [[package]] name = "tracing-core" version = "0.1.33" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e672c95779cf947c5311f83787af4fa8fffd12fb27e4993211a84bdfd9610f9c" +dependencies = [ + "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.19" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e8189decb5ac0fa7bc8b96b7cb9b2701d60d48805aca84a238004d665fcc4008" +dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", +] [[package]] name = "typenum" @@ -3291,6 +3421,12 @@ dependencies = [ "getrandom 0.2.15", ] +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "vcpkg" version = "0.2.15" diff --git a/cli/Cargo.toml b/cli/Cargo.toml index 965bae003..c78dae6b8 100644 --- a/cli/Cargo.toml +++ b/cli/Cargo.toml @@ -24,12 +24,18 @@ clap = { version = "4.5", features = ["derive"] } comfy-table = "7.1.4" dirs = "5.0.1" env_logger = "0.10.1" -limbo_core = { path = "../core", default-features = true, features = ["completion"]} -rustyline = {version = "15.0.0", default-features = true, features = ["derive"]} +limbo_core = { path = "../core", default-features = true, features = [ + "completion", +] } +rustyline = { version = "15.0.0", default-features = true, features = [ + "derive", +] } ctrlc = "3.4.4" csv = "1.3.1" miette = { version = "7.4.0", features = ["fancy"] } cfg-if = "1.0.0" +tracing-subscriber = { version = "0.3.19", features = ["env-filter"] } +tracing = "0.1.41" [features] default = ["io_uring"] diff --git a/cli/main.rs b/cli/main.rs index d118c2c77..a3939fbc5 100644 --- a/cli/main.rs +++ b/cli/main.rs @@ -7,6 +7,7 @@ mod opcodes_dictionary; use rustyline::{error::ReadlineError, Config, Editor}; use std::sync::atomic::Ordering; +use tracing_subscriber::{fmt, prelude::*, EnvFilter}; fn rustyline_config() -> Config { Config::builder() @@ -15,8 +16,11 @@ fn rustyline_config() -> Config { } fn main() -> anyhow::Result<()> { - env_logger::init(); let mut rl = Editor::with_config(rustyline_config())?; + tracing_subscriber::registry() + .with(fmt::layer()) + .with(EnvFilter::from_default_env()) + .init(); let mut app = app::Limbo::new(&mut rl)?; let home = dirs::home_dir().expect("Could not determine home directory"); let history_file = home.join(".limbo_history"); diff --git a/core/Cargo.toml b/core/Cargo.toml index c72bbc5c8..0914142a1 100644 --- a/core/Cargo.toml +++ b/core/Cargo.toml @@ -48,7 +48,9 @@ limbo_sqlite3_parser = { workspace = true } thiserror = "1.0.61" getrandom = { version = "0.2.15" } regex = "1.11.1" -regex-syntax = { version = "0.8.5", default-features = false, features = ["unicode"] } +regex-syntax = { version = "0.8.5", default-features = false, features = [ + "unicode", +] } chrono = { version = "0.4.38", default-features = false, features = ["clock"] } julian_day_converter = "0.4.4" jsonb = { version = "0.4.4", optional = true } @@ -69,8 +71,8 @@ limbo_completion = { workspace = true, optional = true, features = ["static"] } miette = "7.4.0" strum = "0.26" parking_lot = "0.12.3" -tracing = { version = "0.1.41", default-features = false } crossbeam-skiplist = "0.1.3" +tracing = "0.1.41" ryu = "1.0.19" [build-dependencies] @@ -91,9 +93,10 @@ rusqlite = "0.33.0" tempfile = "3.8.0" quickcheck = { version = "1.0", default-features = false } quickcheck_macros = { version = "1.0", default-features = false } -rand = "0.8.5" # Required for quickcheck +rand = "0.8.5" # Required for quickcheck rand_chacha = "0.9.0" env_logger = "0.11.6" +test-log = { version = "0.2.17", features = ["trace"] } [[bench]] name = "benchmark" diff --git a/core/storage/btree.rs b/core/storage/btree.rs index 20e43da0b..924a6eb2c 100644 --- a/core/storage/btree.rs +++ b/core/storage/btree.rs @@ -2744,6 +2744,7 @@ mod tests { use rand_chacha::rand_core::RngCore; use rand_chacha::rand_core::SeedableRng; use rand_chacha::ChaCha8Rng; + use test_log::test; use super::*; use crate::io::{Buffer, Completion, MemoryIO, OpenFlags, IO}; @@ -3242,7 +3243,6 @@ mod tests { } #[test] - #[ignore] pub fn btree_insert_fuzz_run_equal_size() { for size in 1..8 { tracing::info!("======= size:{} =======", size); @@ -3251,25 +3251,21 @@ mod tests { } #[test] - #[ignore] pub fn btree_insert_fuzz_run_random() { btree_insert_fuzz_run(128, 16, |rng| (rng.next_u32() % 4096) as usize); } #[test] - #[ignore] pub fn btree_insert_fuzz_run_small() { btree_insert_fuzz_run(1, 1024, |rng| (rng.next_u32() % 128) as usize); } #[test] - #[ignore] pub fn btree_insert_fuzz_run_big() { btree_insert_fuzz_run(64, 32, |rng| 3 * 1024 + (rng.next_u32() % 1024) as usize); } #[test] - #[ignore] pub fn btree_insert_fuzz_run_overflow() { btree_insert_fuzz_run(64, 32, |rng| (rng.next_u32() % 32 * 1024) as usize); } @@ -3570,6 +3566,7 @@ mod tests { let usable_space = 4096; let mut i = 1000; let seed = thread_rng().gen(); + tracing::info!("seed {}", seed); let mut rng = ChaCha8Rng::seed_from_u64(seed); while i > 0 { i -= 1; diff --git a/tests/Cargo.toml b/tests/Cargo.toml index d7b025c7d..aba2c5529 100644 --- a/tests/Cargo.toml +++ b/tests/Cargo.toml @@ -25,6 +25,9 @@ assert_cmd = "^2" rand_chacha = "0.9.0" rand = "0.9.0" +[dev-dependencies] +test-log = { version = "0.2.17", features = ["trace"] } + # rexpect does not support windows. [target.'cfg(not(windows))'.dependencies] rexpect = "0.6.0" diff --git a/tests/integration/wal/test_wal.rs b/tests/integration/wal/test_wal.rs index 4a1bc9212..7ef3f2ae1 100644 --- a/tests/integration/wal/test_wal.rs +++ b/tests/integration/wal/test_wal.rs @@ -6,7 +6,7 @@ use std::rc::Rc; use std::sync::{Arc, Mutex}; #[allow(clippy::arc_with_non_send_sync)] -#[test] +#[test_log::test] fn test_wal_checkpoint_result() -> Result<()> { let tmp_db = TempDatabase::new("test_wal.db"); let conn = tmp_db.connect_limbo(); From 262c4de548d3cd2f00a7a1963163295df70726e0 Mon Sep 17 00:00:00 2001 From: Pere Diaz Bou Date: Wed, 5 Mar 2025 13:13:18 +0100 Subject: [PATCH 2/4] add line number and thread id to tracing logs --- Cargo.lock | 2 + cli/main.rs | 8 ++- core/vdbe/mod.rs | 2 + tests/Cargo.toml | 2 + tests/integration/wal/test_wal.rs | 87 ++----------------------------- 5 files changed, 17 insertions(+), 84 deletions(-) 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, From 5c0d44d0d8400b8db2b798b785a18213800ba86c Mon Sep 17 00:00:00 2001 From: Pere Diaz Bou Date: Wed, 5 Mar 2025 13:57:30 +0100 Subject: [PATCH 3/4] test_wal conditional setup tracing --- tests/integration/wal/test_wal.rs | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/tests/integration/wal/test_wal.rs b/tests/integration/wal/test_wal.rs index 9e064d3bc..55d2b37b4 100644 --- a/tests/integration/wal/test_wal.rs +++ b/tests/integration/wal/test_wal.rs @@ -11,7 +11,7 @@ use tracing_subscriber::EnvFilter; #[allow(clippy::arc_with_non_send_sync)] #[test] fn test_wal_checkpoint_result() -> Result<()> { - setup_tracing(); + maybe_setup_tracing(); let tmp_db = TempDatabase::new("test_wal.db"); let conn = tmp_db.connect_limbo(); conn.execute("CREATE TABLE t1 (id text);")?; @@ -35,6 +35,17 @@ fn test_wal_checkpoint_result() -> Result<()> { Ok(()) } +fn maybe_setup_tracing() { + let _ = tracing_subscriber::registry() + .with( + tracing_subscriber::fmt::layer() + .with_line_number(true) + .with_thread_ids(true), + ) + .with(EnvFilter::from_default_env()) + .try_init(); +} + /// Execute a statement and get strings result pub(crate) fn execute_and_get_strings( tmp_db: &TempDatabase, From a79b3f5746ae12233d238800befef83dd47b49f6 Mon Sep 17 00:00:00 2001 From: Pere Diaz Bou Date: Wed, 5 Mar 2025 15:52:10 +0100 Subject: [PATCH 4/4] remove unused imports test_wal.rs --- tests/integration/wal/test_wal.rs | 2 -- 1 file changed, 2 deletions(-) diff --git a/tests/integration/wal/test_wal.rs b/tests/integration/wal/test_wal.rs index 55d2b37b4..a0173a2b4 100644 --- a/tests/integration/wal/test_wal.rs +++ b/tests/integration/wal/test_wal.rs @@ -1,9 +1,7 @@ use crate::common::{do_flush, TempDatabase}; use limbo_core::{Connection, LimboError, Result, StepResult}; 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;