Forks on Testnet Causing Roots to Stall

[bw-solana]

Problem

We are occasionally seeing long lived (~2 minutes) forks on testnet that cause root creation to stall.

One such example started on 3/7 at 23:06:56 UTC:

Last common ancestor is 184353487. Looks like 184353488 was late getting to some nodes, likely due to requiring a couple dozens of repaired shreds on average.

This caused 184353492 to be built off 184353487 and start what ended up being the minority fork (we'll call this Fork B and the fork containing 184353488 to be fork A).

We see 1673 nodes vote for 184353488 around 23:06:56 UTC.

We see 581 nodes vote for 184353492 around the same time.

But it seems that the votes for 184353488 were all sent to a leader building off Fork B, which caused the turbine (id=1)vote transactions to be rejected with blockhash_not_found.

This caused Fork B to look like the majority fork early on. Nodes that voted on 184353492 (e.g. 7mtKMUgM24GPTiR2krRimUiQgXRRmMPmmPkQBzMZak8a) kept voting. Nodes that voted on 184353488 (e.g. 5D1fNXzvv5NjV1ysLjirC4WY92RNsVH18vjmcszZd8on) stopped voting and presumably were waiting to switch over to the other fork (requires 38% votes observed to switch).

It seems Fork B never reached the switching threshold. Eventually (around 23:08:29 UTC), The validators that originally voted on fork A refreshed their votes for slots 184353488,184353489,184353490, and this tipped the scales to allow Fork B voters to switch, consensus to be achieved, and new roots to be confirmed.

Refresh occurred at this point because the blockhash for original votes expired. I.e. MAX_PROCESSING_AGE slots had been created on fork A.

The big question is why didn't some leader on fork A ingest the original votes via gossip? Why did it take refreshing these votes?

Proposed Solution

Debug and Fix so that we can come to consensus sooner

[aeyakovenko]

@sakridge should be a priority to fix

[ryoqun]

(i think this is known issue relating to rather deep VOTE_THRESHOLD_DEPTH (= 8), which is also happening on mainnet-beta occasionally).

https://discord.com/channels/428295358100013066/1065744394675826890 see #debug-mb-root-stalls on discord

Maybe my memory is poor but i dont think it used to happen with such frequency. It's often possible to check the explorer in the past month or two or so and see an orange or red spike in the ping. I dont think it was happening that often before but i could be wrong... heres another example: https://metrics.solana.com:3000/d/KCLhfAbMz/replay?orgId=1&var-datasource=Influx-Enterprise&var-testnet=mainnet-beta&var-hostid=C1ocKDYMCm2ooWptMMnpd5VEB2Nx4UMJgRuYofysyzcA&from=1676862594798&to=1676862842685

[bw-solana]

(i think this is known issue relating to rather deep VOTE_THRESHOLD_DEPTH (= 8), which is also happening on mainnet-beta occasionally).

I think the lockout threshold depth explains why it takes validators that were voting on Fork B a while to switch back to voting on Fork A once they realize it is the winning fork. I.e. Fork B likely realized this by the time they ingested slot 184353730, but looks like they didn't start voting on this fork again until around 184353777 due to lockout.

It doesn't explain why it took so long for everyone to realize Fork A was the winning fork (~2 minutes). We should be able to reach this consensus via Gossip votes and not rely on refreshing turbine votes. It appears that we were landing some votes through Gossip (according to banking_stage-leader_slot_packet_counts.committed_transactions_with_successful_result_count), but not enough to convince Fork B to switch over.

[bw-solana]

I was able to confirm something we already suspected:
5D1fNXzvv5NjV1ysLjirC4WY92RNsVH18vjmcszZd8on detected a partition when it was resetting onto slot 184353489. This means the heaviest bank (presumably 184353492) was not the bank that it voted on last (184353488) and the bank it voted on last was not a descendant of the heaviest bank.

Conversely, 7mtKMUgM24GPTiR2krRimUiQgXRRmMPmmPkQBzMZak8a did not detect a partition until slot 184353733.

This just corroborates the narrative that the minor fork (fork B) looked heavier for most of the time until all the refreshed votes for slot 184353488 landed

[ryoqun]

hmm, i still think this is same as the symptom which is happening at mainnet-beta. as you said, VOTE_THRESHOLD_DEPTH itself isn't the root cause. it's just making a partition unnecessarily large/long. i worded poorly.. ;) the root problem is that voting-replaying timing interaction.

As you can see, all nodes who misvoted on fork B (legend: bold vs) was slightly faster (~300ms earlier). This means they just aggressively voted on whatever finished replaying, presumably without any external fork weight info. Also fork A's slow propagation just made both fork A and fork B were finished to replay around same time. (legend: horizontal bars are replay duration). (to reiterate, all nodes who finished replaying fork B just voted on it.) On the other hand, ther nodes voted on fork a, almost same but slightly later. So, baby partitions were born like twin. ;) Then, the fork a voters paused doubling their bet as soon as fork B's vote is gossiped. However, fork B voters was just aggressive to double-down (so that whole cluster come to a conclusion faster on fork b), resulting significant stake (i.e. hampering switch threshold) is locked out as much as VOTE_THRESHOLD_DEPTH on fork b for some time (~2min).

