mirror of
https://github.com/aljazceru/turso.git
synced 2026-02-23 17:05:36 +01:00
betters instrumentation for btree operations
This commit is contained in:
@@ -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;
|
||||
}
|
||||
|
||||
@@ -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)
|
||||
}
|
||||
|
||||
|
||||
@@ -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),
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -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(®isters[*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,
|
||||
|
||||
Reference in New Issue
Block a user