Merge 'betters instrumentation for btree related operations + cleaner debug for RefValue' from Pedro Muniz

Adds an `#[instrument]` to many btree related functions. Also, when
debugging #1717 it would be impossible to debug as the 10Mb SeekKey
would be printed to my terminal making the experience miserable. The
debug implementation now truncates the Blobs and Strings when they are
too big to be useful.

Closes #1721

core/storage/btree.rs

@@ -603,6 +603,7 @@ impl BTreeCursor {
 
     /// Move the cursor to the previous record and return it.
     /// Used in backwards iteration.
+    #[instrument(skip(self), level = Level::TRACE, name = "prev")]
     fn get_prev_record(&mut self) -> Result<CursorResult<bool>> {
         loop {
             let page = self.stack.top();
@@ -713,6 +714,7 @@ impl BTreeCursor {
 
     /// Reads the record of a cell that has overflow pages. This is a state machine that requires to be called until completion so everything
     /// that calls this function should be reentrant.
+    #[instrument(skip_all, level = Level::TRACE)]
     fn process_overflow_read(
         &self,
         payload: &'static [u8],
@@ -740,7 +742,7 @@ impl BTreeCursor {
         if page_btree.get().is_locked() {
             return Ok(CursorResult::IO);
         }
-        tracing::debug!("reading overflow page {} {}", next_page, remaining_to_read);
+        tracing::debug!(next_page, remaining_to_read, "reading overflow page");
         let page = page_btree.get();
         let contents = page.get_contents();
         // The first four bytes of each overflow page are a big-endian integer which is the page number of the next page in the chain, or zero for the final page in the chain.
@@ -1113,6 +1115,7 @@ impl BTreeCursor {
 
     /// Move the cursor to the next record and return it.
     /// Used in forwards iteration, which is the default.
+    #[instrument(skip(self), level = Level::TRACE, name = "next")]
     fn get_next_record(&mut self) -> Result<CursorResult<bool>> {
         if let Some(mv_cursor) = &self.mv_cursor {
             let mut mv_cursor = mv_cursor.borrow_mut();
@@ -1133,10 +1136,10 @@ impl BTreeCursor {
             let contents = mem_page.get().contents.as_ref().unwrap();
             let cell_count = contents.cell_count();
             tracing::debug!(
-                "next: current_before_advance id={} cell={}, cell_count={}",
-                mem_page_rc.get().get().id,
-                self.stack.current_cell_index(),
-                cell_count
+                id = mem_page_rc.get().get().id,
+                cell = self.stack.current_cell_index(),
+                cell_count,
+                "current_before_advance",
             );
 
             let is_index = mem_page_rc.get().is_index();
@@ -1147,10 +1150,10 @@ impl BTreeCursor {
                                                                                                                 // anyways, we won't visit this invalid cell index
             if should_skip_advance {
                 tracing::debug!(
-                    "next: skipping advance, going_upwards: {}, page: {}, cell_idx: {}",
-                    self.going_upwards,
-                    mem_page_rc.get().get().id,
-                    self.stack.current_cell_index()
+                    going_upwards = self.going_upwards,
+                    page = mem_page_rc.get().get().id,
+                    cell_idx = self.stack.current_cell_index(),
+                    "skipping advance",
                 );
                 self.going_upwards = false;
                 return Ok(CursorResult::Ok(true));
@@ -1158,11 +1161,7 @@ impl BTreeCursor {
             // Important to advance only after loading the page in order to not advance > 1 times
             self.stack.advance();
             let cell_idx = self.stack.current_cell_index() as usize;
-            tracing::debug!(
-                "next:current id={} cell={}",
-                mem_page_rc.get().get().id,
-                cell_idx
-            );
+            tracing::debug!(id = mem_page_rc.get().get().id, cell = cell_idx, "current");
 
             if cell_idx == cell_count {
                 // do rightmost
@@ -1260,13 +1259,14 @@ impl BTreeCursor {
     fn move_to_root(&mut self) {
         self.seek_state = CursorSeekState::Start;
         self.going_upwards = false;
-        tracing::trace!("move_to_root({})", self.root_page);
+        tracing::trace!(root_page = self.root_page);
         let mem_page = self.read_page(self.root_page).unwrap();
         self.stack.clear();
         self.stack.push(mem_page);
     }
 
     /// Move the cursor to the rightmost record in the btree.
+    #[instrument(skip(self), level = Level::TRACE)]
     fn move_to_rightmost(&mut self) -> Result<CursorResult<bool>> {
         self.move_to_root();
 
@@ -1636,6 +1636,7 @@ impl BTreeCursor {
 
     /// Specialized version of do_seek() for table btrees that uses binary search instead
     /// of iterating cells in order.
+    #[instrument(skip_all, level = Level::TRACE)]
     fn tablebtree_seek(&mut self, rowid: i64, seek_op: SeekOp) -> Result<CursorResult<bool>> {
         assert!(self.mv_cursor.is_none());
         let iter_dir = seek_op.iteration_direction();
@@ -1754,6 +1755,7 @@ impl BTreeCursor {
         }
     }
 
+    #[instrument(skip_all, level = Level::TRACE)]
     fn indexbtree_seek(
         &mut self,
         key: &ImmutableRecord,
@@ -1988,7 +1990,7 @@ impl BTreeCursor {
         let cmp = {
             let record = self.get_immutable_record();
             let record = record.as_ref().unwrap();
-            tracing::debug!("record={}", record);
+            tracing::debug!(?record);
             let record_slice_equal_number_of_cols =
                 &record.get_values().as_slice()[..key.get_values().len()];
             compare_immutable(
@@ -2029,7 +2031,7 @@ impl BTreeCursor {
     #[instrument(skip_all, level = Level::TRACE)]
     pub fn move_to(&mut self, key: SeekKey<'_>, cmp: SeekOp) -> Result<CursorResult<()>> {
         assert!(self.mv_cursor.is_none());
-        tracing::trace!("move_to(key={:?} cmp={:?})", key, cmp);
+        tracing::trace!(?key, ?cmp);
         // For a table with N rows, we can find any row by row id in O(log(N)) time by starting at the root page and following the B-tree pointers.
         // B-trees consist of interior pages and leaf pages. Interior pages contain pointers to other pages, while leaf pages contain the actual row data.
         //
@@ -2076,6 +2078,7 @@ impl BTreeCursor {
 
     /// Insert a record into the btree.
     /// If the insert operation overflows the page, it will be split and the btree will be balanced.
+    #[instrument(skip_all, level = Level::TRACE)]
     fn insert_into_page(&mut self, bkey: &BTreeKey) -> Result<CursorResult<()>> {
         let record = bkey
             .get_record()
@@ -2115,7 +2118,7 @@ impl BTreeCursor {
                         (return_if_io!(self.find_cell(page, bkey)), page.page_type())
                     };
                     self.stack.set_cell_index(cell_idx as i32);
-                    tracing::debug!("insert_into_page(cell_idx={})", cell_idx);
+                    tracing::debug!(cell_idx);
 
                     // if the cell index is less than the total cells, check: if its an existing
                     // rowid, we are going to update / overwrite the cell
@@ -2129,7 +2132,7 @@ impl BTreeCursor {
                         match cell {
                             BTreeCell::TableLeafCell(tbl_leaf) => {
                                 if tbl_leaf._rowid == bkey.to_rowid() {
-                                    tracing::debug!("insert_into_page: found exact match with cell_idx={cell_idx}, overwriting");
+                                    tracing::debug!("found exact match with cell_idx={cell_idx}, overwriting");
                                     self.overwrite_cell(page.clone(), cell_idx, record)?;
                                     self.state
                                         .mut_write_info()
@@ -2150,7 +2153,7 @@ impl BTreeCursor {
                                         &self.collations,
                                 );
                                 if cmp == Ordering::Equal {
-                                    tracing::debug!("insert_into_page: found exact match with cell_idx={cell_idx}, overwriting");
+                                    tracing::debug!("found exact match with cell_idx={cell_idx}, overwriting");
                                     self.has_record.set(true);
                                     self.overwrite_cell(page.clone(), cell_idx, record)?;
                                     self.state
@@ -2178,10 +2181,7 @@ impl BTreeCursor {
                     let overflow = {
                         let page = page.get();
                         let contents = page.get().contents.as_mut().unwrap();
-                        tracing::debug!(
-                            "insert_into_page(overflow, cell_count={})",
-                            contents.cell_count()
-                        );
+                        tracing::debug!(name: "overflow", cell_count = contents.cell_count());
 
                         insert_into_cell(
                             contents,
@@ -2194,7 +2194,7 @@ impl BTreeCursor {
                     self.stack.set_cell_index(cell_idx as i32);
                     if overflow > 0 {
                         // A balance will happen so save the key we were inserting
-                        tracing::debug!("insert_into_page: balance triggered on key {:?}, page={:?}, cell_idx={}", bkey, page.get().get().id, cell_idx);
+                        tracing::debug!(page = page.get().get().id, cell_idx, "balance triggered:");
                         self.save_context(match bkey {
                             BTreeKey::TableRowId(rowid) => CursorContext::TableRowId(rowid.0),
                             BTreeKey::IndexKey(record) => {
@@ -2241,6 +2241,7 @@ impl BTreeCursor {
     /// This is a naive algorithm that doesn't try to distribute cells evenly by content.
     /// It will try to split the page in half by keys not by content.
     /// Sqlite tries to have a page at least 40% full.
+    #[instrument(skip(self), level = Level::TRACE)]
     fn balance(&mut self) -> Result<CursorResult<()>> {
         assert!(
             matches!(self.state, CursorState::Write(_)),
@@ -3991,6 +3992,7 @@ impl BTreeCursor {
         Ok(CursorResult::Ok(cursor_has_record))
     }
 
+    #[instrument(skip(self), level = Level::TRACE)]
     pub fn rowid(&mut self) -> Result<CursorResult<Option<i64>>> {
         if let Some(mv_cursor) = &self.mv_cursor {
             let mv_cursor = mv_cursor.borrow();
@@ -4029,12 +4031,14 @@ impl BTreeCursor {
         }
     }
 
+    #[instrument(skip(self), level = Level::TRACE)]
     pub fn seek(&mut self, key: SeekKey<'_>, op: SeekOp) -> Result<CursorResult<bool>> {
         assert!(self.mv_cursor.is_none());
+        // Empty trace to capture the span information
+        tracing::trace!("");
         // We need to clear the null flag for the table cursor before seeking,
         // because it might have been set to false by an unmatched left-join row during the previous iteration
         // on the outer loop.
-        tracing::trace!("seek(key={:?}, op={:?})", key, op);
         self.set_null_flag(false);
         let cursor_has_record = return_if_io!(self.do_seek(key, op));
         self.invalidate_record();
@@ -4048,6 +4052,7 @@ impl BTreeCursor {
     /// Return a reference to the record the cursor is currently pointing to.
     /// If record was not parsed yet, then we have to parse it and in case of I/O we yield control
     /// back.
+    #[instrument(skip(self), level = Level::TRACE)]
     pub fn record(&self) -> Result<CursorResult<Option<Ref<ImmutableRecord>>>> {
         if !self.has_record.get() {
             return Ok(CursorResult::Ok(None));
@@ -4115,12 +4120,13 @@ impl BTreeCursor {
         Ok(CursorResult::Ok(Some(record_ref)))
     }
 
-    #[instrument(skip_all, level = Level::TRACE)]
+    #[instrument(skip(self), level = Level::TRACE)]
     pub fn insert(
         &mut self,
         key: &BTreeKey,
         mut moved_before: bool, /* Indicate whether it's necessary to traverse to find the leaf page */
     ) -> Result<CursorResult<()>> {
+        tracing::debug!(valid_state = ?self.valid_state, cursor_state = ?self.state, is_write_in_progress = self.is_write_in_progress());
         match &self.mv_cursor {
             Some(mv_cursor) => match key.maybe_rowid() {
                 Some(rowid) => {
@@ -4132,7 +4138,6 @@ impl BTreeCursor {
                 None => todo!("Support mvcc inserts with index btrees"),
             },
             None => {
-                tracing::debug!("insert(moved={}, key={:?}), valid_state={:?}, cursor_state={:?}, is_write_in_progress={}", moved_before, key, self.valid_state, self.state, self.is_write_in_progress());
                 if self.valid_state != CursorValidState::Valid && !self.is_write_in_progress() {
                     // A balance happened so we need to move.
                     moved_before = false;
@@ -4185,6 +4190,7 @@ impl BTreeCursor {
     /// 7. WaitForBalancingToComplete -> perform balancing
     /// 8. SeekAfterBalancing -> adjust the cursor to a node that is closer to the deleted value. go to Finish
     /// 9. Finish -> Delete operation is done. Return CursorResult(Ok())
+    #[instrument(skip(self), level = Level::TRACE)]
     pub fn delete(&mut self) -> Result<CursorResult<()>> {
         assert!(self.mv_cursor.is_none());
 
@@ -4200,7 +4206,7 @@ impl BTreeCursor {
                 let delete_info = self.state.delete_info().expect("cannot get delete info");
                 delete_info.state.clone()
             };
-            tracing::debug!("delete state: {:?}", delete_state);
+            tracing::debug!(?delete_state);
 
             match delete_state {
                 DeleteState::Start => {
@@ -4675,6 +4681,7 @@ impl BTreeCursor {
     /// ```
     ///
     /// The destruction order would be: [4',4,5,2,6,7,3,1]
+    #[instrument(skip(self), level = Level::TRACE)]
     pub fn btree_destroy(&mut self) -> Result<CursorResult<Option<usize>>> {
         if let CursorState::None = &self.state {
             self.move_to_root();
@@ -4953,6 +4960,7 @@ impl BTreeCursor {
     /// Count the number of entries in the b-tree
     ///
     /// Only supposed to be used in the context of a simple Count Select Statement
+    #[instrument(skip(self), level = Level::TRACE)]
     pub fn count(&mut self) -> Result<CursorResult<usize>> {
         if self.count == 0 {
             self.move_to_root();
@@ -5140,11 +5148,11 @@ impl PageStack {
     }
     /// Push a new page onto the stack.
     /// This effectively means traversing to a child page.
+    #[instrument(skip_all, level = Level::TRACE, name = "pagestack::push")]
     fn _push(&self, page: BTreePage, starting_cell_idx: i32) {
         tracing::trace!(
-            "pagestack::push(current={}, new_page_id={})",
-            self.current_page.get(),
-            page.get().get().id
+            current = self.current_page.get(),
+            new_page_id = page.get().get().id,
         );
         self.increment_current();
         let current = self.current_page.get();
@@ -5167,10 +5175,11 @@ impl PageStack {
 
     /// Pop a page off the stack.
     /// This effectively means traversing back up to a parent page.
+    #[instrument(skip_all, level = Level::TRACE, name = "pagestack::pop")]
     fn pop(&self) {
         let current = self.current_page.get();
         assert!(current >= 0);
-        tracing::trace!("pagestack::pop(current={})", current);
+        tracing::trace!(current);
         self.cell_indices.borrow_mut()[current as usize] = 0;
         self.stack.borrow_mut()[current as usize] = None;
         self.decrement_current();
@@ -5178,16 +5187,13 @@ impl PageStack {
 
     /// Get the top page on the stack.
     /// This is the page that is currently being traversed.
+    #[instrument(skip(self), level = Level::TRACE, name = "pagestack::top", )]
     fn top(&self) -> BTreePage {
         let page = self.stack.borrow()[self.current()]
             .as_ref()
             .unwrap()
             .clone();
-        tracing::trace!(
-            "pagestack::top(current={}, page_id={})",
-            self.current(),
-            page.get().get().id
-        );
+        tracing::trace!(current = self.current(), page_id = page.get().get().id);
         page
     }
 
@@ -5213,22 +5219,22 @@ impl PageStack {
 
     /// Advance the current cell index of the current page to the next cell.
     /// We usually advance after going traversing a new page
+    #[instrument(skip(self), level = Level::TRACE, name = "pagestack::advance",)]
     fn advance(&self) {
         let current = self.current();
         tracing::trace!(
-            "pagestack::advance {}, cell_indices={:?}",
-            self.cell_indices.borrow()[current],
-            self.cell_indices
+            curr_cell_index = self.cell_indices.borrow()[current],
+            cell_indices = ?self.cell_indices,
         );
         self.cell_indices.borrow_mut()[current] += 1;
     }
 
+    #[instrument(skip(self), level = Level::TRACE, name = "pagestack::retreat")]
     fn retreat(&self) {
         let current = self.current();
         tracing::trace!(
-            "pagestack::retreat {}, cell_indices={:?}",
-            self.cell_indices.borrow()[current],
-            self.cell_indices
+            curr_cell_index = self.cell_indices.borrow()[current],
+            cell_indices = ?self.cell_indices,
         );
         self.cell_indices.borrow_mut()[current] -= 1;
     }

core/storage/sqlite3_ondisk.rs

@@ -43,6 +43,8 @@
 
 #![allow(clippy::arc_with_non_send_sync)]
 
+use tracing::{instrument, Level};
+
 use crate::error::LimboError;
 use crate::fast_lock::SpinLock;
 use crate::io::{Buffer, Complete, Completion, ReadCompletion, SyncCompletion, WriteCompletion};
@@ -60,7 +62,6 @@ use std::pin::Pin;
 use std::rc::Rc;
 use std::sync::atomic::{AtomicBool, AtomicU64, Ordering};
 use std::sync::Arc;
-use tracing::trace;
 
 use super::pager::PageRef;
 use super::wal::LimboRwLock;
@@ -784,7 +785,7 @@ pub fn begin_read_page(
     page: PageRef,
     page_idx: usize,
 ) -> Result<()> {
-    trace!("begin_read_btree_page(page_idx = {})", page_idx);
+    tracing::trace!("begin_read_btree_page(page_idx = {})", page_idx);
     let buf = buffer_pool.get();
     let drop_fn = Rc::new(move |buf| {
         let buffer_pool = buffer_pool.clone();
@@ -808,7 +809,7 @@ pub fn finish_read_page(
     buffer_ref: Arc<RefCell<Buffer>>,
     page: PageRef,
 ) -> Result<()> {
-    trace!("finish_read_btree_page(page_idx = {})", page_idx);
+    tracing::trace!("finish_read_btree_page(page_idx = {})", page_idx);
     let pos = if page_idx == DATABASE_HEADER_PAGE_ID {
         DATABASE_HEADER_SIZE
     } else {
@@ -829,12 +830,12 @@ pub fn begin_write_btree_page(
     page: &PageRef,
     write_counter: Rc<RefCell<usize>>,
 ) -> Result<()> {
-    trace!("begin_write_btree_page(page={})", page.get().id);
+    tracing::trace!("begin_write_btree_page(page={})", page.get().id);
     let page_source = &pager.db_file;
     let page_finish = page.clone();
 
     let page_id = page.get().id;
-    trace!("begin_write_btree_page(page_id={})", page_id);
+    tracing::trace!("begin_write_btree_page(page_id={})", page_id);
     let buffer = {
         let page = page.get();
         let contents = page.contents.as_ref().unwrap();
@@ -845,7 +846,7 @@ pub fn begin_write_btree_page(
     let write_complete = {
         let buf_copy = buffer.clone();
         Box::new(move |bytes_written: i32| {
-            trace!("finish_write_btree_page");
+            tracing::trace!("finish_write_btree_page");
             let buf_copy = buf_copy.clone();
             let buf_len = buf_copy.borrow().len();
             *write_counter.borrow_mut() -= 1;
@@ -1517,7 +1518,7 @@ pub fn begin_read_wal_frame(
     buffer_pool: Rc<BufferPool>,
     complete: Box<dyn Fn(Arc<RefCell<Buffer>>) -> ()>,
 ) -> Result<Arc<Completion>> {
-    trace!("begin_read_wal_frame(offset={})", offset);
+    tracing::trace!("begin_read_wal_frame(offset={})", offset);
     let buf = buffer_pool.get();
     let drop_fn = Rc::new(move |buf| {
         let buffer_pool = buffer_pool.clone();
@@ -1530,6 +1531,7 @@ pub fn begin_read_wal_frame(
     Ok(c)
 }
 
+#[instrument(skip(io, page, write_counter, wal_header, checksums), level = Level::TRACE)]
 pub fn begin_write_wal_frame(
     io: &Arc<dyn File>,
     offset: usize,
@@ -1542,7 +1544,7 @@ pub fn begin_write_wal_frame(
 ) -> Result<(u32, u32)> {
     let page_finish = page.clone();
     let page_id = page.get().id;
-    trace!("begin_write_wal_frame(offset={}, page={})", offset, page_id);
+    tracing::trace!(page_id);
 
     let mut header = WalFrameHeader {
         page_number: page_id as u32,
@@ -1612,7 +1614,7 @@ pub fn begin_write_wal_frame(
     #[allow(clippy::arc_with_non_send_sync)]
     let c = Arc::new(Completion::Write(WriteCompletion::new(write_complete)));
     io.pwrite(offset, buffer.clone(), c)?;
-    trace!("Frame written and synced at offset={offset}");
+    tracing::trace!("Frame written and synced");
     Ok(checksums)
 }
 

core/storage/wal.rs

@@ -4,7 +4,7 @@
 use std::array;
 use std::cell::UnsafeCell;
 use std::collections::HashMap;
-use tracing::{debug, trace};
+use tracing::{instrument, Level};
 
 use std::fmt::Formatter;
 use std::sync::atomic::{AtomicBool, AtomicU32, AtomicU64, Ordering};
@@ -572,7 +572,7 @@ impl Wal for WalFile {
 
     /// Read a frame from the WAL.
     fn read_frame(&self, frame_id: u64, page: PageRef, buffer_pool: Rc<BufferPool>) -> Result<()> {
-        debug!("read_frame({})", frame_id);
+        tracing::debug!("read_frame({})", frame_id);
         let offset = self.frame_offset(frame_id);
         page.set_locked();
         let frame = page.clone();
@@ -596,7 +596,7 @@ impl Wal for WalFile {
         frame: *mut u8,
         frame_len: u32,
     ) -> Result<Arc<Completion>> {
-        debug!("read_frame({})", frame_id);
+        tracing::debug!("read_frame({})", frame_id);
         let offset = self.frame_offset(frame_id);
         let complete = Box::new(move |buf: Arc<RefCell<Buffer>>| {
             let buf = buf.borrow();
@@ -667,6 +667,7 @@ impl Wal for WalFile {
         frame_id >= self.checkpoint_threshold
     }
 
+    #[instrument(skip_all, level = Level::TRACE)]
     fn checkpoint(
         &mut self,
         pager: &Pager,
@@ -679,7 +680,7 @@ impl Wal for WalFile {
         );
         'checkpoint_loop: loop {
             let state = self.ongoing_checkpoint.state;
-            debug!("checkpoint(state={:?})", state);
+            tracing::debug!(?state);
             match state {
                 CheckpointState::Start => {
                     // TODO(pere): check what frames are safe to checkpoint between many readers!
@@ -706,7 +707,7 @@ impl Wal for WalFile {
                     self.ongoing_checkpoint.max_frame = max_safe_frame;
                     self.ongoing_checkpoint.current_page = 0;
                     self.ongoing_checkpoint.state = CheckpointState::ReadFrame;
-                    trace!(
+                    tracing::trace!(
                         "checkpoint_start(min_frame={}, max_frame={})",
                         self.ongoing_checkpoint.max_frame,
                         self.ongoing_checkpoint.min_frame
@@ -733,9 +734,11 @@ impl Wal for WalFile {
 
                     for frame in frames.iter().rev() {
                         if *frame >= min_frame && *frame <= max_frame {
-                            debug!(
+                            tracing::debug!(
                                 "checkpoint page(state={:?}, page={}, frame={})",
-                                state, page, *frame
+                                state,
+                                page,
+                                *frame
                             );
                             self.ongoing_checkpoint.page.get().id = page as usize;
 
@@ -823,18 +826,19 @@ impl Wal for WalFile {
         }
     }
 
+    #[instrument(skip_all, level = Level::DEBUG)]
     fn sync(&mut self) -> Result<WalFsyncStatus> {
         let state = *self.sync_state.borrow();
         match state {
             SyncState::NotSyncing => {
                 let shared = self.get_shared();
-                debug!("wal_sync");
+                tracing::debug!("wal_sync");
                 {
                     let syncing = self.syncing.clone();
                     *syncing.borrow_mut() = true;
                     let completion = Completion::Sync(SyncCompletion {
                         complete: Box::new(move |_| {
-                            debug!("wal_sync finish");
+                            tracing::debug!("wal_sync finish");
                             *syncing.borrow_mut() = false;
                         }),
                         is_completed: Cell::new(false),

core/types.rs

@@ -15,7 +15,7 @@ use crate::vdbe::sorter::Sorter;
 use crate::vdbe::Register;
 use crate::vtab::VirtualTableCursor;
 use crate::Result;
-use std::fmt::Display;
+use std::fmt::{Debug, Display};
 
 const MAX_REAL_SIZE: u8 = 15;
 
@@ -153,7 +153,7 @@ pub struct RawSlice {
     len: usize,
 }
 
-#[derive(Debug, PartialEq, Clone)]
+#[derive(PartialEq, Clone)]
 pub enum RefValue {
     Null,
     Integer(i64),
@@ -162,6 +162,36 @@ pub enum RefValue {
     Blob(RawSlice),
 }
 
+impl Debug for RefValue {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        match self {
+            RefValue::Null => write!(f, "Null"),
+            RefValue::Integer(i) => f.debug_tuple("Integer").field(i).finish(),
+            RefValue::Float(float) => f.debug_tuple("Float").field(float).finish(),
+            RefValue::Text(text_ref) => {
+                // truncate string to at most 256 chars
+                let text = text_ref.as_str();
+                let max_len = text.len().min(256);
+                f.debug_struct("Text")
+                    .field("data", &&text[0..max_len])
+                    // Indicates to the developer debugging that the data is truncated for printing
+                    .field("truncated", &(text.len() > max_len))
+                    .finish()
+            }
+            RefValue::Blob(raw_slice) => {
+                // truncate blob_slice to at most 32 bytes
+                let blob = raw_slice.to_slice();
+                let max_len = blob.len().min(32);
+                f.debug_struct("Blob")
+                    .field("data", &&blob[0..max_len])
+                    // Indicates to the developer debugging that the data is truncated for printing
+                    .field("truncated", &(blob.len() > max_len))
+                    .finish()
+            }
+        }
+    }
+}
+
 impl Value {
     // A helper function that makes building a text Value easier.
     pub fn build_text(text: impl AsRef<str>) -> Self {
@@ -691,7 +721,7 @@ impl<'a> TryFrom<&'a RefValue> for &'a str {
 /// A value in a record that has already been serialized can stay serialized and what this struct offsers
 /// is easy acces to each value which point to the payload.
 /// The name might be contradictory as it is immutable in the sense that you cannot modify the values without modifying the payload.
-#[derive(Debug, Eq, Ord, PartialEq, PartialOrd)]
+#[derive(Eq, Ord, PartialEq, PartialOrd)]
 pub struct ImmutableRecord {
     // We have to be super careful with this buffer since we make values point to the payload we need to take care reallocations
     // happen in a controlled manner. If we realocate with values that should be correct, they will now point to undefined data.
@@ -701,6 +731,15 @@ pub struct ImmutableRecord {
     recreating: bool,
 }
 
+impl Debug for ImmutableRecord {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.debug_struct("ImmutableRecord")
+            .field("values", &self.values)
+            .field("recreating", &self.recreating)
+            .finish()
+    }
+}
+
 #[derive(PartialEq)]
 pub enum ParseRecordState {
     Init,

core/vdbe/mod.rs

@@ -58,6 +58,7 @@ use std::{
     rc::{Rc, Weak},
     sync::Arc,
 };
+use tracing::{instrument, Level};
 
 /// We use labels to indicate that we want to jump to whatever the instruction offset
 /// will be at runtime, because the offset cannot always be determined when the jump
@@ -202,7 +203,7 @@ impl<const N: usize> Bitfield<N> {
     }
 }
 
-#[derive(Copy, Clone, PartialEq, Eq)]
+#[derive(Debug, Copy, Clone, PartialEq, Eq)]
 /// The commit state of the program.
 /// There are two states:
 /// - Ready: The program is ready to run the next instruction, or has shut down after
@@ -392,6 +393,7 @@ impl Program {
         }
     }
 
+    #[instrument(skip_all, level = Level::TRACE)]
     pub fn commit_txn(
         &self,
         pager: Rc<Pager>,
@@ -444,6 +446,7 @@ impl Program {
         }
     }
 
+    #[instrument(skip(self, pager, connection), level = Level::TRACE)]
     fn step_end_write_txn(
         &self,
         pager: &Rc<Pager>,
@@ -531,13 +534,13 @@ fn make_record(registers: &[Register], start_reg: &usize, count: &usize) -> Immu
     ImmutableRecord::from_registers(&registers[*start_reg..*start_reg + *count])
 }
 
-#[tracing::instrument(skip(program), level = tracing::Level::TRACE)]
+#[instrument(skip(program), level = Level::TRACE)]
 fn trace_insn(program: &Program, addr: InsnReference, insn: &Insn) {
     if !tracing::enabled!(tracing::Level::TRACE) {
         return;
     }
     tracing::trace!(
-        "{}",
+        "\n{}",
         explain::insn_to_str(
             program,
             addr,