btw, as leader slots are grouped by 4 slots. this condition can be triggered just with 2 leaders' unlucky block propagation/replay coincidence. so, it's likely to happen than intuitively thought.

I know you're kinda frustrated with my own undocumented tool.... at least, it now supports loading saved charts.. so, access https://codepen.io/ryoqun/full/JjNbeyE and feed https://drive.google.com/file/d/1nynJO23g1ZUB_aY3ZiaBlZ1i8Gy5F6wg/view?usp=sharing to it.... bear that it's slow as hell and kinda buggy... (and can crash chrome, iirc; i just need upstream patch to blink around its hit test impl..)

[ryoqun]

also, you can read back my other days diagnostics for this at mainnet-beta here: https://discord.com/channels/428295358100013066/1065744394675826890/1065901707332177960 (again, you can interact with the rainbow chart with data posted there)

[ryoqun]

anyway, i'm amateur at consensus/fork choice. but, i'd like to see what if voting isn't that aggressive to double-down on the same fork's blocks from the same leader.

[bw-solana]

I think most of your analysis is spot on, and it's possible reducing the VOTE_THRESHOLD_DEPTH (to reduce lockout time) would result in forming consensus sooner. That said, I think the vote refresh threshold (i.e. MAX_PROCESSING_AGE) is the main time driver here.

The problem with the VOTE_THRESHOLD_DEPTH theory is that Fork B nodes weren't trying to switch over to Fork A until all the refreshed votes from Fork A nodes hit. The evidence for this is that they were happily voting on Fork B all the way up until 184353743 at time 03/07/2023 23:08:29. This is immediately after the refreshed votes for slot 184353488 landed.

See this query for example of a Fork B node voting on Fork B:
SELECT "latest" FROM "tds"."autogen"."tower-vote" WHERE time > :dashboardTime: AND time < :upperDashboardTime: AND "host_id"='7mtKMUgM24GPTiR2krRimUiQgXRRmMPmmPkQBzMZak8a'

One thing that does make me raise my eyebrows is 184353743 - 2^VOTE_THRESHOLD_DEPTH = 184353487, which is the last common ancestor of Forks A & B...

[t-nelson]

@steviez do you think #28069 might help here? should make the node aware of votes landing via turbine sooner, right?

[steviez]

@steviez do you think #28069 might help here? should make the node aware of votes landing via turbine sooner, right?

In one of comments, I detail some analysis I did where I observed banks getting frozen ~130ms earlier (on average) over a day of steady state runtime. Banks getting frozen earlier means the votes embedded in those blocks getting accounted for earlier, so yes, I think you're right that this change could help in this regard.

I previously had some hesitancy to ship that PR, but will post a comment with my updated thoughts

[behzadnouri]

For cross reference, #29690 claims that

noticed that the bank threads assigned to gossip votes barely manages to commit any transaction to the bank.

which might be relevant to discussions here regarding gossip votes not helping with resolving forks.

[bw-solana]

Investigation Update

Following up on this, it appears we have at least two distinct issues leading to root stalls:

1. The issue detailed in this ticket where Gossip votes don't appear to be landing and roots stall until votes on the majority fork are refreshed through turbine.
2. The issue @ryoqun described where nodes are locked out because they keep voting on the minority fork until they detect VOTE_THRESHOLD_DEPTH (8th from the top) vote hasn't reached 67% stake (up to 256 slots of lockout).

It's fairly straightforward to distinguish between these two by looking at refresh_vote metrics (if partition gets resolved shortly after a bunch of refreshed votes come in, we're in scenario 1). Number 2 appears to be the more common issue on testnet looking over the last couple weeks. 2 also doesn't seem to be a bug. It is by design.

Mitigation Ideas

1. The most straightforward way of minimizing the pain from both symptoms is to reduce repair rate close to zero. For both issues, repairs are the catalyst that lead to long blockstore insertion times that drive the initial forking that later cascades into long root stalls when turbine votes don't land (due to blockhash mismatch) or nodes get locked out (due to voting on minority fork up to vote threshold depth). Obviously, network issues are always going to be present at some rate (or could be induced by malicious leader/turbine node), but any improvements here should decrease likelihood of catalyzing these issues.
2. I'm wondering if we should have a dynamic vote threshold depth check to prevent getting locked out for too long on the minority fork. E.g. what if we had two checks that had to pass in order to continue voting: (1) the existing check where 8th deep vote has to have 67% stake backing it, (2) the 4th deep vote has to have 33% stake backing it. In English, "Are my recent votes moving towards achieving consensus, or am I off in the weeds?" This could cause nodes voting on the minority fork to halt voting sooner --> lockout expire sooner --> vote on majority fork sooner --> roots to be made. This would help with issue 2 above.
3. We could be more aggressive in refreshing the most recent vote in some cases. Currently, we will wait until the blockhash for our latest vote has expired (and we haven't seen it land) in order to refresh it. This means waiting for 150 slots on the current fork (minutes). I don't see much harm in waiting for something significantly less (e.g. 50 slots) before refreshing the most recent vote. We could also implement something tighter and more sophisticated such as tracking which leader we sent our last vote to, and if that leader is voting on a different fork than us (+some other criteria like stake voting on the various forks), refreshing our most recent vote after some very short time. This would help with issue 1 above (bandaid over the missing gossip votes).