sim-rs: track average time for TX to reach lifecycle stages

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<Timestamp>,
+    included_in_eb: Option<Timestamp>,
+    included_in_block: Option<Timestamp>,
+}
+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)]