From 170e4187f0d153c5e0c8b9109bc894b8bd77e79a Mon Sep 17 00:00:00 2001 From: anonymousGiga Date: Thu, 14 Dec 2023 19:05:47 +0800 Subject: [PATCH] Perf: support in-depth measurement of write_to_db. --- Cargo.lock | 1 + bin/reth/Cargo.toml | 5 + crates/perf-metrics/Cargo.toml | 1 + .../perf-metrics/src/dashboard/displayer.rs | 164 ++++++++++++++- crates/perf-metrics/src/dashboard/listener.rs | 14 ++ crates/perf-metrics/src/metrics/execute_tx.rs | 2 +- crates/perf-metrics/src/metrics/metric.rs | 168 +++++++++++++++- crates/perf-metrics/src/metrics/mod.rs | 5 + .../perf-metrics/src/metrics/write_to_db.rs | 189 ++++++++++++++++++ crates/revm/src/processor.rs | 4 +- crates/stages/Cargo.toml | 5 + crates/storage/provider/Cargo.toml | 6 + .../bundle_state_with_receipts.rs | 14 ++ .../src/bundle_state/state_changes.rs | 17 ++ .../src/bundle_state/state_reverts.rs | 13 ++ 15 files changed, 592 insertions(+), 16 deletions(-) create mode 100644 crates/perf-metrics/src/metrics/write_to_db.rs diff --git a/Cargo.lock b/Cargo.lock index 58008288c627..6516962e35cb 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6275,6 +6275,7 @@ dependencies = [ "itertools 0.11.0", "metrics", "parking_lot 0.12.1", + "perf-metrics", "pin-project", "rand 0.8.5", "rayon", diff --git a/bin/reth/Cargo.toml b/bin/reth/Cargo.toml index 3eb93e21bc76..52dbd99ee8c8 100644 --- a/bin/reth/Cargo.toml +++ b/bin/reth/Cargo.toml @@ -183,6 +183,11 @@ enable_execute_measure = [ "reth-stages/enable_execute_measure", "open_performance_dashboard", ] +enable_write_to_db_measure = [ + "perf-metrics/enable_write_to_db_measure", + "reth-stages/enable_write_to_db_measure", + "open_performance_dashboard", +] [build-dependencies] vergen = { version = "8.0.0", features = ["build", "cargo", "git", "gitcl"] } diff --git a/crates/perf-metrics/Cargo.toml b/crates/perf-metrics/Cargo.toml index 14ca13d6ea18..6ea5bc521285 100644 --- a/crates/perf-metrics/Cargo.toml +++ b/crates/perf-metrics/Cargo.toml @@ -24,3 +24,4 @@ enable_execution_duration_record = ["revm-utils"] enable_tps_gas_record = [] enable_db_speed_record = [] enable_execute_measure = ["revm-utils"] +enable_write_to_db_measure = ["revm-utils"] diff --git a/crates/perf-metrics/src/dashboard/displayer.rs b/crates/perf-metrics/src/dashboard/displayer.rs index dc46c5b83906..92d33efbd950 100644 --- a/crates/perf-metrics/src/dashboard/displayer.rs +++ b/crates/perf-metrics/src/dashboard/displayer.rs @@ -28,7 +28,8 @@ const MGAS_TO_GAS: u64 = 1_000_000u64; feature = "enable_opcode_metrics", feature = "enable_cache_record", feature = "enable_execution_duration_record", - feature = "enable_execute_measure" + feature = "enable_execute_measure", + feature = "enable_write_to_db_measure" ))] const COL_WIDTH_MIDDLE: usize = 14; #[cfg(feature = "enable_cache_record")] @@ -36,7 +37,8 @@ const COL_WIDTH_BIG: usize = 20; #[cfg(any( feature = "enable_cache_record", feature = "enable_execution_duration_record", - feature = "enable_execute_measure" + feature = "enable_execute_measure", + feature = "enable_write_to_db_measure" ))] const COL_WIDTH_LARGE: usize = 40; @@ -391,10 +393,6 @@ impl DBSpeedDisplayer { self.record = record; } - fn convert_bytes_to_mega(&self, size: usize) -> f64 { - size as f64 / 1024.0 / 1024.0 - } - pub(crate) fn print(&self) { println!(); println!("===============================Metric of db speed============================"); @@ -403,7 +401,7 @@ impl DBSpeedDisplayer { let col_len = 20; let (size, time) = self.record.header_td_info(); - let header_td_size = self.convert_bytes_to_mega(size); + let header_td_size = convert_bytes_to_mega(size); let header_td_time = time.as_secs_f64(); let header_td_rate = header_td_size / header_td_time; println! {"{:col_len$}{:>col_len$.3}{:>col_len$.3}{:>col_len$.3}", "header_td ", @@ -411,14 +409,14 @@ impl DBSpeedDisplayer { let (size, time) = self.record.block_with_senders_info(); let block_with_senders_time = time.as_secs_f64(); - let block_with_senders_size = self.convert_bytes_to_mega(size); + let block_with_senders_size = convert_bytes_to_mega(size); let block_with_senders_rate = block_with_senders_size / block_with_senders_time; println! {"{:col_len$}{:>col_len$.3}{:>col_len$.3}{:>col_len$.3}", "header_with_senders", block_with_senders_size, block_with_senders_time, block_with_senders_rate}; let (size, time) = self.record.write_to_db_info(); let write_to_db_time = time.as_secs_f64(); - let write_to_db_size = self.convert_bytes_to_mega(size); + let write_to_db_size = convert_bytes_to_mega(size); let write_to_db_rate = write_to_db_size / write_to_db_time; println! {"{:col_len$}{:>col_len$.3}{:>col_len$.3}{:>col_len$.3}", "write_to_db ", write_to_db_size, write_to_db_time, write_to_db_rate}; @@ -690,8 +688,154 @@ impl ExecuteTxsDisplayer { feature = "enable_opcode_metrics", feature = "enable_cache_record", feature = "enable_execution_duration_record", - feature = "enable_execute_measure" + feature = "enable_execute_measure", + feature = "enable_write_to_db_measure" ))] fn cycles_as_secs(cycles: u64) -> f64 { revm_utils::time_utils::convert_cycles_to_duration(cycles).as_secs_f64() } + +#[cfg(feature = "enable_write_to_db_measure")] +use crate::metrics::WriteToDbRecord; + +#[cfg(feature = "enable_write_to_db_measure")] +#[derive(Debug, Default)] +pub(crate) struct WriteToDbDisplayer { + record: WriteToDbRecord, +} + +#[cfg(feature = "enable_write_to_db_measure")] +impl WriteToDbDisplayer { + pub(crate) fn record(&mut self, record: WriteToDbRecord) { + self.record = record; + } + + pub(crate) fn print(&self) { + // size + let revert_storage_size = convert_bytes_to_mega(self.record.revert_storage_size()); + let revert_account_size = convert_bytes_to_mega(self.record.revert_account_size()); + let write_receipts_size = convert_bytes_to_mega(self.record.write_receipts_size()); + let state_account_size = convert_bytes_to_mega(self.record.state_account_size()); + let state_bytecode_size = convert_bytes_to_mega(self.record.state_bytecode_size()); + let state_storage_size = convert_bytes_to_mega(self.record.state_storage_size()); + let total_size = revert_storage_size + + revert_account_size + + write_receipts_size + + state_account_size + + state_bytecode_size + + state_storage_size; + + // time + let total_time = cycles_as_secs(self.record.total_time()); + let revert_storage_time = cycles_as_secs(self.record.revert_storage_time()); + let revert_account_time = cycles_as_secs(self.record.revert_account_time()); + let write_receipts_time = cycles_as_secs(self.record.write_receipts_time()); + let sort_time = cycles_as_secs(self.record.sort_time()); + let state_account_time = cycles_as_secs(self.record.state_account_time()); + let state_bytecode_time = cycles_as_secs(self.record.state_bytecode_time()); + let state_storage_time = cycles_as_secs(self.record.state_storage_time()); + + // time pct + let revert_storage_pct = revert_storage_time as f64 / total_time as f64; + let revert_account_pct = revert_account_time as f64 / total_time as f64; + let write_receipts_pct = write_receipts_time as f64 / total_time as f64; + let sort_pct = sort_time as f64 / total_time as f64; + let state_account_pct = state_account_time as f64 / total_time as f64; + let state_bytecode_pct = state_bytecode_time as f64 / total_time as f64; + let state_storage_pct = state_storage_time as f64 / total_time as f64; + + // rate + let revert_storage_rate = revert_storage_size / revert_storage_time; + let revert_account_rate = revert_account_size / revert_account_time; + let write_receipts_rate = write_receipts_size / write_receipts_time; + let state_account_rate = state_account_size / state_account_time; + let state_bytecode_rate = state_bytecode_size / state_bytecode_time; + let state_storage_rate = state_storage_size / state_storage_time; + let avg_rate = total_size / total_time; + + // print + println!(); + println!("=================================================Metric of write_to_db ==============================================="); + println!( + "{: COL_WIDTH_LARGE$}{: >COL_WIDTH_MIDDLE$}{: >COL_WIDTH_MIDDLE$}{: >COL_WIDTH_LARGE$}", + "Cat.", + "Size (MBytes)", + "Time (s)", + "Time (%)", + "Rate (MBytes/s)" + ); + + self.print_line("total_of_write_to_db", total_size, total_time, 1.0, avg_rate); + self.print_line( + "write_storage_in_revert_state", + revert_storage_size, + revert_storage_time, + revert_storage_pct, + revert_storage_rate, + ); + self.print_line( + "write_account_in_revert_state", + revert_account_size, + revert_account_time, + revert_account_pct, + revert_account_rate, + ); + self.print_line( + "write_receipts", + write_receipts_size, + write_receipts_time, + write_receipts_pct, + write_receipts_rate, + ); + println!( + "{: COL_WIDTH_LARGE$.3}{: >COL_WIDTH_MIDDLE$.3}{: >COL_WIDTH_MIDDLE$.2}{: >COL_WIDTH_LARGE$.3}", + "sort_in_state_changes", + "NAN", + sort_time, + sort_pct, + "NAN" + ); + self.print_line( + "write_account_in_state_changes", + state_account_size, + state_account_time, + state_account_pct, + state_account_rate, + ); + self.print_line( + "write_bytecode_in_state_changes", + state_bytecode_size, + state_bytecode_time, + state_bytecode_pct, + state_bytecode_rate, + ); + self.print_line( + "write_storage_in_state_changes", + state_storage_size, + state_storage_time, + state_storage_pct, + state_storage_rate, + ); + } + + fn print_line(&self, cat: &str, size: f64, time: f64, percent: f64, rate: f64) { + // Cat Size (MBytes) Time (s) Time (%) Rate (MBytes/s) + println!( + "{: COL_WIDTH_LARGE$.3}{: >COL_WIDTH_MIDDLE$.3}{: >COL_WIDTH_MIDDLE$.2}{: >COL_WIDTH_LARGE$.3}", + cat, + size, + time, + percent * 100.0, + rate, + ); + } +} + +#[cfg(any( + feature = "enable_write_to_db_measure", + feature = "enable_write_to_db_measure", + feature = "enable_db_speed_record" +))] +fn convert_bytes_to_mega(size: usize) -> f64 { + size as f64 / 1024.0 / 1024.0 +} diff --git a/crates/perf-metrics/src/dashboard/listener.rs b/crates/perf-metrics/src/dashboard/listener.rs index af7aca85069e..9d9e506bbe90 100644 --- a/crates/perf-metrics/src/dashboard/listener.rs +++ b/crates/perf-metrics/src/dashboard/listener.rs @@ -25,6 +25,9 @@ use super::displayer::TpsAndGasRecordDisplayer; #[cfg(feature = "enable_execute_measure")] use super::displayer::ExecuteTxsDisplayer; +#[cfg(feature = "enable_write_to_db_measure")] +use super::displayer::WriteToDbDisplayer; + #[derive(Debug)] pub struct DashboardListener { events_rx: UnboundedReceiver, @@ -46,6 +49,9 @@ pub struct DashboardListener { #[cfg(feature = "enable_execute_measure")] execute_txs_displayer: ExecuteTxsDisplayer, + + #[cfg(feature = "enable_write_to_db_measure")] + write_to_db_displayer: WriteToDbDisplayer, } impl DashboardListener { @@ -71,6 +77,9 @@ impl DashboardListener { #[cfg(feature = "enable_execute_measure")] execute_txs_displayer: ExecuteTxsDisplayer::default(), + + #[cfg(feature = "enable_write_to_db_measure")] + write_to_db_displayer: WriteToDbDisplayer::default(), } } @@ -117,6 +126,11 @@ impl DashboardListener { self.execute_txs_displayer.record(record); self.execute_txs_displayer.print(); } + #[cfg(feature = "enable_write_to_db_measure")] + MetricEvent::WriteToDbInfo { record } => { + self.write_to_db_displayer.record(record); + self.write_to_db_displayer.print(); + } } } } diff --git a/crates/perf-metrics/src/metrics/execute_tx.rs b/crates/perf-metrics/src/metrics/execute_tx.rs index fcbdb9fd1075..14dbdb51d737 100644 --- a/crates/perf-metrics/src/metrics/execute_tx.rs +++ b/crates/perf-metrics/src/metrics/execute_tx.rs @@ -33,7 +33,7 @@ impl ExecuteTxsRecord { self.start_record = Instant::now(); } /// Start sub record. - pub(super) fn start_sub_recorder(&mut self) { + pub(super) fn start_sub_record(&mut self) { self.sub_record = Instant::now(); } diff --git a/crates/perf-metrics/src/metrics/metric.rs b/crates/perf-metrics/src/metrics/metric.rs index d69231e33a26..0d63a1a72c7c 100644 --- a/crates/perf-metrics/src/metrics/metric.rs +++ b/crates/perf-metrics/src/metrics/metric.rs @@ -8,6 +8,8 @@ use super::execute_tx::ExecuteTxsRecord; use super::speed::DatabaseOperationRecord; #[cfg(feature = "enable_tps_gas_record")] use super::tps_gas::TpsGasRecord; +#[cfg(feature = "enable_write_to_db_measure")] +use super::write_to_db::WriteToDbRecord; #[cfg(feature = "enable_cache_record")] use revm_utils::metrics::types::CacheDbRecord; #[cfg(feature = "enable_opcode_metrics")] @@ -66,6 +68,12 @@ pub enum MetricEvent { /// execute txs record. record: ExecuteTxsRecord, }, + /// Measure write_to_db one deeper level info. + #[cfg(feature = "enable_write_to_db_measure")] + WriteToDbInfo { + /// write_to_db record. + record: WriteToDbRecord, + }, } /// This structure is used to support all metric operations of @@ -90,6 +98,9 @@ struct ExecutionStageMetric { /// Record information on in-depth measurement of function execute_and_verify_receipt. #[cfg(feature = "enable_execute_measure")] execute_tx_record: ExecuteTxsRecord, + /// Record information on in-depth measurement of function write_to_db. + #[cfg(feature = "enable_write_to_db_measure")] + write_to_db_record: WriteToDbRecord, /// A channel for sending recorded indicator information to the dashboard for display. events_tx: Option, @@ -292,6 +303,14 @@ pub fn record_at_end(_cachedb_size: usize) { .expect("No sender") .send(MetricEvent::ExecuteTxsInfo { record: _record.execute_tx_record }); } + #[cfg(feature = "enable_write_to_db_measure")] + { + let _ = _record + .events_tx + .as_mut() + .expect("No sender") + .send(MetricEvent::WriteToDbInfo { record: _record.write_to_db_record }); + } } } // ************************************************************************************************* @@ -328,10 +347,10 @@ pub fn start_execute_tx_record() { /// start execute_tx sub record. #[cfg(feature = "enable_execute_measure")] -pub fn start_execute_tx_sub_recorder() { +pub fn start_execute_tx_sub_record() { unsafe { let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); - _record.execute_tx_record.start_sub_recorder(); + _record.execute_tx_record.start_sub_record(); } } @@ -426,7 +445,150 @@ impl Drop for VerifyAndSaveReceiptsRecord { save_receipts_record(); } } - // ************************************************************************************************* // functions called by executor end // ************************************************************************************************* + +// ************************************************************************************************* +// +// The function within this range will be used to measure write_to_db and will be called in +// write_to_db. +// +// ************************************************************************************************* +/// start write_to_db record. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn start_write_to_db_record() { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.start_record(); + } +} + +/// start write_to_db sub record. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn start_write_to_db_sub_record() { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.start_sub_record(); + } +} + +/// Record data size of write storage changes in StateReverts's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_revert_storage_size(size: usize) { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_revert_storage_size(size); + } +} + +/// Record time of write storage changes in StateReverts's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_revert_storage_time() { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_revert_storage_time(); + } +} + +/// Record data size of write account changes in StateReverts's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_revert_account_size(size: usize) { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_revert_account_size(size); + } +} + +/// Record time of write account changes in StateReverts's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_revert_account_time() { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_revert_account_time(); + } +} + +/// Record data size of write receipts in BundleStateWithReceipts's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_write_receipts_size(size: usize) { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_write_receipts_size(size); + } +} + +/// Record time of write receipts in BundleStateWithReceipts's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_write_receipts_time() { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_write_receipts_time(); + } +} + +/// Record time of sort in StateChanges's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_sort_time() { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_sort_time(); + } +} + +/// Record data size of write account in StateChanges's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_state_account_size(size: usize) { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_state_account_size(size); + } +} + +/// Record time of write account in StateChanges's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_state_account_time() { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_state_account_time(); + } +} + +/// Record data size of write bytecode in StateChanges's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_state_bytecode_size(size: usize) { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_state_bytecode_size(size); + } +} + +/// Record time of write bytecode in StateChanges's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_state_bytecode_time() { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_state_bytecode_time(); + } +} + +/// Record data size of write storage in StateChanges's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_state_storage_size(size: usize) { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_state_storage_size(size); + } +} + +/// Record time of write storage in StateChanges's write_to_db. +#[cfg(feature = "enable_write_to_db_measure")] +pub fn record_state_storage_time() { + unsafe { + let _record = METRIC_RECORDER.as_mut().expect("Metric recorder should not empty!"); + _record.write_to_db_record.record_state_storage_time(); + } +} +// ************************************************************************************************* +// functions called by write_to_db end +// ************************************************************************************************* diff --git a/crates/perf-metrics/src/metrics/mod.rs b/crates/perf-metrics/src/metrics/mod.rs index 386941e0bf06..43f1647807ab 100644 --- a/crates/perf-metrics/src/metrics/mod.rs +++ b/crates/perf-metrics/src/metrics/mod.rs @@ -6,6 +6,8 @@ mod execute_tx; mod speed; #[cfg(feature = "enable_tps_gas_record")] mod tps_gas; +#[cfg(feature = "enable_write_to_db_measure")] +mod write_to_db; pub mod metric; @@ -20,3 +22,6 @@ pub use speed::DatabaseOperationRecord; #[cfg(feature = "enable_execute_measure")] pub use execute_tx::ExecuteTxsRecord; + +#[cfg(feature = "enable_write_to_db_measure")] +pub use write_to_db::WriteToDbRecord; diff --git a/crates/perf-metrics/src/metrics/write_to_db.rs b/crates/perf-metrics/src/metrics/write_to_db.rs new file mode 100644 index 000000000000..f4e6527fbf95 --- /dev/null +++ b/crates/perf-metrics/src/metrics/write_to_db.rs @@ -0,0 +1,189 @@ +//! This module is used to measure the function write_to_db. When measuring +//! function write_to_db, the main measures are: (1) its total time +//! consumption and the time consumption of each sub function; (2) The +//! average write rate and the write rate of each sub function. +use revm_utils::time_utils::instant::Instant; + +/// This structure is used to record all the metrics of write_to_db, including +/// the time spent writing and the amount of data written. +#[derive(Debug, Clone, Copy, Default)] +pub struct WriteToDbRecord { + /// Record the starting time of function write_to_db. + start_record: Instant, + /// Record the start time of each subfunction. + sub_record: Instant, + + /// Time of write_to_db. + total: u64, + + /// Time of write storage changes in StateReverts. + revert_storage_time: u64, + /// Data size of write storage changes in StateReverts. + revert_storage_size: usize, + /// Time of write account changes in StateReverts. + revert_account_time: u64, + /// Data size of write account changes in StateReverts. + revert_account_size: usize, + + /// Time of write receipts. + write_receipts_time: u64, + /// Data size of write receipts. + write_receipts_size: usize, + + /// Time of sort in StateChanges's write_to_db. + sort_time: u64, + /// Time of write account in StateChanges. + state_account_time: u64, + /// Data size of write account in StateChanges. + state_account_size: usize, + /// Time of write bytecode in StateChanges. + state_bytecode_time: u64, + /// Data size of write bytecode in StateChanges. + state_bytecode_size: usize, + /// Time of write storage in StateChanges. + state_storage_time: u64, + /// Data size of write storage in StateChanges. + state_storage_size: usize, +} + +impl WriteToDbRecord { + /// Start record. + pub(super) fn start_record(&mut self) { + self.start_record = Instant::now(); + } + /// Start sub record. + pub(super) fn start_sub_record(&mut self) { + self.sub_record = Instant::now(); + } + /// Record data size of write storage changes in StateReverts. + pub(super) fn record_revert_storage_size(&mut self, size: usize) { + self.revert_storage_size = self.revert_storage_size.checked_add(size).expect("overflow"); + } + /// Record time of write storage changes in StateReverts. + pub(super) fn record_revert_storage_time(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.revert_storage_time = self.revert_storage_time.checked_add(cycles).expect("overflow"); + } + /// Record data size of write account changes in StateReverts. + pub(super) fn record_revert_account_size(&mut self, size: usize) { + self.revert_account_size = self.revert_account_size.checked_add(size).expect("overflow"); + } + /// Record time of write account changes in StateReverts. + pub(super) fn record_revert_account_time(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.revert_account_time = self.revert_account_time.checked_add(cycles).expect("overflow"); + } + /// Record data size of write receipts. + pub(super) fn record_write_receipts_size(&mut self, size: usize) { + self.write_receipts_size = self.write_receipts_size.checked_add(size).expect("overflow"); + } + /// Record time of write receipts. + pub(super) fn record_write_receipts_time(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.write_receipts_time = self.write_receipts_time.checked_add(cycles).expect("overflow"); + } + /// Record time of sort in StateChanges. + pub(super) fn record_sort_time(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.sort_time = self.sort_time.checked_add(cycles).expect("overflow"); + } + /// Record data size of write account in StateChanges. + pub(super) fn record_state_account_size(&mut self, size: usize) { + self.state_account_size = self.state_account_size.checked_add(size).expect("overflow"); + } + /// Record time of write account in StateChanges. + pub(super) fn record_state_account_time(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.state_account_time = self.state_account_time.checked_add(cycles).expect("overflow"); + } + /// Record data size of write bytecode in StateChanges. + pub(super) fn record_state_bytecode_size(&mut self, size: usize) { + self.state_bytecode_size = self.state_bytecode_size.checked_add(size).expect("overflow"); + } + /// Record time of write bytecode in StateChanges. + pub(super) fn record_state_bytecode_time(&mut self) { + let (cycles, _) = self.record_sub_time(); + self.state_bytecode_time = self.state_bytecode_time.checked_add(cycles).expect("overflow"); + } + /// Record data size of write storage in StateChanges. + pub(super) fn record_state_storage_size(&mut self, size: usize) { + self.state_storage_size = self.state_storage_size.checked_add(size).expect("overflow"); + } + /// Record time of write storage in StateChanges. + pub(super) fn record_state_storage_time(&mut self) { + let (cycles, now) = self.record_sub_time(); + self.state_storage_time = self.state_storage_time.checked_add(cycles).expect("overflow"); + self.record_total_time(now); + } + /// Record total time. + fn record_total_time(&mut self, now: Instant) { + let cycles = now.checked_cycles_since(self.start_record).unwrap_or(0); + self.total = self.total.checked_add(cycles).expect("overflow"); + } + /// Record time of sub function. + fn record_sub_time(&mut self) -> (u64, Instant) { + let now = Instant::now(); + let cycles = now.checked_cycles_since(self.sub_record).unwrap_or(0); + self.sub_record = now; + (cycles, now) + } +} + +impl WriteToDbRecord { + /// Return total time of write_to_db. + pub fn total_time(&self) -> u64 { + self.total + } + /// Return time of write storage changes in StateReverts. + pub fn revert_storage_time(&self) -> u64 { + self.revert_storage_time + } + /// Return data size of write storage changes in StateReverts. + pub fn revert_storage_size(&self) -> usize { + self.revert_storage_size + } + /// Return time of write account changes in StateReverts. + pub fn revert_account_time(&self) -> u64 { + self.revert_account_time + } + /// Return data size of write account changes in StateReverts. + pub fn revert_account_size(&self) -> usize { + self.revert_account_size + } + /// Return time of write receipts. + pub fn write_receipts_time(&self) -> u64 { + self.write_receipts_time + } + /// Return data size of write receipts. + pub fn write_receipts_size(&self) -> usize { + self.write_receipts_size + } + /// Return time of sort in StateChanges's write_to_db. + pub fn sort_time(&self) -> u64 { + self.sort_time + } + /// Return time of write account in StateChanges. + pub fn state_account_time(&self) -> u64 { + self.state_account_time + } + /// Return data size of write account in StateChanges. + pub fn state_account_size(&self) -> usize { + self.state_account_size + } + /// Return time of write bytecode in StateChanges. + pub fn state_bytecode_time(&self) -> u64 { + self.state_bytecode_time + } + /// Return data size of write bytecode in StateChanges. + pub fn state_bytecode_size(&self) -> usize { + self.state_bytecode_size + } + /// Return time of write storage in StateChanges. + pub fn state_storage_time(&self) -> u64 { + self.state_storage_time + } + /// Return data size of write storage in StateChanges. + pub fn state_storage_size(&self) -> usize { + self.state_storage_size + } +} diff --git a/crates/revm/src/processor.rs b/crates/revm/src/processor.rs index 96faed235ede..44b73e698d9e 100644 --- a/crates/revm/src/processor.rs +++ b/crates/revm/src/processor.rs @@ -303,7 +303,7 @@ impl<'a> EVMProcessor<'a> { } let time = Instant::now(); #[cfg(feature = "enable_execute_measure")] - perf_metrics::start_execute_tx_sub_recorder(); + perf_metrics::start_execute_tx_sub_record(); self.apply_post_execution_state_change(block, total_difficulty)?; #[cfg(feature = "enable_execute_measure")] perf_metrics::apply_post_execution_state_change_record(); @@ -462,7 +462,7 @@ impl<'a> BlockExecutor for EVMProcessor<'a> { let mut cumulative_gas_used = 0; let mut receipts = Vec::with_capacity(block.body.len()); #[cfg(feature = "enable_execute_measure")] - perf_metrics::start_execute_tx_sub_recorder(); + perf_metrics::start_execute_tx_sub_record(); for (transaction, sender) in block.body.iter().zip(senders) { let time = Instant::now(); // The sum of the transaction’s gas limit, Tg, and the gas utilized in this block prior, diff --git a/crates/stages/Cargo.toml b/crates/stages/Cargo.toml index 0f3a88d13b2e..d30c2a39fdb3 100644 --- a/crates/stages/Cargo.toml +++ b/crates/stages/Cargo.toml @@ -114,6 +114,11 @@ enable_execute_measure = [ "reth-revm/enable_execute_measure", "open_performance_dashboard", ] +enable_write_to_db_measure = [ + "reth-provider/enable_write_to_db_measure", + "perf-metrics/enable_write_to_db_measure", + "open_performance_dashboard", + ] [[bench]] name = "criterion" diff --git a/crates/storage/provider/Cargo.toml b/crates/storage/provider/Cargo.toml index c466e161a71a..95d4e64d7193 100644 --- a/crates/storage/provider/Cargo.toml +++ b/crates/storage/provider/Cargo.toml @@ -42,6 +42,9 @@ alloy-rlp = { workspace = true, optional = true } # parallel utils rayon.workspace = true +# perf-test +perf-metrics.workspace = true + [dev-dependencies] reth-db = { workspace = true, features = ["test-utils"] } reth-primitives = { workspace = true, features = ["arbitrary", "test-utils"] } @@ -63,4 +66,7 @@ optimism = [ enable_cache_record = [] enable_db_speed_record = [ "reth-db/enable_db_speed_record", +] +enable_write_to_db_measure = [ + "perf-metrics/enable_write_to_db_measure" ] \ No newline at end of file diff --git a/crates/storage/provider/src/bundle_state/bundle_state_with_receipts.rs b/crates/storage/provider/src/bundle_state/bundle_state_with_receipts.rs index d1966428940a..a4d413313d4e 100644 --- a/crates/storage/provider/src/bundle_state/bundle_state_with_receipts.rs +++ b/crates/storage/provider/src/bundle_state/bundle_state_with_receipts.rs @@ -376,6 +376,8 @@ impl BundleStateWithReceipts { tx: &TX, is_value_known: OriginalValuesKnown, ) -> Result<(), DatabaseError> { + #[cfg(feature = "enable_write_to_db_measure")] + perf_metrics::start_write_to_db_record(); let (plain_state, reverts) = self.bundle.into_plain_state_and_reverts(is_value_known); StateReverts(reverts).write_to_db(tx, self.first_block)?; @@ -396,11 +398,23 @@ impl BundleStateWithReceipts { let first_tx_index = body_indices.first_tx_num(); for (tx_idx, receipt) in receipts.into_iter().enumerate() { if let Some(receipt) = receipt { + #[cfg(feature = "enable_write_to_db_measure")] + { + let size = std::mem::size_of::() + + receipt + .logs + .iter() + .map(|log| log.topics.len() * 32 + log.data.0.len()) + .sum::(); + perf_metrics::record_write_receipts_size(size); + } receipts_cursor.append(first_tx_index + tx_idx as u64, receipt)?; } } } } + #[cfg(feature = "enable_write_to_db_measure")] + perf_metrics::record_write_receipts_time(); StateChanges(plain_state).write_to_db(tx)?; diff --git a/crates/storage/provider/src/bundle_state/state_changes.rs b/crates/storage/provider/src/bundle_state/state_changes.rs index a62606dedebc..f1d0a05cd46c 100644 --- a/crates/storage/provider/src/bundle_state/state_changes.rs +++ b/crates/storage/provider/src/bundle_state/state_changes.rs @@ -26,6 +26,8 @@ impl StateChanges { self.0.accounts.par_sort_by_key(|a| a.0); self.0.storage.par_sort_by_key(|a| a.address); self.0.contracts.par_sort_by_key(|a| a.0); + #[cfg(feature = "enable_write_to_db_measure")] + perf_metrics::record_sort_time(); // Write new account state tracing::trace!(target: "provider::bundle_state", len = self.0.accounts.len(), "Writing new account state"); @@ -35,18 +37,28 @@ impl StateChanges { if let Some(account) = account { tracing::trace!(target: "provider::bundle_state", ?address, "Updating plain state account"); accounts_cursor.upsert(address, into_reth_acc(account))?; + #[cfg(feature = "enable_write_to_db_measure")] + // sizeof(Address) + sizeof(Account) = 100 + perf_metrics::record_state_account_size(100usize); } else if accounts_cursor.seek_exact(address)?.is_some() { tracing::trace!(target: "provider::bundle_state", ?address, "Deleting plain state account"); accounts_cursor.delete_current()?; } } + #[cfg(feature = "enable_write_to_db_measure")] + perf_metrics::record_state_account_time(); // Write bytecode tracing::trace!(target: "provider::bundle_state", len = self.0.contracts.len(), "Writing bytecodes"); let mut bytecodes_cursor = tx.cursor_write::()?; for (hash, bytecode) in self.0.contracts.into_iter() { + #[cfg(feature = "enable_write_to_db_measure")] + // size_of_val(hash) + size_of::() = 88 + perf_metrics::record_state_bytecode_size(88usize + bytecode.bytecode.0.len()); bytecodes_cursor.upsert(hash, Bytecode(bytecode))?; } + #[cfg(feature = "enable_write_to_db_measure")] + perf_metrics::record_state_bytecode_time(); // Write new storage state and wipe storage if needed. tracing::trace!(target: "provider::bundle_state", len = self.0.storage.len(), "Writing new storage state"); @@ -74,9 +86,14 @@ impl StateChanges { if entry.value != U256::ZERO { storages_cursor.upsert(address, entry)?; + #[cfg(feature = "enable_write_to_db_measure")] + // sizeof(Address) + sizeof(StorageEntry) = 84 + perf_metrics::record_state_storage_size(84usize); } } } + #[cfg(feature = "enable_write_to_db_measure")] + perf_metrics::record_state_storage_time(); Ok(()) } } diff --git a/crates/storage/provider/src/bundle_state/state_reverts.rs b/crates/storage/provider/src/bundle_state/state_reverts.rs index 8b7d5c7c283e..f949eb4b3930 100644 --- a/crates/storage/provider/src/bundle_state/state_reverts.rs +++ b/crates/storage/provider/src/bundle_state/state_reverts.rs @@ -31,6 +31,9 @@ impl StateReverts { ) -> Result<(), DatabaseError> { // Write storage changes tracing::trace!(target: "provider::reverts", "Writing storage changes"); + #[cfg(feature = "enable_write_to_db_measure")] + perf_metrics::start_write_to_db_sub_record(); + let mut storages_cursor = tx.cursor_dup_write::()?; let mut storage_changeset_cursor = tx.cursor_dup_write::()?; for (block_index, mut storage_changes) in self.0.storage.into_iter().enumerate() { @@ -67,9 +70,14 @@ impl StateReverts { tracing::trace!(target: "provider::reverts", ?address, ?storage, "Writing storage reverts"); for (key, value) in StorageRevertsIter::new(storage, wiped_storage) { storage_changeset_cursor.append_dup(storage_id, StorageEntry { key, value })?; + #[cfg(feature = "enable_write_to_db_measure")] + // sizeof(B256) + sizeof(StorageEntry) = 96 + perf_metrics::record_revert_storage_size(96usize); } } } + #[cfg(feature = "enable_write_to_db_measure")] + perf_metrics::record_revert_storage_time(); // Write account changes tracing::trace!(target: "provider::reverts", "Writing account changes"); @@ -83,8 +91,13 @@ impl StateReverts { block_number, AccountBeforeTx { address, info: info.map(into_reth_acc) }, )?; + #[cfg(feature = "enable_write_to_db_measure")] + // sizeof(Address) + sizeof(AccountBeforeTx) = 124 + perf_metrics::record_revert_account_size(124usize); } } + #[cfg(feature = "enable_write_to_db_measure")] + perf_metrics::record_revert_account_time(); Ok(()) }