Log a few timings and a few other small tweaks

Author: anacrolix

src/c_api/ext_fns/handle.rs

@@ -1,5 +1,6 @@
 use libc::size_t;
 use positioned_io::ReadAt;
+use std::time::Instant;
 
 use super::*;
 use crate::c_api::PossumError::NoError;
@@ -115,6 +116,7 @@ pub extern "C" fn possum_single_read_at(
     buf: *mut PossumBuf,
     offset: u64,
 ) -> PossumError {
+    let started = Instant::now();
     let rust_key = key.as_ref();
     let value = match unsafe { handle.as_ref() }
         .unwrap()
@@ -132,14 +134,15 @@ pub extern "C" fn possum_single_read_at(
         Err(err) => return err.into(),
         Ok(ok) => ok,
     };
-    // eprintln!(
-    //     "reading single {} bytes at {} from {}, read {}: {}",
-    //     read_buf.len(),
-    //     offset,
-    //     value.length(),
-    //     r_nbyte,
-    //     rust_key.escape_ascii(),
-    // );
+    debug!(
+        "{:?}: reading single {} bytes at {} from {}, read {}: {}",
+        started.elapsed(),
+        read_buf.len(),
+        offset,
+        value.length(),
+        r_nbyte,
+        rust_key.escape_ascii(),
+    );
     buf.size = r_nbyte;
     NoError
 }

src/lib.rs

@@ -67,10 +67,12 @@ pub mod env;
 mod reader;
 use reader::Reader;
 
-// Concurrency related stuff that's replaced by loom or shuttle.
+// Concurrency-related stuff that's replaced by loom or shuttle.
 pub mod concurrency;
 use concurrency::*;
 
+mod macros;
+
 use self::concurrency::sync::{Arc, Mutex, MutexGuard, RwLock, RwLockReadGuard};
 use crate::handle::WithHandle;
 
@@ -709,7 +711,7 @@ where
     }
 }
 
-#[derive(Ord, PartialOrd, Eq, PartialEq, Copy, Clone)]
+#[derive(Ord, PartialOrd, Eq, PartialEq, Copy, Clone, Debug)]
 struct ReadExtent {
     pub offset: u64,
     pub len: u64,

src/macros.rs

@@ -0,0 +1,26 @@
+#[macro_export]
+macro_rules! log_time {
+    ($fmt:literal, $expr:expr) => {{
+        let start = std::time::Instant::now();
+        let ret = $expr;
+        let duration = start.elapsed();
+        tracing::debug!(target: "possum::timing", duration = ?duration, $fmt);
+        ret
+    }};
+    ({ $($fields:tt)* }, $($exprs:expr),+; $($stmts:stmt);*) => {
+        let start = std::time::Instant::now();
+        $($stmts);+
+        let duration = start.elapsed();
+        tracing::debug!(target: "possum::timing", { duration = ?duration, $($fields)* }, $($exprs),+);
+    };
+    ($($args:expr),+; $($stmt:stmt);+) => {
+        let start = std::time::Instant::now();
+        $($stmt);+
+        let duration = start.elapsed();
+        tracing::debug!(
+            target: "possum::timing",
+            duration = ?duration,
+            $($args),+
+        );
+    };
+}

src/main.rs

@@ -42,6 +42,7 @@ enum DatabaseCommands {
         file: OsString,
     },
     ListKeys {
+        #[arg(default_value = "")]
         prefix: String,
     },
     ReadKey {

src/reader.rs

@@ -41,11 +41,14 @@ where
 
     /// Takes a snapshot and commits the read transaction.
     pub fn begin(self) -> Result<Snapshot> {
-        let file_clones = self.clone_files().context("cloning files")?;
-        self.owned_tx
-            .end_tx(|tx| tx.commit())
-            .context("committing transaction")?
-            .complete();
+        log_time!(
+            { num_files = self.reads.len() },
+            "cloning files";
+            let file_clones = self.clone_files().context("cloning files")?
+        );
+        let commit = || self.owned_tx.end_tx(|tx| tx.commit());
+        let post_work = log_time!("reader commit", commit());
+        post_work.context("committing transaction")?.complete();
         Ok(Snapshot { file_clones })
     }
 
@@ -99,9 +102,14 @@ where
         if self.owned_tx.as_handle().dir_supports_file_cloning() {
             match self.clone_file(file_id, tempdir, cache, src_dir) {
                 Err(err) if err.root_cause_is_unsupported_filesystem() => (),
-                default => return default,
+                Err(err) => return Err(err),
+                default @ Ok(_) => {
+                    info!(%file_id, tempdir = %tempdir.as_ref().unwrap().path().display(), "cloned file");
+                    return default;
+                }
             }
         }
+        warn!(%file_id, ?read_extents, "falling back to segment locking to read");
         self.get_file_for_read_by_segment_locking(file_id, read_extents)
     }
 

src/timing.rs

@@ -0,0 +1,2 @@
+use std::time::Instant;
+