From c528e6bb53c6dd55d6b61f282292f0b6c2563d57 Mon Sep 17 00:00:00 2001 From: Pascal Berrang Date: Sat, 15 Jun 2024 17:29:55 +0300 Subject: [PATCH] Expose commit latency struct for profiling --- src/database.rs | 13 ++++++--- src/latency.rs | 68 ++++++++++++++++++++++++++++++++++++++++++++++ src/lib.rs | 1 + src/transaction.rs | 20 ++++++++++++-- 4 files changed, 95 insertions(+), 7 deletions(-) create mode 100644 src/latency.rs diff --git a/src/database.rs b/src/database.rs index a496374..1f20a77 100644 --- a/src/database.rs +++ b/src/database.rs @@ -1,5 +1,6 @@ use crate::{ error::{mdbx_result, Error, Result}, + latency::CommitLatency, table::Table, transaction::{RO, RW}, Mode, ReadWriteOptions, SyncMode, Transaction, TransactionKind, @@ -77,7 +78,7 @@ pub(crate) enum TxnManagerMessage { }, Commit { tx: TxnPtr, - sender: SyncSender>, + sender: SyncSender>, }, } @@ -284,10 +285,14 @@ where .unwrap(); } TxnManagerMessage::Commit { tx, sender } => { + let mut latency = CommitLatency::new(); sender - .send(mdbx_result(unsafe { - ffi::mdbx_txn_commit_ex(tx.0, ptr::null_mut()) - })) + .send( + mdbx_result(unsafe { + ffi::mdbx_txn_commit_ex(tx.0, &mut latency.0) + }) + .map(|v| (v, latency)), + ) .unwrap(); } }, diff --git a/src/latency.rs b/src/latency.rs new file mode 100644 index 0000000..0cb8c60 --- /dev/null +++ b/src/latency.rs @@ -0,0 +1,68 @@ +use std::{mem, time::Duration}; + +/// Latency statistics for committing transactions. +#[derive(Debug)] +pub struct CommitLatency(pub(crate) ffi::MDBX_commit_latency); + +impl CommitLatency { + pub fn new() -> Self { + unsafe { Self(mem::zeroed()) } + } + + /// Duration of preparation (commit child transactions, update + /// sub-databases records and cursors destroying). + #[inline] + pub const fn preparation(&self) -> Duration { + Self::time_to_duration(self.0.preparation) + } + + /// Duration of GC/freeDB handling & updation. + #[inline] + pub const fn gc_wallclock(&self) -> Duration { + Self::time_to_duration(self.0.gc_wallclock) + } + + /// Duration of internal audit if enabled. + #[inline] + pub const fn audit(&self) -> Duration { + Self::time_to_duration(self.0.audit) + } + + /// Duration of writing dirty/modified data pages to a filesystem, + /// i.e. the summary duration of a `write()` syscalls during commit. + #[inline] + pub const fn write(&self) -> Duration { + Self::time_to_duration(self.0.write) + } + + /// Duration of syncing written data to the disk/storage, i.e. + /// the duration of a `fdatasync()` or a `msync()` syscall during commit. + #[inline] + pub const fn sync(&self) -> Duration { + Self::time_to_duration(self.0.sync) + } + + /// Duration of transaction ending (releasing resources). + #[inline] + pub const fn ending(&self) -> Duration { + Self::time_to_duration(self.0.ending) + } + + /// The total duration of a commit. + #[inline] + pub const fn whole(&self) -> Duration { + Self::time_to_duration(self.0.whole) + } + + /// User-mode CPU time spent on GC update. + #[inline] + pub const fn gc_cputime(&self) -> Duration { + Self::time_to_duration(self.0.gc_cputime) + } + + /// Latency of commit stages in 1/65_536 of seconds units. + #[inline] + const fn time_to_duration(time: u32) -> Duration { + Duration::from_nanos(time as u64 * (1_000_000_000 / 65_536)) + } +} diff --git a/src/lib.rs b/src/lib.rs index a3e1659..0a1e254 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -19,6 +19,7 @@ mod cursor; mod database; mod error; mod flags; +mod latency; mod table; mod transaction; diff --git a/src/transaction.rs b/src/transaction.rs index 633f02c..2ddb5d9 100644 --- a/src/transaction.rs +++ b/src/transaction.rs @@ -2,6 +2,7 @@ use crate::{ database::{Database, DatabaseKind, NoWriteMap, TxnManagerMessage, TxnPtr}, error::{mdbx_result, Result}, flags::{c_enum, TableFlags, WriteFlags}, + latency::CommitLatency, table::Table, Cursor, Decodable, Error, Stat, }; @@ -152,11 +153,16 @@ where } /// Commits the transaction and returns table handles permanently open for the lifetime of `Database`. - pub fn commit_and_rebind_open_dbs(mut self) -> Result<(bool, Vec>)> { + /// Also returns measured latency. + pub fn commit_and_rebind_open_dbs_with_latency( + mut self, + ) -> Result<(bool, CommitLatency, Vec>)> { let txnlck = self.txn.lock(); let txn = txnlck.0; let result = if K::ONLY_CLEAN { - mdbx_result(unsafe { ffi::mdbx_txn_commit_ex(txn, ptr::null_mut()) }) + let mut latency = CommitLatency::new(); + mdbx_result(unsafe { ffi::mdbx_txn_commit_ex(txn, &mut latency.0) }) + .map(|v| (v, latency)) } else { let (sender, rx) = sync_channel(0); self.db @@ -171,9 +177,10 @@ where rx.recv().unwrap() }; self.committed = true; - result.map(|v| { + result.map(|(v, latency)| { ( v, + latency, self.primed_dbis .lock() .iter() @@ -183,6 +190,13 @@ where }) } + /// Commits the transaction and returns table handles permanently open for the lifetime of `Database`. + pub fn commit_and_rebind_open_dbs(self) -> Result<(bool, Vec>)> { + // Drop `CommitLatency` from return value. + self.commit_and_rebind_open_dbs_with_latency() + .map(|v| (v.0, v.2)) + } + /// Opens a handle to an MDBX table. /// /// If `name` is [None], then the returned handle will be for the default table.