Stabilize some banking stage tests #6251

ryoqun · 2019-10-07T14:21:20Z

Problem

Various banking stage tests are fragile.

Summary of Changes

Fixed several race conditions in tests.

This fixes 3 unstable unit tests. For all of them, the root cause of unstability is a race condition between solana-poh-service-tick_producer thread and solana-banking-stage-tx thread. So, to precisely control the timings of solana-poh-service-tick_producer thread, I introduced new PohConfig field just for testing purpose.

The requested explanations for each tests follow (in simpler-hardest order):

test_banking_stage_tick
- Problem: Even if we waited for 600ms, it's possible for ticks not to be produced enough when the ticker thread is stalled under heavy system load.
- Solution: Always ensure enough ticks are produced (in this pull request, produce 6 ticks)
test_banking_stage_entryfication (originally mentioned by the issue)
- Problem: Right in the middle of solana-banking-stage-tx's processing of received packets, the thread may be paused and the solana-poh-service-tick_producer thread starts kicking in. If that is the case and new tick entry unfortunately knocks the maximum tick height, it interrupts the in-flight processing of the packets. Depending on the exact timing, the banking stage interrupt results in MaxHeightReached error from PohRecorder when banking stage tries to record a transaction entry or simply enqueuing code path of (unprocessed_packets=>buffered_packets). Then, at test code, this results in an infinite loop at HERE (btw, this loop is itself a bit off..., should fix it too?), and eventual timeout on the CI, vomitting an odd RocksDB error.
- Solution: Prevent slots from becoming full merely with tick PoH entries.
test_banking_stage_entries_only
- Problem: In addition to the problem and solution of test_banking_stage_entryfication. There are additional issues. First, assertion may be run before banking stage finishes. Second, the wall time resulted from for _ in 0..10 + sleep(Duration::from_millis(200)); may not be enough.
- For the two additional issue, do simple fix: reorder banking_stage.join().unwrap(); up in the test code and replace the 10-time repetition with unbounded looping also with guard for empty entries from entry_receiver

