From 63b30c6c141127ca87e439ff398ab1af0e224112 Mon Sep 17 00:00:00 2001 From: arya2 Date: Wed, 15 Mar 2023 20:00:36 -0400 Subject: [PATCH 1/2] starts the timer at the top of the call() method --- zebra-state/src/service.rs | 50 ++------------------------------------ 1 file changed, 2 insertions(+), 48 deletions(-) diff --git a/zebra-state/src/service.rs b/zebra-state/src/service.rs index ec8abf0b80f..2f9b8f26836 100644 --- a/zebra-state/src/service.rs +++ b/zebra-state/src/service.rs @@ -894,13 +894,12 @@ impl Service for StateService { #[instrument(name = "state", skip(self, req))] fn call(&mut self, req: Request) -> Self::Future { req.count_metric(); + let timer = CodeTimer::start(); match req { // Uses queued_non_finalized_blocks and pending_utxos in the StateService // Accesses shared writeable state in the StateService, NonFinalizedState, and ZebraDb. Request::CommitBlock(prepared) => { - let timer = CodeTimer::start(); - self.assert_block_can_be_validated(&prepared); self.pending_utxos @@ -948,8 +947,6 @@ impl Service for StateService { // Uses queued_finalized_blocks and pending_utxos in the StateService. // Accesses shared writeable state in the StateService. Request::CommitFinalizedBlock(finalized) => { - let timer = CodeTimer::start(); - // # Consensus // // A non-finalized block verification could have called AwaitUtxo @@ -995,8 +992,6 @@ impl Service for StateService { // Uses pending_utxos and queued_non_finalized_blocks in the StateService. // If the UTXO isn't in the queued blocks, runs concurrently using the ReadStateService. Request::AwaitUtxo(outpoint) => { - let timer = CodeTimer::start(); - // Prepare the AwaitUtxo future from PendingUxtos. let response_fut = self.pending_utxos.queue(outpoint); // Only instrument `response_fut`, the ReadStateService already @@ -1151,12 +1146,11 @@ impl Service for ReadStateService { #[instrument(name = "read_state", skip(self, req))] fn call(&mut self, req: ReadRequest) -> Self::Future { req.count_metric(); + let timer = CodeTimer::start(); match req { // Used by the StateService. ReadRequest::Tip => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1180,8 +1174,6 @@ impl Service for ReadStateService { // Used by the StateService. ReadRequest::Depth(hash) => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1205,8 +1197,6 @@ impl Service for ReadStateService { // Used by the StateService. ReadRequest::BestChainNextMedianTimePast => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1234,8 +1224,6 @@ impl Service for ReadStateService { // Used by the get_block (raw) RPC and the StateService. ReadRequest::Block(hash_or_height) => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1263,8 +1251,6 @@ impl Service for ReadStateService { // For the get_raw_transaction RPC and the StateService. ReadRequest::Transaction(hash) => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1288,8 +1274,6 @@ impl Service for ReadStateService { // Used by the getblock (verbose) RPC. ReadRequest::TransactionIdsForBlock(hash_or_height) => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1322,8 +1306,6 @@ impl Service for ReadStateService { } ReadRequest::UnspentBestChainUtxo(outpoint) => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1351,8 +1333,6 @@ impl Service for ReadStateService { // Manually used by the StateService to implement part of AwaitUtxo. ReadRequest::AnyChainUtxo(outpoint) => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1376,8 +1356,6 @@ impl Service for ReadStateService { // Used by the StateService. ReadRequest::BlockLocator => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1403,8 +1381,6 @@ impl Service for ReadStateService { // Used by the StateService. ReadRequest::FindBlockHashes { known_blocks, stop } => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1434,8 +1410,6 @@ impl Service for ReadStateService { // Used by the StateService. ReadRequest::FindBlockHeaders { known_blocks, stop } => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1469,8 +1443,6 @@ impl Service for ReadStateService { } ReadRequest::SaplingTree(hash_or_height) => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1497,8 +1469,6 @@ impl Service for ReadStateService { } ReadRequest::OrchardTree(hash_or_height) => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1526,8 +1496,6 @@ impl Service for ReadStateService { // For the get_address_balance RPC. ReadRequest::AddressBalance(addresses) => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1558,8 +1526,6 @@ impl Service for ReadStateService { addresses, height_range, } => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1594,8 +1560,6 @@ impl Service for ReadStateService { // For the get_address_utxos RPC. ReadRequest::UtxosByAddresses(addresses) => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1623,8 +1587,6 @@ impl Service for ReadStateService { } ReadRequest::CheckBestChainTipNullifiersAndAnchors(unmined_tx) => { - let timer = CodeTimer::start(); - let state = self.clone(); let span = Span::current(); @@ -1664,8 +1626,6 @@ impl Service for ReadStateService { // Used by the get_block and get_block_hash RPCs. ReadRequest::BestChainBlockHash(height) => { - let timer = CodeTimer::start(); - let state = self.clone(); // # Performance @@ -1697,8 +1657,6 @@ impl Service for ReadStateService { // Used by get_block_template RPC. #[cfg(feature = "getblocktemplate-rpcs")] ReadRequest::ChainInfo => { - let timer = CodeTimer::start(); - let state = self.clone(); let latest_non_finalized_state = self.latest_non_finalized_state(); @@ -1739,8 +1697,6 @@ impl Service for ReadStateService { // Used by getmininginfo, getnetworksolps, and getnetworkhashps RPCs. #[cfg(feature = "getblocktemplate-rpcs")] ReadRequest::SolutionRate { num_blocks, height } => { - let timer = CodeTimer::start(); - let state = self.clone(); // # Performance @@ -1794,8 +1750,6 @@ impl Service for ReadStateService { #[cfg(feature = "getblocktemplate-rpcs")] ReadRequest::CheckBlockProposalValidity(prepared) => { - let timer = CodeTimer::start(); - let state = self.clone(); // # Performance From 18e6c85bc1325c5ee906f404deaa86c635cf1a2f Mon Sep 17 00:00:00 2001 From: arya2 Date: Wed, 15 Mar 2023 20:01:01 -0400 Subject: [PATCH 2/2] assigns 'span' at the top of the call methods --- zebra-state/src/service.rs | 32 ++++++++------------------------ 1 file changed, 8 insertions(+), 24 deletions(-) diff --git a/zebra-state/src/service.rs b/zebra-state/src/service.rs index 2f9b8f26836..cceb8c6d067 100644 --- a/zebra-state/src/service.rs +++ b/zebra-state/src/service.rs @@ -895,6 +895,7 @@ impl Service for StateService { fn call(&mut self, req: Request) -> Self::Future { req.count_metric(); let timer = CodeTimer::start(); + let span = Span::current(); match req { // Uses queued_non_finalized_blocks and pending_utxos in the StateService @@ -915,7 +916,7 @@ impl Service for StateService { // there shouldn't be any other code running in the same task, // so we don't need to worry about blocking it: // https://docs.rs/tokio/latest/tokio/task/fn.block_in_place.html - let span = Span::current(); + let rsp_rx = tokio::task::block_in_place(move || { span.in_scope(|| self.queue_and_commit_non_finalized(prepared)) }); @@ -970,7 +971,6 @@ impl Service for StateService { // The work is all done, the future just waits on a channel for the result timer.finish(module_path!(), line!(), "CommitFinalizedBlock"); - let span = Span::current(); async move { rsp_rx .await @@ -996,7 +996,7 @@ impl Service for StateService { let response_fut = self.pending_utxos.queue(outpoint); // Only instrument `response_fut`, the ReadStateService already // instruments its requests with the same span. - let span = Span::current(); + let response_fut = response_fut.instrument(span).boxed(); // Check the non-finalized block queue outside the returned future, @@ -1147,13 +1147,13 @@ impl Service for ReadStateService { fn call(&mut self, req: ReadRequest) -> Self::Future { req.count_metric(); let timer = CodeTimer::start(); + let span = Span::current(); match req { // Used by the StateService. ReadRequest::Tip => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let tip = state.non_finalized_state_receiver.with_watch_data( @@ -1176,7 +1176,6 @@ impl Service for ReadStateService { ReadRequest::Depth(hash) => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let depth = state.non_finalized_state_receiver.with_watch_data( @@ -1199,7 +1198,6 @@ impl Service for ReadStateService { ReadRequest::BestChainNextMedianTimePast => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let non_finalized_state = state.latest_non_finalized_state(); @@ -1226,7 +1224,6 @@ impl Service for ReadStateService { ReadRequest::Block(hash_or_height) => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let block = state.non_finalized_state_receiver.with_watch_data( @@ -1253,7 +1250,6 @@ impl Service for ReadStateService { ReadRequest::Transaction(hash) => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let transaction_and_height = state @@ -1276,7 +1272,6 @@ impl Service for ReadStateService { ReadRequest::TransactionIdsForBlock(hash_or_height) => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let transaction_ids = state.non_finalized_state_receiver.with_watch_data( @@ -1308,7 +1303,6 @@ impl Service for ReadStateService { ReadRequest::UnspentBestChainUtxo(outpoint) => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let utxo = state.non_finalized_state_receiver.with_watch_data( @@ -1335,7 +1329,6 @@ impl Service for ReadStateService { ReadRequest::AnyChainUtxo(outpoint) => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let utxo = state.non_finalized_state_receiver.with_watch_data( @@ -1358,7 +1351,6 @@ impl Service for ReadStateService { ReadRequest::BlockLocator => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let block_locator = state.non_finalized_state_receiver.with_watch_data( @@ -1383,7 +1375,6 @@ impl Service for ReadStateService { ReadRequest::FindBlockHashes { known_blocks, stop } => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let block_hashes = state.non_finalized_state_receiver.with_watch_data( @@ -1412,7 +1403,6 @@ impl Service for ReadStateService { ReadRequest::FindBlockHeaders { known_blocks, stop } => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let block_headers = state.non_finalized_state_receiver.with_watch_data( @@ -1445,7 +1435,6 @@ impl Service for ReadStateService { ReadRequest::SaplingTree(hash_or_height) => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let sapling_tree = state.non_finalized_state_receiver.with_watch_data( @@ -1471,7 +1460,6 @@ impl Service for ReadStateService { ReadRequest::OrchardTree(hash_or_height) => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let orchard_tree = state.non_finalized_state_receiver.with_watch_data( @@ -1498,7 +1486,6 @@ impl Service for ReadStateService { ReadRequest::AddressBalance(addresses) => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let balance = state.non_finalized_state_receiver.with_watch_data( @@ -1528,7 +1515,6 @@ impl Service for ReadStateService { } => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let tx_ids = state.non_finalized_state_receiver.with_watch_data( @@ -1562,7 +1548,6 @@ impl Service for ReadStateService { ReadRequest::UtxosByAddresses(addresses) => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let utxos = state.non_finalized_state_receiver.with_watch_data( @@ -1589,7 +1574,6 @@ impl Service for ReadStateService { ReadRequest::CheckBestChainTipNullifiersAndAnchors(unmined_tx) => { let state = self.clone(); - let span = Span::current(); tokio::task::spawn_blocking(move || { span.in_scope(move || { let latest_non_finalized_best_chain = @@ -1631,7 +1615,7 @@ impl Service for ReadStateService { // # Performance // // Allow other async tasks to make progress while concurrently reading blocks from disk. - let span = Span::current(); + tokio::task::spawn_blocking(move || { span.in_scope(move || { let hash = state.non_finalized_state_receiver.with_watch_data( @@ -1663,7 +1647,7 @@ impl Service for ReadStateService { // # Performance // // Allow other async tasks to make progress while concurrently reading blocks from disk. - let span = Span::current(); + tokio::task::spawn_blocking(move || { span.in_scope(move || { // # Correctness @@ -1702,7 +1686,7 @@ impl Service for ReadStateService { // # Performance // // Allow other async tasks to make progress while concurrently reading blocks from disk. - let span = Span::current(); + tokio::task::spawn_blocking(move || { span.in_scope(move || { let latest_non_finalized_state = state.latest_non_finalized_state(); @@ -1755,7 +1739,7 @@ impl Service for ReadStateService { // # Performance // // Allow other async tasks to make progress while concurrently reading blocks from disk. - let span = Span::current(); + tokio::task::spawn_blocking(move || { span.in_scope(move || { tracing::info!("attempting to validate and commit block proposal onto a cloned non-finalized state");