From 04f15f78d4dc46be4f0a51712b5874ff4b2c8d0e Mon Sep 17 00:00:00 2001 From: Simon Gellis Date: Wed, 18 Dec 2024 11:34:32 -0500 Subject: [PATCH] sim-rs: track average time for TX to reach lifecycle stages --- sim-rs/sim-cli/src/events.rs | 83 +++++++++++++++++++++++++----------- 1 file changed, 59 insertions(+), 24 deletions(-) diff --git a/sim-rs/sim-cli/src/events.rs b/sim-rs/sim-cli/src/events.rs index 8185f71..cbb8624 100644 --- a/sim-rs/sim-cli/src/events.rs +++ b/sim-rs/sim-cli/src/events.rs @@ -159,14 +159,7 @@ impl EventMonitor { } } Event::TransactionGenerated { id, bytes, .. } => { - txs.insert( - id, - Transaction { - bytes, - generated: time, - included_in_ib: None, - }, - ); + txs.insert(id, Transaction::new(bytes, time)); pending_txs.insert(id); } Event::TransactionSent { .. } => { @@ -220,7 +213,10 @@ impl EventMonitor { blocks.insert(slot, (producer, vrf)); } for published_tx in all_txs { - let tx = txs.get(&published_tx).unwrap(); + let tx = txs.get_mut(&published_tx).unwrap(); + if tx.included_in_block.is_none() { + tx.included_in_block = Some(time); + } published_bytes += tx.bytes; pending_txs.remove(&published_tx); } @@ -271,6 +267,12 @@ impl EventMonitor { *ibs_in_eb.entry(id).or_default() += 1.0; *ebs_containing_ib.entry(*ib_id).or_default() += 1.0; pending_ibs.remove(ib_id); + for tx_id in ib_txs.get(ib_id).unwrap() { + let tx = txs.get_mut(tx_id).unwrap(); + if tx.included_in_eb.is_none() { + tx.included_in_eb = Some(time); + } + } } info!( "Pool {} generated an EB with {} IBs(s) in slot {}.", @@ -337,13 +339,26 @@ impl EventMonitor { }); info_span!("leios").in_scope(|| { - let txs_which_reached_ib: Vec<_> = txs + let times_to_reach_ib: Vec<_> = txs .values() - .filter(|tx| tx.included_in_ib.is_some()) + .filter_map(|tx| { + let ib_time = tx.included_in_ib?; + Some(ib_time - tx.generated) + }) .collect(); - let txs_which_reached_eb: BTreeSet<_> = eb_ibs.values() - .flatten() - .flat_map(|ib_id| ib_txs.get(ib_id).cloned().unwrap_or_default()) + let times_to_reach_eb: Vec<_> = txs + .values() + .filter_map(|tx| { + let eb_time = tx.included_in_eb?; + Some(eb_time - tx.generated) + }) + .collect(); + let times_to_reach_block: Vec<_> = txs + .values() + .filter_map(|tx| { + let block_time = tx.included_in_block?; + Some(block_time - tx.generated) + }) .collect(); let empty_ebs = generated_ebs - ibs_in_eb.len() as u64; let ibs_which_reached_eb = ebs_containing_ib.len(); @@ -353,10 +368,9 @@ impl EventMonitor { let ibs_per_tx = compute_stats(ibs_containing_tx.into_values()); let ibs_per_eb = compute_stats(ebs_containing_ib.into_values()); let ebs_per_ib = compute_stats(ibs_in_eb.into_values()); - let times_to_reach_ibs = compute_stats(txs_which_reached_ib.iter().map(|tx| { - let duration = tx.included_in_ib.unwrap() - tx.generated; - duration.as_secs_f64() - })); + let ib_time_stats = compute_stats(times_to_reach_ib.iter().map(|t| t.as_secs_f64())); + let eb_time_stats = compute_stats(times_to_reach_eb.iter().map(|t| t.as_secs_f64())); + let block_time_stats = compute_stats(times_to_reach_block.iter().map(|t| t.as_secs_f64())); let ibs_received = compute_stats( self.node_ids .iter() @@ -372,7 +386,7 @@ impl EventMonitor { ); info!( "{} out of {} transaction(s) were included in at least one IB.", - txs_which_reached_ib.len(), + times_to_reach_ib.len(), txs.len(), ); let avg_age = pending_txs.iter().map(|id| { @@ -394,10 +408,6 @@ impl EventMonitor { pretty_bytes(bytes_per_ib.mean.trunc() as u64, pbo.clone()), pretty_bytes(bytes_per_ib.std_dev.trunc() as u64, pbo), empty_ibs, ); - info!( - "Each transaction took an average of {:.3}s (stddev {:.3}) to be included in an IB.", - times_to_reach_ibs.mean, times_to_reach_ibs.std_dev, - ); info!( "Each node received an average of {:.3} IB(s) (stddev {:.3}).", ibs_received.mean, ibs_received.std_dev, @@ -424,7 +434,7 @@ impl EventMonitor { ); info!( "{} out of {} transaction(s) were included in at least one EB.", - txs_which_reached_eb.len(), txs.len(), + times_to_reach_eb.len(), txs.len(), ); info!("{} total votes were generated.", total_votes); info!("Each stake pool produced an average of {:.3} vote(s) (stddev {:.3}).", @@ -436,6 +446,18 @@ impl EventMonitor { info!("{} L1 block(s) had a Leios endorsement.", leios_blocks_with_endorsements); info!("{} tx(s) were referenced by a Leios endorsement.", leios_txs); info!("{} tx(s) were included directly in a Praos block.", praos_txs); + info!( + "Each transaction took an average of {:.3}s (stddev {:.3}) to be included in an IB.", + ib_time_stats.mean, ib_time_stats.std_dev, + ); + info!( + "Each transaction took an average of {:.3}s (stddev {:.3}) to be included in an EB.", + eb_time_stats.mean, eb_time_stats.std_dev, + ); + info!( + "Each transaction took an average of {:.3}s (stddev {:.3}) to be included in a block.", + block_time_stats.mean, block_time_stats.std_dev, + ); }); info_span!("network").in_scope(|| { @@ -453,6 +475,19 @@ struct Transaction { bytes: u64, generated: Timestamp, included_in_ib: Option, + included_in_eb: Option, + included_in_block: Option, +} +impl Transaction { + fn new(bytes: u64, generated: Timestamp) -> Self { + Self { + bytes, + generated, + included_in_ib: None, + included_in_eb: None, + included_in_block: None, + } + } } #[derive(Default)]