1use std::{sync::Arc, time::Duration};
5
6use parking_lot::RwLock;
7use tokio::time::Instant;
8use tracing::info;
9
10use crate::{
11 CommitConsumerArgs, CommittedSubDag,
12 block::{BlockAPI, VerifiedBlock},
13 commit::{CommitAPI, load_committed_subdag_from_store},
14 commit_finalizer::{CommitFinalizer, CommitFinalizerHandle},
15 context::Context,
16 dag_state::DagState,
17 error::ConsensusResult,
18 linearizer::Linearizer,
19 storage::Store,
20 transaction_vote_tracker::TransactionVoteTracker,
21};
22
23pub(crate) struct CommitObserver {
36 context: Arc<Context>,
37 dag_state: Arc<RwLock<DagState>>,
38 store: Arc<dyn Store>,
40 transaction_vote_tracker: TransactionVoteTracker,
41 commit_interpreter: Linearizer,
43 commit_finalizer_handle: CommitFinalizerHandle,
45}
46
47impl CommitObserver {
48 pub(crate) async fn new(
49 context: Arc<Context>,
50 commit_consumer: CommitConsumerArgs,
51 dag_state: Arc<RwLock<DagState>>,
52 transaction_vote_tracker: TransactionVoteTracker,
53 ) -> Self {
54 let store = dag_state.read().store();
55 let commit_interpreter = Linearizer::new(context.clone(), dag_state.clone());
56 let commit_finalizer_handle = CommitFinalizer::start(
57 context.clone(),
58 dag_state.clone(),
59 transaction_vote_tracker.clone(),
60 commit_consumer.commit_sender.clone(),
61 );
62
63 let mut observer = Self {
64 context,
65 dag_state,
66 store,
67 transaction_vote_tracker,
68 commit_interpreter,
69 commit_finalizer_handle,
70 };
71 observer.recover_and_send_commits(&commit_consumer).await;
72
73 tokio::runtime::Handle::current()
77 .spawn_blocking({
78 let transaction_vote_tracker = observer.transaction_vote_tracker.clone();
79 let gc_round = observer.dag_state.read().gc_round();
80 move || {
81 transaction_vote_tracker.recover_blocks_after_round(gc_round);
82 }
83 })
84 .await
85 .expect("Spawn blocking should not fail");
86
87 observer
88 }
89
90 pub(crate) fn handle_commit(
95 &mut self,
96 committed_leaders: Vec<VerifiedBlock>,
97 local: bool,
98 ) -> ConsensusResult<Vec<CommittedSubDag>> {
99 let _s = self
100 .context
101 .metrics
102 .node_metrics
103 .scope_processing_time
104 .with_label_values(&["CommitObserver::handle_commit"])
105 .start_timer();
106
107 let mut committed_sub_dags = self.commit_interpreter.handle_commit(committed_leaders);
108 self.report_metrics(&committed_sub_dags);
109
110 for subdag in committed_sub_dags.iter_mut() {
112 subdag.decided_with_local_blocks = local;
113 }
114
115 for commit in committed_sub_dags.iter() {
116 tracing::debug!(
117 "Sending commit {} leader {} to finalization and execution.",
118 commit.commit_ref,
119 commit.leader
120 );
121 tracing::trace!("Committed subdag: {:#?}", commit);
122 self.commit_finalizer_handle.send(commit.clone())?;
124 }
125
126 self.dag_state
127 .write()
128 .add_scoring_subdags(committed_sub_dags.clone());
129
130 Ok(committed_sub_dags)
131 }
132
133 async fn recover_and_send_commits(&mut self, commit_consumer: &CommitConsumerArgs) {
134 let now = Instant::now();
135
136 let replay_after_commit_index = commit_consumer.replay_after_commit_index;
137
138 let last_commit = self
139 .store
140 .read_last_commit()
141 .expect("Reading the last commit should not fail");
142 let Some(last_commit) = &last_commit else {
143 assert_eq!(
144 replay_after_commit_index, 0,
145 "Commit replay should start at the beginning if there is no commit history"
146 );
147 info!("Nothing to recover for commit observer - starting new epoch");
148 return;
149 };
150
151 let last_commit_index = last_commit.index();
152 if last_commit_index == replay_after_commit_index {
153 info!(
154 "Nothing to recover for commit observer - replay is requested immediately after last commit index {last_commit_index}"
155 );
156 return;
157 }
158 assert!(last_commit_index > replay_after_commit_index);
159
160 info!(
161 "Recovering commit observer in the range [{}..={last_commit_index}]",
162 replay_after_commit_index + 1,
163 );
164
165 const COMMIT_RECOVERY_BATCH_SIZE: u32 = if cfg!(test) { 3 } else { 250 };
168
169 let mut last_sent_commit_index = replay_after_commit_index;
170
171 self.dag_state.read().ensure_commits_to_write_is_empty();
173
174 let mut seen_unfinalized_commit = false;
175 for start_index in (replay_after_commit_index + 1..=last_commit_index)
176 .step_by(COMMIT_RECOVERY_BATCH_SIZE as usize)
177 {
178 let end_index = start_index
179 .saturating_add(COMMIT_RECOVERY_BATCH_SIZE - 1)
180 .min(last_commit_index);
181
182 let unsent_commits = self
183 .store
184 .scan_commits((start_index..=end_index).into())
185 .expect("Scanning commits should not fail");
186 assert_eq!(
187 unsent_commits.len() as u32,
188 end_index.checked_sub(start_index).unwrap() + 1,
189 "Gap in scanned commits: start index: {start_index}, end index: {end_index}, commits: {:?}",
190 unsent_commits,
191 );
192
193 self.dag_state
196 .write()
197 .recover_commits_to_write(unsent_commits.clone());
198
199 info!(
200 "Recovering {} unsent commits in range [{start_index}..={end_index}]",
201 unsent_commits.len()
202 );
203
204 for commit in unsent_commits.into_iter() {
207 last_sent_commit_index += 1;
209 assert_eq!(commit.index(), last_sent_commit_index);
210
211 let committed_sub_dag =
212 load_committed_subdag_from_store(self.store.as_ref(), commit);
213
214 if !committed_sub_dag.recovered_rejected_transactions && !seen_unfinalized_commit {
215 info!(
216 "Starting to recover unfinalized commit from {}",
217 committed_sub_dag.commit_ref
218 );
219 seen_unfinalized_commit = true;
222 }
223
224 if seen_unfinalized_commit {
225 assert!(!committed_sub_dag.recovered_rejected_transactions);
227 assert!(!committed_sub_dag.decided_with_local_blocks);
230 self.transaction_vote_tracker
233 .recover_and_vote_on_blocks(committed_sub_dag.blocks.clone());
234 }
235
236 self.commit_finalizer_handle
237 .send(committed_sub_dag)
238 .unwrap();
239
240 self.context
241 .metrics
242 .node_metrics
243 .commit_observer_last_recovered_commit_index
244 .set(last_sent_commit_index as i64);
245
246 tokio::task::yield_now().await;
247 }
248 }
249
250 assert_eq!(
251 last_sent_commit_index, last_commit_index,
252 "We should have sent all commits up to the last commit {}",
253 last_commit_index
254 );
255
256 info!(
257 "Commit observer recovery [{}..={}] completed, took {:?}",
258 replay_after_commit_index + 1,
259 last_commit_index,
260 now.elapsed()
261 );
262 }
263
264 fn report_metrics(&self, committed: &[CommittedSubDag]) {
265 let metrics = &self.context.metrics.node_metrics;
266 let utc_now = self.context.clock.timestamp_utc_ms();
267
268 for commit in committed {
269 info!(
270 "Consensus commit {} with leader {} has {} blocks",
271 commit.commit_ref,
272 commit.leader,
273 commit.blocks.len()
274 );
275
276 metrics
277 .last_committed_leader_round
278 .set(commit.leader.round as i64);
279 metrics
280 .last_commit_index
281 .set(commit.commit_ref.index as i64);
282 metrics
283 .blocks_per_commit_count
284 .observe(commit.blocks.len() as f64);
285
286 for block in &commit.blocks {
287 let latency_ms = utc_now.saturating_sub(block.timestamp_ms());
288 metrics
289 .block_commit_latency
290 .observe(Duration::from_millis(latency_ms).as_secs_f64());
291 if block.author() == self.context.own_index {
292 metrics
293 .proposed_block_commit_latency
294 .observe(Duration::from_millis(latency_ms).as_secs_f64());
295 }
296 }
297 }
298
299 self.context
300 .metrics
301 .node_metrics
302 .sub_dags_per_commit_count
303 .observe(committed.len() as f64);
304 }
305}
306
307#[cfg(test)]
308mod tests {
309 use consensus_types::block::BlockRef;
310 use mysten_metrics::monitored_mpsc::UnboundedReceiver;
311 use parking_lot::RwLock;
312 use rstest::rstest;
313 use tokio::time::timeout;
314
315 use super::*;
316 use crate::{
317 CommitIndex, block_verifier::NoopBlockVerifier, context::Context, dag_state::DagState,
318 linearizer::median_timestamp_by_stake, storage::mem_store::MemStore,
319 test_dag_builder::DagBuilder,
320 };
321
322 #[rstest]
323 #[tokio::test]
324 async fn test_handle_commit() {
325 telemetry_subscribers::init_for_testing();
326 let num_authorities = 4;
327 let (context, _keys) = Context::new_for_test(num_authorities);
328 let context = Arc::new(context);
329
330 let mem_store = Arc::new(MemStore::new());
331 let dag_state = Arc::new(RwLock::new(DagState::new(
332 context.clone(),
333 mem_store.clone(),
334 )));
335 let last_processed_commit_index = 0;
336 let (commit_consumer, mut commit_receiver) =
337 CommitConsumerArgs::new(0, last_processed_commit_index);
338 let transaction_vote_tracker = TransactionVoteTracker::new(
339 context.clone(),
340 Arc::new(NoopBlockVerifier {}),
341 dag_state.clone(),
342 );
343
344 let mut observer = CommitObserver::new(
345 context.clone(),
346 commit_consumer,
347 dag_state.clone(),
348 transaction_vote_tracker.clone(),
349 )
350 .await;
351
352 let num_rounds = 10;
354 let mut builder = DagBuilder::new(context.clone());
355 builder
356 .layers(1..=num_rounds)
357 .build()
358 .persist_layers(dag_state.clone());
359 transaction_vote_tracker.add_voted_blocks(
360 builder
361 .all_blocks()
362 .iter()
363 .map(|b| (b.clone(), vec![]))
364 .collect(),
365 );
366
367 let leaders = builder
368 .leader_blocks(1..=num_rounds)
369 .into_iter()
370 .map(Option::unwrap)
371 .collect::<Vec<_>>();
372
373 let commits = observer.handle_commit(leaders.clone(), true).unwrap();
374
375 let mut expected_stored_refs: Vec<BlockRef> = vec![];
377 for (idx, subdag) in commits.iter().enumerate() {
378 tracing::info!("{subdag:?}");
379 assert_eq!(subdag.leader, leaders[idx].reference());
380
381 let expected_ts = {
382 let block_refs = leaders[idx]
383 .ancestors()
384 .iter()
385 .filter(|block_ref| block_ref.round == leaders[idx].round() - 1)
386 .cloned()
387 .collect::<Vec<_>>();
388 let block_opts = dag_state.read().get_blocks(&block_refs);
389 let blocks = block_opts.iter().map(|block_opt| {
390 block_opt
391 .as_ref()
392 .expect("We should have all blocks in dag state.")
393 });
394 median_timestamp_by_stake(&context, blocks).unwrap()
395 };
396
397 let expected_ts = if idx == 0 {
398 expected_ts
399 } else {
400 expected_ts.max(commits[idx - 1].timestamp_ms)
401 };
402
403 assert_eq!(expected_ts, subdag.timestamp_ms);
404
405 if idx == 0 {
406 assert_eq!(subdag.blocks.len(), 1);
409 } else {
410 assert_eq!(subdag.blocks.len(), num_authorities);
413 }
414 for block in subdag.blocks.iter() {
415 expected_stored_refs.push(block.reference());
416 assert!(block.round() <= leaders[idx].round());
417 }
418 assert_eq!(subdag.commit_ref.index, idx as CommitIndex + 1);
419 }
420
421 let mut processed_subdag_index = 0;
423 while let Ok(Some(subdag)) = timeout(Duration::from_secs(1), commit_receiver.recv()).await {
424 assert_eq!(subdag, commits[processed_subdag_index]);
425 processed_subdag_index = subdag.commit_ref.index as usize;
426 if processed_subdag_index == leaders.len() {
427 break;
428 }
429 }
430 assert_eq!(processed_subdag_index, leaders.len());
431
432 let own_committed_blocks = commits
435 .iter()
436 .flat_map(|commit| commit.blocks.iter())
437 .filter(|block| block.author() == context.own_index)
438 .count() as u64;
439 assert!(own_committed_blocks > 0);
440 assert_eq!(
441 context
442 .metrics
443 .node_metrics
444 .proposed_block_commit_latency
445 .get_sample_count(),
446 own_committed_blocks
447 );
448 assert_eq!(
449 context
450 .metrics
451 .node_metrics
452 .proposed_block_finalization_latency
453 .get_sample_count(),
454 own_committed_blocks
455 );
456
457 verify_channel_empty(&mut commit_receiver).await;
458
459 let last_commit = mem_store.read_last_commit().unwrap().unwrap();
461 assert_eq!(
462 last_commit.index(),
463 commits.last().unwrap().commit_ref.index
464 );
465 let all_stored_commits = mem_store
466 .scan_commits((0..=CommitIndex::MAX).into())
467 .unwrap();
468 assert_eq!(all_stored_commits.len(), leaders.len());
469 let blocks_existence = mem_store.contains_blocks(&expected_stored_refs).unwrap();
470 assert!(blocks_existence.iter().all(|exists| *exists));
471 }
472
473 #[tokio::test]
474 async fn test_recover_and_send_commits() {
475 telemetry_subscribers::init_for_testing();
476 let num_authorities = 4;
477 let context = Arc::new(Context::new_for_test(num_authorities).0);
478 let mem_store = Arc::new(MemStore::new());
479 let dag_state = Arc::new(RwLock::new(DagState::new(
480 context.clone(),
481 mem_store.clone(),
482 )));
483 let transaction_vote_tracker = TransactionVoteTracker::new(
484 context.clone(),
485 Arc::new(NoopBlockVerifier {}),
486 dag_state.clone(),
487 );
488 let last_processed_commit_index = 0;
489 let (commit_consumer, mut commit_receiver) =
490 CommitConsumerArgs::new(0, last_processed_commit_index);
491
492 let mut observer = CommitObserver::new(
493 context.clone(),
494 commit_consumer,
495 dag_state.clone(),
496 transaction_vote_tracker.clone(),
497 )
498 .await;
499
500 let num_rounds = 10;
502 let mut builder = DagBuilder::new(context.clone());
503 builder
504 .layers(1..=num_rounds)
505 .build()
506 .persist_layers(dag_state.clone());
507 transaction_vote_tracker.add_voted_blocks(
508 builder
509 .all_blocks()
510 .iter()
511 .map(|b| (b.clone(), vec![]))
512 .collect(),
513 );
514
515 let leaders = builder
516 .leader_blocks(1..=num_rounds)
517 .into_iter()
518 .map(Option::unwrap)
519 .collect::<Vec<_>>();
520
521 let expected_last_processed_index: usize = 2;
524 let mut commits = observer
525 .handle_commit(leaders[..expected_last_processed_index].to_vec(), true)
526 .unwrap();
527
528 let mut processed_subdag_index = 0;
530 while let Ok(Some(subdag)) = timeout(Duration::from_secs(1), commit_receiver.recv()).await {
531 tracing::info!("Processed {subdag}");
532 assert_eq!(subdag, commits[processed_subdag_index]);
533 processed_subdag_index = subdag.commit_ref.index as usize;
534 if processed_subdag_index == expected_last_processed_index {
535 break;
536 }
537 }
538 assert_eq!(processed_subdag_index, expected_last_processed_index);
539
540 verify_channel_empty(&mut commit_receiver).await;
541
542 let last_commit = mem_store.read_last_commit().unwrap().unwrap();
544 assert_eq!(
545 last_commit.index(),
546 expected_last_processed_index as CommitIndex
547 );
548
549 commits.append(
553 &mut observer
554 .handle_commit(leaders[expected_last_processed_index..].to_vec(), true)
555 .unwrap(),
556 );
557
558 let expected_last_sent_index = num_rounds as usize;
559 while let Ok(Some(subdag)) = timeout(Duration::from_secs(1), commit_receiver.recv()).await {
560 tracing::info!("{subdag} was sent but not processed by consumer");
561 assert_eq!(subdag, commits[processed_subdag_index]);
562 assert!(subdag.decided_with_local_blocks);
563 processed_subdag_index = subdag.commit_ref.index as usize;
564 if processed_subdag_index == expected_last_sent_index {
565 break;
566 }
567 }
568 assert_eq!(processed_subdag_index, expected_last_sent_index);
569
570 verify_channel_empty(&mut commit_receiver).await;
571
572 let last_commit = mem_store.read_last_commit().unwrap().unwrap();
576 assert_eq!(last_commit.index(), expected_last_sent_index as CommitIndex);
577
578 {
580 let replay_after_commit_index = 2;
581 let consumer_last_processed_commit_index = 10;
582 let dag_state = Arc::new(RwLock::new(DagState::new(
583 context.clone(),
584 mem_store.clone(),
585 )));
586 let (commit_consumer, mut commit_receiver) = CommitConsumerArgs::new(
587 replay_after_commit_index,
588 consumer_last_processed_commit_index,
589 );
590 let _observer = CommitObserver::new(
591 context.clone(),
592 commit_consumer,
593 dag_state.clone(),
594 transaction_vote_tracker.clone(),
595 )
596 .await;
597
598 let mut processed_subdag_index = replay_after_commit_index;
599 while let Ok(Some(mut subdag)) =
600 timeout(Duration::from_secs(1), commit_receiver.recv()).await
601 {
602 tracing::info!("Received {subdag} on recovery");
603 assert_eq!(subdag.commit_ref.index, processed_subdag_index + 1);
604 assert!(subdag.recovered_rejected_transactions);
605
606 subdag.recovered_rejected_transactions = false;
608 assert_eq!(subdag, commits[processed_subdag_index as usize]);
609
610 assert!(subdag.decided_with_local_blocks);
611 processed_subdag_index = subdag.commit_ref.index;
612 if processed_subdag_index == consumer_last_processed_commit_index {
613 break;
614 }
615 }
616 assert_eq!(processed_subdag_index, consumer_last_processed_commit_index);
617
618 verify_channel_empty(&mut commit_receiver).await;
619 }
620
621 {
623 let replay_after_commit_index = 10;
624 let consumer_last_processed_commit_index = 10;
625 let dag_state = Arc::new(RwLock::new(DagState::new(
626 context.clone(),
627 mem_store.clone(),
628 )));
629 let (commit_consumer, mut commit_receiver) = CommitConsumerArgs::new(
632 replay_after_commit_index,
633 consumer_last_processed_commit_index,
634 );
635 let _observer = CommitObserver::new(
636 context.clone(),
637 commit_consumer,
638 dag_state.clone(),
639 transaction_vote_tracker.clone(),
640 )
641 .await;
642
643 verify_channel_empty(&mut commit_receiver).await;
646 }
647
648 {
650 let replay_after_commit_index = 2;
651 let consumer_last_processed_commit_index = 4;
652 let dag_state = Arc::new(RwLock::new(DagState::new(
653 context.clone(),
654 mem_store.clone(),
655 )));
656 let (commit_consumer, mut commit_receiver) = CommitConsumerArgs::new(
657 replay_after_commit_index,
658 consumer_last_processed_commit_index,
659 );
660 let _observer = CommitObserver::new(
661 context.clone(),
662 commit_consumer,
663 dag_state.clone(),
664 transaction_vote_tracker.clone(),
665 )
666 .await;
667
668 let mut processed_subdag_index = replay_after_commit_index;
671 while let Ok(Some(subdag)) =
672 timeout(Duration::from_secs(1), commit_receiver.recv()).await
673 {
674 tracing::info!("Received {subdag} on recovery");
675 assert_eq!(subdag.commit_ref.index, processed_subdag_index + 1);
676 assert!(subdag.decided_with_local_blocks);
677 processed_subdag_index = subdag.commit_ref.index;
678 if processed_subdag_index == expected_last_sent_index as CommitIndex {
679 break;
680 }
681 }
682 assert_eq!(
683 processed_subdag_index,
684 expected_last_sent_index as CommitIndex
685 );
686
687 verify_channel_empty(&mut commit_receiver).await;
688 }
689
690 {
694 let replay_after_commit_index = 2;
695 let consumer_last_processed_commit_index = 20;
696 let dag_state = Arc::new(RwLock::new(DagState::new(
697 context.clone(),
698 mem_store.clone(),
699 )));
700 let (commit_consumer, mut commit_receiver) = CommitConsumerArgs::new(
701 replay_after_commit_index,
702 consumer_last_processed_commit_index,
703 );
704 let _observer = CommitObserver::new(
705 context.clone(),
706 commit_consumer,
707 dag_state.clone(),
708 transaction_vote_tracker.clone(),
709 )
710 .await;
711
712 let mut processed_subdag_index = replay_after_commit_index;
715 while let Ok(Some(mut subdag)) =
716 timeout(Duration::from_secs(1), commit_receiver.recv()).await
717 {
718 tracing::info!("Received {subdag} on recovery");
719 assert_eq!(subdag.commit_ref.index, processed_subdag_index + 1);
720 assert!(subdag.recovered_rejected_transactions);
721
722 subdag.recovered_rejected_transactions = false;
724 assert_eq!(subdag, commits[processed_subdag_index as usize]);
725
726 assert!(subdag.decided_with_local_blocks);
727 processed_subdag_index = subdag.commit_ref.index;
728 if processed_subdag_index == expected_last_sent_index as CommitIndex {
729 break;
730 }
731 }
732 assert_eq!(
733 processed_subdag_index,
734 expected_last_sent_index as CommitIndex
735 );
736 assert_eq!(10, expected_last_sent_index);
737
738 verify_channel_empty(&mut commit_receiver).await;
739 }
740 }
741
742 async fn verify_channel_empty(receiver: &mut UnboundedReceiver<CommittedSubDag>) {
744 if let Ok(Some(_)) = timeout(Duration::from_secs(1), receiver.recv()).await {
745 panic!("Expected the consensus output channel to be empty, but found more subdags.")
746 }
747 }
748}