From b57e3e56f823d5b56ab86330cbfa5f48d7b8a186 Mon Sep 17 00:00:00 2001 From: Alex Ostrovski Date: Thu, 25 Apr 2024 11:33:29 +0300 Subject: [PATCH 1/7] Fix format specifier for internal errors --- core/lib/zksync_core/src/api_server/web3/metrics.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/core/lib/zksync_core/src/api_server/web3/metrics.rs b/core/lib/zksync_core/src/api_server/web3/metrics.rs index 96ea96b03eee..11299e2cb5e1 100644 --- a/core/lib/zksync_core/src/api_server/web3/metrics.rs +++ b/core/lib/zksync_core/src/api_server/web3/metrics.rs @@ -429,7 +429,7 @@ impl ApiMetrics { // Log internal error details. match err { Web3Error::InternalError(err) => { - tracing::error!("Internal error in method `{method}`: {err}"); + tracing::error!("Internal error in method `{method}`: {err:#}"); } Web3Error::ProxyError(err) => { tracing::warn!("Error proxying call to main node in method `{method}`: {err}"); From 59cb0b162843b296a4910a635a26c9a2c69b9849 Mon Sep 17 00:00:00 2001 From: Alex Ostrovski Date: Thu, 25 Apr 2024 12:27:02 +0300 Subject: [PATCH 2/7] Log long tx submission stages --- .../execution_sandbox/vm_metrics.rs | 61 ++++++++++++++++++- .../src/api_server/tx_sender/mod.rs | 23 ++++--- 2 files changed, 70 insertions(+), 14 deletions(-) diff --git a/core/lib/zksync_core/src/api_server/execution_sandbox/vm_metrics.rs b/core/lib/zksync_core/src/api_server/execution_sandbox/vm_metrics.rs index d2caa11288aa..ddd1fb8926a4 100644 --- a/core/lib/zksync_core/src/api_server/execution_sandbox/vm_metrics.rs +++ b/core/lib/zksync_core/src/api_server/execution_sandbox/vm_metrics.rs @@ -1,13 +1,16 @@ use std::time::Duration; use multivm::interface::{VmExecutionResultAndLogs, VmMemoryMetrics}; -use vise::{Buckets, EncodeLabelSet, EncodeLabelValue, Family, Gauge, Histogram, Metrics}; +use vise::{ + Buckets, EncodeLabelSet, EncodeLabelValue, Family, Gauge, Histogram, LatencyObserver, Metrics, +}; use zksync_shared_metrics::InteractionType; use zksync_state::StorageViewMetrics; use zksync_types::{ event::{extract_long_l2_to_l1_messages, extract_published_bytecodes}, fee::TransactionExecutionMetrics, storage_writes_deduplicator::StorageWritesDeduplicator, + H256, }; use zksync_utils::bytecode::bytecode_len_in_bytes; @@ -95,6 +98,46 @@ pub(in crate::api_server) enum SubmitTxStage { DbInsert, } +#[must_use = "should be `observe()`d"] +#[derive(Debug)] +pub(in crate::api_server) struct SubmitTxLatencyObserver<'a> { + inner: Option>, + tx_hash: H256, + stage: SubmitTxStage, +} + +impl SubmitTxLatencyObserver<'_> { + pub fn set_stage(&mut self, stage: SubmitTxStage) { + self.stage = stage; + } + + pub fn observe(mut self) { + const MIN_LOGGED_LATENCY: Duration = Duration::from_secs(1); + + let latency = self.inner.take().unwrap().observe(); + // ^ `unwrap()` is safe: `LatencyObserver` is only taken out in this method. + if latency > MIN_LOGGED_LATENCY { + tracing::info!( + "Transaction {:?} submission stage {:?} has high latency: {latency:?}", + self.tx_hash, + self.stage + ); + } + } +} + +impl Drop for SubmitTxLatencyObserver<'_> { + fn drop(&mut self) { + if self.inner.is_some() { + tracing::info!( + "Transaction {:?} submission was dropped at stage {:?} due to error or client disconnecting", + self.tx_hash, + self.stage + ); + } + } +} + #[derive(Debug, Metrics)] #[metrics(prefix = "api_web3")] pub(in crate::api_server) struct SandboxMetrics { @@ -103,11 +146,25 @@ pub(in crate::api_server) struct SandboxMetrics { #[metrics(buckets = Buckets::linear(0.0..=2_000.0, 200.0))] pub(super) sandbox_execution_permits: Histogram, #[metrics(buckets = Buckets::LATENCIES)] - pub submit_tx: Family>, + submit_tx: Family>, #[metrics(buckets = Buckets::linear(0.0..=30.0, 3.0))] pub estimate_gas_binary_search_iterations: Histogram, } +impl SandboxMetrics { + pub fn start_tx_submit_stage( + &self, + tx_hash: H256, + stage: SubmitTxStage, + ) -> SubmitTxLatencyObserver<'_> { + SubmitTxLatencyObserver { + inner: Some(self.submit_tx[&stage].start()), + tx_hash, + stage, + } + } +} + #[vise::register] pub(in crate::api_server) static SANDBOX_METRICS: vise::Global = vise::Global::new(); diff --git a/core/lib/zksync_core/src/api_server/tx_sender/mod.rs b/core/lib/zksync_core/src/api_server/tx_sender/mod.rs index e37fd6cf62e4..c368847b510a 100644 --- a/core/lib/zksync_core/src/api_server/tx_sender/mod.rs +++ b/core/lib/zksync_core/src/api_server/tx_sender/mod.rs @@ -307,13 +307,14 @@ impl TxSender { #[tracing::instrument(skip(self, tx))] pub async fn submit_tx(&self, tx: L2Tx) -> Result { - let stage_latency = SANDBOX_METRICS.submit_tx[&SubmitTxStage::Validate].start(); + let tx_hash = tx.hash(); + let stage_latency = SANDBOX_METRICS.start_tx_submit_stage(tx_hash, SubmitTxStage::Validate); let mut connection = self.acquire_replica_connection().await?; let protocol_verison = pending_protocol_version(&mut connection).await?; self.validate_tx(&tx, protocol_verison).await?; stage_latency.observe(); - let stage_latency = SANDBOX_METRICS.submit_tx[&SubmitTxStage::DryRun].start(); + let stage_latency = SANDBOX_METRICS.start_tx_submit_stage(tx_hash, SubmitTxStage::DryRun); let shared_args = self.shared_args().await; let vm_permit = self.0.vm_concurrency_limiter.acquire().await; let vm_permit = vm_permit.ok_or(SubmitTxError::ServerShuttingDown)?; @@ -334,15 +335,14 @@ impl TxSender { vec![], ) .await?; - tracing::info!( - "Submit tx {:?} with execution metrics {:?}", - tx.hash(), + "Submit tx {tx_hash:?} with execution metrics {:?}", execution_output.metrics ); stage_latency.observe(); - let stage_latency = SANDBOX_METRICS.submit_tx[&SubmitTxStage::VerifyExecute].start(); + let stage_latency = + SANDBOX_METRICS.start_tx_submit_stage(tx_hash, SubmitTxStage::VerifyExecute); let computational_gas_limit = self.0.sender_config.validation_computational_gas_limit; let validation_result = self .0 @@ -365,9 +365,9 @@ impl TxSender { return Err(SubmitTxError::FailedToPublishCompressedBytecodes); } - let stage_started_at = Instant::now(); + let mut stage_latency = + SANDBOX_METRICS.start_tx_submit_stage(tx_hash, SubmitTxStage::DbInsert); self.ensure_tx_executable(&tx.clone().into(), &execution_output.metrics, true)?; - let submission_res_handle = self .0 .tx_sink @@ -394,13 +394,12 @@ impl TxSender { } L2TxSubmissionResult::InsertionInProgress => Err(SubmitTxError::InsertionInProgress), L2TxSubmissionResult::Proxied => { - SANDBOX_METRICS.submit_tx[&SubmitTxStage::TxProxy] - .observe(stage_started_at.elapsed()); + stage_latency.set_stage(SubmitTxStage::TxProxy); + stage_latency.observe(); Ok(submission_res_handle) } _ => { - SANDBOX_METRICS.submit_tx[&SubmitTxStage::DbInsert] - .observe(stage_started_at.elapsed()); + stage_latency.observe(); Ok(submission_res_handle) } } From bb8bcf17e2bc9c2fe8bbdf2a11164ce43994bebf Mon Sep 17 00:00:00 2001 From: Alex Ostrovski Date: Thu, 25 Apr 2024 13:20:10 +0300 Subject: [PATCH 3/7] Filter logging for tx submission stages --- .../execution_sandbox/vm_metrics.rs | 9 +++- core/lib/zksync_core/src/api_server/mod.rs | 2 + core/lib/zksync_core/src/api_server/utils.rs | 53 +++++++++++++++++++ .../src/api_server/web3/metrics.rs | 46 +--------------- 4 files changed, 64 insertions(+), 46 deletions(-) create mode 100644 core/lib/zksync_core/src/api_server/utils.rs diff --git a/core/lib/zksync_core/src/api_server/execution_sandbox/vm_metrics.rs b/core/lib/zksync_core/src/api_server/execution_sandbox/vm_metrics.rs index ddd1fb8926a4..6c1f92ed68b4 100644 --- a/core/lib/zksync_core/src/api_server/execution_sandbox/vm_metrics.rs +++ b/core/lib/zksync_core/src/api_server/execution_sandbox/vm_metrics.rs @@ -14,6 +14,8 @@ use zksync_types::{ }; use zksync_utils::bytecode::bytecode_len_in_bytes; +use crate::api_server::utils::ReportFilter; + #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash, EncodeLabelValue, EncodeLabelSet)] #[metrics(label = "type", rename_all = "snake_case")] enum SizeType { @@ -112,11 +114,12 @@ impl SubmitTxLatencyObserver<'_> { } pub fn observe(mut self) { + static FILTER: ReportFilter = report_filter!(Duration::from_secs(10)); const MIN_LOGGED_LATENCY: Duration = Duration::from_secs(1); let latency = self.inner.take().unwrap().observe(); // ^ `unwrap()` is safe: `LatencyObserver` is only taken out in this method. - if latency > MIN_LOGGED_LATENCY { + if latency > MIN_LOGGED_LATENCY && FILTER.should_report() { tracing::info!( "Transaction {:?} submission stage {:?} has high latency: {latency:?}", self.tx_hash, @@ -128,7 +131,9 @@ impl SubmitTxLatencyObserver<'_> { impl Drop for SubmitTxLatencyObserver<'_> { fn drop(&mut self) { - if self.inner.is_some() { + static FILTER: ReportFilter = report_filter!(Duration::from_secs(10)); + + if self.inner.is_some() && FILTER.should_report() { tracing::info!( "Transaction {:?} submission was dropped at stage {:?} due to error or client disconnecting", self.tx_hash, diff --git a/core/lib/zksync_core/src/api_server/mod.rs b/core/lib/zksync_core/src/api_server/mod.rs index b05214e69724..f5e8d159ae5a 100644 --- a/core/lib/zksync_core/src/api_server/mod.rs +++ b/core/lib/zksync_core/src/api_server/mod.rs @@ -1,5 +1,7 @@ // Everywhere in this module the word "block" actually means "miniblock". +#[macro_use] +mod utils; pub mod contract_verification; pub mod execution_sandbox; pub mod healthcheck; diff --git a/core/lib/zksync_core/src/api_server/utils.rs b/core/lib/zksync_core/src/api_server/utils.rs new file mode 100644 index 000000000000..e95ed019f8c4 --- /dev/null +++ b/core/lib/zksync_core/src/api_server/utils.rs @@ -0,0 +1,53 @@ +//! Utils specific to the API server. + +use std::{ + cell::Cell, + thread, + time::{Duration, Instant}, +}; + +/// Allows filtering events (e.g., for logging) so that they are reported no more frequently than with a configurable interval. +/// +/// Current implementation uses thread-local vars in order to not rely on mutexes or other cross-thread primitives. +/// I.e., it only really works if the number of threads accessing it is limited (which is the case for the API server; +/// the number of worker threads is congruent to the CPU count). +#[derive(Debug)] +pub(super) struct ReportFilter { + interval: Duration, + last_timestamp: &'static thread::LocalKey>>, +} + +impl ReportFilter { + // Should only be used from the `report_filter!` macro. + pub const fn new( + interval: Duration, + last_timestamp: &'static thread::LocalKey>>, + ) -> Self { + Self { + interval, + last_timestamp, + } + } + + /// Should be called sparingly, since it involves moderately heavy operations (getting current time). + pub fn should_report(&self) -> bool { + let timestamp = self.last_timestamp.get(); + let now = Instant::now(); + if timestamp.map_or(true, |ts| now - ts > self.interval) { + self.last_timestamp.set(Some(now)); + true + } else { + false + } + } +} + +/// Creates a new filter with the specified reporting interval *per thread*. +macro_rules! report_filter { + ($interval:expr) => {{ + thread_local! { + static LAST_TIMESTAMP: std::cell::Cell> = std::cell::Cell::new(None); + } + ReportFilter::new($interval, &LAST_TIMESTAMP) + }}; +} diff --git a/core/lib/zksync_core/src/api_server/web3/metrics.rs b/core/lib/zksync_core/src/api_server/web3/metrics.rs index 11299e2cb5e1..0788ca3c27bf 100644 --- a/core/lib/zksync_core/src/api_server/web3/metrics.rs +++ b/core/lib/zksync_core/src/api_server/web3/metrics.rs @@ -1,11 +1,6 @@ //! Metrics for the JSON-RPC server. -use std::{ - borrow::Cow, - cell::Cell, - fmt, thread, - time::{Duration, Instant}, -}; +use std::{borrow::Cow, fmt, time::Duration}; use vise::{ Buckets, Counter, DurationAsSecs, EncodeLabelSet, EncodeLabelValue, Family, Gauge, Histogram, @@ -18,44 +13,7 @@ use super::{ backend_jsonrpsee::MethodMetadata, ApiTransport, InternalApiConfig, OptionalApiParams, TypedFilter, }; - -/// Allows filtering events (e.g., for logging) so that they are reported no more frequently than with a configurable interval. -/// -/// Current implementation uses thread-local vars in order to not rely on mutexes or other cross-thread primitives. -/// I.e., it only really works if the number of threads accessing it is limited (which is the case for the API server; -/// the number of worker threads is congruent to the CPU count). -#[derive(Debug)] -struct ReportFilter { - interval: Duration, - last_timestamp: &'static thread::LocalKey>>, -} - -impl ReportFilter { - /// Should be called sparingly, since it involves moderately heavy operations (getting current time). - fn should_report(&self) -> bool { - let timestamp = self.last_timestamp.get(); - let now = Instant::now(); - if timestamp.map_or(true, |ts| now - ts > self.interval) { - self.last_timestamp.set(Some(now)); - true - } else { - false - } - } -} - -/// Creates a new filter with the specified reporting interval *per thread*. -macro_rules! report_filter { - ($interval:expr) => {{ - thread_local! { - static LAST_TIMESTAMP: Cell> = Cell::new(None); - } - ReportFilter { - interval: $interval, - last_timestamp: &LAST_TIMESTAMP, - } - }}; -} +use crate::api_server::utils::ReportFilter; /// Observed version of RPC parameters. Have a bounded upper-limit size (256 bytes), so that we don't over-allocate. #[derive(Debug)] From 0a2398b78dde5b534ef21f26479d4cb1b4dd9913 Mon Sep 17 00:00:00 2001 From: Alex Ostrovski Date: Thu, 25 Apr 2024 14:06:43 +0300 Subject: [PATCH 4/7] Include method name in `rpc_call` span --- .../src/api_server/web3/backend_jsonrpsee/middleware.rs | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/core/lib/zksync_core/src/api_server/web3/backend_jsonrpsee/middleware.rs b/core/lib/zksync_core/src/api_server/web3/backend_jsonrpsee/middleware.rs index 6597c8eb9c25..664dda3f81ab 100644 --- a/core/lib/zksync_core/src/api_server/web3/backend_jsonrpsee/middleware.rs +++ b/core/lib/zksync_core/src/api_server/web3/backend_jsonrpsee/middleware.rs @@ -249,10 +249,13 @@ where static CORRELATION_ID_RNG: RefCell = RefCell::new(SmallRng::from_entropy()); } + // Unlike `MetadataMiddleware`, we don't need to extend the method lifetime to `'static`; + // `tracing` span instantiation allocates a `String` for supplied `&str`s in any case. + let method = request.method_name(); // Wrap a call into a span with unique correlation ID, so that events occurring in the span can be easily filtered. // This works as a cheap alternative to Open Telemetry tracing with its trace / span IDs. let correlation_id = CORRELATION_ID_RNG.with(|rng| rng.borrow_mut().next_u64()); - let call_span = tracing::debug_span!("rpc_call", correlation_id); + let call_span = tracing::debug_span!("rpc_call", method, correlation_id); self.inner.call(request).instrument(call_span) } } From af2d448b0ac42f7dff85fc78c78b76e01d83b197 Mon Sep 17 00:00:00 2001 From: Alex Ostrovski Date: Thu, 25 Apr 2024 14:07:15 +0300 Subject: [PATCH 5/7] Remove method impl spans as obsolete --- .../src/api_server/web3/namespaces/debug.rs | 4 --- .../src/api_server/web3/namespaces/en.rs | 4 --- .../src/api_server/web3/namespaces/eth.rs | 26 ----------------- .../src/api_server/web3/namespaces/web3.rs | 1 - .../src/api_server/web3/namespaces/zks.rs | 28 ------------------- 5 files changed, 63 deletions(-) diff --git a/core/lib/zksync_core/src/api_server/web3/namespaces/debug.rs b/core/lib/zksync_core/src/api_server/web3/namespaces/debug.rs index 7feede944194..a5df3f4b7e65 100644 --- a/core/lib/zksync_core/src/api_server/web3/namespaces/debug.rs +++ b/core/lib/zksync_core/src/api_server/web3/namespaces/debug.rs @@ -56,7 +56,6 @@ impl DebugNamespace { &self.state.current_method } - #[tracing::instrument(skip(self))] pub async fn debug_trace_block_impl( &self, block_id: BlockId, @@ -90,7 +89,6 @@ impl DebugNamespace { Ok(call_trace) } - #[tracing::instrument(skip(self))] pub async fn debug_trace_block_flat_impl( &self, block_id: BlockId, @@ -101,7 +99,6 @@ impl DebugNamespace { Ok(call_trace_flat) } - #[tracing::instrument(skip(self))] pub async fn debug_trace_transaction_impl( &self, tx_hash: H256, @@ -125,7 +122,6 @@ impl DebugNamespace { })) } - #[tracing::instrument(skip(self, request, block_id))] pub async fn debug_trace_call_impl( &self, request: CallRequest, diff --git a/core/lib/zksync_core/src/api_server/web3/namespaces/en.rs b/core/lib/zksync_core/src/api_server/web3/namespaces/en.rs index 208faee3d412..65bcd46b915b 100644 --- a/core/lib/zksync_core/src/api_server/web3/namespaces/en.rs +++ b/core/lib/zksync_core/src/api_server/web3/namespaces/en.rs @@ -37,7 +37,6 @@ impl EnNamespace { &self.state.current_method } - #[tracing::instrument(skip(self))] pub async fn sync_l2_block_impl( &self, block_number: L2BlockNumber, @@ -51,7 +50,6 @@ impl EnNamespace { .map_err(DalError::generalize)?) } - #[tracing::instrument(skip(self))] pub async fn sync_tokens_impl( &self, block_number: Option, @@ -64,7 +62,6 @@ impl EnNamespace { .map_err(DalError::generalize)?) } - #[tracing::instrument(skip(self))] pub async fn genesis_config_impl(&self) -> Result { // If this method will cause some load, we can cache everything in memory let mut storage = self.state.acquire_connection().await?; @@ -155,7 +152,6 @@ impl EnNamespace { Ok(config) } - #[tracing::instrument(skip(self))] pub async fn whitelisted_tokens_for_aa_impl(&self) -> Result, Web3Error> { Ok(self .state diff --git a/core/lib/zksync_core/src/api_server/web3/namespaces/eth.rs b/core/lib/zksync_core/src/api_server/web3/namespaces/eth.rs index 8d8e7fb3aefa..3d2a4bc724ae 100644 --- a/core/lib/zksync_core/src/api_server/web3/namespaces/eth.rs +++ b/core/lib/zksync_core/src/api_server/web3/namespaces/eth.rs @@ -42,7 +42,6 @@ impl EthNamespace { &self.state.current_method } - #[tracing::instrument(skip(self))] pub async fn get_block_number_impl(&self) -> Result { let mut storage = self.state.acquire_connection().await?; let block_number = storage @@ -54,7 +53,6 @@ impl EthNamespace { Ok(block_number.0.into()) } - #[tracing::instrument(skip(self, request, block_id))] pub async fn call_impl( &self, request: CallRequest, @@ -80,7 +78,6 @@ impl EthNamespace { Ok(call_result.into()) } - #[tracing::instrument(skip(self, request, _block))] pub async fn estimate_gas_impl( &self, request: CallRequest, @@ -131,13 +128,11 @@ impl EthNamespace { Ok(fee.gas_limit) } - #[tracing::instrument(skip(self))] pub async fn gas_price_impl(&self) -> Result { let gas_price = self.state.tx_sender.gas_price().await?; Ok(gas_price.into()) } - #[tracing::instrument(skip(self))] pub async fn get_balance_impl( &self, address: Address, @@ -168,7 +163,6 @@ impl EthNamespace { self.current_method().set_block_diff(diff); } - #[tracing::instrument(skip(self, filter))] pub async fn get_logs_impl(&self, mut filter: Filter) -> Result, Web3Error> { self.state.resolve_filter_block_hash(&mut filter).await?; let (from_block, to_block) = self.state.resolve_filter_block_range(&filter).await?; @@ -209,7 +203,6 @@ impl EthNamespace { Ok(logs) } - #[tracing::instrument(skip(self))] pub async fn get_block_impl( &self, block_id: BlockId, @@ -276,7 +269,6 @@ impl EthNamespace { Ok(Some(block.with_transactions(transactions))) } - #[tracing::instrument(skip(self))] pub async fn get_block_transaction_count_impl( &self, block_id: BlockId, @@ -308,7 +300,6 @@ impl EthNamespace { Ok(tx_count.map(Into::into)) } - #[tracing::instrument(skip(self))] pub async fn get_block_receipts_impl( &self, block_id: BlockId, @@ -347,7 +338,6 @@ impl EthNamespace { Ok(Some(receipts)) } - #[tracing::instrument(skip(self))] pub async fn get_code_impl( &self, address: Address, @@ -368,12 +358,10 @@ impl EthNamespace { Ok(contract_code.unwrap_or_default().into()) } - #[tracing::instrument(skip(self))] pub fn chain_id_impl(&self) -> U64 { self.state.api_config.l2_chain_id.as_u64().into() } - #[tracing::instrument(skip(self))] pub async fn get_storage_at_impl( &self, address: Address, @@ -396,7 +384,6 @@ impl EthNamespace { } /// Account nonce. - #[tracing::instrument(skip(self))] pub async fn get_transaction_count_impl( &self, address: Address, @@ -442,7 +429,6 @@ impl EthNamespace { Ok(account_nonce) } - #[tracing::instrument(skip(self))] pub async fn get_transaction_impl( &self, id: TransactionId, @@ -482,7 +468,6 @@ impl EthNamespace { Ok(transaction) } - #[tracing::instrument(skip(self))] pub async fn get_transaction_receipt_impl( &self, hash: H256, @@ -496,7 +481,6 @@ impl EthNamespace { Ok(receipts.into_iter().next()) } - #[tracing::instrument(skip(self))] pub async fn new_block_filter_impl(&self) -> Result { let installed_filters = self .state @@ -519,7 +503,6 @@ impl EthNamespace { .add(TypedFilter::Blocks(next_block_number))) } - #[tracing::instrument(skip(self, filter))] pub async fn new_filter_impl(&self, mut filter: Filter) -> Result { let installed_filters = self .state @@ -540,7 +523,6 @@ impl EthNamespace { .add(TypedFilter::Events(filter, from_block))) } - #[tracing::instrument(skip(self))] pub async fn new_pending_transaction_filter_impl(&self) -> Result { let installed_filters = self .state @@ -555,7 +537,6 @@ impl EthNamespace { ))) } - #[tracing::instrument(skip(self))] pub async fn get_filter_changes_impl(&self, idx: U256) -> Result { let installed_filters = self .state @@ -582,7 +563,6 @@ impl EthNamespace { } } - #[tracing::instrument(skip(self))] pub async fn uninstall_filter_impl(&self, idx: U256) -> Result { let installed_filters = self .state @@ -592,13 +572,11 @@ impl EthNamespace { Ok(installed_filters.lock().await.remove(idx)) } - #[tracing::instrument(skip(self))] pub fn protocol_version(&self) -> String { // TODO (SMA-838): Versioning of our protocol PROTOCOL_VERSION.to_string() } - #[tracing::instrument(skip(self, tx_bytes))] pub async fn send_raw_transaction_impl(&self, tx_bytes: Bytes) -> Result { let (mut tx, hash) = self.state.parse_transaction_bytes(&tx_bytes.0)?; tx.set_input(tx_bytes.0, hash); @@ -611,12 +589,10 @@ impl EthNamespace { }) } - #[tracing::instrument(skip(self))] pub fn accounts_impl(&self) -> Vec
{ Vec::new() } - #[tracing::instrument(skip(self))] pub fn syncing_impl(&self) -> SyncState { if let Some(state) = &self.state.sync_state { // Node supports syncing process (i.e. not the main node). @@ -635,7 +611,6 @@ impl EthNamespace { } } - #[tracing::instrument(skip(self))] pub async fn fee_history_impl( &self, block_count: U64, @@ -685,7 +660,6 @@ impl EthNamespace { }) } - #[tracing::instrument(skip(self, typed_filter))] async fn filter_changes( &self, typed_filter: &mut TypedFilter, diff --git a/core/lib/zksync_core/src/api_server/web3/namespaces/web3.rs b/core/lib/zksync_core/src/api_server/web3/namespaces/web3.rs index 10fa6faf778b..1badef5efc41 100644 --- a/core/lib/zksync_core/src/api_server/web3/namespaces/web3.rs +++ b/core/lib/zksync_core/src/api_server/web3/namespaces/web3.rs @@ -2,7 +2,6 @@ pub struct Web3Namespace; impl Web3Namespace { - #[tracing::instrument(skip(self))] pub fn client_version_impl(&self) -> String { "zkSync/v2.0".to_string() } diff --git a/core/lib/zksync_core/src/api_server/web3/namespaces/zks.rs b/core/lib/zksync_core/src/api_server/web3/namespaces/zks.rs index 294de2009a57..4f0dd72eeda1 100644 --- a/core/lib/zksync_core/src/api_server/web3/namespaces/zks.rs +++ b/core/lib/zksync_core/src/api_server/web3/namespaces/zks.rs @@ -45,7 +45,6 @@ impl ZksNamespace { &self.state.current_method } - #[tracing::instrument(skip(self, request))] pub async fn estimate_fee_impl(&self, request: CallRequest) -> Result { let mut request_with_gas_per_pubdata_overridden = request; self.state @@ -68,7 +67,6 @@ impl ZksNamespace { self.estimate_fee(tx.into()).await } - #[tracing::instrument(skip(self, request))] pub async fn estimate_l1_to_l2_gas_impl( &self, request: CallRequest, @@ -102,37 +100,26 @@ impl ZksNamespace { .await?) } - #[tracing::instrument(skip(self))] pub fn get_bridgehub_contract_impl(&self) -> Option
{ self.state.api_config.bridgehub_proxy_addr } - #[tracing::instrument(skip(self))] pub fn get_main_contract_impl(&self) -> Address { self.state.api_config.diamond_proxy_addr } - #[tracing::instrument(skip(self))] pub fn get_testnet_paymaster_impl(&self) -> Option
{ self.state.api_config.l2_testnet_paymaster_addr } - #[tracing::instrument(skip(self))] pub fn get_bridge_contracts_impl(&self) -> BridgeAddresses { self.state.api_config.bridge_addresses.clone() } - #[tracing::instrument(skip(self))] - pub fn get_base_token_l1_address(&self) -> Option
{ - self.state.api_config.base_token_address - } - - #[tracing::instrument(skip(self))] pub fn l1_chain_id_impl(&self) -> U64 { U64::from(*self.state.api_config.l1_chain_id) } - #[tracing::instrument(skip(self))] pub async fn get_confirmed_tokens_impl( &self, from: u32, @@ -160,7 +147,6 @@ impl ZksNamespace { Ok(tokens) } - #[tracing::instrument(skip(self))] pub async fn get_all_account_balances_impl( &self, address: Address, @@ -203,7 +189,6 @@ impl ZksNamespace { Ok(balances) } - #[tracing::instrument(skip(self))] pub async fn get_l2_to_l1_msg_proof_impl( &self, block_number: L2BlockNumber, @@ -321,7 +306,6 @@ impl ZksNamespace { })) } - #[tracing::instrument(skip(self))] pub async fn get_l2_to_l1_log_proof_impl( &self, tx_hash: H256, @@ -348,7 +332,6 @@ impl ZksNamespace { Ok(log_proof) } - #[tracing::instrument(skip(self))] pub async fn get_l1_batch_number_impl(&self) -> Result { let mut storage = self.state.acquire_connection().await?; let l1_batch_number = storage @@ -360,7 +343,6 @@ impl ZksNamespace { Ok(l1_batch_number.0.into()) } - #[tracing::instrument(skip(self))] pub async fn get_miniblock_range_impl( &self, batch: L1BatchNumber, @@ -378,7 +360,6 @@ impl ZksNamespace { Ok(range.map(|(min, max)| (U64::from(min.0), U64::from(max.0)))) } - #[tracing::instrument(skip(self))] pub async fn get_block_details_impl( &self, block_number: L2BlockNumber, @@ -396,7 +377,6 @@ impl ZksNamespace { .map_err(DalError::generalize)?) } - #[tracing::instrument(skip(self))] pub async fn get_raw_block_transactions_impl( &self, block_number: L2BlockNumber, @@ -414,7 +394,6 @@ impl ZksNamespace { .map_err(DalError::generalize)?) } - #[tracing::instrument(skip(self))] pub async fn get_transaction_details_impl( &self, hash: H256, @@ -433,7 +412,6 @@ impl ZksNamespace { Ok(tx_details) } - #[tracing::instrument(skip(self))] pub async fn get_l1_batch_details_impl( &self, batch_number: L1BatchNumber, @@ -451,7 +429,6 @@ impl ZksNamespace { .map_err(DalError::generalize)?) } - #[tracing::instrument(skip(self))] pub async fn get_bytecode_by_hash_impl( &self, hash: H256, @@ -464,7 +441,6 @@ impl ZksNamespace { .map_err(DalError::generalize)?) } - #[tracing::instrument(skip(self))] pub async fn get_l1_gas_price_impl(&self) -> U64 { let gas_price = self .state @@ -477,7 +453,6 @@ impl ZksNamespace { gas_price.into() } - #[tracing::instrument(skip(self))] pub fn get_fee_params_impl(&self) -> FeeParams { self.state .tx_sender @@ -486,7 +461,6 @@ impl ZksNamespace { .get_fee_model_params() } - #[tracing::instrument(skip(self))] pub async fn get_protocol_version_impl( &self, version_id: Option, @@ -510,7 +484,6 @@ impl ZksNamespace { Ok(protocol_version) } - #[tracing::instrument(skip_all)] pub async fn get_proofs_impl( &self, address: Address, @@ -564,7 +537,6 @@ impl ZksNamespace { })) } - #[tracing::instrument(skip_all)] pub fn get_base_token_l1_address_impl(&self) -> Result { self.state .api_config From 3afcb89073dab875d7561721002d4b86a0a929a2 Mon Sep 17 00:00:00 2001 From: Alex Ostrovski Date: Fri, 26 Apr 2024 10:35:10 +0300 Subject: [PATCH 6/7] Brush up remaining instrumentation --- .../src/api_server/tx_sender/mod.rs | 3 +- .../zksync_core/src/api_server/web3/pubsub.rs | 33 ++++++++----------- 2 files changed, 16 insertions(+), 20 deletions(-) diff --git a/core/lib/zksync_core/src/api_server/tx_sender/mod.rs b/core/lib/zksync_core/src/api_server/tx_sender/mod.rs index d79722cb778c..4c766e9c9c82 100644 --- a/core/lib/zksync_core/src/api_server/tx_sender/mod.rs +++ b/core/lib/zksync_core/src/api_server/tx_sender/mod.rs @@ -305,7 +305,7 @@ impl TxSender { .context("failed acquiring connection to replica DB") } - #[tracing::instrument(skip(self, tx))] + #[tracing::instrument(level = "debug", skip_all, fields(tx.hash = ?tx.hash()))] pub async fn submit_tx(&self, tx: L2Tx) -> Result { let tx_hash = tx.hash(); let stage_latency = SANDBOX_METRICS.start_tx_submit_stage(tx_hash, SubmitTxStage::Validate); @@ -673,6 +673,7 @@ impl TxSender { } } + #[tracing::instrument(level = "debug", skip_all, fields(tx.hash = ?tx.hash()))] pub async fn get_txs_fee_in_wei( &self, mut tx: Transaction, diff --git a/core/lib/zksync_core/src/api_server/web3/pubsub.rs b/core/lib/zksync_core/src/api_server/web3/pubsub.rs index b8dc46c85e71..0ce5698ecea6 100644 --- a/core/lib/zksync_core/src/api_server/web3/pubsub.rs +++ b/core/lib/zksync_core/src/api_server/web3/pubsub.rs @@ -7,6 +7,7 @@ use tokio::{ task::JoinHandle, time::{interval, Duration}, }; +use tracing::Instrument as _; use zksync_dal::{ConnectionPool, Core, CoreDal}; use zksync_types::{L2BlockNumber, H128, H256}; use zksync_web3_decl::{ @@ -344,7 +345,7 @@ impl EthSubscribe { Ok(()) } - #[tracing::instrument(skip(self, pending_sink))] + #[tracing::instrument(level = "debug", skip(self, pending_sink))] pub async fn sub( &self, pending_sink: PendingSubscriptionSink, @@ -357,12 +358,10 @@ impl EthSubscribe { return; }; let blocks_rx = self.blocks.subscribe(); - tokio::spawn(Self::run_subscriber( - sink, - SubscriptionType::Blocks, - blocks_rx, - None, - )); + tokio::spawn( + Self::run_subscriber(sink, SubscriptionType::Blocks, blocks_rx, None) + .in_current_span(), + ); Some(SubscriptionType::Blocks) } @@ -371,12 +370,10 @@ impl EthSubscribe { return; }; let transactions_rx = self.transactions.subscribe(); - tokio::spawn(Self::run_subscriber( - sink, - SubscriptionType::Txs, - transactions_rx, - None, - )); + tokio::spawn( + Self::run_subscriber(sink, SubscriptionType::Txs, transactions_rx, None) + .in_current_span(), + ); Some(SubscriptionType::Txs) } "logs" => { @@ -391,12 +388,10 @@ impl EthSubscribe { return; }; let logs_rx = self.logs.subscribe(); - tokio::spawn(Self::run_subscriber( - sink, - SubscriptionType::Logs, - logs_rx, - Some(filter), - )); + tokio::spawn( + Self::run_subscriber(sink, SubscriptionType::Logs, logs_rx, Some(filter)) + .in_current_span(), + ); Some(SubscriptionType::Logs) } } From 320019ba8145127bd5ab7b1c74bb906c9ee8108b Mon Sep 17 00:00:00 2001 From: Alex Ostrovski Date: Fri, 26 Apr 2024 11:33:27 +0300 Subject: [PATCH 7/7] Fix instrumentation on `get_txs_fee_in_wei()` --- .../src/api_server/tx_sender/mod.rs | 29 +++++++------------ 1 file changed, 10 insertions(+), 19 deletions(-) diff --git a/core/lib/zksync_core/src/api_server/tx_sender/mod.rs b/core/lib/zksync_core/src/api_server/tx_sender/mod.rs index 4c766e9c9c82..557a2debc491 100644 --- a/core/lib/zksync_core/src/api_server/tx_sender/mod.rs +++ b/core/lib/zksync_core/src/api_server/tx_sender/mod.rs @@ -673,7 +673,10 @@ impl TxSender { } } - #[tracing::instrument(level = "debug", skip_all, fields(tx.hash = ?tx.hash()))] + #[tracing::instrument(level = "debug", skip_all, fields( + initiator = ?tx.initiator_account(), + nonce = ?tx.nonce(), + ))] pub async fn get_txs_fee_in_wei( &self, mut tx: Transaction, @@ -792,15 +795,9 @@ impl TxSender { // the transaction succeeds let mut lower_bound = 0; let mut upper_bound = MAX_L2_TX_GAS_LIMIT; - let tx_id = format!( - "{:?}-{}", - tx.initiator_account(), - tx.nonce().unwrap_or(Nonce(0)) - ); tracing::trace!( - "fee estimation tx {:?}: preparation took {:?}, starting binary search", - tx_id, - estimation_started_at.elapsed(), + "preparation took {:?}, starting binary search", + estimation_started_at.elapsed() ); let mut number_of_iterations = 0usize; @@ -832,12 +829,8 @@ impl TxSender { } tracing::trace!( - "fee estimation tx {:?}: iteration {} took {:?}. lower_bound: {}, upper_bound: {}", - tx_id, - number_of_iterations, - iteration_started_at.elapsed(), - lower_bound, - upper_bound, + "iteration {number_of_iterations} took {:?}. lower_bound: {lower_bound}, upper_bound: {upper_bound}", + iteration_started_at.elapsed() ); number_of_iterations += 1; } @@ -896,10 +889,8 @@ impl TxSender { let estimated_gas_for_pubdata = (gas_for_pubdata as f64 * estimated_fee_scale_factor) as u64; - tracing::info!( - initiator = ?tx.initiator_account(), - nonce = %tx.nonce().unwrap_or(Nonce(0)), - "fee estimation: gas for pubdata: {estimated_gas_for_pubdata}, computational gas: {}, overhead gas: {overhead} \ + tracing::debug!( + "gas for pubdata: {estimated_gas_for_pubdata}, computational gas: {}, overhead gas: {overhead} \ (with params base_fee: {base_fee}, gas_per_pubdata_byte: {gas_per_pubdata_byte}) \ estimated_fee_scale_factor: {estimated_fee_scale_factor}", suggested_gas_limit - estimated_gas_for_pubdata,