From 04425b81ce7188116b04e425fb094080dc61bed9 Mon Sep 17 00:00:00 2001 From: Pankaj Garg Date: Wed, 10 May 2023 12:08:55 -0700 Subject: [PATCH] Add stats for LoadedPrograms (#31577) --- program-runtime/src/loaded_programs.rs | 75 +++++++++++++++++++++++++- programs/bpf_loader/src/lib.rs | 4 +- runtime/src/bank.rs | 15 +++++- 3 files changed, 89 insertions(+), 5 deletions(-) diff --git a/program-runtime/src/loaded_programs.rs b/program-runtime/src/loaded_programs.rs index bd6078413e..8392b6012e 100644 --- a/program-runtime/src/loaded_programs.rs +++ b/program-runtime/src/loaded_programs.rs @@ -3,6 +3,7 @@ use solana_rbpf::error::EbpfError; use { crate::{invoke_context::InvokeContext, timings::ExecuteDetailsTimings}, itertools::Itertools, + log::{debug, log_enabled, trace}, percentage::PercentageInteger, solana_measure::measure::Measure, solana_rbpf::{ @@ -111,6 +112,60 @@ pub struct LoadedProgram { pub usage_counter: AtomicU64, } +#[derive(Debug, Default)] +pub struct Stats { + pub hits: AtomicU64, + pub misses: AtomicU64, + pub evictions: HashMap, + pub insertions: AtomicU64, + pub replacements: AtomicU64, + pub one_hit_wonders: AtomicU64, +} + +impl Stats { + /// Logs the measurement values + pub fn submit(&self, slot: Slot) { + let hits = self.hits.load(Ordering::Relaxed); + let misses = self.misses.load(Ordering::Relaxed); + let insertions = self.insertions.load(Ordering::Relaxed); + let replacements = self.replacements.load(Ordering::Relaxed); + let one_hit_wonders = self.one_hit_wonders.load(Ordering::Relaxed); + let evictions: u64 = self.evictions.values().sum(); + datapoint_info!( + "bank-executor-cache-stats", + ("slot", slot, i64), + ("hits", hits, i64), + ("misses", misses, i64), + ("evictions", evictions, i64), + ("insertions", insertions, i64), + ("replacements", replacements, i64), + ("one_hit_wonders", one_hit_wonders, i64), + ); + debug!( + "Loaded Programs Cache Stats -- Hits: {}, Misses: {}, Evictions: {}, Insertions: {}, Replacements: {}, One-Hit-Wonders: {}", + hits, misses, evictions, insertions, replacements, one_hit_wonders, + ); + if log_enabled!(log::Level::Trace) && !self.evictions.is_empty() { + let mut evictions = self.evictions.iter().collect::>(); + evictions.sort_by_key(|e| e.1); + let evictions = evictions + .into_iter() + .rev() + .map(|(program_id, evictions)| { + format!(" {:<44} {}", program_id.to_string(), evictions) + }) + .collect::>(); + let evictions = evictions.join("\n"); + trace!( + "Eviction Details:\n {:<44} {}\n{}", + "Program", + "Count", + evictions + ); + } + } +} + #[derive(Debug, Default)] pub struct LoadProgramMetrics { pub program_id: String, @@ -281,6 +336,7 @@ pub struct LoadedPrograms { entries: HashMap>>, latest_root: Slot, + pub stats: Stats, } #[derive(Debug, Default)] @@ -381,10 +437,12 @@ impl LoadedPrograms { // a chance. second_level.swap_remove(entry_index); } else { + self.stats.replacements.fetch_add(1, Ordering::Relaxed); return (true, existing.clone()); } } } + self.stats.insertions.fetch_add(1, Ordering::Relaxed); second_level.insert(index.unwrap_or(second_level.len()), entry.clone()); (false, entry) } @@ -506,7 +564,14 @@ impl LoadedPrograms { missing.push(key); None }) - .collect(); + .collect::>>(); + + self.stats + .misses + .fetch_add(missing.len() as u64, Ordering::Relaxed); + self.stats + .hits + .fetch_add(found.len() as u64, Ordering::Relaxed); ( LoadedProgramsForTxBatch { entries: found, @@ -592,6 +657,14 @@ impl LoadedPrograms { for (id, program) in remove { if let Some(entries) = self.entries.get_mut(id) { if let Some(candidate) = entries.iter_mut().find(|entry| entry == &program) { + if candidate.usage_counter.load(Ordering::Relaxed) == 1 { + self.stats.one_hit_wonders.fetch_add(1, Ordering::Relaxed); + } + self.stats + .evictions + .entry(*id) + .and_modify(|c| saturating_add_assign!(*c, 1)) + .or_insert(1); *candidate = Arc::new(candidate.to_unloaded()); } } diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 33de855baa..d3c4e71db9 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -150,7 +150,7 @@ pub fn load_program_from_account( program: &BorrowedAccount, programdata: &BorrowedAccount, debugging_features: bool, -) -> Result<(Arc, Option), InstructionError> { +) -> Result<(Arc, LoadProgramMetrics), InstructionError> { if !check_loader_id(program.get_owner()) { ic_logger_msg!( log_collector, @@ -189,7 +189,7 @@ pub fn load_program_from_account( debugging_features, )?); - Ok((loaded_program, Some(load_program_metrics))) + Ok((loaded_program, load_program_metrics)) } fn find_program_in_cache( diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index 9a57788415..e6242b3486 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -101,7 +101,7 @@ use { }, log_collector::LogCollector, sysvar_cache::SysvarCache, - timings::{ExecuteTimingType, ExecuteTimings}, + timings::{ExecuteDetailsTimings, ExecuteTimingType, ExecuteTimings}, }, solana_sdk::{ account::{ @@ -1627,6 +1627,13 @@ impl Bank { }, ); + parent + .loaded_programs_cache + .read() + .unwrap() + .stats + .submit(parent.slot()); + new } @@ -4155,7 +4162,11 @@ impl Bank { programdata.as_ref().unwrap_or(&program), debugging_features, ) - .map(|(loaded_program, _create_executor_metrics)| loaded_program) + .map(|(loaded_program, metrics)| { + let mut timings = ExecuteDetailsTimings::default(); + metrics.submit_datapoint(&mut timings); + loaded_program + }) .map_err(|err| TransactionError::InstructionError(0, err)) }