feat(storage): log tx opening location (#5973)

bin/reth/src/cli/db_type.rs

@@ -54,7 +54,7 @@ impl DatabaseBuilder {
                 let db_path = data_dir.db_path();
 
                 tracing::info!(target: "reth::cli", path = ?db_path, "Opening database");
-                let db = Arc::new(init_db(db_path.clone(), log_level)?);
+                let db = Arc::new(init_db(db_path.clone(), log_level)?.with_metrics());
                 Ok(DatabaseInstance::Real { db, data_dir })
             }
         }

crates/storage/db/src/abstraction/database.rs

@@ -16,9 +16,11 @@ pub trait Database: Send + Sync + Sealed {
     type TXMut: DbTxMut + DbTx + TableImporter + Send + Sync + Debug + 'static;
 
     /// Create read only transaction.
+    #[track_caller]
     fn tx(&self) -> Result<Self::TX, DatabaseError>;
 
     /// Create read write transaction only possible if database is open with write access.
+    #[track_caller]
     fn tx_mut(&self) -> Result<Self::TXMut, DatabaseError>;
 
     /// Takes a function and passes a read-only transaction into it, making sure it's closed in the
@@ -66,6 +68,7 @@ impl<DB: Database> Database for Arc<DB> {
 impl<DB: Database> Database for &DB {
     type TX = <DB as Database>::TX;
     type TXMut = <DB as Database>::TXMut;
+
     fn tx(&self) -> Result<Self::TX, DatabaseError> {
         <DB as Database>::tx(self)
     }

crates/storage/db/src/implementation/mdbx/tx.rs

@@ -13,7 +13,7 @@ use crate::{
 use parking_lot::RwLock;
 use reth_interfaces::db::{DatabaseWriteError, DatabaseWriteOperation};
 use reth_libmdbx::{ffi::DBI, CommitLatency, Transaction, TransactionKind, WriteFlags, RW};
-use reth_tracing::tracing::warn;
+use reth_tracing::tracing::{debug, warn};
 use std::{
     backtrace::Backtrace,
     marker::PhantomData,
@@ -49,12 +49,16 @@ impl<K: TransactionKind> Tx<K> {
     }
 
     /// Creates new `Tx` object with a `RO` or `RW` transaction and optionally enables metrics.
+    #[track_caller]
     pub fn new_with_metrics(inner: Transaction<K>, with_metrics: bool) -> Self {
-        let metrics_handler = with_metrics.then(|| {
+        let metrics_handler = if with_metrics {
             let handler = MetricsHandler::<K>::new(inner.id());
             TransactionMetrics::record_open(handler.transaction_mode());
-            handler
-        });
+            handler.log_transaction_opened();
+            Some(handler)
+        } else {
+            None
+        };
         Self { inner, db_handles: Default::default(), metrics_handler }
     }
 
@@ -177,6 +181,18 @@ impl<K: TransactionKind> MetricsHandler<K> {
         }
     }
 
+    /// Logs the caller location and ID of the transaction that was opened.
+    #[track_caller]
+    fn log_transaction_opened(&self) {
+        debug!(
+            target: "storage::db::mdbx",
+            caller = %core::panic::Location::caller(),
+            id = %self.txn_id,
+            mode = %self.transaction_mode().as_str(),
+            "Transaction opened",
+        );
+    }
+
     /// Logs the backtrace of current call if the duration that the read transaction has been open
     /// is more than [LONG_TRANSACTION_DURATION].
     /// The backtrace is recorded and logged just once, guaranteed by `backtrace_recorded` atomic.
@@ -196,6 +212,7 @@ impl<K: TransactionKind> MetricsHandler<K> {
                     target: "storage::db::mdbx",
                     ?open_duration,
                     ?backtrace,
+                    %self.txn_id,
                     "The database read transaction has been open for too long"
                 );
             }

crates/storage/provider/src/providers/database/mod.rs

@@ -101,6 +101,7 @@ impl<DB: Database> ProviderFactory<DB> {
     /// Returns a provider with a created `DbTx` inside, which allows fetching data from the
     /// database using different types of providers. Example: [`HeaderProvider`]
     /// [`BlockHashReader`]. This may fail if the inner read database transaction fails to open.
+    #[track_caller]
     pub fn provider(&self) -> ProviderResult<DatabaseProviderRO<DB>> {
         let mut provider = DatabaseProvider::new(self.db.tx()?, self.chain_spec.clone());
 
@@ -115,6 +116,7 @@ impl<DB: Database> ProviderFactory<DB> {
     /// data from the database using different types of providers. Example: [`HeaderProvider`]
     /// [`BlockHashReader`].  This may fail if the inner read/write database transaction fails to
     /// open.
+    #[track_caller]
     pub fn provider_rw(&self) -> ProviderResult<DatabaseProviderRW<DB>> {
         let mut provider = DatabaseProvider::new_rw(self.db.tx_mut()?, self.chain_spec.clone());
 
@@ -126,6 +128,7 @@ impl<DB: Database> ProviderFactory<DB> {
     }
 
     /// Storage provider for latest block
+    #[track_caller]
     pub fn latest(&self) -> ProviderResult<StateProviderBox> {
         trace!(target: "providers::db", "Returning latest state provider");
         Ok(Box::new(LatestStateProvider::new(self.db.tx()?)))