From 7622ea5f98fa42b38158d50bea77529c87bea77f Mon Sep 17 00:00:00 2001 From: Piotr Sarna Date: Fri, 14 Apr 2023 09:51:59 +0200 Subject: [PATCH] database: add transaction tracing The tracing is also added to tests, so that the behavior can be observed: ``` $ cargo test -- --nocapture --test-threads 1 test database::tests::test_dirty_write ... 2023-04-14T07:51:15.919503Z TRACE test_dirty_write: mvcc_rs::database: BEGIN { id: 0, begin_ts: 0, write_set: {}, read_set: {} } 2023-04-14T07:51:15.919554Z TRACE test_dirty_write: mvcc_rs::database: BEGIN { id: 1, begin_ts: 1, write_set: {}, read_set: {} } ok test database::tests::test_fuzzy_read ... 2023-04-14T07:51:15.919732Z TRACE test_fuzzy_read: mvcc_rs::database: BEGIN { id: 0, begin_ts: 0, write_set: {}, read_set: {} } 2023-04-14T07:51:15.919762Z TRACE test_fuzzy_read: mvcc_rs::database: COMMIT { id: 0, begin_ts: 0, write_set: {1}, read_set: {1} } 2023-04-14T07:51:15.919778Z TRACE test_fuzzy_read: mvcc_rs::database: BEGIN { id: 1, begin_ts: 2, write_set: {}, read_set: {} } 2023-04-14T07:51:15.919793Z TRACE test_fuzzy_read: mvcc_rs::database: BEGIN { id: 2, begin_ts: 3, write_set: {}, read_set: {} } 2023-04-14T07:51:15.919811Z TRACE test_fuzzy_read: mvcc_rs::database: COMMIT { id: 2, begin_ts: 3, write_set: {1}, read_set: {} } ok test database::tests::test_insert_read ... 2023-04-14T07:51:15.919944Z TRACE test_insert_read: mvcc_rs::database: BEGIN { id: 0, begin_ts: 0, write_set: {}, read_set: {} } 2023-04-14T07:51:15.919974Z TRACE test_insert_read: mvcc_rs::database: COMMIT { id: 0, begin_ts: 0, write_set: {1}, read_set: {1} } 2023-04-14T07:51:15.919989Z TRACE test_insert_read: mvcc_rs::database: BEGIN { id: 1, begin_ts: 2, write_set: {}, read_set: {} } ok test database::tests::test_lost_update ... 2023-04-14T07:51:15.920116Z TRACE test_lost_update: mvcc_rs::database: BEGIN { id: 0, begin_ts: 0, write_set: {}, read_set: {} } 2023-04-14T07:51:15.920146Z TRACE test_lost_update: mvcc_rs::database: COMMIT { id: 0, begin_ts: 0, write_set: {1}, read_set: {1} } 2023-04-14T07:51:15.920161Z TRACE test_lost_update: mvcc_rs::database: BEGIN { id: 1, begin_ts: 2, write_set: {}, read_set: {} } 2023-04-14T07:51:15.920178Z TRACE test_lost_update: mvcc_rs::database: BEGIN { id: 2, begin_ts: 3, write_set: {}, read_set: {} } 2023-04-14T07:51:15.920196Z TRACE test_lost_update: mvcc_rs::database: ROLLBACK { id: 2, begin_ts: 3, write_set: {}, read_set: {} } 2023-04-14T07:51:15.920210Z TRACE test_lost_update: mvcc_rs::database: COMMIT { id: 1, begin_ts: 2, write_set: {1}, read_set: {} } 2023-04-14T07:51:15.920223Z TRACE test_lost_update: mvcc_rs::database: BEGIN { id: 3, begin_ts: 6, write_set: {}, read_set: {} } ok test database::tests::test_read_nonexistent ... 2023-04-14T07:51:15.920352Z TRACE test_read_nonexistent: mvcc_rs::database: BEGIN { id: 0, begin_ts: 0, write_set: {}, read_set: {} } ok ``` --- core/mvcc/database/Cargo.toml | 2 ++ core/mvcc/database/src/database.rs | 34 +++++++++++++++++++++++++++++- 2 files changed, 35 insertions(+), 1 deletion(-) diff --git a/core/mvcc/database/Cargo.toml b/core/mvcc/database/Cargo.toml index 920ead0ad..16a6d4de8 100644 --- a/core/mvcc/database/Cargo.toml +++ b/core/mvcc/database/Cargo.toml @@ -13,6 +13,8 @@ tracing = "0.1.37" criterion = { version = "0.4", features = ["html_reports"] } pprof = { version = "0.11.1", features = ["criterion", "flamegraph"] } shuttle = "0.6.0" +tracing-subscriber = "0" +tracing-test = "0" [[bench]] name = "my_benchmark" diff --git a/core/mvcc/database/src/database.rs b/core/mvcc/database/src/database.rs index 5439a2a76..e7c8c9ea7 100644 --- a/core/mvcc/database/src/database.rs +++ b/core/mvcc/database/src/database.rs @@ -71,6 +71,23 @@ impl Transaction { } } +impl std::fmt::Display for Transaction { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::result::Result<(), std::fmt::Error> { + match self.read_set.try_borrow() { + Ok(read_set) => write!( + f, + "{{ id: {}, begin_ts: {}, write_set: {:?}, read_set: {:?} }}", + self.tx_id, self.begin_ts, self.write_set, read_set + ), + Err(_) => write!( + f, + "{{ id: {}, begin_ts: {}, write_set: {:?}, read_set: }}", + self.tx_id, self.begin_ts, self.write_set + ), + } + } +} + /// Transaction state. #[derive(Debug, Clone, PartialEq)] enum TransactionState { @@ -294,6 +311,7 @@ impl DatabaseInner { let begin_ts = self.get_timestamp(); let tx = Transaction::new(tx_id, begin_ts); let mut txs = self.txs.borrow_mut(); + tracing::trace!("BEGIN {tx}"); txs.insert(tx_id, tx); tx_id } @@ -327,6 +345,7 @@ impl DatabaseInner { } } tx.state = TransactionState::Committed; + tracing::trace!("COMMIT {tx}"); Ok(()) } @@ -344,6 +363,7 @@ impl DatabaseInner { } } } + tracing::trace!("ROLLBACK {tx}"); tx.state = TransactionState::Terminated; } @@ -357,7 +377,7 @@ impl DatabaseInner { } /// A write-write conflict happens when transaction T_m attempts to update a -/// row version that is currently being updated by an active transaction T_n. +/// row version that is currently being updated by an active transaction T_n. fn is_write_write_conflict( txs: &HashMap, tx: &Transaction, @@ -420,7 +440,9 @@ fn is_end_visible(txs: &HashMap, tx: &Transaction, rv: &RowVe mod tests { use super::*; use crate::clock::LocalClock; + use tracing_test::traced_test; + #[traced_test] #[test] fn test_insert_read() { let clock = LocalClock::default(); @@ -441,6 +463,7 @@ mod tests { assert_eq!(tx1_row, row); } + #[traced_test] #[test] fn test_read_nonexistent() { let clock = LocalClock::default(); @@ -450,6 +473,7 @@ mod tests { assert!(row.unwrap().is_none()); } + #[traced_test] #[test] fn test_delete() { let clock = LocalClock::default(); @@ -473,6 +497,7 @@ mod tests { assert!(row.is_none()); } + #[traced_test] #[test] fn test_delete_nonexistent() { let clock = LocalClock::default(); @@ -481,6 +506,7 @@ mod tests { assert_eq!(false, db.delete(tx, 1).unwrap()); } + #[traced_test] #[test] fn test_commit() { let clock = LocalClock::default(); @@ -508,6 +534,7 @@ mod tests { assert_eq!(tx1_updated_row, row); } + #[traced_test] #[test] fn test_rollback() { let clock = LocalClock::default(); @@ -533,6 +560,7 @@ mod tests { assert_eq!(row5, None); } + #[traced_test] #[test] fn test_dirty_write() { let clock = LocalClock::default(); @@ -560,6 +588,7 @@ mod tests { assert_eq!(tx1_row, row); } + #[traced_test] #[test] fn test_dirty_read() { let clock = LocalClock::default(); @@ -580,6 +609,7 @@ mod tests { } #[ignore] + #[traced_test] #[test] fn test_dirty_read_deleted() { let clock = LocalClock::default(); @@ -604,6 +634,7 @@ mod tests { assert_eq!(tx1_row, row); } + #[traced_test] #[test] fn test_fuzzy_read() { let clock = LocalClock::default(); @@ -639,6 +670,7 @@ mod tests { assert_eq!(tx1_row, row); } + #[traced_test] #[test] fn test_lost_update() { let clock = LocalClock::default();