diff --git a/Cargo.lock b/Cargo.lock index ee295dee7b..dcdd531423 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4552,6 +4552,7 @@ dependencies = [ "log 0.4.14", "rand 0.7.3", "solana-measure", + "solana-metrics", "solana-program-runtime", "solana-runtime", "solana-sdk", diff --git a/programs/bpf/Cargo.lock b/programs/bpf/Cargo.lock index 5aa4ce63aa..35dcdc688b 100644 --- a/programs/bpf/Cargo.lock +++ b/programs/bpf/Cargo.lock @@ -2661,6 +2661,7 @@ dependencies = [ "libsecp256k1 0.6.0", "log", "solana-measure", + "solana-metrics", "solana-program-runtime", "solana-sdk", "solana-zk-token-sdk", diff --git a/programs/bpf_loader/Cargo.toml b/programs/bpf_loader/Cargo.toml index 63bd2f5ec5..d952bc7dad 100644 --- a/programs/bpf_loader/Cargo.toml +++ b/programs/bpf_loader/Cargo.toml @@ -15,6 +15,7 @@ byteorder = "1.4.3" log = "0.4.14" libsecp256k1 = "0.6.0" solana-measure = { path = "../../measure", version = "=1.10.0" } +solana-metrics = { path = "../../metrics", version = "=1.10.0" } solana-program-runtime = { path = "../../program-runtime", version = "=1.10.0" } solana-sdk = { path = "../../sdk", version = "=1.10.0" } solana-zk-token-sdk = { path = "../../zk-token-sdk", version = "=1.10.0" } diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index a6a1075e94..251c5f1ec1 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -8,6 +8,9 @@ pub mod upgradeable; pub mod upgradeable_with_jit; pub mod with_jit; +#[macro_use] +extern crate solana_metrics; + use { crate::{ serialization::{deserialize_parameters, serialize_parameters}, @@ -121,9 +124,14 @@ pub fn create_executor( .is_active(&reject_all_elf_rw::id()), ..Config::default() }; + let program_id; + let load_elf_us: u64; + let verify_elf_us: u64; + let mut jit_compile_us = 0u64; let mut executable = { let keyed_accounts = invoke_context.get_keyed_accounts()?; let programdata = keyed_account_at_index(keyed_accounts, programdata_account_index)?; + program_id = *programdata.unsigned_key(); let mut load_elf_time = Measure::start("load_elf_time"); let executable = Executable::::from_elf( &programdata.try_account_ref()?.data()[programdata_offset..], @@ -132,10 +140,11 @@ pub fn create_executor( syscall_registry, ); load_elf_time.stop(); + load_elf_us = load_elf_time.as_us(); invoke_context.timings.create_executor_load_elf_us = invoke_context .timings .create_executor_load_elf_us - .saturating_add(load_elf_time.as_us()); + .saturating_add(load_elf_us); executable } .map_err(|e| map_ebpf_error(invoke_context, e))?; @@ -144,24 +153,33 @@ pub fn create_executor( verifier::check(text_bytes, &config) .map_err(|e| map_ebpf_error(invoke_context, EbpfError::UserError(e.into())))?; verify_code_time.stop(); + verify_elf_us = verify_code_time.as_us(); invoke_context.timings.create_executor_verify_code_us = invoke_context .timings .create_executor_verify_code_us - .saturating_add(verify_code_time.as_us()); + .saturating_add(verify_elf_us); if use_jit { let mut jit_compile_time = Measure::start("jit_compile_time"); let jit_compile_result = Executable::::jit_compile(&mut executable); jit_compile_time.stop(); + jit_compile_us = jit_compile_time.as_us(); invoke_context.timings.create_executor_jit_compile_us = invoke_context .timings .create_executor_jit_compile_us - .saturating_add(jit_compile_time.as_us()); + .saturating_add(jit_compile_us); if let Err(err) = jit_compile_result { ic_msg!(invoke_context, "Failed to compile program {:?}", err); return Err(InstructionError::ProgramFailedToCompile); } } + datapoint_trace!( + "create_executor_trace", + ("program_id", program_id.to_string(), String), + ("load_elf_us", load_elf_us, i64), + ("verify_elf_us", verify_elf_us, i64), + ("jit_compile_us", jit_compile_us, i64), + ); Ok(Arc::new(BpfExecutor { executable })) }