From 5a35a0a1018e168e1d530e93d225493dedb6d0e8 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Sun, 25 Aug 2024 15:26:44 +0900 Subject: [PATCH 01/52] Introduce ledger-tool simulate-block-production --- ci/run-sanity.sh | 31 +- core/Cargo.toml | 6 +- core/src/banking_simulation.rs | 616 +++++++++++++++++++++++++++++ core/src/banking_trace.rs | 10 +- core/src/lib.rs | 1 + cost-model/src/cost_tracker.rs | 14 + gossip/Cargo.toml | 1 + gossip/src/cluster_info.rs | 31 +- ledger-tool/Cargo.toml | 2 +- ledger-tool/src/args.rs | 4 + ledger-tool/src/main.rs | 206 +++++++++- ledger/src/blockstore.rs | 18 +- ledger/src/blockstore_processor.rs | 38 +- runtime/src/bank.rs | 113 +++++- validator/src/admin_rpc_service.rs | 9 +- 15 files changed, 1076 insertions(+), 24 deletions(-) create mode 100644 core/src/banking_simulation.rs diff --git a/ci/run-sanity.sh b/ci/run-sanity.sh index 88a6f40b1adf28..1778aec67a3d66 100755 --- a/ci/run-sanity.sh +++ b/ci/run-sanity.sh @@ -5,9 +5,22 @@ cd "$(dirname "$0")/.." # shellcheck source=multinode-demo/common.sh source multinode-demo/common.sh +if [[ -z $CI ]]; then + # Build eargerly if needed for local development. Otherwise, odd timing error occurs... + $solana_keygen --version + $solana_genesis --version + $solana_faucet --version + $solana_cli --version + $agave_validator --version + $solana_ledger_tool --version +fi + rm -rf config/run/init-completed config/ledger config/snapshot-ledger -SOLANA_RUN_SH_VALIDATOR_ARGS="--full-snapshot-interval-slots 200" timeout 120 ./scripts/run.sh & +SOLANA_RUN_SH_VALIDATOR_ARGS="--full-snapshot-interval-slots 200" \ + SOLANA_VALIDATOR_EXIT_TIMEOUT=30 \ + timeout 120 ./scripts/run.sh & + pid=$! attempts=20 @@ -21,7 +34,7 @@ while [[ ! -f config/run/init-completed ]]; do fi done -snapshot_slot=1 +snapshot_slot=50 latest_slot=0 # wait a bit longer than snapshot_slot @@ -39,5 +52,15 @@ $solana_ledger_tool create-snapshot --ledger config/ledger "$snapshot_slot" conf cp config/ledger/genesis.tar.bz2 config/snapshot-ledger $solana_ledger_tool copy --ledger config/ledger \ --target-db config/snapshot-ledger --starting-slot "$snapshot_slot" --ending-slot "$latest_slot" -$solana_ledger_tool verify --ledger config/snapshot-ledger --block-verification-method blockstore-processor -$solana_ledger_tool verify --ledger config/snapshot-ledger --block-verification-method unified-scheduler +$solana_ledger_tool verify --abort-on-invalid-block \ + --ledger config/snapshot-ledger --block-verification-method blockstore-processor +$solana_ledger_tool verify --abort-on-invalid-block \ + --ledger config/snapshot-ledger --block-verification-method unified-scheduler + +first_simulated_slot=$((latest_slot / 2)) +echo "First simulated slot: ${first_simulated_slot}" +touch config/ledger/simulate_block_production_allowed +$solana_ledger_tool simulate-block-production --ledger config/ledger \ + --first-simulated-slot $first_simulated_slot +$solana_ledger_tool verify --abort-on-invalid-block \ + --ledger config/ledger --enable-hash-overrides diff --git a/core/Cargo.toml b/core/Cargo.toml index bde6144e142ae0..a73f3b80c82532 100644 --- a/core/Cargo.toml +++ b/core/Cargo.toml @@ -101,6 +101,7 @@ serde_json = { workspace = true } serial_test = { workspace = true } # See order-crates-for-publishing.py for using this unusual `path = "."` solana-core = { path = ".", features = ["dev-context-only-utils"] } +solana-gossip = { workspace = true, features = ["dev-context-only-utils"] } solana-ledger = { workspace = true, features = ["dev-context-only-utils"] } solana-logger = { workspace = true } solana-poh = { workspace = true, features = ["dev-context-only-utils"] } @@ -123,7 +124,10 @@ sysctl = { workspace = true } rustc_version = { workspace = true, optional = true } [features] -dev-context-only-utils = [] +dev-context-only-utils = [ + "solana-gossip/dev-context-only-utils", + "solana-runtime/dev-context-only-utils", +] frozen-abi = [ "dep:rustc_version", "dep:solana-frozen-abi", diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs new file mode 100644 index 00000000000000..af9bfb404acf06 --- /dev/null +++ b/core/src/banking_simulation.rs @@ -0,0 +1,616 @@ +#![cfg(feature = "dev-context-only-utils")] +use { + crate::{ + banking_stage::BankingStage, + banking_trace::{ + BankingPacketBatch, BankingTracer, ChannelLabel, TimedTracedEvent, TracedEvent, + BANKING_TRACE_DIR_DEFAULT_BYTE_LIMIT, BASENAME, + }, + validator::BlockProductionMethod, + }, + bincode::deserialize_from, + crossbeam_channel::unbounded, + log::*, + solana_client::connection_cache::ConnectionCache, + solana_gossip::cluster_info::{ClusterInfo, Node}, + solana_ledger::{ + blockstore::{Blockstore, PurgeType}, + leader_schedule_cache::LeaderScheduleCache, + }, + solana_poh::{ + poh_recorder::{PohRecorder, GRACE_TICKS_FACTOR, MAX_GRACE_SLOTS}, + poh_service::{PohService, DEFAULT_HASHES_PER_BATCH, DEFAULT_PINNED_CPU_CORE}, + }, + solana_runtime::{ + bank::{Bank, HashOverrides}, + bank_forks::BankForks, + prioritization_fee_cache::PrioritizationFeeCache, + }, + solana_sdk::{ + genesis_config::GenesisConfig, shred_version::compute_shred_version, slot_history::Slot, + }, + solana_streamer::socket::SocketAddrSpace, + solana_turbine::broadcast_stage::BroadcastStageType, + std::{ + collections::BTreeMap, + fs::File, + io::{self, BufRead, BufReader}, + net::{Ipv4Addr, UdpSocket}, + path::PathBuf, + sync::{ + atomic::{AtomicBool, Ordering}, + Arc, RwLock, + }, + thread::{self, sleep}, + time::{Duration, SystemTime}, + }, + thiserror::Error, +}; + +// This creates a simulated environment around the banking stage to reproduce leader's blocks based +// on recorded banking trace events (`TimedTracedEvent`). +// +// The task of banking stage at the highest level is to pack transactions into their blocks as much +// as possible for scheduled fixed duration. So, there's 3 abstract inputs to simulate: blocks, +// time, and transactions. +// +// In the context of simulation, the first two are simple; both are well defined. +// +// For ancestor blocks, we firstly replay certain number of blocks immediately up to target +// simulation leader's slot with halt_at_slot mechanism, possibly priming various caches, +// ultimately freezing the ancestor block with expected and deterministic hashes. +// +// After replay, a minor tweak is applied during simulation: we forcibly override leader's hashes +// as simulated banking stage creates them, using recorded `BlockAndBankHash` events. This is to +// provide undistinguishable sysvars to TX execution and identical TX age resolution as the +// simulation goes on. Otherwise, vast majority of tx processing would differ because simulated +// block's hashes would definitely differ than the recorded ones as slight block composition +// difference is inevitable. +// +// For poh time, we just use PohRecorder as same as the real environment, which is just 400ms +// timer, external to banking stage and thus mostly irrelevant to banking stage performance. For +// wall time, we use the first BankStatus::BlockAndBankHash and `SystemTime::now()` to define T=0 +// for simulation. Then, simulation progress is timed accordingly. As a context, this syncing is +// needed because all trace events are recorded in UTC, not relative to poh nor to leader schedule +// for simplicity at recording. +// +// Lastly, here's the last and most complicated input to simulate: transactions. +// +// A bit closer look of transaction load profile is like below, regardless of internal banking +// implementation and simulation: +// +// There's ever `BufferedPacketsDecision::Hold`-ed transactions to be processed as the first leader +// slot nears. This is due to solana's general tx broadcast strategy of node's forwarding and +// client's submission, which are unlikely to chabge soon. So, we take this as granted. Then, any +// initial leader block creation starts with rather large number of schedule-able transactions. +// Also, note that additional transactions arrive for the 4 leader slot window (roughly ~1.6 +// seconds). +// +// Simulation have to mimic this load pattern while being agnostic to internal bnaking impl as much +// as possible. For that agnostic objective, `TracedSender`s are sneaked into the SigVerify stage +// and gossip subsystem by `BankingTracer` to trace **all** of `BankingPacketBatch`s' exact payload +// and _sender_'s timing with `SystemTime::now()` for all `ChannelLabel`s. This deliberate tracing +// placement is not to be affected by any banking-tage's capping (if any) and its channel +// consumption pattern. +// +// BankingSimulator consists of 2 phases chronologically: warm-up and on-the-fly. The 2 phases are +// segregated by the aforementioned T=0. +// +// Both phases just sends BankingPacketBatch in the same fashion, pretending to be sigveirfy +// stage/gossip while burning 1 thread to busy loop for precise T=N at ~1us granularity. +// +// Warm up is defined as T=-N secs using slot distance between immediate ancestor of first +// simulated block and root block. As soon as warm up is initiated, we invoke +// `BankingStage::new_num_threads()` as well to simulate the pre-leader slot's tx-buffering time. +pub struct BankingSimulator { + banking_trace_events: BankingTraceEvents, + first_simulated_slot: Slot, +} + +#[derive(Error, Debug)] +pub enum SimulateError { + #[error("IO Error: {0}")] + IoError(#[from] io::Error), + + #[error("Deserialization Error: {0}")] + SerializeError(#[from] bincode::Error), +} + +pub struct BankingTraceEvents { + packet_batches_by_time: BTreeMap, + freeze_time_by_slot: BTreeMap, + hash_overrides: HashOverrides, +} + +impl BankingTraceEvents { + fn read_event_file( + events: &mut Vec, + event_file_path: &PathBuf, + ) -> Result<(), SimulateError> { + let mut reader = BufReader::new(File::open(event_file_path)?); + + loop { + events.push(deserialize_from(&mut reader)?); + + if reader.fill_buf()?.is_empty() { + // EOF is reached at a correct deserialization boundary. + // We're looking-ahead the buf, so NOT calling reader.consume(..) is correct. + break; + } + } + + Ok(()) + } + + pub fn load(event_file_paths: Vec) -> Result { + let mut events = vec![]; + for event_file_path in &event_file_paths { + let old_len = events.len(); + let _ = Self::read_event_file(&mut events, event_file_path).inspect_err(|error| { + error!( + "Reading {event_file_path:?} failed after {} events: {:?} due to file corruption or unclearn validator shutdown", + events.len() - old_len, + error + ); + }); + info!( + "Read {} events from {:?}", + events.len() - old_len, + event_file_path + ); + } + + let mut packet_batches_by_time = BTreeMap::new(); + let mut freeze_time_by_slot = BTreeMap::new(); + let mut hash_overrides = HashOverrides::default(); + for TimedTracedEvent(event_time, event) in events { + match event { + TracedEvent::PacketBatch(label, batch) => { + // Somewhat naively assume that event_times (nanosecond resolution) won't + // collide. + let is_new = packet_batches_by_time + .insert(event_time, (label, batch)) + .is_none(); + assert!(is_new); + } + TracedEvent::BlockAndBankHash(slot, blockhash, bank_hash) => { + let is_new = freeze_time_by_slot.insert(slot, event_time).is_none(); + hash_overrides.add_override(slot, blockhash, bank_hash); + assert!(is_new); + } + } + } + + Ok(Self { + packet_batches_by_time, + freeze_time_by_slot, + hash_overrides, + }) + } + + pub fn hash_overrides(&self) -> &HashOverrides { + &self.hash_overrides + } +} + +impl BankingSimulator { + pub fn new(banking_trace_events: BankingTraceEvents, first_simulated_slot: Slot) -> Self { + Self { + banking_trace_events, + first_simulated_slot, + } + } + + pub fn parent_slot(&self) -> Option { + self.banking_trace_events + .freeze_time_by_slot + .range(..self.first_simulated_slot) + .last() + .map(|(slot, _time)| slot) + .copied() + } + + pub fn start( + self, + genesis_config: GenesisConfig, + bank_forks: Arc>, + blockstore: Arc, + block_production_method: BlockProductionMethod, + ) -> Result<(), SimulateError> { + let mut bank = bank_forks + .read() + .unwrap() + .working_bank_with_scheduler() + .clone_with_scheduler(); + + let leader_schedule_cache = Arc::new(LeaderScheduleCache::new_from_bank(&bank)); + let parent_slot = bank.slot(); + assert_eq!(Some(parent_slot), self.parent_slot()); + + let simulated_leader = leader_schedule_cache + .slot_leader_at(self.first_simulated_slot, None) + .unwrap(); + info!( + "Simulated leader and slot: {}, {}", + simulated_leader, self.first_simulated_slot + ); + + let exit = Arc::new(AtomicBool::default()); + + if let Some(end_slot) = blockstore + .slot_meta_iterator(self.first_simulated_slot) + .unwrap() + .map(|(s, _)| s) + .last() + { + info!("purging slots {}, {}", self.first_simulated_slot, end_slot); + blockstore.purge_from_next_slots(self.first_simulated_slot, end_slot); + blockstore.purge_slots(self.first_simulated_slot, end_slot, PurgeType::Exact); + info!("done: purging"); + } else { + info!("skipping purging..."); + } + + info!("Poh is starting!"); + + let (poh_recorder, entry_receiver, record_receiver) = PohRecorder::new_with_clear_signal( + bank.tick_height(), + bank.last_blockhash(), + bank.clone(), + None, + bank.ticks_per_slot(), + false, + blockstore.clone(), + blockstore.get_new_shred_signal(0), + &leader_schedule_cache, + &genesis_config.poh_config, + None, + exit.clone(), + ); + let poh_recorder = Arc::new(RwLock::new(poh_recorder)); + let poh_service = PohService::new( + poh_recorder.clone(), + &genesis_config.poh_config, + exit.clone(), + bank.ticks_per_slot(), + DEFAULT_PINNED_CPU_CORE, + DEFAULT_HASHES_PER_BATCH, + record_receiver, + ); + let warmup_duration = Duration::from_secs(12); + + let (banking_retracer, retracer_thread) = BankingTracer::new(Some(( + &blockstore.banking_retracer_path(), + exit.clone(), + BANKING_TRACE_DIR_DEFAULT_BYTE_LIMIT, + ))) + .unwrap(); + if banking_retracer.is_enabled() { + info!( + "Enabled banking retracer (dir_byte_limit: {})", + BANKING_TRACE_DIR_DEFAULT_BYTE_LIMIT, + ); + } else { + info!("Disabled banking retracer"); + } + + let (non_vote_sender, non_vote_receiver) = banking_retracer.create_channel_non_vote(); + let (tpu_vote_sender, tpu_vote_receiver) = banking_retracer.create_channel_tpu_vote(); + let (gossip_vote_sender, gossip_vote_receiver) = + banking_retracer.create_channel_gossip_vote(); + + let cluster_info = Arc::new(ClusterInfo::new_with_dummy_keypair( + Node::new_localhost_with_pubkey(&simulated_leader).info, + SocketAddrSpace::Unspecified, + )); + let connection_cache = Arc::new(ConnectionCache::new("connection_kache!")); + let (replay_vote_sender, _replay_vote_receiver) = unbounded(); + let (retransmit_slots_sender, retransmit_slots_receiver) = unbounded(); + let shred_version = compute_shred_version( + &genesis_config.hash(), + Some(&bank_forks.read().unwrap().root_bank().hard_forks()), + ); + let (sender, _receiver) = tokio::sync::mpsc::channel(1); + let broadcast_stage = BroadcastStageType::Standard.new_broadcast_stage( + vec![UdpSocket::bind((Ipv4Addr::LOCALHOST, 0)).unwrap()], + cluster_info.clone(), + entry_receiver, + retransmit_slots_receiver, + exit.clone(), + blockstore.clone(), + bank_forks.clone(), + shred_version, + sender, + ); + + info!("Start banking stage!..."); + let prioritization_fee_cache = &Arc::new(PrioritizationFeeCache::new(0u64)); + let banking_stage = BankingStage::new_num_threads( + block_production_method.clone(), + &cluster_info, + &poh_recorder, + non_vote_receiver, + tpu_vote_receiver, + gossip_vote_receiver, + BankingStage::num_threads(), + None, + replay_vote_sender, + None, + connection_cache, + bank_forks.clone(), + prioritization_fee_cache, + false, + ); + + let (&slot_before_next_leader_slot, &raw_base_event_time) = self + .banking_trace_events + .freeze_time_by_slot + .range(parent_slot..) + .next() + .expect("timed hashes"); + + let base_event_time = raw_base_event_time - warmup_duration; + let base_simulation_time = SystemTime::now(); + + let sender_thread = thread::Builder::new().name("solSimSender".into()).spawn({ + let exit = exit.clone(); + + move || { + let (mut non_vote_count, mut non_vote_tx_count) = (0, 0); + let (mut tpu_vote_count, mut tpu_vote_tx_count) = (0, 0); + let (mut gossip_vote_count, mut gossip_vote_tx_count) = (0, 0); + + info!("start sending!..."); + let timed_batches_to_send = self.banking_trace_events.packet_batches_by_time.range(base_event_time..); + info!( + "simulating banking trace events: {} out of {}, starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", + timed_batches_to_send.clone().count(), + self.banking_trace_events.packet_batches_by_time.len(), + self.first_simulated_slot, + { + let raw_base_event_time: chrono::DateTime = raw_base_event_time.into(); + raw_base_event_time.format("%Y-%m-%d %H:%M:%S.%f") + }, + slot_before_next_leader_slot, + warmup_duration, + ); + let mut simulation_duration_since_base = Duration::default(); + let ( + mut last_log_duration, + mut last_tx_count, + mut last_non_vote_count, + mut last_tpu_vote_tx_count, + mut last_gossip_vote_tx_count + ) = (Duration::default(), 0, 0, 0, 0); + for (&event_time, (label, batches_with_stats)) in timed_batches_to_send { + let required_duration_since_base = + event_time.duration_since(base_event_time).unwrap(); + + // Busy loop for most accurate sending timings + loop { + if simulation_duration_since_base > required_duration_since_base { + break; + } + let current_simulation_time = SystemTime::now(); + simulation_duration_since_base = current_simulation_time + .duration_since(base_simulation_time) + .unwrap(); + } + + let sender = match label { + ChannelLabel::NonVote => &non_vote_sender, + ChannelLabel::TpuVote => &tpu_vote_sender, + ChannelLabel::GossipVote => &gossip_vote_sender, + ChannelLabel::Dummy => unreachable!(), + }; + sender.send(batches_with_stats.clone()).unwrap(); + + let batches = &batches_with_stats.0; + let (batch_count, tx_count) = ( + batches.len(), + batches.iter().map(|batch| batch.len()).sum::(), + ); + debug!( + "sent {:?} {} batches ({} txes)", + label, batch_count, tx_count + ); + let (total_batch_count, total_tx_count) = match label { + ChannelLabel::NonVote => (&mut non_vote_count, &mut non_vote_tx_count), + ChannelLabel::TpuVote => (&mut tpu_vote_count, &mut tpu_vote_tx_count), + ChannelLabel::GossipVote => (&mut gossip_vote_count, &mut gossip_vote_tx_count), + ChannelLabel::Dummy => unreachable!(), + }; + *total_batch_count += batch_count; + *total_tx_count += tx_count; + + let log_interval = simulation_duration_since_base - last_log_duration; + if log_interval > Duration::from_millis(100) { + let current_tx_count = non_vote_tx_count + tpu_vote_tx_count + gossip_vote_tx_count; + let duration =log_interval.as_secs_f64(); + let tps = (current_tx_count - last_tx_count) as f64 / duration; + let non_vote_tps = (non_vote_tx_count - last_non_vote_count) as f64 / duration; + let tpu_vote_tps = (tpu_vote_tx_count - last_tpu_vote_tx_count) as f64 / duration; + let gossip_vote_tps = (gossip_vote_tx_count - last_gossip_vote_tx_count) as f64 / duration; + info!( + "senders(non-,tpu-,gossip-vote): tps: {} (={}+{}+{}) over {:?} not-recved: ({}+{}+{})", + tps as u64, + non_vote_tps as u64, + tpu_vote_tps as u64, + gossip_vote_tps as u64, + log_interval, + non_vote_sender.len(), + tpu_vote_sender.len(), + gossip_vote_sender.len(), + ); + last_log_duration = simulation_duration_since_base; + last_tx_count = current_tx_count; + (last_non_vote_count, last_tpu_vote_tx_count, last_gossip_vote_tx_count) = ( + non_vote_tx_count, tpu_vote_tx_count, gossip_vote_count + ); + } + + if exit.load(Ordering::Relaxed) { + break; + } + } + info!( + "terminating to send...: non_vote: {} ({}), tpu_vote: {} ({}), gossip_vote: {} ({})", + non_vote_count, + non_vote_tx_count, + tpu_vote_count, + tpu_vote_tx_count, + gossip_vote_count, + gossip_vote_tx_count + ); + // hold these senders in join_handle to control banking stage termination! + (non_vote_sender, tpu_vote_sender, gossip_vote_sender) + } + })?; + + sleep(warmup_duration); + info!("warmup done!"); + + loop { + if poh_recorder.read().unwrap().bank().is_none() { + let next_leader_slot = leader_schedule_cache.next_leader_slot( + &simulated_leader, + bank.slot(), + &bank, + Some(&blockstore), + GRACE_TICKS_FACTOR * MAX_GRACE_SLOTS, + ); + debug!("{next_leader_slot:?}"); + poh_recorder + .write() + .unwrap() + .reset(bank.clone_without_scheduler(), next_leader_slot); + info!("Bank::new_from_parent()!"); + + let old_slot = bank.slot(); + if let Some(event_time) = + self.banking_trace_events.freeze_time_by_slot.get(&old_slot) + { + if log_enabled!(log::Level::Info) { + let current_simulation_time = SystemTime::now(); + let elapsed_simulation_time = current_simulation_time + .duration_since(base_simulation_time) + .unwrap(); + let elapsed_event_time = + event_time.duration_since(base_event_time).unwrap(); + info!( + "jitter(parent_slot: {}): {}{:?} (sim: {:?} event: {:?})", + old_slot, + if elapsed_simulation_time > elapsed_event_time { + "+" + } else { + "-" + }, + if elapsed_simulation_time > elapsed_event_time { + elapsed_simulation_time - elapsed_event_time + } else { + elapsed_event_time - elapsed_simulation_time + }, + elapsed_simulation_time, + elapsed_event_time, + ); + } + } + bank.freeze(); + let new_slot = if bank.slot() == parent_slot { + info!("initial leader block!"); + self.first_simulated_slot + } else { + info!("next leader block!"); + bank.slot() + 1 + }; + info!("new leader bank slot: {new_slot}"); + let new_leader = leader_schedule_cache + .slot_leader_at(new_slot, None) + .unwrap(); + if simulated_leader != new_leader { + info!( + "bank cost: slot: {} {:?} (frozen)", + bank.slot(), + bank.read_cost_tracker() + .map(|t| (t.block_cost(), t.vote_cost())) + .unwrap() + ); + info!( + "{} isn't leader anymore at slot {}; new leader: {}", + simulated_leader, new_slot, new_leader + ); + break; + } else if sender_thread.is_finished() { + warn!("sender thread existed maybe due to completion of sending traced events"); + break; + } + let new_bank = Bank::new_from_parent( + bank.clone_without_scheduler(), + &simulated_leader, + new_slot, + ); + // make sure parent is frozen for finalized hashes via the above + // new()-ing of its child bank + banking_retracer.hash_event(bank.slot(), &bank.last_blockhash(), &bank.hash()); + if *bank.collector_id() == simulated_leader { + info!( + "bank cost: slot: {} {:?} (frozen)", + bank.slot(), + bank.read_cost_tracker() + .map(|t| (t.block_cost(), t.vote_cost())) + .unwrap() + ); + } + retransmit_slots_sender.send(bank.slot()).unwrap(); + bank_forks.write().unwrap().insert(new_bank); + bank = bank_forks + .read() + .unwrap() + .working_bank_with_scheduler() + .clone_with_scheduler(); + poh_recorder + .write() + .unwrap() + .set_bank(bank.clone_with_scheduler(), false); + } else { + debug!( + "bank cost: slot: {} {:?} (ongoing)", + bank.slot(), + bank.read_cost_tracker() + .map(|t| (t.block_cost(), t.vote_cost())) + .unwrap() + ); + } + + sleep(Duration::from_millis(10)); + } + + info!("Sleeping a bit before signaling exit"); + sleep(Duration::from_millis(100)); + exit.store(true, Ordering::Relaxed); + + // The order is important. consuming sender_thread by joining will terminate banking_stage, + // in turn banking_retracer thread will termianl + sender_thread.join().unwrap(); + banking_stage.join().unwrap(); + poh_service.join().unwrap(); + if let Some(retracer_thread) = retracer_thread { + retracer_thread.join().unwrap().unwrap(); + } + + info!("Joining broadcast stage..."); + drop(poh_recorder); + drop(retransmit_slots_sender); + broadcast_stage.join().unwrap(); + + Ok(()) + } + + pub fn event_file_name(index: usize) -> String { + if index == 0 { + BASENAME.to_string() + } else { + format!("{BASENAME}.{index}") + } + } +} diff --git a/core/src/banking_trace.rs b/core/src/banking_trace.rs index cc077dfa2c2755..150e9a33e1940f 100644 --- a/core/src/banking_trace.rs +++ b/core/src/banking_trace.rs @@ -42,7 +42,7 @@ pub enum TraceError { TooSmallDirByteLimit(DirByteLimit, DirByteLimit), } -const BASENAME: &str = "events"; +pub(crate) const BASENAME: &str = "events"; const TRACE_FILE_ROTATE_COUNT: u64 = 14; // target 2 weeks retention under normal load const TRACE_FILE_WRITE_INTERVAL_MS: u64 = 100; const BUF_WRITER_CAPACITY: usize = 10 * 1024 * 1024; @@ -359,6 +359,14 @@ impl TracedSender { } self.sender.send(batch) } + + pub fn len(&self) -> usize { + self.sender.len() + } + + pub fn is_empty(&self) -> bool { + self.len() == 0 + } } #[cfg(any(test, feature = "dev-context-only-utils"))] diff --git a/core/src/lib.rs b/core/src/lib.rs index da9d69ed508875..2ba671ca62b580 100644 --- a/core/src/lib.rs +++ b/core/src/lib.rs @@ -10,6 +10,7 @@ pub mod accounts_hash_verifier; pub mod admin_rpc_post_init; +pub mod banking_simulation; pub mod banking_stage; pub mod banking_trace; pub mod cache_block_meta_service; diff --git a/cost-model/src/cost_tracker.rs b/cost-model/src/cost_tracker.rs index 23583068fb13b3..3fe827faf35fb6 100644 --- a/cost-model/src/cost_tracker.rs +++ b/cost-model/src/cost_tracker.rs @@ -106,6 +106,16 @@ impl Default for CostTracker { } impl CostTracker { + pub fn new_from_parent(&self) -> Self { + let mut new = Self::default(); + new.set_limits( + self.account_cost_limit, + self.block_cost_limit, + self.vote_cost_limit, + ); + new + } + pub fn reset(&mut self) { self.cost_by_writable_accounts.clear(); self.block_cost = 0; @@ -192,6 +202,10 @@ impl CostTracker { self.block_cost } + pub fn vote_cost(&self) -> u64 { + self.vote_cost + } + pub fn transaction_count(&self) -> u64 { self.transaction_count } diff --git a/gossip/Cargo.toml b/gossip/Cargo.toml index 679c4a93f91e09..5d7a9d7025a49f 100644 --- a/gossip/Cargo.toml +++ b/gossip/Cargo.toml @@ -66,6 +66,7 @@ test-case = { workspace = true } rustc_version = { workspace = true, optional = true } [features] +dev-context-only-utils = [] frozen-abi = [ "dep:rustc_version", "dep:solana-frozen-abi", diff --git a/gossip/src/cluster_info.rs b/gossip/src/cluster_info.rs index f2e93765560ece..5a2a1d254f7ae3 100644 --- a/gossip/src/cluster_info.rs +++ b/gossip/src/cluster_info.rs @@ -453,12 +453,11 @@ fn retain_staked( } impl ClusterInfo { - pub fn new( + fn do_new( contact_info: ContactInfo, keypair: Arc, socket_addr_space: SocketAddrSpace, ) -> Self { - assert_eq!(contact_info.pubkey(), &keypair.pubkey()); let id = *contact_info.pubkey(); let me = Self { gossip: CrdsGossip::default(), @@ -484,6 +483,28 @@ impl ClusterInfo { me } + pub fn new( + contact_info: ContactInfo, + keypair: Arc, + socket_addr_space: SocketAddrSpace, + ) -> Self { + assert_eq!(contact_info.pubkey(), &keypair.pubkey()); + Self::do_new(contact_info, keypair, socket_addr_space) + } + + #[cfg(feature = "dev-context-only-utils")] + pub fn new_with_dummy_keypair( + contact_info: ContactInfo, + socket_addr_space: SocketAddrSpace, + ) -> Self { + // Obviously, we can't create a Keypair for given pubkey arbitrarily... But ClusterInfo is + // needed for ledger-tool simulate-block-production. So, forcibly create one with incorrect + // Keypair. Note that the returned ClusterInfo is half-broken, but it's okay for the + // minimum usage by the subcommand. + let keypair = Arc::new(Keypair::new()); + Self::do_new(contact_info, keypair, socket_addr_space) + } + pub fn set_contact_debug_interval(&mut self, new: u64) { self.contact_debug_interval = new; } @@ -670,7 +691,11 @@ impl ClusterInfo { } pub fn id(&self) -> Pubkey { - self.keypair.read().unwrap().pubkey() + // `self.keypair.read().unwrap().pubkey()` is more straight-forward to use here. + // However, self.keypair could be dummy in some very odd situation + // (i.e. ledger-tool's simulate-leader-production). So, use `self.my_contact_info` here. + // Other than the edge case, both are equivalent. + *self.my_contact_info.read().unwrap().pubkey() } pub fn keypair(&self) -> RwLockReadGuard> { diff --git a/ledger-tool/Cargo.toml b/ledger-tool/Cargo.toml index 39061de55f2382..abfa07ade49d38 100644 --- a/ledger-tool/Cargo.toml +++ b/ledger-tool/Cargo.toml @@ -32,7 +32,7 @@ solana-bpf-loader-program = { workspace = true } solana-clap-utils = { workspace = true } solana-cli-output = { workspace = true } solana-compute-budget = { workspace = true } -solana-core = { workspace = true } +solana-core = { workspace = true, features = ["dev-context-only-utils"] } solana-cost-model = { workspace = true } solana-entry = { workspace = true } solana-feature-set = { workspace = true } diff --git a/ledger-tool/src/args.rs b/ledger-tool/src/args.rs index d2bc0f691e130f..d01c542465256f 100644 --- a/ledger-tool/src/args.rs +++ b/ledger-tool/src/args.rs @@ -214,6 +214,8 @@ pub fn parse_process_options(ledger_path: &Path, arg_matches: &ArgMatches<'_>) - let debug_keys = pubkeys_of(arg_matches, "debug_key") .map(|pubkeys| Arc::new(pubkeys.into_iter().collect::>())); let allow_dead_slots = arg_matches.is_present("allow_dead_slots"); + let abort_on_invalid_block = arg_matches.is_present("abort_on_invalid_block"); + let no_block_cost_limits = arg_matches.is_present("no_block_cost_limits"); ProcessOptions { new_hard_forks, @@ -230,6 +232,8 @@ pub fn parse_process_options(ledger_path: &Path, arg_matches: &ArgMatches<'_>) - allow_dead_slots, halt_at_slot, use_snapshot_archives_at_startup, + abort_on_invalid_block, + no_block_cost_limits, ..ProcessOptions::default() } } diff --git a/ledger-tool/src/main.rs b/ledger-tool/src/main.rs index 0c74d53f3e41e2..60205a5d4ea201 100644 --- a/ledger-tool/src/main.rs +++ b/ledger-tool/src/main.rs @@ -31,13 +31,17 @@ use { }, solana_cli_output::OutputFormat, solana_core::{ + banking_simulation::{BankingSimulator, BankingTraceEvents}, system_monitor_service::{SystemMonitorService, SystemMonitorStatsReportConfig}, - validator::BlockVerificationMethod, + validator::{BlockProductionMethod, BlockVerificationMethod}, }, solana_cost_model::{cost_model::CostModel, cost_tracker::CostTracker}, solana_feature_set::{self as feature_set, FeatureSet}, solana_ledger::{ - blockstore::{create_new_ledger, Blockstore}, + blockstore::{ + banking_trace_path, create_new_ledger, simulate_block_production_marker_path, + Blockstore, + }, blockstore_options::{AccessType, LedgerColumnOptions}, blockstore_processor::{ ProcessSlotCallback, TransactionStatusMessage, TransactionStatusSender, @@ -83,8 +87,8 @@ use { }, std::{ collections::{HashMap, HashSet}, - ffi::OsStr, - fs::File, + ffi::{OsStr, OsString}, + fs::{read_dir, File}, io::{self, Write}, mem::swap, path::{Path, PathBuf}, @@ -536,6 +540,74 @@ fn assert_capitalization(bank: &Bank) { assert!(bank.calculate_and_verify_capitalization(debug_verify)); } +fn load_banking_trace_events_or_exit(ledger_path: &Path) -> BankingTraceEvents { + let file_paths = read_banking_trace_event_file_paths_or_exit(banking_trace_path(ledger_path)); + + info!("Using: banking trace event files: {file_paths:?}"); + match BankingTraceEvents::load(file_paths) { + Ok(banking_trace_events) => banking_trace_events, + Err(error) => { + eprintln!("Failed to load banking trace events: {error:?}"); + exit(1) + } + } +} + +fn read_banking_trace_event_file_paths_or_exit(banking_trace_path: PathBuf) -> Vec { + if !banking_trace_path.exists() { + eprintln!("Error: ledger doesn't have the banking trace dir: {banking_trace_path:?}"); + exit(1); + } + info!("Using: banking trace events dir: {banking_trace_path:?}"); + + let entries = match read_dir(&banking_trace_path) { + Ok(entries) => entries, + Err(error) => { + eprintln!("Error: failed to open banking_trace_path: {error:?}"); + exit(1); + } + }; + + let mut entry_names = entries + .flat_map(|entry| entry.ok().map(|entry| entry.file_name())) + .collect::>(); + + let mut event_file_paths = vec![]; + + if entry_names.is_empty() { + warn!("banking_trace_path dir is empty."); + return event_file_paths; + } + + for index in 0.. { + let event_file_name: OsString = BankingSimulator::event_file_name(index).into(); + if entry_names.remove(&event_file_name) { + event_file_paths.push(banking_trace_path.join(event_file_name)); + } else { + break; + } + } + + if event_file_paths.is_empty() { + warn!("Error: no event files found"); + } + + if !entry_names.is_empty() { + let full_names = entry_names + .into_iter() + .map(|name| banking_trace_path.join(name)) + .collect::>(); + warn!( + "Some files in {banking_trace_path:?} is ignored due to gapped events file rotation \ + or unrecognized names: {full_names:?}" + ); + } + + // Reverse to load in the chronicle order (note that this isn't strictly needed) + event_file_paths.reverse(); + event_file_paths +} + struct SlotRecorderConfig { transaction_recorder: Option>, transaction_status_sender: Option, @@ -1146,6 +1218,30 @@ fn main() { "geyser_plugin_config", ]) .help("In addition to the bank hash, optionally include accounts and/or transactions details for the slot"), + ) + .arg( + Arg::with_name("abort_on_invalid_block") + .long("abort-on-invalid-block") + .takes_value(false) + .help( + "Exits with failed status early as soon as any bad block is detected", + ), + ) + .arg( + Arg::with_name("no_block_cost_limits") + .long("no-block-cost-limits") + .takes_value(false) + .help("Sets block cost limits to the max"), + ) + .arg( + Arg::with_name("enable_hash_overrides") + .long("enable-hash-overrides") + .takes_value(false) + .help( + "Enable to override blockhashes and bank hashes from banking trace \ + event files to correctly verify blocks produced by \ + the simulate-block-production subcommand", + ), ), ) .subcommand( @@ -1388,6 +1484,36 @@ fn main() { .help("If snapshot creation should succeed with a capitalization delta."), ), ) + .subcommand( + SubCommand::with_name("simulate-block-production") + .about("Simulate producing blocks with banking trace event files in the ledger") + .arg(&load_genesis_config_arg) + .args(&accounts_db_config_args) + .args(&snapshot_config_args) + .arg( + Arg::with_name("block_production_method") + .long("block-production-method") + .value_name("METHOD") + .takes_value(true) + .possible_values(BlockProductionMethod::cli_names()) + .help(BlockProductionMethod::cli_message()), + ) + .arg( + Arg::with_name("first_simulated_slot") + .long("first-simulated-slot") + .value_name("SLOT") + .validator(is_slot) + .takes_value(true) + .required(true) + .help("Start simulation at the given slot") + ) + .arg( + Arg::with_name("no_block_cost_limits") + .long("no-block-cost-limits") + .takes_value(false) + .help("Sets block cost limits to the max"), + ), + ) .subcommand( SubCommand::with_name("accounts") .about("Print account stats and contents after processing the ledger") @@ -1662,6 +1788,12 @@ fn main() { ); let mut process_options = parse_process_options(&ledger_path, arg_matches); + if arg_matches.is_present("enable_hash_overrides") { + let banking_trace_events = load_banking_trace_events_or_exit(&ledger_path); + process_options.hash_overrides = + Some(banking_trace_events.hash_overrides().clone()); + } + let (slot_callback, slot_recorder_config) = setup_slot_recording(arg_matches); process_options.slot_callback = slot_callback; let transaction_status_sender = slot_recorder_config @@ -2350,6 +2482,72 @@ fn main() { system_monitor_service.join().unwrap(); } } + ("simulate-block-production", Some(arg_matches)) => { + let marker_file = simulate_block_production_marker_path(&ledger_path); + if !marker_file.exists() { + eprintln!( + "simulate-block-production is for development purposes only. \ + It's thus a pretty destructive operation on \ + the ledger ({ledger_path:?}). \ + Create an empty file at {marker_file:?} if this is intentional." + ); + exit(1); + } + + let mut process_options = parse_process_options(&ledger_path, arg_matches); + + let banking_trace_events = load_banking_trace_events_or_exit(&ledger_path); + process_options.hash_overrides = + Some(banking_trace_events.hash_overrides().clone()); + + let slot = value_t!(arg_matches, "first_simulated_slot", Slot).unwrap(); + let simulator = BankingSimulator::new(banking_trace_events, slot); + let Some(parent_slot) = simulator.parent_slot() else { + eprintln!( + "Couldn't determine parent_slot of first_simulated_slot: {slot} \ + due to missing banking_trace_event data." + ); + exit(1); + }; + process_options.halt_at_slot = Some(parent_slot); + + let blockstore = Arc::new(open_blockstore( + &ledger_path, + arg_matches, + AccessType::Primary, // needed for purging already existing simulated block shreds... + )); + let genesis_config = open_genesis_config_by(&ledger_path, arg_matches); + let LoadAndProcessLedgerOutput { bank_forks, .. } = + load_and_process_ledger_or_exit( + arg_matches, + &genesis_config, + blockstore.clone(), + process_options, + None, // transaction status sender + ); + + let block_production_method = value_t!( + arg_matches, + "block_production_method", + BlockProductionMethod + ) + .unwrap_or_default(); + + info!("Using: block-production-method: {block_production_method}"); + + match simulator.start( + genesis_config, + bank_forks, + blockstore, + block_production_method, + ) { + Ok(()) => println!("Ok"), + Err(error) => { + eprintln!("{error:?}"); + exit(1); + } + }; + } ("accounts", Some(arg_matches)) => { let process_options = parse_process_options(&ledger_path, arg_matches); let genesis_config = open_genesis_config_by(&ledger_path, arg_matches); diff --git a/ledger/src/blockstore.rs b/ledger/src/blockstore.rs index 2101896d9a0558..e0756330f37d88 100644 --- a/ledger/src/blockstore.rs +++ b/ledger/src/blockstore.rs @@ -299,6 +299,18 @@ impl SlotMetaWorkingSetEntry { } } +pub fn banking_trace_path(path: &Path) -> PathBuf { + path.join("banking_trace") +} + +pub fn banking_retrace_path(path: &Path) -> PathBuf { + path.join("banking_retrace") +} + +pub fn simulate_block_production_marker_path(path: &Path) -> PathBuf { + path.join("simulate_block_production_allowed") +} + impl Blockstore { pub fn db(self) -> Arc { self.db @@ -309,7 +321,11 @@ impl Blockstore { } pub fn banking_trace_path(&self) -> PathBuf { - self.ledger_path.join("banking_trace") + banking_trace_path(&self.ledger_path) + } + + pub fn banking_retracer_path(&self) -> PathBuf { + banking_retrace_path(&self.ledger_path) } /// Opens a Ledger in directory, provides "infinite" window of shreds diff --git a/ledger/src/blockstore_processor.rs b/ledger/src/blockstore_processor.rs index b34bdee591dd9c..cd3fc1ff486f51 100644 --- a/ledger/src/blockstore_processor.rs +++ b/ledger/src/blockstore_processor.rs @@ -1,5 +1,3 @@ -#[cfg(feature = "dev-context-only-utils")] -use qualifier_attr::qualifiers; use { crate::{ block_error::BlockError, @@ -76,6 +74,8 @@ use { thiserror::Error, ExecuteTimingType::{NumExecuteBatches, TotalBatchesLen}, }; +#[cfg(feature = "dev-context-only-utils")] +use {qualifier_attr::qualifiers, solana_runtime::bank::HashOverrides}; pub struct TransactionBatchWithIndexes<'a, 'b> { pub batch: TransactionBatch<'a, 'b>, @@ -768,6 +768,10 @@ pub struct ProcessOptions { /// This is useful for debugging. pub run_final_accounts_hash_calc: bool, pub use_snapshot_archives_at_startup: UseSnapshotArchivesAtStartup, + #[cfg(feature = "dev-context-only-utils")] + pub hash_overrides: Option, + pub abort_on_invalid_block: bool, + pub no_block_cost_limits: bool, } pub fn test_process_blockstore( @@ -903,6 +907,20 @@ pub fn process_blockstore_from_root( // Starting slot must be a root, and thus has no parents assert_eq!(bank_forks.read().unwrap().banks().len(), 1); let bank = bank_forks.read().unwrap().root_bank(); + #[cfg(feature = "dev-context-only-utils")] + if let Some(hash_overrides) = &opts.hash_overrides { + info!( + "Will override following slots' hashes: {:#?}", + hash_overrides + ); + bank.set_hash_overrides(hash_overrides.clone()); + } + if opts.no_block_cost_limits { + info!("setting block cost limits to MAX"); + bank.write_cost_tracker() + .unwrap() + .set_limits(u64::MAX, u64::MAX, u64::MAX); + } assert!(bank.parent().is_none()); (bank.slot(), bank.hash()) }; @@ -1837,7 +1855,7 @@ fn load_frozen_forks( let mut progress = ConfirmationProgress::new(last_entry_hash); let mut m = Measure::start("process_single_slot"); let bank = bank_forks.write().unwrap().insert_from_ledger(bank); - if process_single_slot( + if let Err(error) = process_single_slot( blockstore, &bank, replay_tx_thread_pool, @@ -1849,10 +1867,11 @@ fn load_frozen_forks( entry_notification_sender, None, timing, - ) - .is_err() - { + ) { assert!(bank_forks.write().unwrap().remove(bank.slot()).is_some()); + if opts.abort_on_invalid_block { + Err(error)? + } continue; } txs += progress.num_txs; @@ -2055,6 +2074,13 @@ pub fn process_single_slot( replay_vote_sender, timing, ) + .and_then(|()| { + if let Some((result, completed_timings)) = bank.wait_for_completed_scheduler() { + timing.accumulate(&completed_timings); + result? + } + Ok(()) + }) .map_err(|err| { let slot = bank.slot(); warn!("slot {} failed to verify: {}", slot, err); diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index 44d8195c993c5a..4c8a1fa243e4b4 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -507,6 +507,8 @@ impl PartialEq for Bank { if std::ptr::eq(self, other) { return true; } + // Suppress rustfmt until https://github.com/rust-lang/rustfmt/issues/5920 is fixed ... + #[rustfmt::skip] let Self { skipped_rewrites: _, rc: _, @@ -545,6 +547,8 @@ impl PartialEq for Bank { stakes_cache, epoch_stakes, is_delta, + #[cfg(feature = "dev-context-only-utils")] + hash_overrides, // TODO: Confirm if all these fields are intentionally ignored! rewards: _, cluster_type: _, @@ -602,6 +606,10 @@ impl PartialEq for Bank { && *stakes_cache.stakes() == *other.stakes_cache.stakes() && epoch_stakes == &other.epoch_stakes && is_delta.load(Relaxed) == other.is_delta.load(Relaxed) + // No deadlock is possbile, when Arc::ptr_eq() returns false, because of being + // different Mutexes. + && (Arc::ptr_eq(hash_overrides, &other.hash_overrides) || + *hash_overrides.lock().unwrap() == *other.hash_overrides.lock().unwrap()) } } @@ -670,6 +678,50 @@ pub trait DropCallback: fmt::Debug { #[derive(Debug, Default)] pub struct OptionalDropCallback(Option>); +#[derive(Default, Debug, Clone, PartialEq)] +#[cfg(feature = "dev-context-only-utils")] +pub struct HashOverrides { + hashes: HashMap, +} + +#[cfg(feature = "dev-context-only-utils")] +impl HashOverrides { + fn get_hash_override(&self, slot: Slot) -> Option<&HashOverride> { + self.hashes.get(&slot) + } + + fn get_blockhash_override(&self, slot: Slot) -> Option<&Hash> { + self.get_hash_override(slot) + .map(|hash_override| &hash_override.blockhash) + } + + fn get_bank_hash_override(&self, slot: Slot) -> Option<&Hash> { + self.get_hash_override(slot) + .map(|hash_override| &hash_override.bank_hash) + } + + pub fn add_override(&mut self, slot: Slot, blockhash: Hash, bank_hash: Hash) { + let is_new = self + .hashes + .insert( + slot, + HashOverride { + blockhash, + bank_hash, + }, + ) + .is_none(); + assert!(is_new); + } +} + +#[derive(Debug, Clone, PartialEq)] +#[cfg(feature = "dev-context-only-utils")] +struct HashOverride { + blockhash: Hash, + bank_hash: Hash, +} + /// Manager for the state of all accounts and programs after processing its entries. #[derive(Debug)] pub struct Bank { @@ -846,6 +898,11 @@ pub struct Bank { /// Fee structure to use for assessing transaction fees. fee_structure: FeeStructure, + + /// blockhash and bank_hash overrides keyed by slot for simulated block production. + /// This _field_ was needed to be DCOU-ed to avoid 2 locks per bank freezing... + #[cfg(feature = "dev-context-only-utils")] + hash_overrides: Arc>, } struct VoteWithStakeDelegations { @@ -964,6 +1021,8 @@ impl Bank { compute_budget: None, transaction_account_lock_limit: None, fee_structure: FeeStructure::default(), + #[cfg(feature = "dev-context-only-utils")] + hash_overrides: Arc::new(Mutex::new(HashOverrides::default())), }; bank.transaction_processor = @@ -1205,7 +1264,7 @@ impl Bank { .map(|drop_callback| drop_callback.clone_box()), )), freeze_started: AtomicBool::new(false), - cost_tracker: RwLock::new(CostTracker::default()), + cost_tracker: RwLock::new(parent.read_cost_tracker().unwrap().new_from_parent()), accounts_data_size_initial, accounts_data_size_delta_on_chain: AtomicI64::new(0), accounts_data_size_delta_off_chain: AtomicI64::new(0), @@ -1216,6 +1275,8 @@ impl Bank { compute_budget: parent.compute_budget, transaction_account_lock_limit: parent.transaction_account_lock_limit, fee_structure: parent.fee_structure.clone(), + #[cfg(feature = "dev-context-only-utils")] + hash_overrides: parent.hash_overrides.clone(), }; let (_, ancestors_time_us) = measure_us!({ @@ -1592,6 +1653,8 @@ impl Bank { compute_budget: runtime_config.compute_budget, transaction_account_lock_limit: runtime_config.transaction_account_lock_limit, fee_structure: FeeStructure::default(), + #[cfg(feature = "dev-context-only-utils")] + hash_overrides: Arc::new(Mutex::new(HashOverrides::default())), }; bank.transaction_processor = @@ -3137,6 +3200,27 @@ impl Bank { // readers can starve this write lock acquisition and ticks would be slowed down too // much if the write lock is acquired for each tick. let mut w_blockhash_queue = self.blockhash_queue.write().unwrap(); + + #[cfg(feature = "dev-context-only-utils")] + let blockhash_override = self + .hash_overrides + .lock() + .unwrap() + .get_blockhash_override(self.slot()) + .copied() + .inspect(|blockhash_override| { + if blockhash_override != blockhash { + info!( + "bank: slot: {}: overrode blockhash: {} with {}", + self.slot(), + blockhash, + blockhash_override + ); + } + }); + #[cfg(feature = "dev-context-only-utils")] + let blockhash = blockhash_override.as_ref().unwrap_or(blockhash); + w_blockhash_queue.register_hash(blockhash, self.fee_rate_governor.lamports_per_signature); self.update_recent_blockhashes_locked(&w_blockhash_queue); } @@ -5272,6 +5356,29 @@ impl Bank { hash = hard_forked_hash; } + #[cfg(feature = "dev-context-only-utils")] + let hash_override = self + .hash_overrides + .lock() + .unwrap() + .get_bank_hash_override(slot) + .copied() + .inspect(|&hash_override| { + if hash_override != hash { + info!( + "bank: slot: {}: overrode bank hash: {} with {}", + self.slot(), + hash, + hash_override + ); + } + }); + // Avoid to optimize out `hash` along with the whole computation by super smart rustc. + // hash_override is used by ledger-tool's simulate-block-production, which prefers + // the actual bank freezing processing for accurate simulation. + #[cfg(feature = "dev-context-only-utils")] + let hash = hash_override.unwrap_or(std::hint::black_box(hash)); + let bank_hash_stats = self .rc .accounts @@ -6829,6 +6936,10 @@ impl Bank { None => Err(TransactionError::AccountNotFound), } } + + pub fn set_hash_overrides(&self, hash_overrides: HashOverrides) { + *self.hash_overrides.lock().unwrap() = hash_overrides; + } } /// Compute how much an account has changed size. This function is useful when the data size delta diff --git a/validator/src/admin_rpc_service.rs b/validator/src/admin_rpc_service.rs index 99ef4b53a0b94d..45af1f26dfd183 100644 --- a/validator/src/admin_rpc_service.rs +++ b/validator/src/admin_rpc_service.rs @@ -26,7 +26,7 @@ use { }, std::{ collections::{HashMap, HashSet}, - error, + env, error, fmt::{self, Display}, net::SocketAddr, path::{Path, PathBuf}, @@ -266,7 +266,12 @@ impl AdminRpc for AdminRpcImpl { // (rocksdb background processing or some other stuck thread perhaps?). // // If the process is still alive after five seconds, exit harder - thread::sleep(Duration::from_secs(5)); + thread::sleep(Duration::from_secs( + env::var("SOLANA_VALIDATOR_EXIT_TIMEOUT") + .ok() + .and_then(|x| x.parse().ok()) + .unwrap_or(5), + )); warn!("validator exit timeout"); std::process::exit(0); }) From 69a854821d641d9909a5ce0eed49cf317e284504 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Tue, 27 Aug 2024 14:40:25 +0900 Subject: [PATCH 02/52] Move counting code out of time-sensitive loop --- core/src/banking_simulation.rs | 19 ++++++++++++------- 1 file changed, 12 insertions(+), 7 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index af9bfb404acf06..981752611899cb 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -362,9 +362,18 @@ impl BankingSimulator { info!("start sending!..."); let timed_batches_to_send = self.banking_trace_events.packet_batches_by_time.range(base_event_time..); + let event_count = timed_batches_to_send.clone().count(); + let batch_and_tx_counts = timed_batches_to_send.clone().map(|(_, (_label, batches_with_stats))| { + let batches = &batches_with_stats.0; + ( + batches.len(), + batches.iter().map(|batch| batch.len()).sum::(), + ) + }).collect::>(); + let timed_batches_to_send = timed_batches_to_send.zip(batch_and_tx_counts.into_iter()); info!( "simulating banking trace events: {} out of {}, starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", - timed_batches_to_send.clone().count(), + event_count, self.banking_trace_events.packet_batches_by_time.len(), self.first_simulated_slot, { @@ -382,7 +391,8 @@ impl BankingSimulator { mut last_tpu_vote_tx_count, mut last_gossip_vote_tx_count ) = (Duration::default(), 0, 0, 0, 0); - for (&event_time, (label, batches_with_stats)) in timed_batches_to_send { + for ((&event_time, (label, batches_with_stats)), (batch_count, tx_count)) in + timed_batches_to_send { let required_duration_since_base = event_time.duration_since(base_event_time).unwrap(); @@ -405,11 +415,6 @@ impl BankingSimulator { }; sender.send(batches_with_stats.clone()).unwrap(); - let batches = &batches_with_stats.0; - let (batch_count, tx_count) = ( - batches.len(), - batches.iter().map(|batch| batch.len()).sum::(), - ); debug!( "sent {:?} {} batches ({} txes)", label, batch_count, tx_count From 1561deee4e04fc6ba53ed6dcb0b82e8d90ebbc7a Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Tue, 27 Aug 2024 16:31:29 +0900 Subject: [PATCH 03/52] Avoid misleading ::clone() altogether --- core/src/banking_simulation.rs | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 981752611899cb..4d919097aad486 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -211,7 +211,7 @@ impl BankingSimulator { } pub fn start( - self, + mut self, genesis_config: GenesisConfig, bank_forks: Arc>, blockstore: Arc, @@ -361,16 +361,16 @@ impl BankingSimulator { let (mut gossip_vote_count, mut gossip_vote_tx_count) = (0, 0); info!("start sending!..."); - let timed_batches_to_send = self.banking_trace_events.packet_batches_by_time.range(base_event_time..); - let event_count = timed_batches_to_send.clone().count(); - let batch_and_tx_counts = timed_batches_to_send.clone().map(|(_, (_label, batches_with_stats))| { + let timed_batches_to_send = self.banking_trace_events.packet_batches_by_time.split_off(&base_event_time); + let event_count = timed_batches_to_send.len(); + let batch_and_tx_counts = timed_batches_to_send.values().map(|(_label, batches_with_stats)| { let batches = &batches_with_stats.0; ( batches.len(), batches.iter().map(|batch| batch.len()).sum::(), ) }).collect::>(); - let timed_batches_to_send = timed_batches_to_send.zip(batch_and_tx_counts.into_iter()); + let timed_batches_to_send = timed_batches_to_send.into_iter().zip(batch_and_tx_counts.into_iter()); info!( "simulating banking trace events: {} out of {}, starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", event_count, @@ -391,7 +391,7 @@ impl BankingSimulator { mut last_tpu_vote_tx_count, mut last_gossip_vote_tx_count ) = (Duration::default(), 0, 0, 0, 0); - for ((&event_time, (label, batches_with_stats)), (batch_count, tx_count)) in + for ((event_time, (label, batches_with_stats)), (batch_count, tx_count)) in timed_batches_to_send { let required_duration_since_base = event_time.duration_since(base_event_time).unwrap(); @@ -413,7 +413,7 @@ impl BankingSimulator { ChannelLabel::GossipVote => &gossip_vote_sender, ChannelLabel::Dummy => unreachable!(), }; - sender.send(batches_with_stats.clone()).unwrap(); + sender.send(batches_with_stats).unwrap(); debug!( "sent {:?} {} batches ({} txes)", From 2be40492edfcb4451d6b800755613db04c01dc18 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Tue, 27 Aug 2024 16:41:41 +0900 Subject: [PATCH 04/52] Use while instead of loop+break --- core/src/banking_simulation.rs | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 4d919097aad486..c739505845b806 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -397,10 +397,7 @@ impl BankingSimulator { event_time.duration_since(base_event_time).unwrap(); // Busy loop for most accurate sending timings - loop { - if simulation_duration_since_base > required_duration_since_base { - break; - } + while simulation_duration_since_base < required_duration_since_base { let current_simulation_time = SystemTime::now(); simulation_duration_since_base = current_simulation_time .duration_since(base_simulation_time) From dfa976566ea3755b1c95f8202e0184c2f8f6e00f Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Tue, 27 Aug 2024 23:30:13 +0900 Subject: [PATCH 05/52] Add comment of using BTreeMap --- core/src/banking_simulation.rs | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index c739505845b806..51af42108715cc 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -117,6 +117,7 @@ pub enum SimulateError { } pub struct BankingTraceEvents { + /// BTreeMap is intentional because events could be unordered slightly due to tracing jitter. packet_batches_by_time: BTreeMap, freeze_time_by_slot: BTreeMap, hash_overrides: HashOverrides, @@ -166,6 +167,13 @@ impl BankingTraceEvents { for TimedTracedEvent(event_time, event) in events { match event { TracedEvent::PacketBatch(label, batch) => { + // Deserialized PacketBatches will mostly be ordered by event_time, but this + // isn't guaranteed when traced, because time are measured by multiple _sender_ + // threads withtout synchnotization among them to avoid overhead. + // + // Also, there's a possiblity of system clock change. In this case, + // the simulation is meaningless, though... + // // Somewhat naively assume that event_times (nanosecond resolution) won't // collide. let is_new = packet_batches_by_time From 39846f6f2d2dc0c0781b49f35c05f7efe5cfb3c6 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Tue, 27 Aug 2024 23:36:10 +0900 Subject: [PATCH 06/52] Reduce simulation jitter due to mem deallocs --- core/src/banking_simulation.rs | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 51af42108715cc..26fbdf6463b540 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -378,7 +378,12 @@ impl BankingSimulator { batches.iter().map(|batch| batch.len()).sum::(), ) }).collect::>(); - let timed_batches_to_send = timed_batches_to_send.into_iter().zip(batch_and_tx_counts.into_iter()); + // Convert to a large plain old Vec and drain on it, finally dropping it outside + // the simulation loop to avoid jitter due to interleaved deallocs of BTreeMap. + let mut timed_batches_to_send = timed_batches_to_send + .into_iter() + .zip(batch_and_tx_counts.into_iter()) + .collect::>(); info!( "simulating banking trace events: {} out of {}, starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", event_count, @@ -400,7 +405,7 @@ impl BankingSimulator { mut last_gossip_vote_tx_count ) = (Duration::default(), 0, 0, 0, 0); for ((event_time, (label, batches_with_stats)), (batch_count, tx_count)) in - timed_batches_to_send { + timed_batches_to_send.drain(..) { let required_duration_since_base = event_time.duration_since(base_event_time).unwrap(); @@ -472,6 +477,7 @@ impl BankingSimulator { gossip_vote_count, gossip_vote_tx_count ); + drop(timed_batches_to_send); // hold these senders in join_handle to control banking stage termination! (non_vote_sender, tpu_vote_sender, gossip_vote_sender) } From 8dad62c71682552a3e66cbe9d094a7b7085ef7e4 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Tue, 27 Aug 2024 23:56:51 +0900 Subject: [PATCH 07/52] Rename to CostTracker::new_from_parent_limits() --- cost-model/src/cost_tracker.rs | 2 +- runtime/src/bank.rs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/cost-model/src/cost_tracker.rs b/cost-model/src/cost_tracker.rs index 3fe827faf35fb6..55d905047990a5 100644 --- a/cost-model/src/cost_tracker.rs +++ b/cost-model/src/cost_tracker.rs @@ -106,7 +106,7 @@ impl Default for CostTracker { } impl CostTracker { - pub fn new_from_parent(&self) -> Self { + pub fn new_from_parent_limits(&self) -> Self { let mut new = Self::default(); new.set_limits( self.account_cost_limit, diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index 4c8a1fa243e4b4..8421ecaa176baf 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -1264,7 +1264,7 @@ impl Bank { .map(|drop_callback| drop_callback.clone_box()), )), freeze_started: AtomicBool::new(false), - cost_tracker: RwLock::new(parent.read_cost_tracker().unwrap().new_from_parent()), + cost_tracker: RwLock::new(parent.read_cost_tracker().unwrap().new_from_parent_limits()), accounts_data_size_initial, accounts_data_size_delta_on_chain: AtomicI64::new(0), accounts_data_size_delta_off_chain: AtomicI64::new(0), From 849cc6b5cbced4a89c8214102e3df18238e82a23 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 10:20:41 +0900 Subject: [PATCH 08/52] Make ::load() take a slice --- core/src/banking_simulation.rs | 4 ++-- ledger-tool/src/main.rs | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 26fbdf6463b540..a489db42ae3d90 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -143,9 +143,9 @@ impl BankingTraceEvents { Ok(()) } - pub fn load(event_file_paths: Vec) -> Result { + pub fn load(event_file_paths: &[PathBuf]) -> Result { let mut events = vec![]; - for event_file_path in &event_file_paths { + for event_file_path in event_file_paths { let old_len = events.len(); let _ = Self::read_event_file(&mut events, event_file_path).inspect_err(|error| { error!( diff --git a/ledger-tool/src/main.rs b/ledger-tool/src/main.rs index 60205a5d4ea201..8efcb06580edd8 100644 --- a/ledger-tool/src/main.rs +++ b/ledger-tool/src/main.rs @@ -544,7 +544,7 @@ fn load_banking_trace_events_or_exit(ledger_path: &Path) -> BankingTraceEvents { let file_paths = read_banking_trace_event_file_paths_or_exit(banking_trace_path(ledger_path)); info!("Using: banking trace event files: {file_paths:?}"); - match BankingTraceEvents::load(file_paths) { + match BankingTraceEvents::load(&file_paths) { Ok(banking_trace_events) => banking_trace_events, Err(error) => { eprintln!("Failed to load banking trace events: {error:?}"); From e09a4b2bfe0ce6959f4adb5cc347253cf2f96d2d Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 10:35:47 +0900 Subject: [PATCH 09/52] Clean up retracer code a bit --- core/src/banking_simulation.rs | 26 +++++++++++--------------- 1 file changed, 11 insertions(+), 15 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index a489db42ae3d90..8635e80bfabe50 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -287,25 +287,21 @@ impl BankingSimulator { ); let warmup_duration = Duration::from_secs(12); - let (banking_retracer, retracer_thread) = BankingTracer::new(Some(( + let (retracer, retracer_thread) = BankingTracer::new(Some(( &blockstore.banking_retracer_path(), exit.clone(), BANKING_TRACE_DIR_DEFAULT_BYTE_LIMIT, ))) .unwrap(); - if banking_retracer.is_enabled() { - info!( - "Enabled banking retracer (dir_byte_limit: {})", - BANKING_TRACE_DIR_DEFAULT_BYTE_LIMIT, - ); - } else { - info!("Disabled banking retracer"); - } + assert!(retracer.is_enabled()); + info!( + "Enabled banking retracer (dir_byte_limit: {})", + BANKING_TRACE_DIR_DEFAULT_BYTE_LIMIT, + ); - let (non_vote_sender, non_vote_receiver) = banking_retracer.create_channel_non_vote(); - let (tpu_vote_sender, tpu_vote_receiver) = banking_retracer.create_channel_tpu_vote(); - let (gossip_vote_sender, gossip_vote_receiver) = - banking_retracer.create_channel_gossip_vote(); + let (non_vote_sender, non_vote_receiver) = retracer.create_channel_non_vote(); + let (tpu_vote_sender, tpu_vote_receiver) = retracer.create_channel_tpu_vote(); + let (gossip_vote_sender, gossip_vote_receiver) = retracer.create_channel_gossip_vote(); let cluster_info = Arc::new(ClusterInfo::new_with_dummy_keypair( Node::new_localhost_with_pubkey(&simulated_leader).info, @@ -567,7 +563,7 @@ impl BankingSimulator { ); // make sure parent is frozen for finalized hashes via the above // new()-ing of its child bank - banking_retracer.hash_event(bank.slot(), &bank.last_blockhash(), &bank.hash()); + retracer.hash_event(bank.slot(), &bank.last_blockhash(), &bank.hash()); if *bank.collector_id() == simulated_leader { info!( "bank cost: slot: {} {:?} (frozen)", @@ -606,7 +602,7 @@ impl BankingSimulator { exit.store(true, Ordering::Relaxed); // The order is important. consuming sender_thread by joining will terminate banking_stage, - // in turn banking_retracer thread will termianl + // in turn retracer thread will termianl sender_thread.join().unwrap(); banking_stage.join().unwrap(); poh_service.join().unwrap(); From 6b9ba1f3ef22312a5ec1b35eec9357bf1b1daba9 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 10:44:11 +0900 Subject: [PATCH 10/52] Add comment about BaningTracer even inside sim --- core/src/banking_simulation.rs | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 8635e80bfabe50..eaab955d5d43c8 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -287,6 +287,16 @@ impl BankingSimulator { ); let warmup_duration = Duration::from_secs(12); + // Enable BankingTracer to approximate the real environment as close as possible because + // it's not expected to disable BankingTracer on production environments. + // + // It's not likely for it to affect the banking stage performance noticeably. So, make sure + // that assumption is held here. That said, it incurs additional channel sending, + // SystemTime::now() and buffered seq IO, and indirectly functions as a background dropper + // of `BankingPacketBatch`. + // + // Lastly, the actual retraced events can be used to evaluate simulation timing accuracy in + // the future. let (retracer, retracer_thread) = BankingTracer::new(Some(( &blockstore.banking_retracer_path(), exit.clone(), From 94682271c707ea5cba0efdd6f17b3190b818d9ec Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 10:48:30 +0900 Subject: [PATCH 11/52] Remove redundant dcou dev-dependencies --- core/Cargo.toml | 1 - 1 file changed, 1 deletion(-) diff --git a/core/Cargo.toml b/core/Cargo.toml index a73f3b80c82532..a7206f10b193f0 100644 --- a/core/Cargo.toml +++ b/core/Cargo.toml @@ -101,7 +101,6 @@ serde_json = { workspace = true } serial_test = { workspace = true } # See order-crates-for-publishing.py for using this unusual `path = "."` solana-core = { path = ".", features = ["dev-context-only-utils"] } -solana-gossip = { workspace = true, features = ["dev-context-only-utils"] } solana-ledger = { workspace = true, features = ["dev-context-only-utils"] } solana-logger = { workspace = true } solana-poh = { workspace = true, features = ["dev-context-only-utils"] } From 168ee1d2b3a9d14ad455abf2bc7c0567485436da Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 12:42:21 +0900 Subject: [PATCH 12/52] Apply suggestions from code review Co-authored-by: Andrew Fitzgerald --- core/src/banking_simulation.rs | 55 +++++++++++++++++----------------- 1 file changed, 27 insertions(+), 28 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index eaab955d5d43c8..88aee96e4c3dc6 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -47,57 +47,56 @@ use { thiserror::Error, }; -// This creates a simulated environment around the banking stage to reproduce leader's blocks based +// This creates a simulated environment around `BankingStage` to produce leader's blocks based // on recorded banking trace events (`TimedTracedEvent`). // -// The task of banking stage at the highest level is to pack transactions into their blocks as much -// as possible for scheduled fixed duration. So, there's 3 abstract inputs to simulate: blocks, +// At a high level, the task of `BankingStage` is to pack transactions into assigned, fixed-duration, leader blocks. So, there are 3 abstract inputs to simulate: blocks, // time, and transactions. // // In the context of simulation, the first two are simple; both are well defined. // -// For ancestor blocks, we firstly replay certain number of blocks immediately up to target -// simulation leader's slot with halt_at_slot mechanism, possibly priming various caches, -// ultimately freezing the ancestor block with expected and deterministic hashes. +// For ancestor blocks, we first replay a certain number of blocks immediately up to target +// simulation leader's slot with `halt_at_slot` mechanism. +Ultimately freezing the ancestor block with expected and deterministic hashes. +This has the added possible benefit of warming caches that may be used during simulation. // // After replay, a minor tweak is applied during simulation: we forcibly override leader's hashes -// as simulated banking stage creates them, using recorded `BlockAndBankHash` events. This is to -// provide undistinguishable sysvars to TX execution and identical TX age resolution as the -// simulation goes on. Otherwise, vast majority of tx processing would differ because simulated -// block's hashes would definitely differ than the recorded ones as slight block composition +// as the simulated `BankingStage` creates them, using recorded `BlockAndBankHash` events. This is to +// provide indistinguishable sysvars to TX execution and identical TX age resolution as the +// simulation goes on. Otherwise, the vast majority of TX processing would differ because the simulated +// block's hashes would differ than the recorded ones as block composition // difference is inevitable. // -// For poh time, we just use PohRecorder as same as the real environment, which is just 400ms -// timer, external to banking stage and thus mostly irrelevant to banking stage performance. For -// wall time, we use the first BankStatus::BlockAndBankHash and `SystemTime::now()` to define T=0 -// for simulation. Then, simulation progress is timed accordingly. As a context, this syncing is -// needed because all trace events are recorded in UTC, not relative to poh nor to leader schedule +// As in the real environment, for PoH time we use the `PohRecorder`. +// This is simply a 400ms timer, external to `BankingStage` and thus mostly irrelevant to `BankingStage` performance. For +// wall time, we use the first `BankStatus::BlockAndBankHash` and `SystemTime::now()` to define T=0 +// for simulation. Then, simulation progress is timed accordingly. For context, this syncing is +// necessary because all trace events are recorded in UTC, not relative to poh nor to leader schedule // for simplicity at recording. // -// Lastly, here's the last and most complicated input to simulate: transactions. +// Lastly, the last and most complicated input to simulate: transactions. // -// A bit closer look of transaction load profile is like below, regardless of internal banking +// A closer look of the transaction load profile is below, regardless of internal banking // implementation and simulation: // -// There's ever `BufferedPacketsDecision::Hold`-ed transactions to be processed as the first leader -// slot nears. This is due to solana's general tx broadcast strategy of node's forwarding and -// client's submission, which are unlikely to chabge soon. So, we take this as granted. Then, any -// initial leader block creation starts with rather large number of schedule-able transactions. -// Also, note that additional transactions arrive for the 4 leader slot window (roughly ~1.6 +// Due to solana's general tx broadcast strategy of client's submission and optional +// node forwarding, many transactions often arrive before the first leader slot begins. +// Thus, the initial leader block creation typically starts with rather large number of schedule-able transactions. +// Also, note that additional transactions arrive during the 4 leader slot window (roughly ~1.6 // seconds). // -// Simulation have to mimic this load pattern while being agnostic to internal bnaking impl as much -// as possible. For that agnostic objective, `TracedSender`s are sneaked into the SigVerify stage -// and gossip subsystem by `BankingTracer` to trace **all** of `BankingPacketBatch`s' exact payload +// Simulation must mimic this load pattern while being agnostic to internal banking impl as much +// as possible. For that agnostic objective, `TracedSender`s were introduced into the `SigVerify` stage +// and gossip subsystem by `BankingTracer` to trace **all** `BankingPacketBatch`s' exact payload // and _sender_'s timing with `SystemTime::now()` for all `ChannelLabel`s. This deliberate tracing -// placement is not to be affected by any banking-tage's capping (if any) and its channel +// placement is not to be affected by any `BankingStage`'s internal capacity (if any) nor by its channel // consumption pattern. // // BankingSimulator consists of 2 phases chronologically: warm-up and on-the-fly. The 2 phases are // segregated by the aforementioned T=0. // -// Both phases just sends BankingPacketBatch in the same fashion, pretending to be sigveirfy -// stage/gossip while burning 1 thread to busy loop for precise T=N at ~1us granularity. +// Both phases just send `BankingPacketBatch` in the same fashion, pretending to be +// `SigVerifyStage`/gossip from a single thread to busy loop for precise T=N at ~1us granularity. // // Warm up is defined as T=-N secs using slot distance between immediate ancestor of first // simulated block and root block. As soon as warm up is initiated, we invoke From a11de4ee57d1da11ac0554856d5d097e348e84c4 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 12:52:15 +0900 Subject: [PATCH 13/52] Fix up and promote to doc comments --- core/src/banking_simulation.rs | 109 +++++++++++++++++---------------- 1 file changed, 55 insertions(+), 54 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 88aee96e4c3dc6..3a0a50cdfb0b95 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -47,60 +47,61 @@ use { thiserror::Error, }; -// This creates a simulated environment around `BankingStage` to produce leader's blocks based -// on recorded banking trace events (`TimedTracedEvent`). -// -// At a high level, the task of `BankingStage` is to pack transactions into assigned, fixed-duration, leader blocks. So, there are 3 abstract inputs to simulate: blocks, -// time, and transactions. -// -// In the context of simulation, the first two are simple; both are well defined. -// -// For ancestor blocks, we first replay a certain number of blocks immediately up to target -// simulation leader's slot with `halt_at_slot` mechanism. -Ultimately freezing the ancestor block with expected and deterministic hashes. -This has the added possible benefit of warming caches that may be used during simulation. -// -// After replay, a minor tweak is applied during simulation: we forcibly override leader's hashes -// as the simulated `BankingStage` creates them, using recorded `BlockAndBankHash` events. This is to -// provide indistinguishable sysvars to TX execution and identical TX age resolution as the -// simulation goes on. Otherwise, the vast majority of TX processing would differ because the simulated -// block's hashes would differ than the recorded ones as block composition -// difference is inevitable. -// -// As in the real environment, for PoH time we use the `PohRecorder`. -// This is simply a 400ms timer, external to `BankingStage` and thus mostly irrelevant to `BankingStage` performance. For -// wall time, we use the first `BankStatus::BlockAndBankHash` and `SystemTime::now()` to define T=0 -// for simulation. Then, simulation progress is timed accordingly. For context, this syncing is -// necessary because all trace events are recorded in UTC, not relative to poh nor to leader schedule -// for simplicity at recording. -// -// Lastly, the last and most complicated input to simulate: transactions. -// -// A closer look of the transaction load profile is below, regardless of internal banking -// implementation and simulation: -// -// Due to solana's general tx broadcast strategy of client's submission and optional -// node forwarding, many transactions often arrive before the first leader slot begins. -// Thus, the initial leader block creation typically starts with rather large number of schedule-able transactions. -// Also, note that additional transactions arrive during the 4 leader slot window (roughly ~1.6 -// seconds). -// -// Simulation must mimic this load pattern while being agnostic to internal banking impl as much -// as possible. For that agnostic objective, `TracedSender`s were introduced into the `SigVerify` stage -// and gossip subsystem by `BankingTracer` to trace **all** `BankingPacketBatch`s' exact payload -// and _sender_'s timing with `SystemTime::now()` for all `ChannelLabel`s. This deliberate tracing -// placement is not to be affected by any `BankingStage`'s internal capacity (if any) nor by its channel -// consumption pattern. -// -// BankingSimulator consists of 2 phases chronologically: warm-up and on-the-fly. The 2 phases are -// segregated by the aforementioned T=0. -// -// Both phases just send `BankingPacketBatch` in the same fashion, pretending to be -// `SigVerifyStage`/gossip from a single thread to busy loop for precise T=N at ~1us granularity. -// -// Warm up is defined as T=-N secs using slot distance between immediate ancestor of first -// simulated block and root block. As soon as warm up is initiated, we invoke -// `BankingStage::new_num_threads()` as well to simulate the pre-leader slot's tx-buffering time. +/// This creates a simulated environment around `BankingStage` to produce leader's blocks based on +/// recorded banking trace events (`TimedTracedEvent`). +/// +/// At a high level, the task of `BankingStage` is to pack transactions into assigned, +/// fixed-duration, leader blocks. So, there are 3 abstract inputs to simulate: blocks, time, and +/// transactions. +/// +/// In the context of simulation, the first two are simple; both are well defined. +/// +/// For ancestor blocks, we first replay a certain number of blocks immediately up to target +/// simulation leader's slot with `halt_at_slot` mechanism. Ultimately freezing the ancestor block +/// with expected and deterministic hashes. This has the added possible benefit of warming caches +/// that may be used during simulation. +/// +/// After replay, a minor tweak is applied during simulation: we forcibly override leader's hashes +/// as the simulated `BankingStage` creates them, using recorded `BlockAndBankHash` events. This is +/// to provide indistinguishable sysvars to TX execution and identical TX age resolution as the +/// simulation goes on. Otherwise, the vast majority of TX processing would differ because the +/// simulated block's hashes would differ than the recorded ones as block composition difference is +/// inevitable. +/// +/// As in the real environment, for PoH time we use the `PohRecorder`. This is simply a 400ms +/// timer, external to `BankingStage` and thus mostly irrelevant to `BankingStage` performance. For +/// wall time, we use the first `BankStatus::BlockAndBankHash` and `SystemTime::now()` to define +/// T=0 for simulation. Then, simulation progress is timed accordingly. For context, this syncing +/// is necessary because all trace events are recorded in UTC, not relative to poh nor to leader +/// schedule for simplicity at recording. +/// +/// Lastly, the last and most complicated input to simulate: transactions. +/// +/// A closer look of the transaction load profile is below, regardless of internal banking +/// implementation and simulation: +/// +/// Due to solana's general tx broadcast strategy of client's submission and optional node +/// forwarding, many transactions often arrive before the first leader slot begins. Thus, the +/// initial leader block creation typically starts with rather large number of schedule-able +/// transactions. Also, note that additional transactions arrive during the 4 leader slot window +/// (roughly ~1.6 seconds). +/// +/// Simulation must mimic this load pattern while being agnostic to internal banking impl as much +/// as possible. For that agnostic objective, `TracedSender`s were introduced into the `SigVerify` +/// stage and gossip subsystem by `BankingTracer` to trace **all** `BankingPacketBatch`s' exact +/// payload and _sender_'s timing with `SystemTime::now()` for all `ChannelLabel`s. This deliberate +/// tracing placement is not to be affected by any `BankingStage`'s internal capacity (if any) nor +/// by its channel consumption pattern. +/// +/// BankingSimulator consists of 2 phases chronologically: warm-up and on-the-fly. The 2 phases are +/// segregated by the aforementioned T=0. +/// +/// Both phases just send `BankingPacketBatch` in the same fashion, pretending to be +/// `SigVerifyStage`/gossip from a single thread to busy loop for precise T=N at ~1us granularity. +/// +/// Warm up is defined as T=-N secs using slot distance between immediate ancestor of first +/// simulated block and root block. As soon as warm up is initiated, we invoke +/// `BankingStage::new_num_threads()` as well to simulate the pre-leader slot's tx-buffering time. pub struct BankingSimulator { banking_trace_events: BankingTraceEvents, first_simulated_slot: Slot, From c9d4330f8020bf850ff9032901a688ba83520a85 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 12:56:14 +0900 Subject: [PATCH 14/52] Make warm-up code and doc simpler --- core/src/banking_simulation.rs | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 3a0a50cdfb0b95..7bb6c855b2144d 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -27,7 +27,9 @@ use { prioritization_fee_cache::PrioritizationFeeCache, }, solana_sdk::{ - genesis_config::GenesisConfig, shred_version::compute_shred_version, slot_history::Slot, + clock::{Slot, DEFAULT_MS_PER_SLOT, HOLD_TRANSACTIONS_SLOT_OFFSET}, + genesis_config::GenesisConfig, + shred_version::compute_shred_version, }, solana_streamer::socket::SocketAddrSpace, solana_turbine::broadcast_stage::BroadcastStageType, @@ -99,8 +101,7 @@ use { /// Both phases just send `BankingPacketBatch` in the same fashion, pretending to be /// `SigVerifyStage`/gossip from a single thread to busy loop for precise T=N at ~1us granularity. /// -/// Warm up is defined as T=-N secs using slot distance between immediate ancestor of first -/// simulated block and root block. As soon as warm up is initiated, we invoke +/// Warm-up starts at T=-WARMUP_DURATION (~ 13 secs). As soon as warm up is initiated, we invoke /// `BankingStage::new_num_threads()` as well to simulate the pre-leader slot's tx-buffering time. pub struct BankingSimulator { banking_trace_events: BankingTraceEvents, @@ -116,6 +117,10 @@ pub enum SimulateError { SerializeError(#[from] bincode::Error), } +// Defined to be enough to cover the holding phase prior to leader slots with some idling (+5 secs) +const WARMUP_DURATION: Duration = + Duration::from_secs(HOLD_TRANSACTIONS_SLOT_OFFSET * DEFAULT_MS_PER_SLOT + 5); + pub struct BankingTraceEvents { /// BTreeMap is intentional because events could be unordered slightly due to tracing jitter. packet_batches_by_time: BTreeMap, @@ -285,7 +290,6 @@ impl BankingSimulator { DEFAULT_HASHES_PER_BATCH, record_receiver, ); - let warmup_duration = Duration::from_secs(12); // Enable BankingTracer to approximate the real environment as close as possible because // it's not expected to disable BankingTracer on production environments. @@ -363,7 +367,7 @@ impl BankingSimulator { .next() .expect("timed hashes"); - let base_event_time = raw_base_event_time - warmup_duration; + let base_event_time = raw_base_event_time - WARMUP_DURATION; let base_simulation_time = SystemTime::now(); let sender_thread = thread::Builder::new().name("solSimSender".into()).spawn({ @@ -400,7 +404,7 @@ impl BankingSimulator { raw_base_event_time.format("%Y-%m-%d %H:%M:%S.%f") }, slot_before_next_leader_slot, - warmup_duration, + WARMUP_DURATION, ); let mut simulation_duration_since_base = Duration::default(); let ( @@ -489,7 +493,7 @@ impl BankingSimulator { } })?; - sleep(warmup_duration); + sleep(WARMUP_DURATION); info!("warmup done!"); loop { From a2fac7be26b4f89174f77c47897cc83931f3aa51 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 13:06:08 +0900 Subject: [PATCH 15/52] Further clean up timed_batches_to_send --- core/src/banking_simulation.rs | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 7bb6c855b2144d..ed1e6027b31906 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -10,6 +10,7 @@ use { }, bincode::deserialize_from, crossbeam_channel::unbounded, + itertools::Itertools, log::*, solana_client::connection_cache::ConnectionCache, solana_gossip::cluster_info::{ClusterInfo, Node}, @@ -379,8 +380,8 @@ impl BankingSimulator { let (mut gossip_vote_count, mut gossip_vote_tx_count) = (0, 0); info!("start sending!..."); + let total_batch_count = self.banking_trace_events.packet_batches_by_time.len(); let timed_batches_to_send = self.banking_trace_events.packet_batches_by_time.split_off(&base_event_time); - let event_count = timed_batches_to_send.len(); let batch_and_tx_counts = timed_batches_to_send.values().map(|(_label, batches_with_stats)| { let batches = &batches_with_stats.0; ( @@ -392,12 +393,12 @@ impl BankingSimulator { // the simulation loop to avoid jitter due to interleaved deallocs of BTreeMap. let mut timed_batches_to_send = timed_batches_to_send .into_iter() - .zip(batch_and_tx_counts.into_iter()) + .zip_eq(batch_and_tx_counts.into_iter()) .collect::>(); info!( "simulating banking trace events: {} out of {}, starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", - event_count, - self.banking_trace_events.packet_batches_by_time.len(), + timed_batches_to_send.len(), + total_batch_count, self.first_simulated_slot, { let raw_base_event_time: chrono::DateTime = raw_base_event_time.into(); From fffe86f262aedf5c54a6426fe5e5b6d85280b3d7 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 14:19:48 +0900 Subject: [PATCH 16/52] Fix wrong units... --- core/src/banking_simulation.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index ed1e6027b31906..4f661419a365d5 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -120,7 +120,7 @@ pub enum SimulateError { // Defined to be enough to cover the holding phase prior to leader slots with some idling (+5 secs) const WARMUP_DURATION: Duration = - Duration::from_secs(HOLD_TRANSACTIONS_SLOT_OFFSET * DEFAULT_MS_PER_SLOT + 5); + Duration::from_millis(HOLD_TRANSACTIONS_SLOT_OFFSET * DEFAULT_MS_PER_SLOT + 5000); pub struct BankingTraceEvents { /// BTreeMap is intentional because events could be unordered slightly due to tracing jitter. From 35e235a9176f65f13f98e43037896a6f1c127f02 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 15:29:32 +0900 Subject: [PATCH 17/52] Replace new_with_dummy_keypair() with traits --- core/Cargo.toml | 3 +- core/benches/forwarder.rs | 2 +- core/src/banking_simulation.rs | 46 ++++++++++++++++--- core/src/banking_stage.rs | 46 ++++++++++++++----- core/src/banking_stage/forward_worker.rs | 12 +++-- core/src/banking_stage/forwarder.rs | 15 +++--- .../scheduler_controller.rs | 17 ++++--- core/src/next_leader.rs | 5 +- gossip/Cargo.toml | 1 - gossip/src/cluster_info.rs | 31 ++----------- 10 files changed, 107 insertions(+), 71 deletions(-) diff --git a/core/Cargo.toml b/core/Cargo.toml index a7206f10b193f0..5ff0f13a2d5a27 100644 --- a/core/Cargo.toml +++ b/core/Cargo.toml @@ -105,7 +105,7 @@ solana-ledger = { workspace = true, features = ["dev-context-only-utils"] } solana-logger = { workspace = true } solana-poh = { workspace = true, features = ["dev-context-only-utils"] } solana-program-runtime = { workspace = true } -solana-runtime = { workspace = true, features = ["dev-context-only-utils"] } +solana-runtime = { workspace = true } solana-sdk = { workspace = true, features = ["dev-context-only-utils"] } solana-stake-program = { workspace = true } solana-unified-scheduler-pool = { workspace = true, features = [ @@ -124,7 +124,6 @@ rustc_version = { workspace = true, optional = true } [features] dev-context-only-utils = [ - "solana-gossip/dev-context-only-utils", "solana-runtime/dev-context-only-utils", ] frozen-abi = [ diff --git a/core/benches/forwarder.rs b/core/benches/forwarder.rs index bf40e1be7ac17e..10a050f3d97d4b 100644 --- a/core/benches/forwarder.rs +++ b/core/benches/forwarder.rs @@ -34,7 +34,7 @@ use { struct BenchSetup { exit: Arc, poh_service: PohService, - forwarder: Forwarder, + forwarder: Forwarder>, unprocessed_packet_batches: UnprocessedTransactionStorage, tracker: LeaderSlotMetricsTracker, stats: BankingStageStats, diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 4f661419a365d5..3bb46182113517 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -1,7 +1,7 @@ #![cfg(feature = "dev-context-only-utils")] use { crate::{ - banking_stage::BankingStage, + banking_stage::{BankingStage, LikeClusterInfo}, banking_trace::{ BankingPacketBatch, BankingTracer, ChannelLabel, TimedTracedEvent, TracedEvent, BANKING_TRACE_DIR_DEFAULT_BYTE_LIMIT, BASENAME, @@ -13,7 +13,10 @@ use { itertools::Itertools, log::*, solana_client::connection_cache::ConnectionCache, - solana_gossip::cluster_info::{ClusterInfo, Node}, + solana_gossip::{ + cluster_info::{ClusterInfo, Node}, + contact_info::ContactInfo, + }, solana_ledger::{ blockstore::{Blockstore, PurgeType}, leader_schedule_cache::LeaderScheduleCache, @@ -30,7 +33,10 @@ use { solana_sdk::{ clock::{Slot, DEFAULT_MS_PER_SLOT, HOLD_TRANSACTIONS_SLOT_OFFSET}, genesis_config::GenesisConfig, + pubkey::Pubkey, shred_version::compute_shred_version, + signature::Signer, + signer::keypair::Keypair, }, solana_streamer::socket::SocketAddrSpace, solana_turbine::broadcast_stage::BroadcastStageType, @@ -207,6 +213,24 @@ impl BankingTraceEvents { } } +#[derive(Clone)] +struct DummyClusterInfo { + id: Pubkey, +} + +impl LikeClusterInfo for DummyClusterInfo { + fn id(&self) -> Pubkey { + self.id + } + + fn lookup_contact_info(&self, _id: &Pubkey, _map: F) -> Option + where + F: FnOnce(&ContactInfo) -> Y, + { + None + } +} + impl BankingSimulator { pub fn new(banking_trace_events: BankingTraceEvents, first_simulated_slot: Slot) -> Self { Self { @@ -318,10 +342,6 @@ impl BankingSimulator { let (tpu_vote_sender, tpu_vote_receiver) = retracer.create_channel_tpu_vote(); let (gossip_vote_sender, gossip_vote_receiver) = retracer.create_channel_gossip_vote(); - let cluster_info = Arc::new(ClusterInfo::new_with_dummy_keypair( - Node::new_localhost_with_pubkey(&simulated_leader).info, - SocketAddrSpace::Unspecified, - )); let connection_cache = Arc::new(ConnectionCache::new("connection_kache!")); let (replay_vote_sender, _replay_vote_receiver) = unbounded(); let (retransmit_slots_sender, retransmit_slots_receiver) = unbounded(); @@ -330,6 +350,16 @@ impl BankingSimulator { Some(&bank_forks.read().unwrap().root_bank().hard_forks()), ); let (sender, _receiver) = tokio::sync::mpsc::channel(1); + + // Create a completely-dummy ClusterInfo for the broadcast stage. + // We only need it to write shreds into the blockstore and it seems given ClusterInfo is + // irrevant for the neccesary minimum work for this simulation. + let random_keypair = Arc::new(Keypair::new()); + let cluster_info = Arc::new(ClusterInfo::new( + Node::new_localhost_with_pubkey(&random_keypair.pubkey()).info, + random_keypair, + SocketAddrSpace::Unspecified, + )); let broadcast_stage = BroadcastStageType::Standard.new_broadcast_stage( vec![UdpSocket::bind((Ipv4Addr::LOCALHOST, 0)).unwrap()], cluster_info.clone(), @@ -343,6 +373,10 @@ impl BankingSimulator { ); info!("Start banking stage!..."); + // Create a partially-dummy ClusterInfo for the banking stage. + let cluster_info = DummyClusterInfo { + id: simulated_leader, + }; let prioritization_fee_cache = &Arc::new(PrioritizationFeeCache::new(0u64)); let banking_stage = BankingStage::new_num_threads( block_production_method.clone(), diff --git a/core/src/banking_stage.rs b/core/src/banking_stage.rs index 5c9768aa0bc215..8dff75832106a9 100644 --- a/core/src/banking_stage.rs +++ b/core/src/banking_stage.rs @@ -31,7 +31,7 @@ use { crossbeam_channel::{unbounded, Receiver, RecvTimeoutError, Sender}, histogram::Histogram, solana_client::connection_cache::ConnectionCache, - solana_gossip::cluster_info::ClusterInfo, + solana_gossip::{cluster_info::ClusterInfo, contact_info::ContactInfo}, solana_ledger::blockstore_processor::TransactionStatusSender, solana_measure::measure_us, solana_perf::{data_budget::DataBudget, packet::PACKETS_PER_BATCH}, @@ -40,9 +40,10 @@ use { bank_forks::BankForks, prioritization_fee_cache::PrioritizationFeeCache, vote_sender_types::ReplayVoteSender, }, - solana_sdk::timing::AtomicInterval, + solana_sdk::{pubkey::Pubkey, timing::AtomicInterval}, std::{ cmp, env, + ops::Deref, sync::{ atomic::{AtomicU64, AtomicUsize, Ordering}, Arc, RwLock, @@ -323,12 +324,33 @@ pub struct FilterForwardingResults { pub(crate) total_filter_packets_us: u64, } +pub trait LikeClusterInfo: Send + Sync + 'static + Clone { + fn id(&self) -> Pubkey; + + fn lookup_contact_info(&self, id: &Pubkey, map: F) -> Option + where + F: FnOnce(&ContactInfo) -> Y; +} + +impl LikeClusterInfo for Arc { + fn id(&self) -> Pubkey { + self.deref().id() + } + + fn lookup_contact_info(&self, id: &Pubkey, map: F) -> Option + where + F: FnOnce(&ContactInfo) -> Y, + { + self.deref().lookup_contact_info(id, map) + } +} + impl BankingStage { /// Create the stage using `bank`. Exit when `verified_receiver` is dropped. #[allow(clippy::too_many_arguments)] pub fn new( block_production_method: BlockProductionMethod, - cluster_info: &Arc, + cluster_info: &impl LikeClusterInfo, poh_recorder: &Arc>, non_vote_receiver: BankingPacketReceiver, tpu_vote_receiver: BankingPacketReceiver, @@ -362,7 +384,7 @@ impl BankingStage { #[allow(clippy::too_many_arguments)] pub fn new_num_threads( block_production_method: BlockProductionMethod, - cluster_info: &Arc, + cluster_info: &impl LikeClusterInfo, poh_recorder: &Arc>, non_vote_receiver: BankingPacketReceiver, tpu_vote_receiver: BankingPacketReceiver, @@ -413,7 +435,7 @@ impl BankingStage { #[allow(clippy::too_many_arguments)] pub fn new_thread_local_multi_iterator( - cluster_info: &Arc, + cluster_info: &impl LikeClusterInfo, poh_recorder: &Arc>, non_vote_receiver: BankingPacketReceiver, tpu_vote_receiver: BankingPacketReceiver, @@ -497,7 +519,7 @@ impl BankingStage { #[allow(clippy::too_many_arguments)] pub fn new_central_scheduler( - cluster_info: &Arc, + cluster_info: &impl LikeClusterInfo, poh_recorder: &Arc>, non_vote_receiver: BankingPacketReceiver, tpu_vote_receiver: BankingPacketReceiver, @@ -629,7 +651,7 @@ impl BankingStage { Self { bank_thread_hdls } } - fn spawn_thread_local_multi_iterator_thread( + fn spawn_thread_local_multi_iterator_thread( id: u32, packet_receiver: BankingPacketReceiver, bank_forks: Arc>, @@ -637,7 +659,7 @@ impl BankingStage { committer: Committer, transaction_recorder: TransactionRecorder, log_messages_bytes_limit: Option, - mut forwarder: Forwarder, + mut forwarder: Forwarder, unprocessed_transaction_storage: UnprocessedTransactionStorage, ) -> JoinHandle<()> { let mut packet_receiver = PacketReceiver::new(id, packet_receiver, bank_forks); @@ -664,9 +686,9 @@ impl BankingStage { } #[allow(clippy::too_many_arguments)] - fn process_buffered_packets( + fn process_buffered_packets( decision_maker: &DecisionMaker, - forwarder: &mut Forwarder, + forwarder: &mut Forwarder, consumer: &Consumer, unprocessed_transaction_storage: &mut UnprocessedTransactionStorage, banking_stage_stats: &BankingStageStats, @@ -730,10 +752,10 @@ impl BankingStage { } } - fn process_loop( + fn process_loop( packet_receiver: &mut PacketReceiver, decision_maker: &DecisionMaker, - forwarder: &mut Forwarder, + forwarder: &mut Forwarder, consumer: &Consumer, id: u32, mut unprocessed_transaction_storage: UnprocessedTransactionStorage, diff --git a/core/src/banking_stage/forward_worker.rs b/core/src/banking_stage/forward_worker.rs index 6c9fd45e029c2f..61cf311f0a8cf8 100644 --- a/core/src/banking_stage/forward_worker.rs +++ b/core/src/banking_stage/forward_worker.rs @@ -4,6 +4,7 @@ use { scheduler_messages::{FinishedForwardWork, ForwardWork}, ForwardOption, }, + crate::banking_stage::LikeClusterInfo, crossbeam_channel::{Receiver, RecvError, SendError, Sender}, thiserror::Error, }; @@ -16,19 +17,19 @@ pub enum ForwardWorkerError { Send(#[from] SendError), } -pub(crate) struct ForwardWorker { +pub(crate) struct ForwardWorker { forward_receiver: Receiver, forward_option: ForwardOption, - forwarder: Forwarder, + forwarder: Forwarder, forwarded_sender: Sender, } #[allow(dead_code)] -impl ForwardWorker { +impl ForwardWorker { pub fn new( forward_receiver: Receiver, forward_option: ForwardOption, - forwarder: Forwarder, + forwarder: Forwarder, forwarded_sender: Sender, ) -> Self { Self { @@ -90,6 +91,7 @@ mod tests { }, crossbeam_channel::unbounded, solana_client::connection_cache::ConnectionCache, + solana_gossip::cluster_info::ClusterInfo, solana_ledger::{ blockstore::Blockstore, genesis_utils::GenesisConfigInfo, get_tmp_ledger_path_auto_delete, leader_schedule_cache::LeaderScheduleCache, @@ -121,7 +123,7 @@ mod tests { forwarded_receiver: Receiver, } - fn setup_test_frame() -> (TestFrame, ForwardWorker) { + fn setup_test_frame() -> (TestFrame, ForwardWorker>) { let GenesisConfigInfo { genesis_config, mint_keypair, diff --git a/core/src/banking_stage/forwarder.rs b/core/src/banking_stage/forwarder.rs index 563c93861cd30e..82af221842dd0b 100644 --- a/core/src/banking_stage/forwarder.rs +++ b/core/src/banking_stage/forwarder.rs @@ -6,14 +6,15 @@ use { ForwardOption, }, crate::{ - banking_stage::immutable_deserialized_packet::ImmutableDeserializedPacket, + banking_stage::{ + immutable_deserialized_packet::ImmutableDeserializedPacket, LikeClusterInfo, + }, next_leader::{next_leader, next_leader_tpu_vote}, tracer_packet_stats::TracerPacketStats, }, solana_client::connection_cache::ConnectionCache, solana_connection_cache::client_connection::ClientConnection as TpuConnection, solana_feature_set::FeatureSet, - solana_gossip::cluster_info::ClusterInfo, solana_measure::measure_us, solana_perf::{data_budget::DataBudget, packet::Packet}, solana_poh::poh_recorder::PohRecorder, @@ -27,21 +28,21 @@ use { }, }; -pub struct Forwarder { +pub struct Forwarder { poh_recorder: Arc>, bank_forks: Arc>, socket: UdpSocket, - cluster_info: Arc, + cluster_info: T, connection_cache: Arc, data_budget: Arc, forward_packet_batches_by_accounts: ForwardPacketBatchesByAccounts, } -impl Forwarder { +impl Forwarder { pub fn new( poh_recorder: Arc>, bank_forks: Arc>, - cluster_info: Arc, + cluster_info: T, connection_cache: Arc, data_budget: Arc, ) -> Self { @@ -307,7 +308,7 @@ mod tests { unprocessed_packet_batches::{DeserializedPacket, UnprocessedPacketBatches}, unprocessed_transaction_storage::ThreadType, }, - solana_gossip::cluster_info::Node, + solana_gossip::cluster_info::{ClusterInfo, Node}, solana_ledger::{blockstore::Blockstore, genesis_utils::GenesisConfigInfo}, solana_perf::packet::PacketFlags, solana_poh::{poh_recorder::create_test_recorder, poh_service::PohService}, diff --git a/core/src/banking_stage/transaction_scheduler/scheduler_controller.rs b/core/src/banking_stage/transaction_scheduler/scheduler_controller.rs index b576fd1576511d..9966a0527d0286 100644 --- a/core/src/banking_stage/transaction_scheduler/scheduler_controller.rs +++ b/core/src/banking_stage/transaction_scheduler/scheduler_controller.rs @@ -19,7 +19,7 @@ use { forwarder::Forwarder, immutable_deserialized_packet::ImmutableDeserializedPacket, packet_deserializer::PacketDeserializer, - ForwardOption, TOTAL_BUFFERED_PACKETS, + ForwardOption, LikeClusterInfo, TOTAL_BUFFERED_PACKETS, }, arrayvec::ArrayVec, crossbeam_channel::RecvTimeoutError, @@ -44,7 +44,7 @@ use { }; /// Controls packet and transaction flow into scheduler, and scheduling execution. -pub(crate) struct SchedulerController { +pub(crate) struct SchedulerController { /// Decision maker for determining what should be done with transactions. decision_maker: DecisionMaker, /// Packet/Transaction ingress. @@ -68,17 +68,17 @@ pub(crate) struct SchedulerController { /// Metric report handles for the worker threads. worker_metrics: Vec>, /// State for forwarding packets to the leader, if enabled. - forwarder: Option, + forwarder: Option>, } -impl SchedulerController { +impl SchedulerController { pub fn new( decision_maker: DecisionMaker, packet_deserializer: PacketDeserializer, bank_forks: Arc>, scheduler: PrioGraphScheduler, worker_metrics: Vec>, - forwarder: Option, + forwarder: Option>, ) -> Self { Self { decision_maker, @@ -670,6 +670,7 @@ mod tests { }, crossbeam_channel::{unbounded, Receiver, Sender}, itertools::Itertools, + solana_gossip::cluster_info::ClusterInfo, solana_ledger::{ blockstore::Blockstore, genesis_utils::GenesisConfigInfo, get_tmp_ledger_path_auto_delete, leader_schedule_cache::LeaderScheduleCache, @@ -705,7 +706,7 @@ mod tests { finished_consume_work_sender: Sender, } - fn create_test_frame(num_threads: usize) -> (TestFrame, SchedulerController) { + fn create_test_frame(num_threads: usize) -> (TestFrame, SchedulerController>) { let GenesisConfigInfo { mut genesis_config, mint_keypair, @@ -800,7 +801,9 @@ mod tests { // in order to keep the decision as recent as possible for processing. // In the tests, the decision will not become stale, so it is more convenient // to receive first and then schedule. - fn test_receive_then_schedule(scheduler_controller: &mut SchedulerController) { + fn test_receive_then_schedule( + scheduler_controller: &mut SchedulerController>, + ) { let decision = scheduler_controller .decision_maker .make_consume_or_forward_decision(); diff --git a/core/src/next_leader.rs b/core/src/next_leader.rs index 7e77ecd869e4a1..738e728dcc4a30 100644 --- a/core/src/next_leader.rs +++ b/core/src/next_leader.rs @@ -1,4 +1,5 @@ use { + crate::banking_stage::LikeClusterInfo, itertools::Itertools, solana_gossip::{cluster_info::ClusterInfo, contact_info::ContactInfo}, solana_poh::poh_recorder::PohRecorder, @@ -34,14 +35,14 @@ pub(crate) fn upcoming_leader_tpu_vote_sockets( } pub(crate) fn next_leader_tpu_vote( - cluster_info: &ClusterInfo, + cluster_info: &impl LikeClusterInfo, poh_recorder: &RwLock, ) -> Option<(Pubkey, SocketAddr)> { next_leader(cluster_info, poh_recorder, ContactInfo::tpu_vote) } pub(crate) fn next_leader( - cluster_info: &ClusterInfo, + cluster_info: &impl LikeClusterInfo, poh_recorder: &RwLock, port_selector: F, ) -> Option<(Pubkey, SocketAddr)> diff --git a/gossip/Cargo.toml b/gossip/Cargo.toml index 5d7a9d7025a49f..679c4a93f91e09 100644 --- a/gossip/Cargo.toml +++ b/gossip/Cargo.toml @@ -66,7 +66,6 @@ test-case = { workspace = true } rustc_version = { workspace = true, optional = true } [features] -dev-context-only-utils = [] frozen-abi = [ "dep:rustc_version", "dep:solana-frozen-abi", diff --git a/gossip/src/cluster_info.rs b/gossip/src/cluster_info.rs index 5a2a1d254f7ae3..f2e93765560ece 100644 --- a/gossip/src/cluster_info.rs +++ b/gossip/src/cluster_info.rs @@ -453,11 +453,12 @@ fn retain_staked( } impl ClusterInfo { - fn do_new( + pub fn new( contact_info: ContactInfo, keypair: Arc, socket_addr_space: SocketAddrSpace, ) -> Self { + assert_eq!(contact_info.pubkey(), &keypair.pubkey()); let id = *contact_info.pubkey(); let me = Self { gossip: CrdsGossip::default(), @@ -483,28 +484,6 @@ impl ClusterInfo { me } - pub fn new( - contact_info: ContactInfo, - keypair: Arc, - socket_addr_space: SocketAddrSpace, - ) -> Self { - assert_eq!(contact_info.pubkey(), &keypair.pubkey()); - Self::do_new(contact_info, keypair, socket_addr_space) - } - - #[cfg(feature = "dev-context-only-utils")] - pub fn new_with_dummy_keypair( - contact_info: ContactInfo, - socket_addr_space: SocketAddrSpace, - ) -> Self { - // Obviously, we can't create a Keypair for given pubkey arbitrarily... But ClusterInfo is - // needed for ledger-tool simulate-block-production. So, forcibly create one with incorrect - // Keypair. Note that the returned ClusterInfo is half-broken, but it's okay for the - // minimum usage by the subcommand. - let keypair = Arc::new(Keypair::new()); - Self::do_new(contact_info, keypair, socket_addr_space) - } - pub fn set_contact_debug_interval(&mut self, new: u64) { self.contact_debug_interval = new; } @@ -691,11 +670,7 @@ impl ClusterInfo { } pub fn id(&self) -> Pubkey { - // `self.keypair.read().unwrap().pubkey()` is more straight-forward to use here. - // However, self.keypair could be dummy in some very odd situation - // (i.e. ledger-tool's simulate-leader-production). So, use `self.my_contact_info` here. - // Other than the edge case, both are equivalent. - *self.my_contact_info.read().unwrap().pubkey() + self.keypair.read().unwrap().pubkey() } pub fn keypair(&self) -> RwLockReadGuard> { From 8fcbe113a6f96ffc427325307d0a28ca23daca19 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 23:25:29 +0900 Subject: [PATCH 18/52] Tweak --no-block-cost-limits description --- ledger-tool/src/main.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ledger-tool/src/main.rs b/ledger-tool/src/main.rs index 8efcb06580edd8..b9d7d20b8d412b 100644 --- a/ledger-tool/src/main.rs +++ b/ledger-tool/src/main.rs @@ -1231,7 +1231,7 @@ fn main() { Arg::with_name("no_block_cost_limits") .long("no-block-cost-limits") .takes_value(false) - .help("Sets block cost limits to the max"), + .help("Disable block cost limits effectively by setting them to the max"), ) .arg( Arg::with_name("enable_hash_overrides") @@ -1511,7 +1511,7 @@ fn main() { Arg::with_name("no_block_cost_limits") .long("no-block-cost-limits") .takes_value(false) - .help("Sets block cost limits to the max"), + .help("Disable block cost limits effectively by setting them to the max"), ), ) .subcommand( From d573884f33239714982df693eaaa961922436413 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 23:46:44 +0900 Subject: [PATCH 19/52] Remove redundant dev-dependencies --- core/Cargo.toml | 1 - 1 file changed, 1 deletion(-) diff --git a/core/Cargo.toml b/core/Cargo.toml index 5ff0f13a2d5a27..bbceb94dbc659e 100644 --- a/core/Cargo.toml +++ b/core/Cargo.toml @@ -105,7 +105,6 @@ solana-ledger = { workspace = true, features = ["dev-context-only-utils"] } solana-logger = { workspace = true } solana-poh = { workspace = true, features = ["dev-context-only-utils"] } solana-program-runtime = { workspace = true } -solana-runtime = { workspace = true } solana-sdk = { workspace = true, features = ["dev-context-only-utils"] } solana-stake-program = { workspace = true } solana-unified-scheduler-pool = { workspace = true, features = [ From b24a7e3378fc715d7467719a237107f48330459e Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 23:49:24 +0900 Subject: [PATCH 20/52] Use RwLock to mimic real ClusterInfo --- core/src/banking_simulation.rs | 15 ++++++++------- 1 file changed, 8 insertions(+), 7 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 3bb46182113517..a3bb981b629e76 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -213,14 +213,15 @@ impl BankingTraceEvents { } } -#[derive(Clone)] struct DummyClusterInfo { - id: Pubkey, + // Artifically wrap Pubkey with RwLock to induce lock contention if any to minic the real + // ClusterInfo + id: RwLock, } -impl LikeClusterInfo for DummyClusterInfo { +impl LikeClusterInfo for Arc { fn id(&self) -> Pubkey { - self.id + *self.id.read().unwrap() } fn lookup_contact_info(&self, _id: &Pubkey, _map: F) -> Option @@ -374,9 +375,9 @@ impl BankingSimulator { info!("Start banking stage!..."); // Create a partially-dummy ClusterInfo for the banking stage. - let cluster_info = DummyClusterInfo { - id: simulated_leader, - }; + let cluster_info = Arc::new(DummyClusterInfo { + id: simulated_leader.into(), + }); let prioritization_fee_cache = &Arc::new(PrioritizationFeeCache::new(0u64)); let banking_stage = BankingStage::new_num_threads( block_production_method.clone(), From 61f5fb37d63d168ed309250be6721a9e27ba62ef Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 28 Aug 2024 23:55:52 +0900 Subject: [PATCH 21/52] Fix typo --- core/src/banking_simulation.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index a3bb981b629e76..055218545e52ee 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -343,7 +343,7 @@ impl BankingSimulator { let (tpu_vote_sender, tpu_vote_receiver) = retracer.create_channel_tpu_vote(); let (gossip_vote_sender, gossip_vote_receiver) = retracer.create_channel_gossip_vote(); - let connection_cache = Arc::new(ConnectionCache::new("connection_kache!")); + let connection_cache = Arc::new(ConnectionCache::new("connection_cache_sim")); let (replay_vote_sender, _replay_vote_receiver) = unbounded(); let (retransmit_slots_sender, retransmit_slots_receiver) = unbounded(); let shred_version = compute_shred_version( From 7594dbfd8abb7f1cd4b55865afa090d44cfd59f1 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Thu, 29 Aug 2024 13:50:24 +0900 Subject: [PATCH 22/52] Refactor too long BankingSimulator::start() --- core/src/banking_simulation.rs | 561 ++++++++++++++++++++++++--------- 1 file changed, 406 insertions(+), 155 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 055218545e52ee..991ffcbad1f094 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -4,12 +4,12 @@ use { banking_stage::{BankingStage, LikeClusterInfo}, banking_trace::{ BankingPacketBatch, BankingTracer, ChannelLabel, TimedTracedEvent, TracedEvent, - BANKING_TRACE_DIR_DEFAULT_BYTE_LIMIT, BASENAME, + TracedSender, TracerThread, BANKING_TRACE_DIR_DEFAULT_BYTE_LIMIT, BASENAME, }, validator::BlockProductionMethod, }, bincode::deserialize_from, - crossbeam_channel::unbounded, + crossbeam_channel::{unbounded, Sender}, itertools::Itertools, log::*, solana_client::connection_cache::ConnectionCache, @@ -28,6 +28,7 @@ use { solana_runtime::{ bank::{Bank, HashOverrides}, bank_forks::BankForks, + installed_scheduler_pool::BankWithScheduler, prioritization_fee_cache::PrioritizationFeeCache, }, solana_sdk::{ @@ -39,9 +40,10 @@ use { signer::keypair::Keypair, }, solana_streamer::socket::SocketAddrSpace, - solana_turbine::broadcast_stage::BroadcastStageType, + solana_turbine::broadcast_stage::{BroadcastStage, BroadcastStageType}, std::{ collections::BTreeMap, + fmt::Display, fs::File, io::{self, BufRead, BufReader}, net::{Ipv4Addr, UdpSocket}, @@ -50,7 +52,7 @@ use { atomic::{AtomicBool, Ordering}, Arc, RwLock, }, - thread::{self, sleep}, + thread::{self, sleep, JoinHandle}, time::{Duration, SystemTime}, }, thiserror::Error, @@ -128,10 +130,16 @@ pub enum SimulateError { const WARMUP_DURATION: Duration = Duration::from_millis(HOLD_TRANSACTIONS_SLOT_OFFSET * DEFAULT_MS_PER_SLOT + 5000); +/// BTreeMap is intentional because events could be unordered slightly due to tracing jitter. +type PacketBatchesByTime = BTreeMap; + +type FreezeTimeBySlot = BTreeMap; + +type EventSenderThread = JoinHandle<(TracedSender, TracedSender, TracedSender)>; + pub struct BankingTraceEvents { - /// BTreeMap is intentional because events could be unordered slightly due to tracing jitter. - packet_batches_by_time: BTreeMap, - freeze_time_by_slot: BTreeMap, + packet_batches_by_time: PacketBatchesByTime, + freeze_time_by_slot: FreezeTimeBySlot, hash_overrides: HashOverrides, } @@ -232,6 +240,207 @@ impl LikeClusterInfo for Arc { } } +struct SimulatorLoopLogger { + simulated_leader: Pubkey, + freeze_time_by_slot: FreezeTimeBySlot, + base_event_time: SystemTime, + base_simulation_time: SystemTime, +} + +impl SimulatorLoopLogger { + fn new( + simulated_leader: Pubkey, + base_event_time: SystemTime, + base_simulation_time: SystemTime, + freeze_time_by_slot: FreezeTimeBySlot, + ) -> Self { + Self { + simulated_leader, + base_event_time, + base_simulation_time, + freeze_time_by_slot, + } + } + + fn bank_costs(bank: &Bank) -> (u64, u64) { + bank.read_cost_tracker() + .map(|t| (t.block_cost(), t.vote_cost())) + .unwrap() + } + + fn log_frozen_bank_cost(&self, bank: &Bank) { + info!( + "bank cost: slot: {} {:?} (frozen)", + bank.slot(), + Self::bank_costs(bank), + ); + } + + fn log_ongoing_bank_cost(&self, bank: &Bank) { + debug!( + "bank cost: slot: {} {:?} (ongoing)", + bank.slot(), + Self::bank_costs(bank), + ); + } + + fn log_jitter(&self, bank: &Bank) { + let old_slot = bank.slot(); + if let Some(event_time) = self.freeze_time_by_slot.get(&old_slot) { + if log_enabled!(log::Level::Info) { + let current_simulation_time = SystemTime::now(); + let elapsed_simulation_time = current_simulation_time + .duration_since(self.base_simulation_time) + .unwrap(); + let elapsed_event_time = event_time.duration_since(self.base_event_time).unwrap(); + info!( + "jitter(parent_slot: {}): {}{:?} (sim: {:?} event: {:?})", + old_slot, + if elapsed_simulation_time > elapsed_event_time { + "+" + } else { + "-" + }, + if elapsed_simulation_time > elapsed_event_time { + elapsed_simulation_time - elapsed_event_time + } else { + elapsed_event_time - elapsed_simulation_time + }, + elapsed_simulation_time, + elapsed_event_time, + ); + } + } + } + + fn on_new_leader(&self, bank: &Bank, new_slot: Slot, new_leader: Pubkey) { + self.log_frozen_bank_cost(bank); + info!( + "{} isn't leader anymore at slot {}; new leader: {}", + self.simulated_leader, new_slot, new_leader + ); + } +} + +struct SenderLoopLogger<'a> { + non_vote_sender: &'a TracedSender, + tpu_vote_sender: &'a TracedSender, + gossip_vote_sender: &'a TracedSender, + last_log_duration: Duration, + last_tx_count: usize, + last_non_vote_count: usize, + last_tpu_vote_tx_count: usize, + last_gossip_vote_tx_count: usize, + non_vote_count: usize, + non_vote_tx_count: usize, + tpu_vote_count: usize, + tpu_vote_tx_count: usize, + gossip_vote_count: usize, + gossip_vote_tx_count: usize, +} + +impl<'a> SenderLoopLogger<'a> { + fn new( + non_vote_sender: &'a TracedSender, + tpu_vote_sender: &'a TracedSender, + gossip_vote_sender: &'a TracedSender, + ) -> Self { + Self { + non_vote_sender, + tpu_vote_sender, + gossip_vote_sender, + last_log_duration: Duration::default(), + last_tx_count: 0, + last_non_vote_count: 0, + last_tpu_vote_tx_count: 0, + last_gossip_vote_tx_count: 0, + non_vote_count: 0, + non_vote_tx_count: 0, + tpu_vote_count: 0, + tpu_vote_tx_count: 0, + gossip_vote_count: 0, + gossip_vote_tx_count: 0, + } + } + + fn on_sending_batches( + &mut self, + &simulation_duration_since_base: &Duration, + label: ChannelLabel, + batch_count: usize, + tx_count: usize, + ) { + debug!( + "sent {:?} {} batches ({} txes)", + label, batch_count, tx_count + ); + + let (total_batch_count, total_tx_count) = match label { + ChannelLabel::NonVote => (&mut self.non_vote_count, &mut self.non_vote_tx_count), + ChannelLabel::TpuVote => (&mut self.tpu_vote_count, &mut self.tpu_vote_tx_count), + ChannelLabel::GossipVote => { + (&mut self.gossip_vote_count, &mut self.gossip_vote_tx_count) + } + ChannelLabel::Dummy => unreachable!(), + }; + *total_batch_count += batch_count; + *total_tx_count += tx_count; + + let log_interval = simulation_duration_since_base - self.last_log_duration; + if log_interval > Duration::from_millis(100) { + let current_tx_count = + self.non_vote_tx_count + self.tpu_vote_tx_count + self.gossip_vote_tx_count; + let duration = log_interval.as_secs_f64(); + let tps = (current_tx_count - self.last_tx_count) as f64 / duration; + let non_vote_tps = + (self.non_vote_tx_count - self.last_non_vote_count) as f64 / duration; + let tpu_vote_tps = + (self.tpu_vote_tx_count - self.last_tpu_vote_tx_count) as f64 / duration; + let gossip_vote_tps = + (self.gossip_vote_tx_count - self.last_gossip_vote_tx_count) as f64 / duration; + info!( + "senders(non-,tpu-,gossip-vote): tps: {} (={}+{}+{}) over {:?} not-recved: ({}+{}+{})", + tps as u64, + non_vote_tps as u64, + tpu_vote_tps as u64, + gossip_vote_tps as u64, + log_interval, + self.non_vote_sender.len(), + self.tpu_vote_sender.len(), + self.gossip_vote_sender.len(), + ); + self.last_log_duration = simulation_duration_since_base; + self.last_tx_count = current_tx_count; + ( + self.last_non_vote_count, + self.last_tpu_vote_tx_count, + self.last_gossip_vote_tx_count, + ) = ( + self.non_vote_tx_count, + self.tpu_vote_tx_count, + self.gossip_vote_count, + ); + } + } + + fn on_terminating(self) { + info!( + "terminating to send...: non_vote: {} ({}), tpu_vote: {} ({}), gossip_vote: {} ({})", + self.non_vote_count, + self.non_vote_tx_count, + self.tpu_vote_count, + self.tpu_vote_tx_count, + self.gossip_vote_count, + self.gossip_vote_tx_count, + ); + } + + fn format_as_timestamp(time: SystemTime) -> impl Display { + let time: chrono::DateTime = time.into(); + time.format("%Y-%m-%d %H:%M:%S.%f") + } +} + impl BankingSimulator { pub fn new(banking_trace_events: BankingTraceEvents, first_simulated_slot: Slot) -> Self { Self { @@ -249,42 +458,58 @@ impl BankingSimulator { .copied() } - pub fn start( - mut self, + #[allow(clippy::type_complexity)] + fn prepare_simulation( + parent_slot: Slot, + first_simulated_slot: Slot, genesis_config: GenesisConfig, - bank_forks: Arc>, - blockstore: Arc, + bank_forks: &Arc>, + blockstore: &Arc, block_production_method: BlockProductionMethod, - ) -> Result<(), SimulateError> { - let mut bank = bank_forks + ) -> ( + Pubkey, + TracedSender, + TracedSender, + TracedSender, + BankWithScheduler, + PohService, + Arc>, + BankingStage, + BroadcastStage, + Arc, + Sender, + Arc, + TracerThread, + Arc, + ) { + let bank = bank_forks .read() .unwrap() .working_bank_with_scheduler() .clone_with_scheduler(); let leader_schedule_cache = Arc::new(LeaderScheduleCache::new_from_bank(&bank)); - let parent_slot = bank.slot(); - assert_eq!(Some(parent_slot), self.parent_slot()); + assert_eq!(parent_slot, bank.slot()); let simulated_leader = leader_schedule_cache - .slot_leader_at(self.first_simulated_slot, None) + .slot_leader_at(first_simulated_slot, None) .unwrap(); info!( "Simulated leader and slot: {}, {}", - simulated_leader, self.first_simulated_slot + simulated_leader, first_simulated_slot ); let exit = Arc::new(AtomicBool::default()); if let Some(end_slot) = blockstore - .slot_meta_iterator(self.first_simulated_slot) + .slot_meta_iterator(first_simulated_slot) .unwrap() .map(|(s, _)| s) .last() { - info!("purging slots {}, {}", self.first_simulated_slot, end_slot); - blockstore.purge_from_next_slots(self.first_simulated_slot, end_slot); - blockstore.purge_slots(self.first_simulated_slot, end_slot, PurgeType::Exact); + info!("purging slots {}, {}", first_simulated_slot, end_slot); + blockstore.purge_from_next_slots(first_simulated_slot, end_slot); + blockstore.purge_slots(first_simulated_slot, end_slot, PurgeType::Exact); info!("done: purging"); } else { info!("skipping purging..."); @@ -396,27 +621,46 @@ impl BankingSimulator { false, ); - let (&slot_before_next_leader_slot, &raw_base_event_time) = self - .banking_trace_events - .freeze_time_by_slot + ( + simulated_leader, + non_vote_sender, + tpu_vote_sender, + gossip_vote_sender, + bank, + poh_service, + poh_recorder, + banking_stage, + broadcast_stage, + leader_schedule_cache, + retransmit_slots_sender, + retracer, + retracer_thread, + exit, + ) + } + + fn start_event_sender_thread( + parent_slot: Slot, + first_simulated_slot: Slot, + freeze_time_by_slot: &FreezeTimeBySlot, + mut packet_batches_by_time: PacketBatchesByTime, + non_vote_sender: TracedSender, + tpu_vote_sender: TracedSender, + gossip_vote_sender: TracedSender, + exit: Arc, + ) -> Result<(EventSenderThread, SystemTime, SystemTime), SimulateError> { + let (&_slot, &raw_base_event_time) = freeze_time_by_slot .range(parent_slot..) .next() .expect("timed hashes"); - let base_event_time = raw_base_event_time - WARMUP_DURATION; let base_simulation_time = SystemTime::now(); - let sender_thread = thread::Builder::new().name("solSimSender".into()).spawn({ - let exit = exit.clone(); - + let handle = thread::Builder::new().name("solSimSender".into()).spawn({ move || { - let (mut non_vote_count, mut non_vote_tx_count) = (0, 0); - let (mut tpu_vote_count, mut tpu_vote_tx_count) = (0, 0); - let (mut gossip_vote_count, mut gossip_vote_tx_count) = (0, 0); - info!("start sending!..."); - let total_batch_count = self.banking_trace_events.packet_batches_by_time.len(); - let timed_batches_to_send = self.banking_trace_events.packet_batches_by_time.split_off(&base_event_time); + let total_batch_count = packet_batches_by_time.len(); + let timed_batches_to_send = packet_batches_by_time.split_off(&base_event_time); let batch_and_tx_counts = timed_batches_to_send.values().map(|(_label, batches_with_stats)| { let batches = &batches_with_stats.0; ( @@ -434,22 +678,17 @@ impl BankingSimulator { "simulating banking trace events: {} out of {}, starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", timed_batches_to_send.len(), total_batch_count, - self.first_simulated_slot, - { - let raw_base_event_time: chrono::DateTime = raw_base_event_time.into(); - raw_base_event_time.format("%Y-%m-%d %H:%M:%S.%f") - }, - slot_before_next_leader_slot, + first_simulated_slot, + SenderLoopLogger::format_as_timestamp(raw_base_event_time), + parent_slot, WARMUP_DURATION, ); let mut simulation_duration_since_base = Duration::default(); - let ( - mut last_log_duration, - mut last_tx_count, - mut last_non_vote_count, - mut last_tpu_vote_tx_count, - mut last_gossip_vote_tx_count - ) = (Duration::default(), 0, 0, 0, 0); + let mut logger = SenderLoopLogger::new( + &non_vote_sender, + &tpu_vote_sender, + &gossip_vote_sender, + ); for ((event_time, (label, batches_with_stats)), (batch_count, tx_count)) in timed_batches_to_send.drain(..) { let required_duration_since_base = @@ -471,66 +710,43 @@ impl BankingSimulator { }; sender.send(batches_with_stats).unwrap(); - debug!( - "sent {:?} {} batches ({} txes)", - label, batch_count, tx_count - ); - let (total_batch_count, total_tx_count) = match label { - ChannelLabel::NonVote => (&mut non_vote_count, &mut non_vote_tx_count), - ChannelLabel::TpuVote => (&mut tpu_vote_count, &mut tpu_vote_tx_count), - ChannelLabel::GossipVote => (&mut gossip_vote_count, &mut gossip_vote_tx_count), - ChannelLabel::Dummy => unreachable!(), - }; - *total_batch_count += batch_count; - *total_tx_count += tx_count; - - let log_interval = simulation_duration_since_base - last_log_duration; - if log_interval > Duration::from_millis(100) { - let current_tx_count = non_vote_tx_count + tpu_vote_tx_count + gossip_vote_tx_count; - let duration =log_interval.as_secs_f64(); - let tps = (current_tx_count - last_tx_count) as f64 / duration; - let non_vote_tps = (non_vote_tx_count - last_non_vote_count) as f64 / duration; - let tpu_vote_tps = (tpu_vote_tx_count - last_tpu_vote_tx_count) as f64 / duration; - let gossip_vote_tps = (gossip_vote_tx_count - last_gossip_vote_tx_count) as f64 / duration; - info!( - "senders(non-,tpu-,gossip-vote): tps: {} (={}+{}+{}) over {:?} not-recved: ({}+{}+{})", - tps as u64, - non_vote_tps as u64, - tpu_vote_tps as u64, - gossip_vote_tps as u64, - log_interval, - non_vote_sender.len(), - tpu_vote_sender.len(), - gossip_vote_sender.len(), - ); - last_log_duration = simulation_duration_since_base; - last_tx_count = current_tx_count; - (last_non_vote_count, last_tpu_vote_tx_count, last_gossip_vote_tx_count) = ( - non_vote_tx_count, tpu_vote_tx_count, gossip_vote_count - ); - } - + logger.on_sending_batches(&simulation_duration_since_base, label, batch_count, tx_count); if exit.load(Ordering::Relaxed) { break; } } - info!( - "terminating to send...: non_vote: {} ({}), tpu_vote: {} ({}), gossip_vote: {} ({})", - non_vote_count, - non_vote_tx_count, - tpu_vote_count, - tpu_vote_tx_count, - gossip_vote_count, - gossip_vote_tx_count - ); + logger.on_terminating(); drop(timed_batches_to_send); // hold these senders in join_handle to control banking stage termination! (non_vote_sender, tpu_vote_sender, gossip_vote_sender) } })?; + Ok((handle, base_event_time, base_simulation_time)) + } - sleep(WARMUP_DURATION); - info!("warmup done!"); + #[allow(clippy::too_many_arguments)] + fn enter_simulation_loop( + parent_slot: Slot, + first_simulated_slot: Slot, + freeze_time_by_slot: FreezeTimeBySlot, + base_event_time: SystemTime, + base_simulation_time: SystemTime, + sender_thread: &EventSenderThread, + mut bank: BankWithScheduler, + poh_recorder: Arc>, + simulated_leader: Pubkey, + bank_forks: &RwLock, + blockstore: &Blockstore, + leader_schedule_cache: &LeaderScheduleCache, + retransmit_slots_sender: &Sender, + retracer: &BankingTracer, + ) { + let logger = SimulatorLoopLogger::new( + simulated_leader, + base_event_time, + base_simulation_time, + freeze_time_by_slot, + ); loop { if poh_recorder.read().unwrap().bank().is_none() { @@ -538,7 +754,7 @@ impl BankingSimulator { &simulated_leader, bank.slot(), &bank, - Some(&blockstore), + Some(blockstore), GRACE_TICKS_FACTOR * MAX_GRACE_SLOTS, ); debug!("{next_leader_slot:?}"); @@ -548,39 +764,11 @@ impl BankingSimulator { .reset(bank.clone_without_scheduler(), next_leader_slot); info!("Bank::new_from_parent()!"); - let old_slot = bank.slot(); - if let Some(event_time) = - self.banking_trace_events.freeze_time_by_slot.get(&old_slot) - { - if log_enabled!(log::Level::Info) { - let current_simulation_time = SystemTime::now(); - let elapsed_simulation_time = current_simulation_time - .duration_since(base_simulation_time) - .unwrap(); - let elapsed_event_time = - event_time.duration_since(base_event_time).unwrap(); - info!( - "jitter(parent_slot: {}): {}{:?} (sim: {:?} event: {:?})", - old_slot, - if elapsed_simulation_time > elapsed_event_time { - "+" - } else { - "-" - }, - if elapsed_simulation_time > elapsed_event_time { - elapsed_simulation_time - elapsed_event_time - } else { - elapsed_event_time - elapsed_simulation_time - }, - elapsed_simulation_time, - elapsed_event_time, - ); - } - } + logger.log_jitter(&bank); bank.freeze(); let new_slot = if bank.slot() == parent_slot { info!("initial leader block!"); - self.first_simulated_slot + first_simulated_slot } else { info!("next leader block!"); bank.slot() + 1 @@ -589,18 +777,8 @@ impl BankingSimulator { let new_leader = leader_schedule_cache .slot_leader_at(new_slot, None) .unwrap(); - if simulated_leader != new_leader { - info!( - "bank cost: slot: {} {:?} (frozen)", - bank.slot(), - bank.read_cost_tracker() - .map(|t| (t.block_cost(), t.vote_cost())) - .unwrap() - ); - info!( - "{} isn't leader anymore at slot {}; new leader: {}", - simulated_leader, new_slot, new_leader - ); + if new_leader != simulated_leader { + logger.on_new_leader(&bank, new_slot, new_leader); break; } else if sender_thread.is_finished() { warn!("sender thread existed maybe due to completion of sending traced events"); @@ -615,13 +793,7 @@ impl BankingSimulator { // new()-ing of its child bank retracer.hash_event(bank.slot(), &bank.last_blockhash(), &bank.hash()); if *bank.collector_id() == simulated_leader { - info!( - "bank cost: slot: {} {:?} (frozen)", - bank.slot(), - bank.read_cost_tracker() - .map(|t| (t.block_cost(), t.vote_cost())) - .unwrap() - ); + logger.log_frozen_bank_cost(&bank); } retransmit_slots_sender.send(bank.slot()).unwrap(); bank_forks.write().unwrap().insert(new_bank); @@ -635,18 +807,22 @@ impl BankingSimulator { .unwrap() .set_bank(bank.clone_with_scheduler(), false); } else { - debug!( - "bank cost: slot: {} {:?} (ongoing)", - bank.slot(), - bank.read_cost_tracker() - .map(|t| (t.block_cost(), t.vote_cost())) - .unwrap() - ); + logger.log_ongoing_bank_cost(&bank); } sleep(Duration::from_millis(10)); } + } + fn finish_simulation( + sender_thread: EventSenderThread, + poh_service: PohService, + banking_stage: BankingStage, + broadcast_stage: BroadcastStage, + retransmit_slots_sender: Sender, + retracer_thread: TracerThread, + exit: Arc, + ) { info!("Sleeping a bit before signaling exit"); sleep(Duration::from_millis(100)); exit.store(true, Ordering::Relaxed); @@ -661,9 +837,84 @@ impl BankingSimulator { } info!("Joining broadcast stage..."); - drop(poh_recorder); drop(retransmit_slots_sender); broadcast_stage.join().unwrap(); + } + + pub fn start( + self, + genesis_config: GenesisConfig, + bank_forks: Arc>, + blockstore: Arc, + block_production_method: BlockProductionMethod, + ) -> Result<(), SimulateError> { + let parent_slot = self.parent_slot().unwrap(); + + let ( + simulated_leader, + non_vote_sender, + tpu_vote_sender, + gossip_vote_sender, + bank, + poh_service, + poh_recorder, + banking_stage, + broadcast_stage, + leader_schedule_cache, + retransmit_slots_sender, + retracer, + retracer_thread, + exit, + ) = Self::prepare_simulation( + parent_slot, + self.first_simulated_slot, + genesis_config, + &bank_forks, + &blockstore, + block_production_method, + ); + + let (sender_thread, base_event_time, base_simulation_time) = + Self::start_event_sender_thread( + parent_slot, + self.first_simulated_slot, + &self.banking_trace_events.freeze_time_by_slot, + self.banking_trace_events.packet_batches_by_time, + non_vote_sender, + tpu_vote_sender, + gossip_vote_sender, + exit.clone(), + )?; + + sleep(WARMUP_DURATION); + info!("warmup done!"); + + Self::enter_simulation_loop( + parent_slot, + self.first_simulated_slot, + self.banking_trace_events.freeze_time_by_slot, + base_event_time, + base_simulation_time, + &sender_thread, + bank, + poh_recorder, + simulated_leader, + &bank_forks, + &blockstore, + &leader_schedule_cache, + &retransmit_slots_sender, + &retracer, + ); + + Self::finish_simulation( + sender_thread, + poh_service, + banking_stage, + broadcast_stage, + retransmit_slots_sender, + retracer_thread, + exit, + ); Ok(()) } From d0dc2f6caf9c493f2c50fcff23a5eb435649d87d Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Thu, 29 Aug 2024 22:47:48 +0900 Subject: [PATCH 23/52] Reduce indent --- core/src/banking_simulation.rs | 122 ++++++++++++++++----------------- 1 file changed, 60 insertions(+), 62 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 991ffcbad1f094..d69b2b7618c7e1 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -656,70 +656,68 @@ impl BankingSimulator { let base_event_time = raw_base_event_time - WARMUP_DURATION; let base_simulation_time = SystemTime::now(); - let handle = thread::Builder::new().name("solSimSender".into()).spawn({ - move || { - info!("start sending!..."); - let total_batch_count = packet_batches_by_time.len(); - let timed_batches_to_send = packet_batches_by_time.split_off(&base_event_time); - let batch_and_tx_counts = timed_batches_to_send.values().map(|(_label, batches_with_stats)| { - let batches = &batches_with_stats.0; - ( - batches.len(), - batches.iter().map(|batch| batch.len()).sum::(), - ) - }).collect::>(); - // Convert to a large plain old Vec and drain on it, finally dropping it outside - // the simulation loop to avoid jitter due to interleaved deallocs of BTreeMap. - let mut timed_batches_to_send = timed_batches_to_send - .into_iter() - .zip_eq(batch_and_tx_counts.into_iter()) - .collect::>(); - info!( - "simulating banking trace events: {} out of {}, starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", - timed_batches_to_send.len(), - total_batch_count, - first_simulated_slot, - SenderLoopLogger::format_as_timestamp(raw_base_event_time), - parent_slot, - WARMUP_DURATION, - ); - let mut simulation_duration_since_base = Duration::default(); - let mut logger = SenderLoopLogger::new( - &non_vote_sender, - &tpu_vote_sender, - &gossip_vote_sender, - ); - for ((event_time, (label, batches_with_stats)), (batch_count, tx_count)) in - timed_batches_to_send.drain(..) { - let required_duration_since_base = - event_time.duration_since(base_event_time).unwrap(); - - // Busy loop for most accurate sending timings - while simulation_duration_since_base < required_duration_since_base { - let current_simulation_time = SystemTime::now(); - simulation_duration_since_base = current_simulation_time - .duration_since(base_simulation_time) - .unwrap(); - } - - let sender = match label { - ChannelLabel::NonVote => &non_vote_sender, - ChannelLabel::TpuVote => &tpu_vote_sender, - ChannelLabel::GossipVote => &gossip_vote_sender, - ChannelLabel::Dummy => unreachable!(), - }; - sender.send(batches_with_stats).unwrap(); - - logger.on_sending_batches(&simulation_duration_since_base, label, batch_count, tx_count); - if exit.load(Ordering::Relaxed) { - break; - } + let handle = thread::Builder::new().name("solSimSender".into()).spawn(move || { + info!("start sending!..."); + let total_batch_count = packet_batches_by_time.len(); + let timed_batches_to_send = packet_batches_by_time.split_off(&base_event_time); + let batch_and_tx_counts = timed_batches_to_send.values().map(|(_label, batches_with_stats)| { + let batches = &batches_with_stats.0; + ( + batches.len(), + batches.iter().map(|batch| batch.len()).sum::(), + ) + }).collect::>(); + // Convert to a large plain old Vec and drain on it, finally dropping it outside + // the simulation loop to avoid jitter due to interleaved deallocs of BTreeMap. + let mut timed_batches_to_send = timed_batches_to_send + .into_iter() + .zip_eq(batch_and_tx_counts.into_iter()) + .collect::>(); + info!( + "simulating banking trace events: {} out of {}, starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", + timed_batches_to_send.len(), + total_batch_count, + first_simulated_slot, + SenderLoopLogger::format_as_timestamp(raw_base_event_time), + parent_slot, + WARMUP_DURATION, + ); + let mut simulation_duration_since_base = Duration::default(); + let mut logger = SenderLoopLogger::new( + &non_vote_sender, + &tpu_vote_sender, + &gossip_vote_sender, + ); + for ((event_time, (label, batches_with_stats)), (batch_count, tx_count)) in + timed_batches_to_send.drain(..) { + let required_duration_since_base = + event_time.duration_since(base_event_time).unwrap(); + + // Busy loop for most accurate sending timings + while simulation_duration_since_base < required_duration_since_base { + let current_simulation_time = SystemTime::now(); + simulation_duration_since_base = current_simulation_time + .duration_since(base_simulation_time) + .unwrap(); + } + + let sender = match label { + ChannelLabel::NonVote => &non_vote_sender, + ChannelLabel::TpuVote => &tpu_vote_sender, + ChannelLabel::GossipVote => &gossip_vote_sender, + ChannelLabel::Dummy => unreachable!(), + }; + sender.send(batches_with_stats).unwrap(); + + logger.on_sending_batches(&simulation_duration_since_base, label, batch_count, tx_count); + if exit.load(Ordering::Relaxed) { + break; } - logger.on_terminating(); - drop(timed_batches_to_send); - // hold these senders in join_handle to control banking stage termination! - (non_vote_sender, tpu_vote_sender, gossip_vote_sender) } + logger.on_terminating(); + drop(timed_batches_to_send); + // hold these senders in join_handle to control banking stage termination! + (non_vote_sender, tpu_vote_sender, gossip_vote_sender) })?; Ok((handle, base_event_time, base_simulation_time)) } From d66c5db93375a746618507ccbfdd193a1efaf527 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Thu, 29 Aug 2024 22:49:37 +0900 Subject: [PATCH 24/52] Calculate required_duration in advance --- core/src/banking_simulation.rs | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index d69b2b7618c7e1..5870d15e8425d2 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -365,7 +365,7 @@ impl<'a> SenderLoopLogger<'a> { fn on_sending_batches( &mut self, - &simulation_duration_since_base: &Duration, + &simulation_duration: &Duration, label: ChannelLabel, batch_count: usize, tx_count: usize, @@ -386,7 +386,7 @@ impl<'a> SenderLoopLogger<'a> { *total_batch_count += batch_count; *total_tx_count += tx_count; - let log_interval = simulation_duration_since_base - self.last_log_duration; + let log_interval = simulation_duration - self.last_log_duration; if log_interval > Duration::from_millis(100) { let current_tx_count = self.non_vote_tx_count + self.tpu_vote_tx_count + self.gossip_vote_tx_count; @@ -409,7 +409,7 @@ impl<'a> SenderLoopLogger<'a> { self.tpu_vote_sender.len(), self.gossip_vote_sender.len(), ); - self.last_log_duration = simulation_duration_since_base; + self.last_log_duration = simulation_duration; self.last_tx_count = current_tx_count; ( self.last_non_vote_count, @@ -671,10 +671,13 @@ impl BankingSimulator { // the simulation loop to avoid jitter due to interleaved deallocs of BTreeMap. let mut timed_batches_to_send = timed_batches_to_send .into_iter() + .map(|(event_time, batches)| + (event_time.duration_since(base_event_time).unwrap(), batches) + ) .zip_eq(batch_and_tx_counts.into_iter()) .collect::>(); info!( - "simulating banking trace events: {} out of {}, starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", + "simulating events: {} (out of {}), starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", timed_batches_to_send.len(), total_batch_count, first_simulated_slot, @@ -682,21 +685,18 @@ impl BankingSimulator { parent_slot, WARMUP_DURATION, ); - let mut simulation_duration_since_base = Duration::default(); + let mut simulation_duration = Duration::default(); let mut logger = SenderLoopLogger::new( &non_vote_sender, &tpu_vote_sender, &gossip_vote_sender, ); - for ((event_time, (label, batches_with_stats)), (batch_count, tx_count)) in + for ((required_duration, (label, batches_with_stats)), (batch_count, tx_count)) in timed_batches_to_send.drain(..) { - let required_duration_since_base = - event_time.duration_since(base_event_time).unwrap(); - // Busy loop for most accurate sending timings - while simulation_duration_since_base < required_duration_since_base { + while simulation_duration < required_duration { let current_simulation_time = SystemTime::now(); - simulation_duration_since_base = current_simulation_time + simulation_duration = current_simulation_time .duration_since(base_simulation_time) .unwrap(); } @@ -709,7 +709,7 @@ impl BankingSimulator { }; sender.send(batches_with_stats).unwrap(); - logger.on_sending_batches(&simulation_duration_since_base, label, batch_count, tx_count); + logger.on_sending_batches(&simulation_duration, label, batch_count, tx_count); if exit.load(Ordering::Relaxed) { break; } From e357af8e538cefb3c8723a2d3029ef4364b5b389 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Thu, 29 Aug 2024 22:58:08 +0900 Subject: [PATCH 25/52] Use correct format specifier instead of cast --- core/src/banking_simulation.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 5870d15e8425d2..0fe4888979ea82 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -399,11 +399,11 @@ impl<'a> SenderLoopLogger<'a> { let gossip_vote_tps = (self.gossip_vote_tx_count - self.last_gossip_vote_tx_count) as f64 / duration; info!( - "senders(non-,tpu-,gossip-vote): tps: {} (={}+{}+{}) over {:?} not-recved: ({}+{}+{})", - tps as u64, - non_vote_tps as u64, - tpu_vote_tps as u64, - gossip_vote_tps as u64, + "senders(non-,tpu-,gossip-vote): tps: {:.0} (={:.0}+{:.0}+{:.0}) over {:?} not-recved: ({}+{}+{})", + tps, + non_vote_tps, + tpu_vote_tps, + gossip_vote_tps, log_interval, self.non_vote_sender.len(), self.tpu_vote_sender.len(), From 4228e2e5bc1e5a987a6490ecb1168a926f357a30 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Thu, 29 Aug 2024 23:01:07 +0900 Subject: [PATCH 26/52] Align formatting by using ::* --- core/src/banking_simulation.rs | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 0fe4888979ea82..345020b18f63ab 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -375,13 +375,12 @@ impl<'a> SenderLoopLogger<'a> { label, batch_count, tx_count ); + use ChannelLabel::*; let (total_batch_count, total_tx_count) = match label { - ChannelLabel::NonVote => (&mut self.non_vote_count, &mut self.non_vote_tx_count), - ChannelLabel::TpuVote => (&mut self.tpu_vote_count, &mut self.tpu_vote_tx_count), - ChannelLabel::GossipVote => { - (&mut self.gossip_vote_count, &mut self.gossip_vote_tx_count) - } - ChannelLabel::Dummy => unreachable!(), + NonVote => (&mut self.non_vote_count, &mut self.non_vote_tx_count), + TpuVote => (&mut self.tpu_vote_count, &mut self.tpu_vote_tx_count), + GossipVote => (&mut self.gossip_vote_count, &mut self.gossip_vote_tx_count), + Dummy => unreachable!(), }; *total_batch_count += batch_count; *total_tx_count += tx_count; From 78ac1d288a70b8faea85cbe223e1e438f70a0ef3 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Thu, 29 Aug 2024 23:13:25 +0900 Subject: [PATCH 27/52] Make envs overridable --- ci/run-sanity.sh | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ci/run-sanity.sh b/ci/run-sanity.sh index 1778aec67a3d66..177774da62859c 100755 --- a/ci/run-sanity.sh +++ b/ci/run-sanity.sh @@ -17,8 +17,8 @@ fi rm -rf config/run/init-completed config/ledger config/snapshot-ledger -SOLANA_RUN_SH_VALIDATOR_ARGS="--full-snapshot-interval-slots 200" \ - SOLANA_VALIDATOR_EXIT_TIMEOUT=30 \ +SOLANA_RUN_SH_VALIDATOR_ARGS="${SOLANA_RUN_SH_VALIDATOR_ARGS} --full-snapshot-interval-slots 200" \ + SOLANA_VALIDATOR_EXIT_TIMEOUT="${SOLANA_VALIDATOR_EXIT_TIMEOUT:-30}" \ timeout 120 ./scripts/run.sh & pid=$! From 33398a3dcb60d3c992ff9d058d30e2bb3d5cceaa Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Thu, 29 Aug 2024 23:47:49 +0900 Subject: [PATCH 28/52] Add comment for SOLANA_VALIDATOR_EXIT_TIMEOUT --- ci/run-sanity.sh | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/ci/run-sanity.sh b/ci/run-sanity.sh index 177774da62859c..31cb7a449a8d51 100755 --- a/ci/run-sanity.sh +++ b/ci/run-sanity.sh @@ -17,8 +17,12 @@ fi rm -rf config/run/init-completed config/ledger config/snapshot-ledger +# Sanity-check that agave-validator can successfully terminate itself without relying on +# process::exit() by extending the timeout... +# Also the banking_tracer thread needs some extra time to flush due to +# unsynchronized and buffered IO. SOLANA_RUN_SH_VALIDATOR_ARGS="${SOLANA_RUN_SH_VALIDATOR_ARGS} --full-snapshot-interval-slots 200" \ - SOLANA_VALIDATOR_EXIT_TIMEOUT="${SOLANA_VALIDATOR_EXIT_TIMEOUT:-30}" \ + SOLANA_VALIDATOR_EXIT_TIMEOUT="${SOLANA_VALIDATOR_EXIT_TIMEOUT:-3600}" \ timeout 120 ./scripts/run.sh & pid=$! From 7026f1bb281dda8203673a669124f1b251175a3f Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Fri, 30 Aug 2024 00:15:30 +0900 Subject: [PATCH 29/52] Clarify comment a bit --- core/src/banking_simulation.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 345020b18f63ab..38c46704cfa140 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -824,8 +824,8 @@ impl BankingSimulator { sleep(Duration::from_millis(100)); exit.store(true, Ordering::Relaxed); - // The order is important. consuming sender_thread by joining will terminate banking_stage, - // in turn retracer thread will termianl + // The order is important. consuming sender_thread by joining will drop some channels. That + // triggers termination of banking_stage, in turn retracer thread be terminated. sender_thread.join().unwrap(); banking_stage.join().unwrap(); poh_service.join().unwrap(); From 29db91529c0606e68f30cfcb85373e3dc5455f1e Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Fri, 30 Aug 2024 00:20:02 +0900 Subject: [PATCH 30/52] Fix typoss --- core/src/banking_simulation.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 38c46704cfa140..f5146d411fe015 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -824,8 +824,8 @@ impl BankingSimulator { sleep(Duration::from_millis(100)); exit.store(true, Ordering::Relaxed); - // The order is important. consuming sender_thread by joining will drop some channels. That - // triggers termination of banking_stage, in turn retracer thread be terminated. + // The order is important. Consuming sender_thread by joining will drop some channels. That + // triggers termination of banking_stage, in turn retracer thread will be terminated. sender_thread.join().unwrap(); banking_stage.join().unwrap(); poh_service.join().unwrap(); From 9a3efd5eb8459f72c0f21b7d03dcd7642aa62d36 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Fri, 30 Aug 2024 11:10:10 +0900 Subject: [PATCH 31/52] Fix typos Co-authored-by: Andrew Fitzgerald --- core/src/banking_simulation.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index f5146d411fe015..b7a12c533cde45 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -189,7 +189,7 @@ impl BankingTraceEvents { TracedEvent::PacketBatch(label, batch) => { // Deserialized PacketBatches will mostly be ordered by event_time, but this // isn't guaranteed when traced, because time are measured by multiple _sender_ - // threads withtout synchnotization among them to avoid overhead. + // threads withtout synchronization among them to avoid overhead. // // Also, there's a possiblity of system clock change. In this case, // the simulation is meaningless, though... @@ -222,7 +222,7 @@ impl BankingTraceEvents { } struct DummyClusterInfo { - // Artifically wrap Pubkey with RwLock to induce lock contention if any to minic the real + // Artifically wrap Pubkey with RwLock to induce lock contention if any to mimic the real // ClusterInfo id: RwLock, } From ca135343aac47a71259bcfd75134b3d81ee4f253 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Fri, 30 Aug 2024 13:19:13 +0900 Subject: [PATCH 32/52] Use correct variant name: DeserializeError --- core/src/banking_simulation.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index b7a12c533cde45..b769717265de40 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -123,7 +123,7 @@ pub enum SimulateError { IoError(#[from] io::Error), #[error("Deserialization Error: {0}")] - SerializeError(#[from] bincode::Error), + DeserializeError(#[from] bincode::Error), } // Defined to be enough to cover the holding phase prior to leader slots with some idling (+5 secs) From 715d3c57dfd0c517313f2541e67e0afbe781277e Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Fri, 30 Aug 2024 13:20:23 +0900 Subject: [PATCH 33/52] Remove SimulatorLoopLogger::new() --- core/src/banking_simulation.rs | 18 ++---------------- 1 file changed, 2 insertions(+), 16 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index b769717265de40..b93d6d47acd1c1 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -248,20 +248,6 @@ struct SimulatorLoopLogger { } impl SimulatorLoopLogger { - fn new( - simulated_leader: Pubkey, - base_event_time: SystemTime, - base_simulation_time: SystemTime, - freeze_time_by_slot: FreezeTimeBySlot, - ) -> Self { - Self { - simulated_leader, - base_event_time, - base_simulation_time, - freeze_time_by_slot, - } - } - fn bank_costs(bank: &Bank) -> (u64, u64) { bank.read_cost_tracker() .map(|t| (t.block_cost(), t.vote_cost())) @@ -738,12 +724,12 @@ impl BankingSimulator { retransmit_slots_sender: &Sender, retracer: &BankingTracer, ) { - let logger = SimulatorLoopLogger::new( + let logger = SimulatorLoopLogger { simulated_leader, base_event_time, base_simulation_time, freeze_time_by_slot, - ); + }; loop { if poh_recorder.read().unwrap().bank().is_none() { From 86b905d97fbf777e294a6b33931cd3b9756d2e87 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Fri, 30 Aug 2024 13:27:52 +0900 Subject: [PATCH 34/52] Fix typos more --- core/src/banking_simulation.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index b93d6d47acd1c1..6ccdbfdce9900f 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -169,7 +169,7 @@ impl BankingTraceEvents { let old_len = events.len(); let _ = Self::read_event_file(&mut events, event_file_path).inspect_err(|error| { error!( - "Reading {event_file_path:?} failed after {} events: {:?} due to file corruption or unclearn validator shutdown", + "Reading {event_file_path:?} failed after {} events: {:?} due to file corruption or unclean validator shutdown", events.len() - old_len, error ); @@ -189,9 +189,9 @@ impl BankingTraceEvents { TracedEvent::PacketBatch(label, batch) => { // Deserialized PacketBatches will mostly be ordered by event_time, but this // isn't guaranteed when traced, because time are measured by multiple _sender_ - // threads withtout synchronization among them to avoid overhead. + // threads without synchronization among them to avoid overhead. // - // Also, there's a possiblity of system clock change. In this case, + // Also, there's a possibility of system clock change. In this case, // the simulation is meaningless, though... // // Somewhat naively assume that event_times (nanosecond resolution) won't @@ -222,7 +222,7 @@ impl BankingTraceEvents { } struct DummyClusterInfo { - // Artifically wrap Pubkey with RwLock to induce lock contention if any to mimic the real + // Artificially wrap Pubkey with RwLock to induce lock contention if any to mimic the real // ClusterInfo id: RwLock, } @@ -564,7 +564,7 @@ impl BankingSimulator { // Create a completely-dummy ClusterInfo for the broadcast stage. // We only need it to write shreds into the blockstore and it seems given ClusterInfo is - // irrevant for the neccesary minimum work for this simulation. + // irrelevant for the neccesary minimum work for this simulation. let random_keypair = Arc::new(Keypair::new()); let cluster_info = Arc::new(ClusterInfo::new( Node::new_localhost_with_pubkey(&random_keypair.pubkey()).info, From ed7b9c8a000b08a6b4b9cb2e62e6dc04a1b6153d Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Fri, 30 Aug 2024 13:27:53 +0900 Subject: [PATCH 35/52] Add explicit _batch in field names --- core/src/banking_simulation.rs | 37 ++++++++++++++++++---------------- 1 file changed, 20 insertions(+), 17 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 6ccdbfdce9900f..6a5375bd8f0fe0 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -314,14 +314,14 @@ struct SenderLoopLogger<'a> { gossip_vote_sender: &'a TracedSender, last_log_duration: Duration, last_tx_count: usize, - last_non_vote_count: usize, + last_non_vote_batch_count: usize, last_tpu_vote_tx_count: usize, last_gossip_vote_tx_count: usize, - non_vote_count: usize, + non_vote_batch_count: usize, non_vote_tx_count: usize, - tpu_vote_count: usize, + tpu_vote_batch_count: usize, tpu_vote_tx_count: usize, - gossip_vote_count: usize, + gossip_vote_batch_count: usize, gossip_vote_tx_count: usize, } @@ -337,14 +337,14 @@ impl<'a> SenderLoopLogger<'a> { gossip_vote_sender, last_log_duration: Duration::default(), last_tx_count: 0, - last_non_vote_count: 0, + last_non_vote_batch_count: 0, last_tpu_vote_tx_count: 0, last_gossip_vote_tx_count: 0, - non_vote_count: 0, + non_vote_batch_count: 0, non_vote_tx_count: 0, - tpu_vote_count: 0, + tpu_vote_batch_count: 0, tpu_vote_tx_count: 0, - gossip_vote_count: 0, + gossip_vote_batch_count: 0, gossip_vote_tx_count: 0, } } @@ -363,9 +363,12 @@ impl<'a> SenderLoopLogger<'a> { use ChannelLabel::*; let (total_batch_count, total_tx_count) = match label { - NonVote => (&mut self.non_vote_count, &mut self.non_vote_tx_count), - TpuVote => (&mut self.tpu_vote_count, &mut self.tpu_vote_tx_count), - GossipVote => (&mut self.gossip_vote_count, &mut self.gossip_vote_tx_count), + NonVote => (&mut self.non_vote_batch_count, &mut self.non_vote_tx_count), + TpuVote => (&mut self.tpu_vote_batch_count, &mut self.tpu_vote_tx_count), + GossipVote => ( + &mut self.gossip_vote_batch_count, + &mut self.gossip_vote_tx_count, + ), Dummy => unreachable!(), }; *total_batch_count += batch_count; @@ -378,7 +381,7 @@ impl<'a> SenderLoopLogger<'a> { let duration = log_interval.as_secs_f64(); let tps = (current_tx_count - self.last_tx_count) as f64 / duration; let non_vote_tps = - (self.non_vote_tx_count - self.last_non_vote_count) as f64 / duration; + (self.non_vote_tx_count - self.last_non_vote_batch_count) as f64 / duration; let tpu_vote_tps = (self.tpu_vote_tx_count - self.last_tpu_vote_tx_count) as f64 / duration; let gossip_vote_tps = @@ -397,13 +400,13 @@ impl<'a> SenderLoopLogger<'a> { self.last_log_duration = simulation_duration; self.last_tx_count = current_tx_count; ( - self.last_non_vote_count, + self.last_non_vote_batch_count, self.last_tpu_vote_tx_count, self.last_gossip_vote_tx_count, ) = ( self.non_vote_tx_count, self.tpu_vote_tx_count, - self.gossip_vote_count, + self.gossip_vote_batch_count, ); } } @@ -411,11 +414,11 @@ impl<'a> SenderLoopLogger<'a> { fn on_terminating(self) { info!( "terminating to send...: non_vote: {} ({}), tpu_vote: {} ({}), gossip_vote: {} ({})", - self.non_vote_count, + self.non_vote_batch_count, self.non_vote_tx_count, - self.tpu_vote_count, + self.tpu_vote_batch_count, self.tpu_vote_tx_count, - self.gossip_vote_count, + self.gossip_vote_batch_count, self.gossip_vote_tx_count, ); } From e3f6bf2d9ad5410c41410f4d39d7e6373b03de77 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Fri, 30 Aug 2024 13:42:08 +0900 Subject: [PATCH 36/52] Avoid unneeded events: Vec<_> buffering --- core/src/banking_simulation.rs | 81 +++++++++++++++++----------------- 1 file changed, 40 insertions(+), 41 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 6a5375bd8f0fe0..22ff75781271a5 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -137,6 +137,7 @@ type FreezeTimeBySlot = BTreeMap; type EventSenderThread = JoinHandle<(TracedSender, TracedSender, TracedSender)>; +#[derive(Default)] pub struct BankingTraceEvents { packet_batches_by_time: PacketBatchesByTime, freeze_time_by_slot: FreezeTimeBySlot, @@ -145,13 +146,13 @@ pub struct BankingTraceEvents { impl BankingTraceEvents { fn read_event_file( - events: &mut Vec, event_file_path: &PathBuf, + mut callback: impl FnMut(TimedTracedEvent), ) -> Result<(), SimulateError> { let mut reader = BufReader::new(File::open(event_file_path)?); loop { - events.push(deserialize_from(&mut reader)?); + callback(deserialize_from(&mut reader)?); if reader.fill_buf()?.is_empty() { // EOF is reached at a correct deserialization boundary. @@ -164,56 +165,54 @@ impl BankingTraceEvents { } pub fn load(event_file_paths: &[PathBuf]) -> Result { - let mut events = vec![]; + let mut event_count = 0; + let mut events = Self::default(); for event_file_path in event_file_paths { - let old_len = events.len(); - let _ = Self::read_event_file(&mut events, event_file_path).inspect_err(|error| { - error!( + let old_event_count = event_count; + // Silence errors here as this can happen under normal operation... + let _ = Self::read_event_file( + event_file_path, + |event| { event_count += 1; events.load_event(event); } + ) + .inspect_err(|error| warn!( "Reading {event_file_path:?} failed after {} events: {:?} due to file corruption or unclean validator shutdown", - events.len() - old_len, + event_count - old_event_count, error - ); - }); + )); info!( "Read {} events from {:?}", - events.len() - old_len, + event_count - old_event_count, event_file_path ); } - let mut packet_batches_by_time = BTreeMap::new(); - let mut freeze_time_by_slot = BTreeMap::new(); - let mut hash_overrides = HashOverrides::default(); - for TimedTracedEvent(event_time, event) in events { - match event { - TracedEvent::PacketBatch(label, batch) => { - // Deserialized PacketBatches will mostly be ordered by event_time, but this - // isn't guaranteed when traced, because time are measured by multiple _sender_ - // threads without synchronization among them to avoid overhead. - // - // Also, there's a possibility of system clock change. In this case, - // the simulation is meaningless, though... - // - // Somewhat naively assume that event_times (nanosecond resolution) won't - // collide. - let is_new = packet_batches_by_time - .insert(event_time, (label, batch)) - .is_none(); - assert!(is_new); - } - TracedEvent::BlockAndBankHash(slot, blockhash, bank_hash) => { - let is_new = freeze_time_by_slot.insert(slot, event_time).is_none(); - hash_overrides.add_override(slot, blockhash, bank_hash); - assert!(is_new); - } + Ok(events) + } + + fn load_event(&mut self, TimedTracedEvent(event_time, event): TimedTracedEvent) { + match event { + TracedEvent::PacketBatch(label, batch) => { + // Deserialized PacketBatches will mostly be ordered by event_time, but this + // isn't guaranteed when traced, because time are measured by multiple _sender_ + // threads without synchronization among them to avoid overhead. + // + // Also, there's a possibility of system clock change. In this case, + // the simulation is meaningless, though... + // + // Somewhat naively assume that event_times (nanosecond resolution) won't + // collide. + let is_new = self + .packet_batches_by_time + .insert(event_time, (label, batch)) + .is_none(); + assert!(is_new); + } + TracedEvent::BlockAndBankHash(slot, blockhash, bank_hash) => { + let is_new = self.freeze_time_by_slot.insert(slot, event_time).is_none(); + self.hash_overrides.add_override(slot, blockhash, bank_hash); + assert!(is_new); } } - - Ok(Self { - packet_batches_by_time, - freeze_time_by_slot, - hash_overrides, - }) } pub fn hash_overrides(&self) -> &HashOverrides { From 666e1b0bb2ac79dd45ffa3cb91b4447f5dbf6515 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Fri, 30 Aug 2024 14:41:46 +0900 Subject: [PATCH 37/52] Manually adjust logging code styles --- core/src/banking_simulation.rs | 26 ++++++++------------------ 1 file changed, 8 insertions(+), 18 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 22ff75781271a5..28655cc6e17c28 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -175,14 +175,13 @@ impl BankingTraceEvents { |event| { event_count += 1; events.load_event(event); } ) .inspect_err(|error| warn!( - "Reading {event_file_path:?} failed after {} events: {:?} due to file corruption or unclean validator shutdown", - event_count - old_event_count, - error + "Reading {:?} failed after {} events: {:?} due to file corruption or unclean validator shutdown", + event_file_path, event_count - old_event_count, error, )); info!( "Read {} events from {:?}", event_count - old_event_count, - event_file_path + event_file_path, ); } @@ -387,14 +386,8 @@ impl<'a> SenderLoopLogger<'a> { (self.gossip_vote_tx_count - self.last_gossip_vote_tx_count) as f64 / duration; info!( "senders(non-,tpu-,gossip-vote): tps: {:.0} (={:.0}+{:.0}+{:.0}) over {:?} not-recved: ({}+{}+{})", - tps, - non_vote_tps, - tpu_vote_tps, - gossip_vote_tps, - log_interval, - self.non_vote_sender.len(), - self.tpu_vote_sender.len(), - self.gossip_vote_sender.len(), + tps, non_vote_tps, tpu_vote_tps, gossip_vote_tps, log_interval, + self.non_vote_sender.len(), self.tpu_vote_sender.len(), self.gossip_vote_sender.len(), ); self.last_log_duration = simulation_duration; self.last_tx_count = current_tx_count; @@ -483,7 +476,7 @@ impl BankingSimulator { .unwrap(); info!( "Simulated leader and slot: {}, {}", - simulated_leader, first_simulated_slot + simulated_leader, first_simulated_slot, ); let exit = Arc::new(AtomicBool::default()); @@ -665,12 +658,9 @@ impl BankingSimulator { .collect::>(); info!( "simulating events: {} (out of {}), starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", - timed_batches_to_send.len(), - total_batch_count, - first_simulated_slot, + timed_batches_to_send.len(), total_batch_count, first_simulated_slot, SenderLoopLogger::format_as_timestamp(raw_base_event_time), - parent_slot, - WARMUP_DURATION, + parent_slot, WARMUP_DURATION, ); let mut simulation_duration = Duration::default(); let mut logger = SenderLoopLogger::new( From 1a1b620c8e29f0c855f1fbfd118e09a52f3a2632 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Fri, 30 Aug 2024 15:45:36 +0900 Subject: [PATCH 38/52] Align name: spawn_sender_loop/enter_simulator_loop --- core/src/banking_simulation.rs | 27 +++++++++++++-------------- 1 file changed, 13 insertions(+), 14 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 28655cc6e17c28..70d96c488a072a 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -619,7 +619,7 @@ impl BankingSimulator { ) } - fn start_event_sender_thread( + fn spawn_sender_loop( parent_slot: Slot, first_simulated_slot: Slot, freeze_time_by_slot: &FreezeTimeBySlot, @@ -700,7 +700,7 @@ impl BankingSimulator { } #[allow(clippy::too_many_arguments)] - fn enter_simulation_loop( + fn enter_simulator_loop( parent_slot: Slot, first_simulated_slot: Slot, freeze_time_by_slot: FreezeTimeBySlot, @@ -849,22 +849,21 @@ impl BankingSimulator { block_production_method, ); - let (sender_thread, base_event_time, base_simulation_time) = - Self::start_event_sender_thread( - parent_slot, - self.first_simulated_slot, - &self.banking_trace_events.freeze_time_by_slot, - self.banking_trace_events.packet_batches_by_time, - non_vote_sender, - tpu_vote_sender, - gossip_vote_sender, - exit.clone(), - )?; + let (sender_thread, base_event_time, base_simulation_time) = Self::spawn_sender_loop( + parent_slot, + self.first_simulated_slot, + &self.banking_trace_events.freeze_time_by_slot, + self.banking_trace_events.packet_batches_by_time, + non_vote_sender, + tpu_vote_sender, + gossip_vote_sender, + exit.clone(), + )?; sleep(WARMUP_DURATION); info!("warmup done!"); - Self::enter_simulation_loop( + Self::enter_simulator_loop( parent_slot, self.first_simulated_slot, self.banking_trace_events.freeze_time_by_slot, From 3a6912e64491a2b7fcaab27c67add995ab7708bb Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Fri, 30 Aug 2024 16:04:44 +0900 Subject: [PATCH 39/52] Refactor by introducing {Sender,Simulator}Loop --- core/src/banking_simulation.rs | 566 ++++++++++++++++----------------- 1 file changed, 278 insertions(+), 288 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 70d96c488a072a..6a2235fac55a12 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -306,6 +306,233 @@ impl SimulatorLoopLogger { } } +struct SenderLoop { + parent_slot: Slot, + first_simulated_slot: Slot, + packet_batches_by_time: PacketBatchesByTime, + non_vote_sender: TracedSender, + tpu_vote_sender: TracedSender, + gossip_vote_sender: TracedSender, + exit: Arc, + raw_base_event_time: SystemTime, + base_event_time: SystemTime, + base_simulation_time: SystemTime, +} + +impl SenderLoop { + fn spawn(self) -> Result { + let handle = thread::Builder::new() + .name("solSimSender".into()) + .spawn(move || self.start())?; + Ok(handle) + } + + fn start(mut self) -> (TracedSender, TracedSender, TracedSender) { + info!("start sending!..."); + let total_batch_count = self.packet_batches_by_time.len(); + let timed_batches_to_send = self.packet_batches_by_time.split_off(&self.base_event_time); + let batch_and_tx_counts = timed_batches_to_send + .values() + .map(|(_label, batches_with_stats)| { + let batches = &batches_with_stats.0; + ( + batches.len(), + batches.iter().map(|batch| batch.len()).sum::(), + ) + }) + .collect::>(); + // Convert to a large plain old Vec and drain on it, finally dropping it outside + // the simulation loop to avoid jitter due to interleaved deallocs of BTreeMap. + let mut timed_batches_to_send = timed_batches_to_send + .into_iter() + .map(|(event_time, batches)| { + ( + event_time.duration_since(self.base_event_time).unwrap(), + batches, + ) + }) + .zip_eq(batch_and_tx_counts) + .collect::>(); + info!( + "simulating events: {} (out of {}), starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", + timed_batches_to_send.len(), total_batch_count, self.first_simulated_slot, + SenderLoopLogger::format_as_timestamp(self.raw_base_event_time), + self.parent_slot, WARMUP_DURATION, + ); + let mut simulation_duration = Duration::default(); + let mut logger = SenderLoopLogger::new( + &self.non_vote_sender, + &self.tpu_vote_sender, + &self.gossip_vote_sender, + ); + for ((required_duration, (label, batches_with_stats)), (batch_count, tx_count)) in + timed_batches_to_send.drain(..) + { + // Busy loop for most accurate sending timings + while simulation_duration < required_duration { + let current_simulation_time = SystemTime::now(); + simulation_duration = current_simulation_time + .duration_since(self.base_simulation_time) + .unwrap(); + } + + let sender = match label { + ChannelLabel::NonVote => &self.non_vote_sender, + ChannelLabel::TpuVote => &self.tpu_vote_sender, + ChannelLabel::GossipVote => &self.gossip_vote_sender, + ChannelLabel::Dummy => unreachable!(), + }; + sender.send(batches_with_stats).unwrap(); + + logger.on_sending_batches(&simulation_duration, label, batch_count, tx_count); + if self.exit.load(Ordering::Relaxed) { + break; + } + } + logger.on_terminating(); + drop(timed_batches_to_send); + // hold these senders in join_handle to control banking stage termination! + ( + self.non_vote_sender, + self.tpu_vote_sender, + self.gossip_vote_sender, + ) + } +} + +struct SimulatorLoop { + bank: BankWithScheduler, + parent_slot: Slot, + first_simulated_slot: Slot, + freeze_time_by_slot: FreezeTimeBySlot, + base_event_time: SystemTime, + base_simulation_time: SystemTime, + poh_recorder: Arc>, + simulated_leader: Pubkey, + bank_forks: Arc>, + blockstore: Arc, + leader_schedule_cache: Arc, + retransmit_slots_sender: Sender, + retracer: Arc, +} + +impl SimulatorLoop { + fn enter(self, sender_thread: EventSenderThread) -> (EventSenderThread, Sender) { + sleep(WARMUP_DURATION); + info!("warmup done!"); + self.start(sender_thread) + } + + fn start(self, sender_thread: EventSenderThread) -> (EventSenderThread, Sender) { + let logger = SimulatorLoopLogger { + simulated_leader: self.simulated_leader, + base_event_time: self.base_event_time, + base_simulation_time: self.base_simulation_time, + freeze_time_by_slot: self.freeze_time_by_slot, + }; + let mut bank = self.bank; + + loop { + if self.poh_recorder.read().unwrap().bank().is_none() { + let next_leader_slot = self.leader_schedule_cache.next_leader_slot( + &self.simulated_leader, + bank.slot(), + &bank, + Some(&self.blockstore), + GRACE_TICKS_FACTOR * MAX_GRACE_SLOTS, + ); + debug!("{next_leader_slot:?}"); + self.poh_recorder + .write() + .unwrap() + .reset(bank.clone_without_scheduler(), next_leader_slot); + info!("Bank::new_from_parent()!"); + + logger.log_jitter(&bank); + bank.freeze(); + let new_slot = if bank.slot() == self.parent_slot { + info!("initial leader block!"); + self.first_simulated_slot + } else { + info!("next leader block!"); + bank.slot() + 1 + }; + info!("new leader bank slot: {new_slot}"); + let new_leader = self + .leader_schedule_cache + .slot_leader_at(new_slot, None) + .unwrap(); + if new_leader != self.simulated_leader { + logger.on_new_leader(&bank, new_slot, new_leader); + break; + } else if sender_thread.is_finished() { + warn!("sender thread existed maybe due to completion of sending traced events"); + break; + } + let new_bank = Bank::new_from_parent( + bank.clone_without_scheduler(), + &self.simulated_leader, + new_slot, + ); + // make sure parent is frozen for finalized hashes via the above + // new()-ing of its child bank + self.retracer + .hash_event(bank.slot(), &bank.last_blockhash(), &bank.hash()); + if *bank.collector_id() == self.simulated_leader { + logger.log_frozen_bank_cost(&bank); + } + self.retransmit_slots_sender.send(bank.slot()).unwrap(); + self.bank_forks.write().unwrap().insert(new_bank); + bank = self + .bank_forks + .read() + .unwrap() + .working_bank_with_scheduler() + .clone_with_scheduler(); + self.poh_recorder + .write() + .unwrap() + .set_bank(bank.clone_with_scheduler(), false); + } else { + logger.log_ongoing_bank_cost(&bank); + } + + sleep(Duration::from_millis(10)); + } + + (sender_thread, self.retransmit_slots_sender) + } +} + +struct SimulatorThreads { + poh_service: PohService, + banking_stage: BankingStage, + broadcast_stage: BroadcastStage, + retracer_thread: TracerThread, + exit: Arc, +} + +impl SimulatorThreads { + fn finish(self, sender_thread: EventSenderThread, retransmit_slots_sender: Sender) { + info!("Sleeping a bit before signaling exit"); + sleep(Duration::from_millis(100)); + self.exit.store(true, Ordering::Relaxed); + + // The order is important. Consuming sender_thread by joining will drop some channels. That + // triggers termination of banking_stage, in turn retracer thread will be terminated. + sender_thread.join().unwrap(); + self.banking_stage.join().unwrap(); + self.poh_service.join().unwrap(); + if let Some(retracer_thread) = self.retracer_thread { + retracer_thread.join().unwrap().unwrap(); + } + + info!("Joining broadcast stage..."); + drop(retransmit_slots_sender); + self.broadcast_stage.join().unwrap(); + } +} + struct SenderLoopLogger<'a> { non_vote_sender: &'a TracedSender, tpu_vote_sender: &'a TracedSender, @@ -438,30 +665,16 @@ impl BankingSimulator { .copied() } - #[allow(clippy::type_complexity)] fn prepare_simulation( - parent_slot: Slot, - first_simulated_slot: Slot, + self, genesis_config: GenesisConfig, - bank_forks: &Arc>, - blockstore: &Arc, + bank_forks: Arc>, + blockstore: Arc, block_production_method: BlockProductionMethod, - ) -> ( - Pubkey, - TracedSender, - TracedSender, - TracedSender, - BankWithScheduler, - PohService, - Arc>, - BankingStage, - BroadcastStage, - Arc, - Sender, - Arc, - TracerThread, - Arc, - ) { + ) -> (SenderLoop, SimulatorLoop, SimulatorThreads) { + let parent_slot = self.parent_slot().unwrap(); + let packet_batches_by_time = self.banking_trace_events.packet_batches_by_time; + let freeze_time_by_slot = self.banking_trace_events.freeze_time_by_slot; let bank = bank_forks .read() .unwrap() @@ -472,24 +685,24 @@ impl BankingSimulator { assert_eq!(parent_slot, bank.slot()); let simulated_leader = leader_schedule_cache - .slot_leader_at(first_simulated_slot, None) + .slot_leader_at(self.first_simulated_slot, None) .unwrap(); info!( "Simulated leader and slot: {}, {}", - simulated_leader, first_simulated_slot, + simulated_leader, self.first_simulated_slot, ); let exit = Arc::new(AtomicBool::default()); if let Some(end_slot) = blockstore - .slot_meta_iterator(first_simulated_slot) + .slot_meta_iterator(self.first_simulated_slot) .unwrap() .map(|(s, _)| s) .last() { - info!("purging slots {}, {}", first_simulated_slot, end_slot); - blockstore.purge_from_next_slots(first_simulated_slot, end_slot); - blockstore.purge_slots(first_simulated_slot, end_slot, PurgeType::Exact); + info!("purging slots {}, {}", self.first_simulated_slot, end_slot); + blockstore.purge_from_next_slots(self.first_simulated_slot, end_slot); + blockstore.purge_slots(self.first_simulated_slot, end_slot, PurgeType::Exact); info!("done: purging"); } else { info!("skipping purging..."); @@ -601,34 +814,6 @@ impl BankingSimulator { false, ); - ( - simulated_leader, - non_vote_sender, - tpu_vote_sender, - gossip_vote_sender, - bank, - poh_service, - poh_recorder, - banking_stage, - broadcast_stage, - leader_schedule_cache, - retransmit_slots_sender, - retracer, - retracer_thread, - exit, - ) - } - - fn spawn_sender_loop( - parent_slot: Slot, - first_simulated_slot: Slot, - freeze_time_by_slot: &FreezeTimeBySlot, - mut packet_batches_by_time: PacketBatchesByTime, - non_vote_sender: TracedSender, - tpu_vote_sender: TracedSender, - gossip_vote_sender: TracedSender, - exit: Arc, - ) -> Result<(EventSenderThread, SystemTime, SystemTime), SimulateError> { let (&_slot, &raw_base_event_time) = freeze_time_by_slot .range(parent_slot..) .next() @@ -636,184 +821,44 @@ impl BankingSimulator { let base_event_time = raw_base_event_time - WARMUP_DURATION; let base_simulation_time = SystemTime::now(); - let handle = thread::Builder::new().name("solSimSender".into()).spawn(move || { - info!("start sending!..."); - let total_batch_count = packet_batches_by_time.len(); - let timed_batches_to_send = packet_batches_by_time.split_off(&base_event_time); - let batch_and_tx_counts = timed_batches_to_send.values().map(|(_label, batches_with_stats)| { - let batches = &batches_with_stats.0; - ( - batches.len(), - batches.iter().map(|batch| batch.len()).sum::(), - ) - }).collect::>(); - // Convert to a large plain old Vec and drain on it, finally dropping it outside - // the simulation loop to avoid jitter due to interleaved deallocs of BTreeMap. - let mut timed_batches_to_send = timed_batches_to_send - .into_iter() - .map(|(event_time, batches)| - (event_time.duration_since(base_event_time).unwrap(), batches) - ) - .zip_eq(batch_and_tx_counts.into_iter()) - .collect::>(); - info!( - "simulating events: {} (out of {}), starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", - timed_batches_to_send.len(), total_batch_count, first_simulated_slot, - SenderLoopLogger::format_as_timestamp(raw_base_event_time), - parent_slot, WARMUP_DURATION, - ); - let mut simulation_duration = Duration::default(); - let mut logger = SenderLoopLogger::new( - &non_vote_sender, - &tpu_vote_sender, - &gossip_vote_sender, - ); - for ((required_duration, (label, batches_with_stats)), (batch_count, tx_count)) in - timed_batches_to_send.drain(..) { - // Busy loop for most accurate sending timings - while simulation_duration < required_duration { - let current_simulation_time = SystemTime::now(); - simulation_duration = current_simulation_time - .duration_since(base_simulation_time) - .unwrap(); - } - - let sender = match label { - ChannelLabel::NonVote => &non_vote_sender, - ChannelLabel::TpuVote => &tpu_vote_sender, - ChannelLabel::GossipVote => &gossip_vote_sender, - ChannelLabel::Dummy => unreachable!(), - }; - sender.send(batches_with_stats).unwrap(); - - logger.on_sending_batches(&simulation_duration, label, batch_count, tx_count); - if exit.load(Ordering::Relaxed) { - break; - } - } - logger.on_terminating(); - drop(timed_batches_to_send); - // hold these senders in join_handle to control banking stage termination! - (non_vote_sender, tpu_vote_sender, gossip_vote_sender) - })?; - Ok((handle, base_event_time, base_simulation_time)) - } - - #[allow(clippy::too_many_arguments)] - fn enter_simulator_loop( - parent_slot: Slot, - first_simulated_slot: Slot, - freeze_time_by_slot: FreezeTimeBySlot, - base_event_time: SystemTime, - base_simulation_time: SystemTime, - sender_thread: &EventSenderThread, - mut bank: BankWithScheduler, - poh_recorder: Arc>, - simulated_leader: Pubkey, - bank_forks: &RwLock, - blockstore: &Blockstore, - leader_schedule_cache: &LeaderScheduleCache, - retransmit_slots_sender: &Sender, - retracer: &BankingTracer, - ) { - let logger = SimulatorLoopLogger { - simulated_leader, + let sender_loop = SenderLoop { + parent_slot, + first_simulated_slot: self.first_simulated_slot, + packet_batches_by_time, + non_vote_sender, + tpu_vote_sender, + gossip_vote_sender, + exit: exit.clone(), + raw_base_event_time, base_event_time, base_simulation_time, - freeze_time_by_slot, }; - loop { - if poh_recorder.read().unwrap().bank().is_none() { - let next_leader_slot = leader_schedule_cache.next_leader_slot( - &simulated_leader, - bank.slot(), - &bank, - Some(blockstore), - GRACE_TICKS_FACTOR * MAX_GRACE_SLOTS, - ); - debug!("{next_leader_slot:?}"); - poh_recorder - .write() - .unwrap() - .reset(bank.clone_without_scheduler(), next_leader_slot); - info!("Bank::new_from_parent()!"); - - logger.log_jitter(&bank); - bank.freeze(); - let new_slot = if bank.slot() == parent_slot { - info!("initial leader block!"); - first_simulated_slot - } else { - info!("next leader block!"); - bank.slot() + 1 - }; - info!("new leader bank slot: {new_slot}"); - let new_leader = leader_schedule_cache - .slot_leader_at(new_slot, None) - .unwrap(); - if new_leader != simulated_leader { - logger.on_new_leader(&bank, new_slot, new_leader); - break; - } else if sender_thread.is_finished() { - warn!("sender thread existed maybe due to completion of sending traced events"); - break; - } - let new_bank = Bank::new_from_parent( - bank.clone_without_scheduler(), - &simulated_leader, - new_slot, - ); - // make sure parent is frozen for finalized hashes via the above - // new()-ing of its child bank - retracer.hash_event(bank.slot(), &bank.last_blockhash(), &bank.hash()); - if *bank.collector_id() == simulated_leader { - logger.log_frozen_bank_cost(&bank); - } - retransmit_slots_sender.send(bank.slot()).unwrap(); - bank_forks.write().unwrap().insert(new_bank); - bank = bank_forks - .read() - .unwrap() - .working_bank_with_scheduler() - .clone_with_scheduler(); - poh_recorder - .write() - .unwrap() - .set_bank(bank.clone_with_scheduler(), false); - } else { - logger.log_ongoing_bank_cost(&bank); - } - - sleep(Duration::from_millis(10)); - } - } - - fn finish_simulation( - sender_thread: EventSenderThread, - poh_service: PohService, - banking_stage: BankingStage, - broadcast_stage: BroadcastStage, - retransmit_slots_sender: Sender, - retracer_thread: TracerThread, - exit: Arc, - ) { - info!("Sleeping a bit before signaling exit"); - sleep(Duration::from_millis(100)); - exit.store(true, Ordering::Relaxed); + let simulator_loop = SimulatorLoop { + bank, + parent_slot, + first_simulated_slot: self.first_simulated_slot, + freeze_time_by_slot, + base_event_time, + base_simulation_time, + poh_recorder, + simulated_leader, + bank_forks, + blockstore, + leader_schedule_cache, + retransmit_slots_sender, + retracer, + }; - // The order is important. Consuming sender_thread by joining will drop some channels. That - // triggers termination of banking_stage, in turn retracer thread will be terminated. - sender_thread.join().unwrap(); - banking_stage.join().unwrap(); - poh_service.join().unwrap(); - if let Some(retracer_thread) = retracer_thread { - retracer_thread.join().unwrap().unwrap(); - } + let simulator_threads = SimulatorThreads { + poh_service, + banking_stage, + broadcast_stage, + retracer_thread, + exit, + }; - info!("Joining broadcast stage..."); - drop(retransmit_slots_sender); - broadcast_stage.join().unwrap(); + (sender_loop, simulator_loop, simulator_threads) } pub fn start( @@ -823,72 +868,17 @@ impl BankingSimulator { blockstore: Arc, block_production_method: BlockProductionMethod, ) -> Result<(), SimulateError> { - let parent_slot = self.parent_slot().unwrap(); - - let ( - simulated_leader, - non_vote_sender, - tpu_vote_sender, - gossip_vote_sender, - bank, - poh_service, - poh_recorder, - banking_stage, - broadcast_stage, - leader_schedule_cache, - retransmit_slots_sender, - retracer, - retracer_thread, - exit, - ) = Self::prepare_simulation( - parent_slot, - self.first_simulated_slot, + let (sender_loop, simulator_loop, simulator_threads) = self.prepare_simulation( genesis_config, - &bank_forks, - &blockstore, + bank_forks, + blockstore, block_production_method, ); - let (sender_thread, base_event_time, base_simulation_time) = Self::spawn_sender_loop( - parent_slot, - self.first_simulated_slot, - &self.banking_trace_events.freeze_time_by_slot, - self.banking_trace_events.packet_batches_by_time, - non_vote_sender, - tpu_vote_sender, - gossip_vote_sender, - exit.clone(), - )?; + let sender_thread = sender_loop.spawn()?; + let (sender_thread, retransmit_slots_sender) = simulator_loop.enter(sender_thread); - sleep(WARMUP_DURATION); - info!("warmup done!"); - - Self::enter_simulator_loop( - parent_slot, - self.first_simulated_slot, - self.banking_trace_events.freeze_time_by_slot, - base_event_time, - base_simulation_time, - &sender_thread, - bank, - poh_recorder, - simulated_leader, - &bank_forks, - &blockstore, - &leader_schedule_cache, - &retransmit_slots_sender, - &retracer, - ); - - Self::finish_simulation( - sender_thread, - poh_service, - banking_stage, - broadcast_stage, - retransmit_slots_sender, - retracer_thread, - exit, - ); + simulator_threads.finish(sender_thread, retransmit_slots_sender); Ok(()) } From c1d1235176b801b40f0d3127f0fc6f6b3e63d8b1 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Fri, 30 Aug 2024 23:56:39 +0900 Subject: [PATCH 40/52] Fix out-of-sync sim due to timed preprocessing --- core/src/banking_simulation.rs | 87 ++++++++++++++++++---------------- 1 file changed, 47 insertions(+), 40 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 6a2235fac55a12..1e5992e5afc300 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -135,6 +135,11 @@ type PacketBatchesByTime = BTreeMap; +type TimedBatchesToSend = Vec<( + (Duration, (ChannelLabel, BankingPacketBatch)), + (usize, usize), +)>; + type EventSenderThread = JoinHandle<(TracedSender, TracedSender, TracedSender)>; #[derive(Default)] @@ -309,17 +314,26 @@ impl SimulatorLoopLogger { struct SenderLoop { parent_slot: Slot, first_simulated_slot: Slot, - packet_batches_by_time: PacketBatchesByTime, non_vote_sender: TracedSender, tpu_vote_sender: TracedSender, gossip_vote_sender: TracedSender, exit: Arc, raw_base_event_time: SystemTime, - base_event_time: SystemTime, base_simulation_time: SystemTime, + total_batch_count: usize, + timed_batches_to_send: TimedBatchesToSend, } impl SenderLoop { + fn log_starting(&self) { + info!( + "simulating events: {} (out of {}), starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", + self.timed_batches_to_send.len(), self.total_batch_count, self.first_simulated_slot, + SenderLoopLogger::format_as_timestamp(self.raw_base_event_time), + self.parent_slot, WARMUP_DURATION, + ); + } + fn spawn(self) -> Result { let handle = thread::Builder::new() .name("solSimSender".into()) @@ -328,45 +342,14 @@ impl SenderLoop { } fn start(mut self) -> (TracedSender, TracedSender, TracedSender) { - info!("start sending!..."); - let total_batch_count = self.packet_batches_by_time.len(); - let timed_batches_to_send = self.packet_batches_by_time.split_off(&self.base_event_time); - let batch_and_tx_counts = timed_batches_to_send - .values() - .map(|(_label, batches_with_stats)| { - let batches = &batches_with_stats.0; - ( - batches.len(), - batches.iter().map(|batch| batch.len()).sum::(), - ) - }) - .collect::>(); - // Convert to a large plain old Vec and drain on it, finally dropping it outside - // the simulation loop to avoid jitter due to interleaved deallocs of BTreeMap. - let mut timed_batches_to_send = timed_batches_to_send - .into_iter() - .map(|(event_time, batches)| { - ( - event_time.duration_since(self.base_event_time).unwrap(), - batches, - ) - }) - .zip_eq(batch_and_tx_counts) - .collect::>(); - info!( - "simulating events: {} (out of {}), starting at slot {} (based on {} from traced event slot: {}) (warmup: -{:?})", - timed_batches_to_send.len(), total_batch_count, self.first_simulated_slot, - SenderLoopLogger::format_as_timestamp(self.raw_base_event_time), - self.parent_slot, WARMUP_DURATION, - ); - let mut simulation_duration = Duration::default(); let mut logger = SenderLoopLogger::new( &self.non_vote_sender, &self.tpu_vote_sender, &self.gossip_vote_sender, ); + let mut simulation_duration = Duration::default(); for ((required_duration, (label, batches_with_stats)), (batch_count, tx_count)) in - timed_batches_to_send.drain(..) + self.timed_batches_to_send.drain(..) { // Busy loop for most accurate sending timings while simulation_duration < required_duration { @@ -390,7 +373,7 @@ impl SenderLoop { } } logger.on_terminating(); - drop(timed_batches_to_send); + drop(self.timed_batches_to_send); // hold these senders in join_handle to control banking stage termination! ( self.non_vote_sender, @@ -431,7 +414,6 @@ impl SimulatorLoop { freeze_time_by_slot: self.freeze_time_by_slot, }; let mut bank = self.bank; - loop { if self.poh_recorder.read().unwrap().bank().is_none() { let next_leader_slot = self.leader_schedule_cache.next_leader_slot( @@ -673,7 +655,7 @@ impl BankingSimulator { block_production_method: BlockProductionMethod, ) -> (SenderLoop, SimulatorLoop, SimulatorThreads) { let parent_slot = self.parent_slot().unwrap(); - let packet_batches_by_time = self.banking_trace_events.packet_batches_by_time; + let mut packet_batches_by_time = self.banking_trace_events.packet_batches_by_time; let freeze_time_by_slot = self.banking_trace_events.freeze_time_by_slot; let bank = bank_forks .read() @@ -821,17 +803,39 @@ impl BankingSimulator { let base_event_time = raw_base_event_time - WARMUP_DURATION; let base_simulation_time = SystemTime::now(); + let total_batch_count = packet_batches_by_time.len(); + let timed_batches_to_send = packet_batches_by_time.split_off(&base_event_time); + let batch_and_tx_counts = timed_batches_to_send + .values() + .map(|(_label, batches_with_stats)| { + let batches = &batches_with_stats.0; + ( + batches.len(), + batches.iter().map(|batch| batch.len()).sum::(), + ) + }) + .collect::>(); + // Convert to a large plain old Vec and drain on it, finally dropping it outside + // the simulation loop to avoid jitter due to interleaved deallocs of BTreeMap. + let timed_batches_to_send = timed_batches_to_send + .into_iter() + .map(|(event_time, batches)| { + (event_time.duration_since(base_event_time).unwrap(), batches) + }) + .zip_eq(batch_and_tx_counts) + .collect::>(); + let sender_loop = SenderLoop { parent_slot, first_simulated_slot: self.first_simulated_slot, - packet_batches_by_time, non_vote_sender, tpu_vote_sender, gossip_vote_sender, exit: exit.clone(), raw_base_event_time, - base_event_time, base_simulation_time, + total_batch_count, + timed_batches_to_send, }; let simulator_loop = SimulatorLoop { @@ -875,6 +879,9 @@ impl BankingSimulator { block_production_method, ); + sender_loop.log_starting(); + // Spawning and entering these two loops must be done at the same time as they're timed. + // So, all the mundane setup must be done in advance. let sender_thread = sender_loop.spawn()?; let (sender_thread, retransmit_slots_sender) = simulator_loop.enter(sender_thread); From 62e9c61a2dec6be506c4622e2bb49a0a1ed7aaee Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Sat, 31 Aug 2024 00:53:12 +0900 Subject: [PATCH 41/52] Fix too-early base_simulation_time creation --- core/src/banking_simulation.rs | 38 ++++++++++++++++++++-------------- 1 file changed, 23 insertions(+), 15 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 1e5992e5afc300..f56fc9e10a6fc2 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -319,7 +319,6 @@ struct SenderLoop { gossip_vote_sender: TracedSender, exit: Arc, raw_base_event_time: SystemTime, - base_simulation_time: SystemTime, total_batch_count: usize, timed_batches_to_send: TimedBatchesToSend, } @@ -334,14 +333,17 @@ impl SenderLoop { ); } - fn spawn(self) -> Result { + fn spawn(self, base_simulation_time: SystemTime) -> Result { let handle = thread::Builder::new() .name("solSimSender".into()) - .spawn(move || self.start())?; + .spawn(move || self.start(base_simulation_time))?; Ok(handle) } - fn start(mut self) -> (TracedSender, TracedSender, TracedSender) { + fn start( + mut self, + base_simulation_time: SystemTime, + ) -> (TracedSender, TracedSender, TracedSender) { let mut logger = SenderLoopLogger::new( &self.non_vote_sender, &self.tpu_vote_sender, @@ -355,7 +357,7 @@ impl SenderLoop { while simulation_duration < required_duration { let current_simulation_time = SystemTime::now(); simulation_duration = current_simulation_time - .duration_since(self.base_simulation_time) + .duration_since(base_simulation_time) .unwrap(); } @@ -389,7 +391,6 @@ struct SimulatorLoop { first_simulated_slot: Slot, freeze_time_by_slot: FreezeTimeBySlot, base_event_time: SystemTime, - base_simulation_time: SystemTime, poh_recorder: Arc>, simulated_leader: Pubkey, bank_forks: Arc>, @@ -400,17 +401,25 @@ struct SimulatorLoop { } impl SimulatorLoop { - fn enter(self, sender_thread: EventSenderThread) -> (EventSenderThread, Sender) { + fn enter( + self, + base_simulation_time: SystemTime, + sender_thread: EventSenderThread, + ) -> (EventSenderThread, Sender) { sleep(WARMUP_DURATION); info!("warmup done!"); - self.start(sender_thread) + self.start(base_simulation_time, sender_thread) } - fn start(self, sender_thread: EventSenderThread) -> (EventSenderThread, Sender) { + fn start( + self, + base_simulation_time: SystemTime, + sender_thread: EventSenderThread, + ) -> (EventSenderThread, Sender) { let logger = SimulatorLoopLogger { simulated_leader: self.simulated_leader, base_event_time: self.base_event_time, - base_simulation_time: self.base_simulation_time, + base_simulation_time, freeze_time_by_slot: self.freeze_time_by_slot, }; let mut bank = self.bank; @@ -801,7 +810,6 @@ impl BankingSimulator { .next() .expect("timed hashes"); let base_event_time = raw_base_event_time - WARMUP_DURATION; - let base_simulation_time = SystemTime::now(); let total_batch_count = packet_batches_by_time.len(); let timed_batches_to_send = packet_batches_by_time.split_off(&base_event_time); @@ -833,7 +841,6 @@ impl BankingSimulator { gossip_vote_sender, exit: exit.clone(), raw_base_event_time, - base_simulation_time, total_batch_count, timed_batches_to_send, }; @@ -844,7 +851,6 @@ impl BankingSimulator { first_simulated_slot: self.first_simulated_slot, freeze_time_by_slot, base_event_time, - base_simulation_time, poh_recorder, simulated_leader, bank_forks, @@ -880,10 +886,12 @@ impl BankingSimulator { ); sender_loop.log_starting(); + let base_simulation_time = SystemTime::now(); // Spawning and entering these two loops must be done at the same time as they're timed. // So, all the mundane setup must be done in advance. - let sender_thread = sender_loop.spawn()?; - let (sender_thread, retransmit_slots_sender) = simulator_loop.enter(sender_thread); + let sender_thread = sender_loop.spawn(base_simulation_time)?; + let (sender_thread, retransmit_slots_sender) = + simulator_loop.enter(base_simulation_time, sender_thread); simulator_threads.finish(sender_thread, retransmit_slots_sender); From fe7331baecd91017feee619214c7096c4b00305c Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 4 Sep 2024 00:40:07 +0900 Subject: [PATCH 42/52] Don't log confusing info! after leader slots --- core/src/banking_simulation.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index f56fc9e10a6fc2..8238641b4ef81d 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -448,7 +448,6 @@ impl SimulatorLoop { info!("next leader block!"); bank.slot() + 1 }; - info!("new leader bank slot: {new_slot}"); let new_leader = self .leader_schedule_cache .slot_leader_at(new_slot, None) @@ -459,6 +458,8 @@ impl SimulatorLoop { } else if sender_thread.is_finished() { warn!("sender thread existed maybe due to completion of sending traced events"); break; + } else { + info!("new leader bank slot: {new_slot}"); } let new_bank = Bank::new_from_parent( bank.clone_without_scheduler(), From 33af3dad5a30c254171b6c03bf9688b1ce7e8ea8 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 4 Sep 2024 00:46:37 +0900 Subject: [PATCH 43/52] Add justification comment of BroadcastStage --- core/src/banking_simulation.rs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index 8238641b4ef81d..c46c113e63ca3a 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -771,6 +771,8 @@ impl BankingSimulator { random_keypair, SocketAddrSpace::Unspecified, )); + // Broadcast stage is needed to save the simulated blocks for post-run analysis by + // inserting produced shreds into the blockstore. let broadcast_stage = BroadcastStageType::Standard.new_broadcast_stage( vec![UdpSocket::bind((Ipv4Addr::LOCALHOST, 0)).unwrap()], cluster_info.clone(), From bb7edea5da8f5c4ab408a3acb63c14648d32ffe3 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Mon, 9 Sep 2024 22:20:06 +0900 Subject: [PATCH 44/52] Align timeout values --- ci/run-sanity.sh | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/ci/run-sanity.sh b/ci/run-sanity.sh index 31cb7a449a8d51..9d207811b3ce12 100755 --- a/ci/run-sanity.sh +++ b/ci/run-sanity.sh @@ -21,9 +21,10 @@ rm -rf config/run/init-completed config/ledger config/snapshot-ledger # process::exit() by extending the timeout... # Also the banking_tracer thread needs some extra time to flush due to # unsynchronized and buffered IO. +validator_timeout="${SOLANA_VALIDATOR_EXIT_TIMEOUT:-120}" SOLANA_RUN_SH_VALIDATOR_ARGS="${SOLANA_RUN_SH_VALIDATOR_ARGS} --full-snapshot-interval-slots 200" \ - SOLANA_VALIDATOR_EXIT_TIMEOUT="${SOLANA_VALIDATOR_EXIT_TIMEOUT:-3600}" \ - timeout 120 ./scripts/run.sh & + SOLANA_VALIDATOR_EXIT_TIMEOUT="$validator_timeout" \ + timeout "$validator_timeout" ./scripts/run.sh & pid=$! From c43281f58df25acb70f44daba629a872b89b7b61 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Mon, 9 Sep 2024 22:52:34 +0900 Subject: [PATCH 45/52] Comment about snapshot_slot=50 --- ci/run-sanity.sh | 3 +++ 1 file changed, 3 insertions(+) diff --git a/ci/run-sanity.sh b/ci/run-sanity.sh index 9d207811b3ce12..cd4ca4d77ff365 100755 --- a/ci/run-sanity.sh +++ b/ci/run-sanity.sh @@ -39,6 +39,9 @@ while [[ ! -f config/run/init-completed ]]; do fi done +# Needs bunch of slots for simulate-block-production. +# Better yet, run ~20 secs to run longer than its warm-up. +# As a bonus, this works as a sanity test of general slot-rooting behavior. snapshot_slot=50 latest_slot=0 From 791b094701ee4c83fe87e61ba4766d7510351fe5 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Mon, 9 Sep 2024 23:11:59 +0900 Subject: [PATCH 46/52] Don't squash all errors unconditionally --- core/src/banking_simulation.rs | 41 +++++++++++++++++++++------------- 1 file changed, 25 insertions(+), 16 deletions(-) diff --git a/core/src/banking_simulation.rs b/core/src/banking_simulation.rs index c46c113e63ca3a..a8a67b3e5653b2 100644 --- a/core/src/banking_simulation.rs +++ b/core/src/banking_simulation.rs @@ -156,14 +156,10 @@ impl BankingTraceEvents { ) -> Result<(), SimulateError> { let mut reader = BufReader::new(File::open(event_file_path)?); - loop { + // EOF is reached at a correct deserialization boundary or just the file is just empty. + // We want to look-ahead the buf, so NOT calling reader.consume(..) is correct. + while !reader.fill_buf()?.is_empty() { callback(deserialize_from(&mut reader)?); - - if reader.fill_buf()?.is_empty() { - // EOF is reached at a correct deserialization boundary. - // We're looking-ahead the buf, so NOT calling reader.consume(..) is correct. - break; - } } Ok(()) @@ -174,20 +170,33 @@ impl BankingTraceEvents { let mut events = Self::default(); for event_file_path in event_file_paths { let old_event_count = event_count; - // Silence errors here as this can happen under normal operation... - let _ = Self::read_event_file( - event_file_path, - |event| { event_count += 1; events.load_event(event); } - ) - .inspect_err(|error| warn!( - "Reading {:?} failed after {} events: {:?} due to file corruption or unclean validator shutdown", - event_file_path, event_count - old_event_count, error, - )); + let read_result = Self::read_event_file(event_file_path, |event| { + event_count += 1; + events.load_event(event); + }); info!( "Read {} events from {:?}", event_count - old_event_count, event_file_path, ); + + if matches!( + read_result, + Err(SimulateError::DeserializeError(ref deser_err)) + if matches!( + &**deser_err, + bincode::ErrorKind::Io(io_err) + if io_err.kind() == std::io::ErrorKind::UnexpectedEof + ) + ) { + // Silence errors here as this can happen under normal operation... + warn!( + "Reading {:?} failed {:?} due to file corruption or unclean validator shutdown", + event_file_path, read_result, + ); + } else { + read_result? + } } Ok(events) From e577e539d9ae979610d087869b1eba07e838bc93 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Mon, 9 Sep 2024 23:38:47 +0900 Subject: [PATCH 47/52] Remove repetitive exitence check --- ledger-tool/src/main.rs | 4 ---- 1 file changed, 4 deletions(-) diff --git a/ledger-tool/src/main.rs b/ledger-tool/src/main.rs index b9d7d20b8d412b..4d8450f5ac7549 100644 --- a/ledger-tool/src/main.rs +++ b/ledger-tool/src/main.rs @@ -554,10 +554,6 @@ fn load_banking_trace_events_or_exit(ledger_path: &Path) -> BankingTraceEvents { } fn read_banking_trace_event_file_paths_or_exit(banking_trace_path: PathBuf) -> Vec { - if !banking_trace_path.exists() { - eprintln!("Error: ledger doesn't have the banking trace dir: {banking_trace_path:?}"); - exit(1); - } info!("Using: banking trace events dir: {banking_trace_path:?}"); let entries = match read_dir(&banking_trace_path) { From 8d2187ec6fffd9f50c93ca73cfc87f216da36130 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Mon, 9 Sep 2024 23:44:51 +0900 Subject: [PATCH 48/52] Promote no_block_cost_limits logging level --- ledger/src/blockstore_processor.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ledger/src/blockstore_processor.rs b/ledger/src/blockstore_processor.rs index cd3fc1ff486f51..89a013531f407c 100644 --- a/ledger/src/blockstore_processor.rs +++ b/ledger/src/blockstore_processor.rs @@ -916,7 +916,7 @@ pub fn process_blockstore_from_root( bank.set_hash_overrides(hash_overrides.clone()); } if opts.no_block_cost_limits { - info!("setting block cost limits to MAX"); + warn!("setting block cost limits to MAX"); bank.write_cost_tracker() .unwrap() .set_limits(u64::MAX, u64::MAX, u64::MAX); From 9208fb833680282058b6a17f9d75eb6bb964d825 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Tue, 10 Sep 2024 23:59:51 +0900 Subject: [PATCH 49/52] Make ci/run-sanity.sh more robust --- ci/run-sanity.sh | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/ci/run-sanity.sh b/ci/run-sanity.sh index cd4ca4d77ff365..ef955f274db29f 100755 --- a/ci/run-sanity.sh +++ b/ci/run-sanity.sh @@ -66,9 +66,13 @@ $solana_ledger_tool verify --abort-on-invalid-block \ --ledger config/snapshot-ledger --block-verification-method unified-scheduler first_simulated_slot=$((latest_slot / 2)) +purge_slot=$((first_simulated_slot + latest_slot / 4)) echo "First simulated slot: ${first_simulated_slot}" touch config/ledger/simulate_block_production_allowed +# Purge some slots so that later verify fails if sim is broken +$solana_ledger_tool purge --ledger config/ledger "$purge_slot" $solana_ledger_tool simulate-block-production --ledger config/ledger \ --first-simulated-slot $first_simulated_slot +# Slots should be available and correctly replayable upto snapshot_slot at least. $solana_ledger_tool verify --abort-on-invalid-block \ - --ledger config/ledger --enable-hash-overrides + --ledger config/ledger --enable-hash-overrides --halt-at-slot "$snapshot_slot" From 284a1b6d8e2357f3da76f2ee6c99749a8305c19d Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 11 Sep 2024 00:04:11 +0900 Subject: [PATCH 50/52] Improve wordking of --enable-hash-overrides --- ledger-tool/src/main.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ledger-tool/src/main.rs b/ledger-tool/src/main.rs index 4d8450f5ac7549..c18818ef1f1482 100644 --- a/ledger-tool/src/main.rs +++ b/ledger-tool/src/main.rs @@ -1234,7 +1234,7 @@ fn main() { .long("enable-hash-overrides") .takes_value(false) .help( - "Enable to override blockhashes and bank hashes from banking trace \ + "Enable override of blockhashes and bank hashes from banking trace \ event files to correctly verify blocks produced by \ the simulate-block-production subcommand", ), From f4a1ca8ea3d9482c47a3b60848f93ed6f7a60e5f Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 11 Sep 2024 14:27:16 +0900 Subject: [PATCH 51/52] Remove marker-file based abortion mechanism --- ledger-tool/src/main.rs | 16 +--------------- ledger/src/blockstore.rs | 4 ---- 2 files changed, 1 insertion(+), 19 deletions(-) diff --git a/ledger-tool/src/main.rs b/ledger-tool/src/main.rs index c18818ef1f1482..a9b9a864bd9b42 100644 --- a/ledger-tool/src/main.rs +++ b/ledger-tool/src/main.rs @@ -38,10 +38,7 @@ use { solana_cost_model::{cost_model::CostModel, cost_tracker::CostTracker}, solana_feature_set::{self as feature_set, FeatureSet}, solana_ledger::{ - blockstore::{ - banking_trace_path, create_new_ledger, simulate_block_production_marker_path, - Blockstore, - }, + blockstore::{banking_trace_path, create_new_ledger, Blockstore}, blockstore_options::{AccessType, LedgerColumnOptions}, blockstore_processor::{ ProcessSlotCallback, TransactionStatusMessage, TransactionStatusSender, @@ -2479,17 +2476,6 @@ fn main() { } } ("simulate-block-production", Some(arg_matches)) => { - let marker_file = simulate_block_production_marker_path(&ledger_path); - if !marker_file.exists() { - eprintln!( - "simulate-block-production is for development purposes only. \ - It's thus a pretty destructive operation on \ - the ledger ({ledger_path:?}). \ - Create an empty file at {marker_file:?} if this is intentional." - ); - exit(1); - } - let mut process_options = parse_process_options(&ledger_path, arg_matches); let banking_trace_events = load_banking_trace_events_or_exit(&ledger_path); diff --git a/ledger/src/blockstore.rs b/ledger/src/blockstore.rs index e0756330f37d88..54f612483be958 100644 --- a/ledger/src/blockstore.rs +++ b/ledger/src/blockstore.rs @@ -307,10 +307,6 @@ pub fn banking_retrace_path(path: &Path) -> PathBuf { path.join("banking_retrace") } -pub fn simulate_block_production_marker_path(path: &Path) -> PathBuf { - path.join("simulate_block_production_allowed") -} - impl Blockstore { pub fn db(self) -> Arc { self.db From 0e8aca5fdbcf201620583d87c7b98363865a57b3 Mon Sep 17 00:00:00 2001 From: Ryo Onodera Date: Wed, 11 Sep 2024 15:19:03 +0900 Subject: [PATCH 52/52] Remove needless touch --- ci/run-sanity.sh | 1 - 1 file changed, 1 deletion(-) diff --git a/ci/run-sanity.sh b/ci/run-sanity.sh index ef955f274db29f..17c47a7a956de8 100755 --- a/ci/run-sanity.sh +++ b/ci/run-sanity.sh @@ -68,7 +68,6 @@ $solana_ledger_tool verify --abort-on-invalid-block \ first_simulated_slot=$((latest_slot / 2)) purge_slot=$((first_simulated_slot + latest_slot / 4)) echo "First simulated slot: ${first_simulated_slot}" -touch config/ledger/simulate_block_production_allowed # Purge some slots so that later verify fails if sim is broken $solana_ledger_tool purge --ledger config/ledger "$purge_slot" $solana_ledger_tool simulate-block-production --ledger config/ledger \