diff --git a/collator/src/collator/build_block.rs b/collator/src/collator/build_block.rs index 07a80ecf7..2d9a7badf 100644 --- a/collator/src/collator/build_block.rs +++ b/collator/src/collator/build_block.rs @@ -1,7 +1,10 @@ +use std::time::Duration; + use anyhow::{bail, Result}; use everscale_types::merkle::*; use everscale_types::models::*; use everscale_types::prelude::*; +use humantime::format_duration; use tokio::time::Instant; use tycho_block_util::config::BlockchainConfigExt; use tycho_block_util::dict::RelaxedAugDict; @@ -22,6 +25,8 @@ impl CollatorStdImpl { ) -> Result<(Box, ShardStateStuff)> { tracing::debug!(target: tracing_targets::COLLATOR, "finalize_block()"); + let histogram = HistogramGuard::begin("tycho_collator_finalize_block_time"); + let mc_data = &self.working_state().mc_data; let prev_shard_data = &self.working_state().prev_shard_data; @@ -32,7 +37,11 @@ impl CollatorStdImpl { let is_masterchain = collation_data.block_id_short.shard.is_masterchain(); let config_address = &self.working_state().mc_data.config().address; + let build_account_blocks_elapsed; let (account_blocks, shard_accounts) = { + let histogram = + HistogramGuard::begin("tycho_collator_finalize_build_account_blocks_time"); + let mut account_blocks = RelaxedAugDict::new(); let mut shard_accounts = RelaxedAugDict::from_full(prev_shard_data.observable_accounts()); @@ -86,6 +95,7 @@ impl CollatorStdImpl { )?; } + build_account_blocks_elapsed = histogram.finish(); (account_blocks.build()?, shard_accounts.build()?) }; @@ -94,22 +104,32 @@ impl CollatorStdImpl { // calc value flow let mut value_flow = collation_data.value_flow.clone(); + let build_in_msgs_elapsed; let in_msgs = { + let histogram = HistogramGuard::begin("tycho_collator_finalize_build_in_msgs_time"); + let mut in_msgs = RelaxedAugDict::new(); // TODO: use more effective algorithm than iter and set for (msg_id, msg) in collation_data.in_msgs.iter() { in_msgs.set_as_lazy(msg_id, &msg.import_fees, &msg.in_msg)?; } + + build_in_msgs_elapsed = histogram.finish(); in_msgs.build()? }; value_flow.imported = in_msgs.root_extra().value_imported.clone(); + let build_out_msgs_elapsed; let out_msgs = { + let histogram = HistogramGuard::begin("tycho_collator_finalize_build_out_msgs_time"); + let mut out_msgs = RelaxedAugDict::new(); // TODO: use more effective algorithm than iter and set for (msg_id, msg) in collation_data.out_msgs.iter() { out_msgs.set_as_lazy(msg_id, &msg.exported_value, &msg.out_msg)?; } + + build_out_msgs_elapsed = histogram.finish(); out_msgs.build()? }; @@ -129,7 +149,11 @@ impl CollatorStdImpl { // build master state extra or get a ref to last applied master block // TODO: extract min_ref_mc_seqno from processed_upto info when we have many shards // collation_data.update_ref_min_mc_seqno(min_ref_mc_seqno); + let build_mc_state_extra_elapsed; let (mc_state_extra, master_ref) = if is_masterchain { + let histogram = + HistogramGuard::begin("tycho_collator_finish_build_mc_state_extra_time"); + let (extra, min_ref_mc_seqno) = self.create_mc_state_extra( collation_data, new_config_params.map(|params| BlockchainConfig { @@ -138,8 +162,11 @@ impl CollatorStdImpl { }), )?; collation_data.update_ref_min_mc_seqno(min_ref_mc_seqno); + + build_mc_state_extra_elapsed = histogram.finish(); (Some(extra), None) } else { + build_mc_state_extra_elapsed = Duration::ZERO; (None, Some(mc_data.get_master_ref())) }; @@ -177,7 +204,11 @@ impl CollatorStdImpl { })); } + let build_state_update_elapsed; let state_update = { + let histogram = + HistogramGuard::begin("tycho_collator_finalize_build_state_update_time"); + // build new state let mut new_observable_state = Box::new(ShardStateUnsplit { global_id: mc_data.global_id(), @@ -218,70 +249,83 @@ impl CollatorStdImpl { let new_state_root = CellBuilder::build_from(&new_observable_state)?; // calc merkle update - create_merkle_update( + let merkle_update = create_merkle_update( prev_shard_data.pure_state_root(), &new_state_root, &self.working_state().usage_tree, - )? - }; + )?; - // calc block extra - let mut new_block_extra = BlockExtra { - in_msg_description: Lazy::new(&in_msgs)?, - out_msg_description: Lazy::new(&out_msgs)?, - account_blocks: Lazy::new(&account_blocks)?, - rand_seed: collation_data.rand_seed, - created_by: collation_data.created_by, - ..Default::default() + build_state_update_elapsed = histogram.finish(); + merkle_update }; - if let Some(mc_state_extra) = mc_state_extra { - let new_mc_block_extra = McBlockExtra { - shards: mc_state_extra.shards.clone(), - fees: collation_data.shard_fees.clone(), - // TODO: Signatures for previous blocks - prev_block_signatures: Default::default(), - mint_msg: collation_data - .mint_msg - .as_ref() - .map(Lazy::new) - .transpose()?, - recover_create_msg: collation_data - .recover_create_msg - .as_ref() - .map(Lazy::new) - .transpose()?, - copyleft_msgs: Default::default(), - config: if mc_state_extra.after_key_block { - Some(mc_state_extra.config.clone()) - } else { - None - }, + let build_block_elapsed; + let new_block_id; + let new_block_boc; + let new_block = { + let histogram = HistogramGuard::begin("tycho_collator_finalize_build_block_time"); + + // calc block extra + let mut new_block_extra = BlockExtra { + in_msg_description: Lazy::new(&in_msgs)?, + out_msg_description: Lazy::new(&out_msgs)?, + account_blocks: Lazy::new(&account_blocks)?, + rand_seed: collation_data.rand_seed, + created_by: collation_data.created_by, + ..Default::default() }; - new_block_extra.custom = Some(Lazy::new(&new_mc_block_extra)?); - } + if let Some(mc_state_extra) = mc_state_extra { + let new_mc_block_extra = McBlockExtra { + shards: mc_state_extra.shards.clone(), + fees: collation_data.shard_fees.clone(), + // TODO: Signatures for previous blocks + prev_block_signatures: Default::default(), + mint_msg: collation_data + .mint_msg + .as_ref() + .map(Lazy::new) + .transpose()?, + recover_create_msg: collation_data + .recover_create_msg + .as_ref() + .map(Lazy::new) + .transpose()?, + copyleft_msgs: Default::default(), + config: if mc_state_extra.after_key_block { + Some(mc_state_extra.config.clone()) + } else { + None + }, + }; - // construct block - let new_block = Block { - global_id: mc_data.global_id(), - info: Lazy::new(&new_block_info)?, - value_flow: Lazy::new(&value_flow)?, - state_update: Lazy::new(&state_update)?, - // do not use out msgs queue updates - out_msg_queue_updates: None, - extra: Lazy::new(&new_block_extra)?, - }; + new_block_extra.custom = Some(Lazy::new(&new_mc_block_extra)?); + } - // TODO: Check (assert) whether the serialized block contains usage cells - let new_block_root = CellBuilder::build_from(&new_block)?; + // construct block + let new_block = Block { + global_id: mc_data.global_id(), + info: Lazy::new(&new_block_info)?, + value_flow: Lazy::new(&value_flow)?, + state_update: Lazy::new(&state_update)?, + // do not use out msgs queue updates + out_msg_queue_updates: None, + extra: Lazy::new(&new_block_extra)?, + }; - let new_block_boc = everscale_types::boc::Boc::encode(&new_block_root); - let new_block_id = BlockId { - shard: collation_data.block_id_short.shard, - seqno: collation_data.block_id_short.seqno, - root_hash: *new_block_root.repr_hash(), - file_hash: Boc::file_hash(&new_block_boc), + build_block_elapsed = histogram.finish(); + + // TODO: Check (assert) whether the serialized block contains usage cells + let new_block_root = CellBuilder::build_from(&new_block)?; + + new_block_boc = everscale_types::boc::Boc::encode(&new_block_root); + new_block_id = BlockId { + shard: collation_data.block_id_short.shard, + seqno: collation_data.block_id_short.seqno, + root_hash: *new_block_root.repr_hash(), + file_hash: Boc::file_hash(&new_block_boc), + }; + new_block }; // TODO: build collated data from collation_data.shard_top_block_descriptors @@ -302,12 +346,33 @@ impl CollatorStdImpl { // build new shard state using merkle update // to get updated state without UsageTree - let _histogram = HistogramGuard::begin("tycho_collator_apply_temp_merkle_update_time"); + let build_new_state_elapsed; + let new_state_stuff = { + let histogram = HistogramGuard::begin("tycho_collator_finalize_build_new_state_time"); + + let pure_prev_state_root = prev_shard_data.pure_state_root(); + let new_state_root = state_update.apply(pure_prev_state_root)?; + let new_state_stuff = + ShardStateStuff::from_root(&new_block_id, new_state_root, &self.state_tracker)?; + + build_new_state_elapsed = histogram.finish(); + new_state_stuff + }; - let pure_prev_state_root = prev_shard_data.pure_state_root(); - let new_state_root = state_update.apply(pure_prev_state_root)?; - let new_state_stuff = - ShardStateStuff::from_root(&new_block_id, new_state_root, &self.state_tracker)?; + let total_elapsed = histogram.finish(); + + tracing::debug!( + target: tracing_targets::COLLATOR, + total = %format_duration(total_elapsed), + build_account_blocks = %format_duration(build_account_blocks_elapsed), + build_in_msgs = %format_duration(build_in_msgs_elapsed), + build_out_msgs = %format_duration(build_out_msgs_elapsed), + build_mc_state_extra = %format_duration(build_mc_state_extra_elapsed), + build_state_update = %format_duration(build_state_update_elapsed), + build_block = %format_duration(build_block_elapsed), + build_new_state = %format_duration(build_new_state_elapsed), + "finalize block timings" + ); Ok((block_candidate, new_state_stuff)) } diff --git a/collator/src/collator/do_collate.rs b/collator/src/collator/do_collate.rs index a5814284d..83dfc4529 100644 --- a/collator/src/collator/do_collate.rs +++ b/collator/src/collator/do_collate.rs @@ -1,6 +1,6 @@ use std::collections::VecDeque; use std::sync::Arc; -use std::time::Duration; +use std::time::{Duration, Instant}; use anyhow::{anyhow, bail, Result}; use everscale_types::models::*; @@ -9,6 +9,7 @@ use everscale_types::prelude::*; use humantime::format_duration; use sha2::Digest; use ton_executor::{ExecuteParams, ExecutorOutput, PreloadedBlockchainConfig}; +use tycho_util::metrics::HistogramGuard; use tycho_util::FastHashMap; use super::types::{CachedMempoolAnchor, SpecialOrigin}; @@ -34,7 +35,9 @@ impl CollatorStdImpl { next_chain_time: u64, top_shard_blocks_info: Option>, ) -> Result<()> { - let mut timer = std::time::Instant::now(); + let histogram = HistogramGuard::begin("tycho_do_collate_total_time"); + + let prepare_histogram = HistogramGuard::begin("tycho_do_collate_prepare_time"); let mc_data = &self.working_state().mc_data; let prev_shard_data = &self.working_state().prev_shard_data; @@ -139,11 +142,24 @@ impl CollatorStdImpl { prev_shard_data.observable_accounts().clone(), ); - let do_collate_prepare_elapsed = timer.elapsed(); - timer = std::time::Instant::now(); + let prepare_elapsed = prepare_histogram.finish(); + + let init_iterator_elapsed; + let mut internal_messages_iterator; + { + let histogram = HistogramGuard::begin("tycho_do_collate_init_iterator_time"); + internal_messages_iterator = self.init_internal_mq_iterator().await?; + init_iterator_elapsed = histogram.finish(); + } + + let execute_histogram = HistogramGuard::begin("tycho_do_collate_execute_time"); // execute tick transaction and special transactions (mint, recover) + + let execute_tick_elapsed; if self.shard_id.is_masterchain() { + let histogram = HistogramGuard::begin("tycho_do_collate_execute_tick_time"); + self.create_ticktock_transactions( TickTock::Tick, &mut collation_data, @@ -153,6 +169,10 @@ impl CollatorStdImpl { self.create_special_transactions(&mut collation_data, &mut exec_manager) .await?; + + execute_tick_elapsed = histogram.finish(); + } else { + execute_tick_elapsed = Duration::ZERO; } let mut all_existing_internals_finished = false; @@ -160,23 +180,14 @@ impl CollatorStdImpl { let mut block_limits_reached = false; - let mut do_collate_ticktock_special_elapsed = timer.elapsed(); - timer = std::time::Instant::now(); - - let mut internal_messages_iterator = self.init_internal_mq_iterator().await?; - - let do_collate_init_iterator_elapsed = timer.elapsed(); - timer = std::time::Instant::now(); - // indicate that there are still unprocessed internals when collation loop finished let mut has_pending_internals = false; - let mut do_collate_fill_msgs_set_elapsed = Duration::ZERO; - let mut do_collate_exec_msgs_elapsed = Duration::ZERO; - let mut do_collate_process_transactions_elapsed = Duration::ZERO; - + let mut fill_msgs_total_elapsed = Duration::ZERO; + let mut process_msgs_total_elapsed = Duration::ZERO; + let mut process_txs_total_elapsed = Duration::ZERO; loop { - // let mut one_set_timer = std::time::Instant::now(); + let timer = Instant::now(); let mut executed_internal_messages = vec![]; let mut internal_messages_sources = FastHashMap::default(); @@ -304,22 +315,23 @@ impl CollatorStdImpl { let mut msgs_set_offset = collation_data.processed_upto.processed_offset; let mut msgs_set_full_processed = false; - do_collate_fill_msgs_set_elapsed += timer.elapsed(); - timer = std::time::Instant::now(); + fill_msgs_total_elapsed += timer.elapsed(); let mut messages_inserted_to_iterator = 0; let mut executed_messages = 0; // execute msgs processing by groups while !msgs_set_full_processed { + // Process messages + timer = std::time::Instant::now(); let tick = exec_manager.tick(msgs_set_offset).await?; - msgs_set_full_processed = tick.finished; + process_msgs_total_elapsed += timer.elapsed(); + msgs_set_full_processed = tick.finished; let one_tick_executed_count = tick.items.len(); - do_collate_exec_msgs_elapsed += timer.elapsed(); + // Process transactions timer = std::time::Instant::now(); - for item in tick.items { if let MsgInfo::Int(int_msg_info) = &item.in_message.info { let key = InternalMessageKey { @@ -367,8 +379,7 @@ impl CollatorStdImpl { msgs_set_offset = tick.new_offset; - do_collate_process_transactions_elapsed += timer.elapsed(); - timer = std::time::Instant::now(); + process_txs_total_elapsed += timer.elapsed(); // TODO: when processing transactions we should check block limits // currently we simply check only transactions count @@ -386,6 +397,8 @@ impl CollatorStdImpl { } } + timer = std::time::Instant::now(); + // HACK: temporary always full process msgs set and check block limits after if collation_data.tx_count >= self.config.block_txs_limit { tracing::debug!(target: tracing_targets::COLLATOR, @@ -427,30 +440,36 @@ impl CollatorStdImpl { has_pending_internals = internal_messages_iterator.peek(true)?.is_some(); - do_collate_process_transactions_elapsed += timer.elapsed(); - timer = std::time::Instant::now(); + process_txs_total_elapsed += timer.elapsed(); if block_limits_reached { // block is full - exit loop break; } } + metrics::histogram!("tycho_do_collate_fill_msgs_total_time") + .record(fill_msgs_total_elapsed); + metrics::histogram!("tycho_do_collate_process_msgs_total_time") + .record(process_msgs_total_elapsed); + metrics::histogram!("tycho_do_collate_process_txs_total_time") + .record(process_txs_total_elapsed); // execute tock transaction + let execute_tock_elapsed; if self.shard_id.is_masterchain() { + let histogram = HistogramGuard::begin("tycho_do_collate_execute_tock_time"); self.create_ticktock_transactions( TickTock::Tock, &mut collation_data, &mut exec_manager, ) .await?; + execute_tock_elapsed = histogram.finish(); + } else { + execute_tock_elapsed = Duration::ZERO; } - do_collate_ticktock_special_elapsed += timer.elapsed(); - timer = std::time::Instant::now(); - - // let do_collate_execute_elapsed_ms = timer.elapsed().as_millis() as u32; - // timer = std::time::Instant::now(); + let execute_elapsed = execute_histogram.finish(); let diff = Arc::new(internal_messages_iterator.take_diff()); @@ -480,83 +499,59 @@ impl CollatorStdImpl { tokio::task::block_in_place(|| self.finalize_block(&mut collation_data, exec_manager))?; tokio::task::yield_now().await; - self.mq_adapter - .apply_diff(diff.clone(), candidate.block_id.as_short_id()) - .await?; - - let do_collate_build_block_elapsed = timer.elapsed(); - timer = std::time::Instant::now(); - - // return collation result - let collation_result = BlockCollationResult { - candidate, - new_state_stuff: new_state_stuff.clone(), - has_pending_internals, - }; + let apply_queue_diff_elapsed; + { + let histogram = HistogramGuard::begin("tycho_do_collate_apply_queue_diff_time"); + self.mq_adapter + .apply_diff(diff.clone(), candidate.block_id.as_short_id()) + .await?; + apply_queue_diff_elapsed = histogram.finish(); + } - self.listener.on_block_candidate(collation_result).await?; + let handle_block_candidate_elapsed; + { + let histogram = HistogramGuard::begin("tycho_do_collate_handle_block_candidate_time"); + + // return collation result + self.listener + .on_block_candidate(BlockCollationResult { + candidate, + new_state_stuff: new_state_stuff.clone(), + has_pending_internals, + }) + .await?; - // update PrevData in working state - self.update_working_state(new_state_stuff)?; - self.update_working_state_pending_internals(Some(has_pending_internals))?; + // update PrevData in working state + self.update_working_state(new_state_stuff)?; + self.update_working_state_pending_internals(Some(has_pending_internals))?; - let do_collate_update_state_elapsed = timer.elapsed(); + handle_block_candidate_elapsed = histogram.finish(); + } // metrics - let labels = [("workchain", self.shard_id.workchain().to_string())]; + let labels = &[("workchain", self.shard_id.workchain().to_string())]; - metrics::counter!("tycho_do_collate_tx_total", &labels) + metrics::counter!("tycho_do_collate_tx_total", labels) .increment(collation_data.tx_count as _); - metrics::histogram!("tycho_do_collate_msgs_exec_count_all", &labels) + metrics::histogram!("tycho_do_collate_msgs_exec_count_all", labels) .record(collation_data.execute_count_all); - metrics::histogram!("tycho_do_collate_msgs_exec_count_ext", &labels) + metrics::histogram!("tycho_do_collate_msgs_exec_count_ext", labels) .record(collation_data.execute_count_ext); - metrics::histogram!("tycho_do_collate_msgs_exec_count_int", &labels) + metrics::histogram!("tycho_do_collate_msgs_exec_count_int", labels) .record(collation_data.execute_count_int); - metrics::histogram!("tycho_do_collate_msgs_exec_count_new_int", &labels) + metrics::histogram!("tycho_do_collate_msgs_exec_count_new_int", labels) .record(collation_data.execute_count_new_int); - metrics::gauge!("tycho_do_collate_int_msgs_queue_length", &labels) - .increment(collation_data.enqueue_count); - metrics::gauge!("tycho_do_collate_int_msgs_queue_length", &labels) - .decrement(collation_data.dequeue_count); - - let do_collate_execute_elapsed = do_collate_fill_msgs_set_elapsed - + do_collate_exec_msgs_elapsed - + do_collate_process_transactions_elapsed; - let do_collate_total_elapsed = do_collate_prepare_elapsed - + do_collate_init_iterator_elapsed - + do_collate_execute_elapsed - + do_collate_build_block_elapsed - + do_collate_update_state_elapsed - + do_collate_ticktock_special_elapsed; - collation_data.total_execute_msgs_time_mc = do_collate_exec_msgs_elapsed.as_micros(); - - metrics::histogram!("tycho_do_collate_total_time", &labels) - .record(do_collate_total_elapsed); - metrics::histogram!("tycho_do_collate_prepare_time", &labels) - .record(do_collate_prepare_elapsed); - metrics::histogram!("tycho_do_collate_init_iterator_time", &labels) - .record(do_collate_init_iterator_elapsed); - metrics::histogram!("tycho_do_collate_execute_time", &labels) - .record(do_collate_execute_elapsed); - metrics::histogram!("tycho_do_collate_fill_msgs_set_time", &labels) - .record(do_collate_fill_msgs_set_elapsed); - metrics::histogram!("tycho_do_collate_exec_msgs_time", &labels) - .record(do_collate_exec_msgs_elapsed); - metrics::histogram!("tycho_do_collate_process_transactions_time", &labels) - .record(do_collate_process_transactions_elapsed); - metrics::histogram!("tycho_do_collate_build_block_time", &labels) - .record(do_collate_build_block_elapsed); - metrics::histogram!("tycho_do_collate_update_state_time", &labels) - .record(do_collate_update_state_elapsed); - if self.shard_id.is_masterchain() { - metrics::histogram!("tycho_do_collate_ticktock_special_time", &labels) - .record(do_collate_ticktock_special_elapsed); - } + metrics::gauge!("tycho_do_collate_int_msgs_queue_length", labels).increment( + (collation_data.enqueue_count as i64 - collation_data.dequeue_count as i64) as f64, + ); + collation_data.total_execute_msgs_time_mc = process_msgs_total_elapsed.as_micros(); self.update_stats(&collation_data); + + let total_elapsed = histogram.finish(); + tracing::info!(target: tracing_targets::COLLATOR, "{:?}", self.stats); tracing::info!(target: tracing_targets::COLLATOR, @@ -567,7 +562,7 @@ impl CollatorStdImpl { new_msgs_created={}, new_msgs_added={}, \ in_msgs={}, out_msgs={}, \ read_new_msgs_from_iterator={}, inserted_new_msgs_to_iterator={}", - do_collate_total_elapsed.as_millis(), + total_elapsed.as_millis(), collation_data.start_lt, collation_data.next_lt, collation_data.execute_count_all, collation_data.execute_count_ext, collation_data.execute_count_int, collation_data.execute_count_new_int, collation_data.enqueue_count, collation_data.dequeue_count, @@ -583,16 +578,19 @@ impl CollatorStdImpl { tracing::info!( target: tracing_targets::COLLATOR, - total = %format_duration(do_collate_total_elapsed), - prepare = %format_duration(do_collate_prepare_elapsed), - init_iterator = %format_duration(do_collate_init_iterator_elapsed), - execute = %format_duration(do_collate_execute_elapsed), - fill_msgs_set = %format_duration(do_collate_fill_msgs_set_elapsed), - exec_msgs = %format_duration(do_collate_exec_msgs_elapsed), - process_transactions = %format_duration(do_collate_process_transactions_elapsed), - build_block = %format_duration(do_collate_build_block_elapsed), - update_state = %format_duration(do_collate_update_state_elapsed), - ticktop_special = %format_duration(do_collate_ticktock_special_elapsed), + total = %format_duration(total_elapsed), + prepare = %format_duration(prepare_elapsed), + init_iterator = %format_duration(init_iterator_elapsed), + execute_total = %format_duration(execute_elapsed), + execute_tick = %format_duration(execute_tick_elapsed), + execute_tock = %format_duration(execute_tock_elapsed), + + fill_msgs_total = %format_duration(fill_msgs_total_elapsed), + process_msgs_total = %format_duration(process_msgs_total_elapsed), + process_txs_total = %format_duration(process_txs_total_elapsed), + + apply_queue_diff = %format_duration(apply_queue_diff_elapsed), + handle_block_candidate = %format_duration(handle_block_candidate_elapsed), "timings" ); diff --git a/scripts/gen-dashboard.py b/scripts/gen-dashboard.py index 1675ff62d..fcfba6578 100644 --- a/scripts/gen-dashboard.py +++ b/scripts/gen-dashboard.py @@ -382,16 +382,37 @@ def jrpc() -> RowPanel: return create_row("JRPC", metrics) -def collator_do_collate() -> RowPanel: +def collator_finalize_block() -> RowPanel: metrics = [ create_counter_panel( - "tycho_do_collate_msgs_exec_count_all_sum", - "Number of all executed messages over time", + "tycho_collator_finalize_block_time", "Total time to finalize block" + ), + create_counter_panel( + "tycho_collator_finalize_build_account_blocks_time", "Build account blocks" + ), + create_counter_panel( + "tycho_collator_finalize_build_in_msgs_time", "Build InMsgDescr" + ), + create_counter_panel( + "tycho_collator_finalize_build_out_msgs_time", + "Build OutMsgDescr", + ), + create_counter_panel( + "tycho_collator_finish_build_mc_state_extra_time", "Build McStateExtra" + ), + create_counter_panel( + "tycho_collator_finalize_build_state_update_time", "Compute MerkleUpdate" ), + create_counter_panel("tycho_collator_finalize_build_block_time", "Build Block"), create_counter_panel( - "tycho_do_collate_msgs_exec_count_ext_sum", - "Number of executed external messages over time", + "tycho_collator_finalize_build_new_state_time", "Build State" ), + ] + return create_row("Finalize Block", metrics) + + +def collator_do_collate() -> RowPanel: + metrics = [ create_counter_panel( "tycho_do_collate_tx_total", "Number of transactions over time", @@ -406,23 +427,26 @@ def collator_do_collate() -> RowPanel: ), create_heatmap_panel("tycho_do_collate_execute_time", "Execution time"), create_heatmap_panel( - "tycho_do_collate_fill_msgs_set_time", "Fill messages time" + "tycho_do_collate_execute_tick_time", "Execute Tick special transactions" + ), + create_heatmap_panel( + "tycho_do_collate_execute_tock_time", "Execute Tock special transactions" + ), + create_heatmap_panel( + "tycho_do_collate_fill_msgs_total_time", "Sum of fill messages times" ), create_heatmap_panel( - "tycho_do_collate_exec_msgs_time", "Execute messages time" + "tycho_do_collate_process_msgs_total_time", "Sum of execute messages times" ), create_heatmap_panel( - "tycho_do_collate_process_transactions_time", - "Process transactions time", + "tycho_do_collate_process_txs_total_time", + "Sum of process transactions times", ), create_heatmap_panel( - "tycho_do_collate_ticktock_special_time", - "Process special transactions time", + "tycho_do_collate_apply_queue_diff_time", "Apply message queue diff" ), - create_heatmap_panel("tycho_do_collate_build_block_time", "Build block time"), - create_heatmap_panel("tycho_do_collate_update_state_time", "Update state time"), create_heatmap_panel( - "tycho_collator_adapter_handle_state_time", "Handle state by collator" + "tycho_do_collate_handle_block_candidate_time", "Handle block candidate" ), create_heatmap_panel( "tycho_collator_adapter_on_block_accepted_ext_time", @@ -507,6 +531,7 @@ def templates() -> Templating: core_bc(), core_block_strider(), collator_do_collate(), + collator_finalize_block(), collator_execution_manager(), net_conn_manager(), net_request_handler(), diff --git a/util/src/metrics/histogram_guard.rs b/util/src/metrics/histogram_guard.rs index 39d1a6a93..135dde75e 100644 --- a/util/src/metrics/histogram_guard.rs +++ b/util/src/metrics/histogram_guard.rs @@ -1,23 +1,43 @@ -use std::time::Instant; +use std::time::{Duration, Instant}; #[must_use = "The guard is used to update the histogram when it is dropped"] pub struct HistogramGuard { - name: &'static str, + name: Option<&'static str>, started_at: Instant, } impl HistogramGuard { pub fn begin(name: &'static str) -> Self { Self { - name, + name: Some(name), started_at: Instant::now(), } } + + pub fn begin_with_labels<'a, T>( + name: &'static str, + labels: &'a T, + ) -> HistogramGuardWithLabels<'a, T> + where + &'a T: metrics::IntoLabels, + { + HistogramGuardWithLabels::begin(name, labels) + } + + pub fn finish(mut self) -> Duration { + let duration = self.started_at.elapsed(); + if let Some(name) = self.name.take() { + metrics::histogram!(name).record(duration); + } + duration + } } impl Drop for HistogramGuard { fn drop(&mut self) { - metrics::histogram!(self.name).record(self.started_at.elapsed()); + if let Some(name) = self.name.take() { + metrics::histogram!(name).record(self.started_at.elapsed()); + } } } @@ -26,7 +46,7 @@ pub struct HistogramGuardWithLabels<'a, T: 'static> where &'a T: metrics::IntoLabels, { - name: &'static str, + name: Option<&'static str>, started_at: Instant, labels: &'a T, } @@ -37,11 +57,19 @@ where { pub fn begin(name: &'static str, labels: &'a T) -> Self { Self { - name, + name: Some(name), started_at: Instant::now(), labels, } } + + pub fn finish(mut self) -> Duration { + let duration = self.started_at.elapsed(); + if let Some(name) = self.name.take() { + metrics::histogram!(name, self.labels).record(duration); + } + duration + } } impl<'a, T> Drop for HistogramGuardWithLabels<'a, T> @@ -49,6 +77,8 @@ where &'a T: metrics::IntoLabels, { fn drop(&mut self) { - metrics::histogram!(self.name, self.labels).record(self.started_at.elapsed()); + if let Some(name) = self.name.take() { + metrics::histogram!(name, self.labels).record(self.started_at.elapsed()); + } } }