Add stats for LoadedPrograms (#31577)

This commit is contained in:
Pankaj Garg 2023-05-10 12:08:55 -07:00 committed by GitHub
parent e1b57b8a37
commit 04425b81ce
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 89 additions and 5 deletions

View File

@ -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<Pubkey, u64>,
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::<Vec<_>>();
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::<Vec<_>>();
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<Pubkey, Vec<Arc<LoadedProgram>>>,
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::<HashMap<Pubkey, Arc<LoadedProgram>>>();
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());
}
}

View File

@ -150,7 +150,7 @@ pub fn load_program_from_account(
program: &BorrowedAccount,
programdata: &BorrowedAccount,
debugging_features: bool,
) -> Result<(Arc<LoadedProgram>, Option<LoadProgramMetrics>), InstructionError> {
) -> Result<(Arc<LoadedProgram>, 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(

View File

@ -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))
}