diff --git a/Cargo.lock b/Cargo.lock index 23b5617215..6dafc2d38a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5495,6 +5495,7 @@ version = "0.1.0" dependencies = [ "diem-crypto", "diem-global-constants", + "diem-metrics", "diem-types", "diem-workspace-hack", "ethers", diff --git a/execution/executor/src/lib.rs b/execution/executor/src/lib.rs index 6651d60baa..f848895a8a 100644 --- a/execution/executor/src/lib.rs +++ b/execution/executor/src/lib.rs @@ -23,6 +23,9 @@ use crate::{ DIEM_EXECUTOR_EXECUTE_AND_COMMIT_CHUNK_SECONDS, DIEM_EXECUTOR_EXECUTE_BLOCK_SECONDS, DIEM_EXECUTOR_SAVE_TRANSACTIONS_SECONDS, DIEM_EXECUTOR_TRANSACTIONS_SAVED, DIEM_EXECUTOR_VM_EXECUTE_BLOCK_SECONDS, + DIEM_EXECUTOR_EXECUTE_AND_COMMIT_CHUNK_VERIFY_LATENCY, + DIEM_EXECUTOR_EXECUTE_AND_COMMIT_CHUNK_EXECUTION_LATENCY, + DIEM_EXECUTOR_EXECUTE_AND_COMMIT_CHUNK_SAVE_TX_LATENCY }, speculation_cache::SpeculationCache, types::{ProcessedVMOutput, TransactionData}, @@ -59,7 +62,7 @@ use std::{ collections::{hash_map, HashMap, HashSet}, convert::TryFrom, marker::PhantomData, - sync::Arc, + sync::Arc, time::Instant, }; use storage_interface::{state_view::VerifiedStateView, DbReaderWriter, TreeState}; @@ -605,22 +608,44 @@ impl ChunkExecutor for Executor { .num_txns_in_request(txn_list_with_proof.transactions.len()), "sync_request_received", ); - + + // temp time the transaction execution. + let start_time = Instant::now(); + let metrics_timer_vl = DIEM_EXECUTOR_EXECUTE_AND_COMMIT_CHUNK_VERIFY_LATENCY.start_timer(); // 2. Verify input transaction list. let (transactions, transaction_infos) = self.verify_chunk(txn_list_with_proof, &verified_target_li)?; + + let latency = start_time.elapsed(); + metrics_timer_vl.observe_duration(); + dbg!("verify_chunk latency", &latency); // 3. Execute transactions. + + // temp time the transaction execution. + let start_time = Instant::now(); + let metrics_timer_el = DIEM_EXECUTOR_EXECUTE_AND_COMMIT_CHUNK_EXECUTION_LATENCY.start_timer(); + let first_version = self.cache.synced_trees().txn_accumulator().num_leaves(); let (output, txns_to_commit, reconfig_events) = self.execute_chunk(first_version, transactions, transaction_infos)?; + let latency = start_time.elapsed(); + metrics_timer_el.observe_duration(); + dbg!("execute_chunk latency", &latency); + + + // temp time the transaction execution. + let start_time = Instant::now(); + let metrics_timer_stxl = DIEM_EXECUTOR_EXECUTE_AND_COMMIT_CHUNK_SAVE_TX_LATENCY.start_timer(); + // 4. Commit to DB. let ledger_info_to_commit = Self::find_chunk_li(verified_target_li, epoch_change_li, &output)?; if ledger_info_to_commit.is_none() && txns_to_commit.is_empty() { return Ok(reconfig_events); } + fail_point!("executor::commit_chunk", |_| { Err(anyhow::anyhow!("Injected error in commit_chunk")) }); @@ -630,6 +655,10 @@ impl ChunkExecutor for Executor { ledger_info_to_commit.as_ref(), )?; + let latency = start_time.elapsed(); + metrics_timer_stxl.observe_duration(); + dbg!("save_transactions latency", &latency); + // 5. Cache maintenance. let output_trees = output.executed_trees().clone(); if let Some(ledger_info_with_sigs) = &ledger_info_to_commit { diff --git a/execution/executor/src/metrics.rs b/execution/executor/src/metrics.rs index 0a33a5d901..3f7e4508c5 100644 --- a/execution/executor/src/metrics.rs +++ b/execution/executor/src/metrics.rs @@ -67,3 +67,33 @@ pub static DIEM_EXECUTOR_TRANSACTIONS_SAVED: Lazy = Lazy::new(|| { ) .unwrap() }); + +pub static DIEM_EXECUTOR_EXECUTE_AND_COMMIT_CHUNK_VERIFY_LATENCY: Lazy = Lazy::new(|| { + register_histogram!( + // metric name + "diem_executor_execute_and_commit_chunk_verify_latency", + // metric description + "The time spent to verify a chunk in Diem executor" + ) + .unwrap() +}); + +pub static DIEM_EXECUTOR_EXECUTE_AND_COMMIT_CHUNK_EXECUTION_LATENCY: Lazy = Lazy::new(|| { + register_histogram!( + // metric name + "diem_executor_execute_and_commit_chunk_execution_latency", + // metric description + "The time spent to execute a chunk in Diem executor" + ) + .unwrap() +}); + +pub static DIEM_EXECUTOR_EXECUTE_AND_COMMIT_CHUNK_SAVE_TX_LATENCY: Lazy = Lazy::new(|| { + register_histogram!( + // metric name + "diem_executor_execute_and_commit_chunk_save_tx_latency", + // metric description + "The time spent to save a transaction in Diem executor" + ) + .unwrap() +}); diff --git a/language/diem-vm/src/counters.rs b/language/diem-vm/src/counters.rs index 01b8ce0fac..b3277d4352 100644 --- a/language/diem-vm/src/counters.rs +++ b/language/diem-vm/src/counters.rs @@ -70,3 +70,11 @@ pub static TXN_GAS_USAGE: Lazy = pub static CRITICAL_ERRORS: Lazy = Lazy::new(|| { register_int_counter!("diem_vm_critical_errors", "Number of critical errors").unwrap() }); + +pub static EXECUTOR_SINGLE_TX_LATENCY: Lazy = Lazy::new(|| { + register_histogram!( + "diem_vm_executor_single_tx_latency", + "Latency to execute a single transaction in the VM" + ) + .unwrap() +}); diff --git a/language/diem-vm/src/diem_transaction_executor.rs b/language/diem-vm/src/diem_transaction_executor.rs index 50953cc1ba..de36803310 100644 --- a/language/diem-vm/src/diem_transaction_executor.rs +++ b/language/diem-vm/src/diem_transaction_executor.rs @@ -43,7 +43,7 @@ use move_vm_types::gas_schedule::GasStatus; use rayon::prelude::*; use std::{ collections::HashSet, - convert::{AsMut, AsRef}, + convert::{AsMut, AsRef}, time::Instant, }; pub struct DiemVM(DiemVMImpl); @@ -768,8 +768,26 @@ impl DiemVM { debug!(log_context, "Retry after reconfiguration"); continue; }; + + + // temp time the transaction execution. + let start_time = Instant::now(); + let metric_single_tx_lat = EXECUTOR_SINGLE_TX_LATENCY.start_timer(); + let (vm_status, output, sender) = self.execute_single_transaction(&txn, data_cache, &log_context)?; + + match &txn { + PreprocessedTransaction::UserTransaction(t) => { + dbg!(&t.sequence_number()); + }, + _ => {}, + }; + dbg!("tx sender", &sender); + let latency = start_time.elapsed(); + metric_single_tx_lat.observe_duration(); + dbg!("single tx latency", &latency); + if !output.status().is_discarded() { data_cache.push_write_set(output.write_set()); } else { diff --git a/language/move-vm/natives/Cargo.toml b/language/move-vm/natives/Cargo.toml index 71cbdd49ce..c7bedfad41 100644 --- a/language/move-vm/natives/Cargo.toml +++ b/language/move-vm/natives/Cargo.toml @@ -22,6 +22,7 @@ diem-workspace-hack = { path = "../../../common/workspace-hack" } move-core-types = { path = "../../move-core/types" } move-vm-types = { path = "../types" } move-binary-format = { path = "../../move-binary-format" } +diem-metrics = { path = "../../../common/metrics" } ######### 0L ######## diem-global-constants = { path = "../../../config/global-constants"} diff --git a/language/move-vm/natives/src/counters.rs b/language/move-vm/natives/src/counters.rs new file mode 100644 index 0000000000..4ac98f1812 --- /dev/null +++ b/language/move-vm/natives/src/counters.rs @@ -0,0 +1,20 @@ +use diem_metrics::{ + register_histogram, register_int_counter, Histogram, IntCounter +}; +use once_cell::sync::Lazy; + +pub static MOVE_VM_NATIVE_VERIFY_VDF_LATENCY: Lazy = Lazy::new(|| { + register_histogram!( + "diem_move_vm_native_verify_vdf_latency", + "Latency to verify a VDF challenge" + ) + .unwrap() +}); + +pub static MOVE_VM_NATIVE_VERIFY_VDF_PROOF_COUNT: Lazy = Lazy::new(|| { + register_int_counter!("diem_move_vm_native_verify_vdf_proof_count", "Cumulative number of verified proofs").unwrap() +}); + +pub static MOVE_VM_NATIVE_VERIFY_VDF_PROOF_ERROR_COUNT: Lazy = Lazy::new(|| { + register_int_counter!("diem_move_vm_native_verify_vdf_proof_error_count", "Cumulative number of errors while verifying proofs").unwrap() +}); diff --git a/language/move-vm/natives/src/lib.rs b/language/move-vm/natives/src/lib.rs index 532ea0f3c9..ffb5a71d8f 100644 --- a/language/move-vm/natives/src/lib.rs +++ b/language/move-vm/natives/src/lib.rs @@ -14,6 +14,7 @@ pub mod signer; pub mod vector; //////// 0L //////// +pub mod counters; pub mod vdf; pub mod ol_decimal; pub mod ol_hash; diff --git a/language/move-vm/natives/src/vdf.rs b/language/move-vm/natives/src/vdf.rs index 86d28f0cf1..eaee4cc08b 100644 --- a/language/move-vm/natives/src/vdf.rs +++ b/language/move-vm/natives/src/vdf.rs @@ -11,10 +11,12 @@ use move_vm_types::{ natives::function::{native_gas, NativeContext, NativeResult}, values::{Reference, Value}, }; -use std::collections::VecDeque; +use std::{collections::VecDeque, time::Instant}; use std::convert::TryFrom; use move_binary_format::errors::{PartialVMError, PartialVMResult}; use smallvec::smallvec; +use crate::counters::{MOVE_VM_NATIVE_VERIFY_VDF_LATENCY, MOVE_VM_NATIVE_VERIFY_VDF_PROOF_COUNT, + MOVE_VM_NATIVE_VERIFY_VDF_PROOF_ERROR_COUNT}; /// Rust implementation of Move's `native public fun verify(challenge: vector, difficulty: u64, alleged_solution: vector): bool` pub fn verify( @@ -22,14 +24,21 @@ pub fn verify( _ty_args: Vec, mut arguments: VecDeque, ) -> PartialVMResult { + // temporary logging. + let start_time = Instant::now(); + let metric_timer = MOVE_VM_NATIVE_VERIFY_VDF_LATENCY.start_timer(); + if arguments.len() != 4 { let msg = format!( "wrong number of arguments for vdf_verify expected 4 found {}", arguments.len() ); + MOVE_VM_NATIVE_VERIFY_VDF_PROOF_ERROR_COUNT.inc(); return Err(PartialVMError::new(StatusCode::UNREACHABLE).with_message(msg)); } + MOVE_VM_NATIVE_VERIFY_VDF_PROOF_COUNT.inc(); + // pop the arguments (reverse order). let security = pop_arg!(arguments, Reference) .read_ref()? @@ -49,7 +58,8 @@ pub fn verify( // refuse to try anthing with a security parameter above 2048 for DOS risk. if security > 2048 { - return Err(PartialVMError::new(StatusCode::UNREACHABLE).with_message("VDF security parameter above threshold".to_string())); + MOVE_VM_NATIVE_VERIFY_VDF_PROOF_ERROR_COUNT.inc(); + return Err(PartialVMError::new(StatusCode::UNREACHABLE).with_message("VDF security parameter above threshold".to_string())); } // TODO change the `cost_index` when we have our own cost table. @@ -59,6 +69,12 @@ pub fn verify( let result = v.verify(&challenge, difficulty, &solution); let return_values = smallvec![Value::bool(result.is_ok())]; + + // temporary logging + let latency = start_time.elapsed(); + metric_timer.observe_duration(); + dbg!("vdf verification latency", &latency); + Ok(NativeResult::ok(cost, return_values)) } diff --git a/mempool/src/shared_mempool/tasks.rs b/mempool/src/shared_mempool/tasks.rs index 072616d952..65d17713dd 100644 --- a/mempool/src/shared_mempool/tasks.rs +++ b/mempool/src/shared_mempool/tasks.rs @@ -82,7 +82,11 @@ pub(crate) async fn process_client_transaction_submission( timer: HistogramTimer, ) where V: TransactionValidation, -{ +{ + dbg!("new transaction", &transaction); + dbg!("new transaction", &transaction.sender()); + dbg!("new transaction", &transaction.sequence_number()); + timer.stop_and_record(); let _timer = counters::process_txn_submit_latency_timer(counters::CLIENT_LABEL, counters::CLIENT_LABEL); @@ -432,6 +436,10 @@ pub(crate) async fn process_consensus_request(mempool: &Mutex, req: counters::REQUEST_SUCCESS_LABEL }; let latency = start_time.elapsed(); + + dbg!("mempool_service latency", &latency); + + counters::mempool_service_latency(counter_label, result, latency); }