(First starting from #5660, I ended up with spotting other similar race conditions in neighbor tests, so fixed them as well.)

Fixes #5660

Fixes solana-labs#5660

ryoqun · 2019-10-07T14:24:13Z

core/src/banking_stage.rs

@@ -1128,18 +1140,20 @@ mod tests {
            let bank = Bank::new(&genesis_block);
            bank.process_transaction(&fund_tx).unwrap();
            //receive entries + ticks
-            for _ in 0..10 {
+            loop {
                let entries: Vec<Entry> = entry_receiver
                    .iter()
                    .map(|(_bank, (entry, _tick_height))| entry)
                    .collect();

                assert!(entries.verify(&blockhash));


this assertion should be moved inside the newly-added empty guard if clause.

ryoqun · 2019-10-07T14:25:10Z

core/src/banking_stage.rs

@@ -1031,7 +1038,6 @@ mod tests {
                vote_receiver,
            );
            trace!("sending bank");
-            sleep(Duration::from_millis(600));


Because poh_config's life time is controlled by the target_tick_count, this is no longer needed.

ryoqun · 2019-10-07T14:35:18Z

core/src/banking_stage.rs

-                    bank.process_transactions(&entry.transactions)
-                        .iter()
-                        .for_each(|x| assert_eq!(*x, Ok(())));
+                if !entries.is_empty() {


Under high load, I observed empty entries are returned.

ryoqun · 2019-10-07T14:36:34Z

core/src/poh_service.rs

+                    if poh_config.target_tick_count.is_none() {
+                        Self::sleepy_tick_producer(poh_recorder, &poh_config, &poh_exit_);
+                    } else {
+                        Self::short_lived_tick_producer(poh_recorder, &poh_config, &poh_exit_);


naming: or short_lived_sleepy_tick_producer.. (too long?)

I like descriptive names 👍

ryoqun · 2019-10-07T23:18:04Z

core/src/banking_stage.rs

 ) -> (
    Arc<AtomicBool>,
    Arc<Mutex<PohRecorder>>,
    PohService,
    Receiver<WorkingBankEntry>,
 ) {
    let exit = Arc::new(AtomicBool::new(false));
-    let poh_config = Arc::new(PohConfig::default());
+    let poh_config = if let Some(poh_config) = poh_config {


Hmm, I'm sure there is better way to write in more idiomatic Rust way.

Maybe let poh_config = Arc::new(poh_config.unwrap_or(PohConfig::default())) 😄

carllin · 2019-10-08T09:19:37Z

@ryoqun, thanks for taking this on! In the Problem description of this PR, could you describe in greater detail the race condition that is making the test fragile? It would better frame the discussion for this change.

ryoqun · 2019-10-09T16:01:52Z

@carllin Thanks for checking this out! Sure thing, I'll elaborate it! I'll work on to finish this up tomorrow's work-time in JST. :)

ryoqun · 2019-10-10T21:44:46Z

@carllin Sorry for being late... I added the details of race conditions. Hope that clarifies what I wanted to fix... Also updated this PR with your comments!

carllin · 2019-10-11T19:52:47Z

core/src/banking_stage.rs

@@ -1020,8 +1021,10 @@ mod tests {
            let blocktree = Arc::new(
                Blocktree::open(&ledger_path).expect("Expected to be able to open database ledger"),
            );
+            let mut poh_config = PohConfig::default();
+            poh_config.target_tick_count = Some(6);


The purpose of this test is to check that the number of ticks output is genesis_block.ticks_per_slot, no matter how many extra ticks are sent by the PohService. For clarity, instead of the magic number 6, can we write this as genesis_block.ticks_per_slot + num_extra_ticks for some number num_extra_ticks?

sure thing! done at a9138d1

You were right 😄 for the same reasons as you found in the other cases listed below, this should also use bank.max_tick_height() instead of genesis_block.ticks_per_slot for clarity and consistency

Nice catch! done cef4770

carllin · 2019-10-11T20:13:56Z

core/src/banking_stage.rs

@@ -1212,8 +1220,11 @@ mod tests {
                    Blocktree::open(&ledger_path)
                        .expect("Expected to be able to open database ledger"),
                );
+                let mut poh_config = PohConfig::default();
+                // limit the tick to 1 to prevent clearing working_bank at PohRecord then PohRecorderError(MaxHeightReached) at BankingStage
+                poh_config.target_tick_count = Some(1);


Good catch, quite a subtle bug, especially for your first time through the code base :)

Instead of the magic number 1, can we use something like genesis_block.ticks_per_slot - 1, to make it clear that there's nothing special about this number, it just needs to be < genesis_block.ticks_per_slot

sure thing! done at a9138d1

Well, I couldn't directly use genesis_block.ticks_per_slot because subtracting -1 from it still causes the race condition, so I chose different one: b07bf58

@ryoqun, ah yes, it's because of a special case where slot 0 generates one less tick than all the other slots. For instance, if genesis_block.ticks_per_slot is equal to 10, then the first slot will have bank.max_tick_height of 9, so PoH will, starting at 0, generate a tick for tick_heights 0->1, 1->2, 2->3...8->9, which is only 9 ticks. The next slot, slot 1, will then generate 10 ticks because it's max tick height is 19, and it will start generating a tick for tick heights 9->10, 10->11, ... 18 -> 19. This is all because in the past we wanted to keep the first tick in a slot as 0-indexed.

This open PR here actually will address this issue: #6263, if you are curious and want to take a look :D

Thanks for very detailed explanation! I'll look at it. :D

carllin · 2019-10-11T20:14:47Z

core/src/banking_stage.rs

@@ -1069,8 +1071,11 @@ mod tests {
            let blocktree = Arc::new(
                Blocktree::open(&ledger_path).expect("Expected to be able to open database ledger"),
            );
+            let mut poh_config = PohConfig::default();
+            // limit the tick to 1 to prevent clearing working_bank at PohRecord then PohRecorderError(MaxHeightReached) at BankingStage
+            poh_config.target_tick_count = Some(1);


Instead of the magic number 1, can we use something like genesis_block.ticks_per_slot - 1, to make it clear that there's nothing special about this number, it just needs to be < genesis_block.ticks_per_slot

sure thing! done at a9138d1

Well, I couldn't directly use genesis_block.ticks_per_slot because subtracting -1 from it still causes the race condition, so I chose different one: b07bf58

carllin · 2019-10-11T20:17:51Z

@ryoqun, looking good! Just a few nits, and a little more plumbing to make CI pass :)

ryoqun · 2019-10-12T08:05:01Z

core/src/banking_stage.rs

        }
        Blocktree::destroy(&ledger_path).unwrap();
    }

    #[test]
-    #[ignore]


…g bank

codecov · 2019-10-13T12:34:11Z

Codecov Report

Merging #6251 into master will decrease coverage by 13.5%.
The diff coverage is 85.1%.

@@            Coverage Diff            @@
##           master   #6251      +/-   ##
=========================================
- Coverage    77.9%   64.4%   -13.6%     
=========================================
  Files         216     216              
  Lines       40601   49205    +8604     
=========================================
+ Hits        31654   31717      +63     
- Misses       8947   17488    +8541

mvines · 2019-10-14T15:01:41Z

@carllin - does this look good to land? It's green

Stabilize some banking stage tests

2262ee1

Fixes solana-labs#5660

ryoqun commented Oct 7, 2019

View reviewed changes

mvines requested a review from carllin October 7, 2019 21:10

mvines added the CI Pull Request is ready to enter CI label Oct 7, 2019

solana-grimes removed the CI Pull Request is ready to enter CI label Oct 7, 2019

Fix CI...

9df5ba3

ryoqun commented Oct 7, 2019

View reviewed changes

clean up

b9a248a

ryoqun marked this pull request as ready for review October 10, 2019 21:43

carllin added the CI Pull Request is ready to enter CI label Oct 11, 2019

solana-grimes removed the CI Pull Request is ready to enter CI label Oct 11, 2019

carllin reviewed Oct 11, 2019

View reviewed changes

ryoqun added 2 commits October 12, 2019 16:20

Fix ci

cf6d0b0

Address review nits

a9138d1

ryoqun commented Oct 12, 2019

View reviewed changes

ryoqun requested a review from carllin October 12, 2019 08:12

Use bank.max_tick_height due to off-by-one for no PohRecord's clearin…

b07bf58

…g bank

carllin added the CI Pull Request is ready to enter CI label Oct 12, 2019

solana-grimes removed the CI Pull Request is ready to enter CI label Oct 12, 2019

Fix CI...

5a39891

mvines added the CI Pull Request is ready to enter CI label Oct 14, 2019

solana-grimes removed the CI Pull Request is ready to enter CI label Oct 14, 2019

ryoqun mentioned this pull request Oct 15, 2019

Reject TXs when there is a mismatch #6236

Merged

Use bank.max_tick_height() instead for clarity

cef4770

mvines added the CI Pull Request is ready to enter CI label Oct 16, 2019

solana-grimes removed the CI Pull Request is ready to enter CI label Oct 16, 2019

carllin approved these changes Oct 16, 2019

View reviewed changes

carllin merged commit e267dfa into solana-labs:master Oct 16, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Stabilize some banking stage tests #6251

Stabilize some banking stage tests #6251

ryoqun commented Oct 7, 2019 •

edited

Loading

ryoqun Oct 7, 2019

ryoqun Oct 7, 2019 •

edited

Loading

ryoqun Oct 7, 2019

ryoqun Oct 7, 2019

carllin Oct 8, 2019

ryoqun Oct 7, 2019

carllin Oct 8, 2019 •

edited

Loading

carllin commented Oct 8, 2019

ryoqun commented Oct 9, 2019

ryoqun commented Oct 10, 2019

carllin Oct 11, 2019 •

edited

Loading

ryoqun Oct 12, 2019

carllin Oct 14, 2019 •

edited

Loading

ryoqun Oct 16, 2019

carllin Oct 11, 2019

ryoqun Oct 12, 2019

ryoqun Oct 12, 2019

carllin Oct 14, 2019 •

edited

Loading

ryoqun Oct 16, 2019

carllin Oct 11, 2019

ryoqun Oct 12, 2019

ryoqun Oct 12, 2019

carllin commented Oct 11, 2019

ryoqun Oct 12, 2019

codecov bot commented Oct 13, 2019 •

edited

Loading

mvines commented Oct 14, 2019

Stabilize some banking stage tests #6251

Stabilize some banking stage tests #6251

Conversation

ryoqun commented Oct 7, 2019 • edited Loading

Problem

Summary of Changes

Choose a reason for hiding this comment

ryoqun Oct 7, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

carllin Oct 8, 2019 • edited Loading

Choose a reason for hiding this comment

carllin commented Oct 8, 2019

ryoqun commented Oct 9, 2019

ryoqun commented Oct 10, 2019

carllin Oct 11, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

carllin Oct 14, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

carllin Oct 14, 2019 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

carllin commented Oct 11, 2019

Choose a reason for hiding this comment

codecov bot commented Oct 13, 2019 • edited Loading

Codecov Report

mvines commented Oct 14, 2019

ryoqun commented Oct 7, 2019 •

edited

Loading

ryoqun Oct 7, 2019 •

edited

Loading

carllin Oct 8, 2019 •

edited

Loading

carllin Oct 11, 2019 •

edited

Loading

carllin Oct 14, 2019 •

edited

Loading

carllin Oct 14, 2019 •

edited

Loading

codecov bot commented Oct 13, 2019 •

edited

Loading