Fork choice write lock held for 4+ seconds on `fusaka-devnet-3-lighthouse-geth-1`

[jimmygchen]

I noticed a few instances of very slow data column gossip validation and it looks like it's due to long wait on fork choice write lock

Code:

lighthouse/beacon_node/beacon_chain/src/beacon_chain.rs

Lines 3892 to 3894 in 8a4f6cf

	// Take an exclusive write-lock on fork choice. It's very important to prevent deadlocks by
	// avoiding taking other locks whilst holding this lock.
	let mut fork_choice = self.canonical_head.fork_choice_write_lock();

This was also confirmed via metric

Also noticing it on other supernode instances

https://grafana.observability.ethpandaops.io/goto/Y6Pv-RjNR?orgId=1

[michaelsproul]

This could be happening concurrently with block import, which holds the fork choice lock in order to prevent inconsistency between fork choice and the DB.

One way to fix this might be to release the fork choice lock while writing the state. For this to be safe though I think we would have to prevent any other thread from writing fork choice to disk while we wait for block import (otherwise we violate the invariant about a block being in fork choice implying that it and its state are in the DB). This could look something like marking fork choice as "dirty" when adding the block (but before doing the DB write), and then marking it as un-dirty when the DB write completes (OR block import fails)

I dunno, seems a bit gnarly either way. Having this lock on fork choice interact with an operation that is known to be slow (disk write) is quite difficult.

[michaelsproul]

Looking closer at the trace, does this delay really matter? The column has been gossip verified and propagated prior to import_available_block running. I think the case I was imagining was worse (verification gets blocked waiting for the fc read lock required to check block duplication)

The trace here feels like an issue that might be addressed by Mark's block status tracking: we would not even attempt to import the block off the back of this column import because it is a duplicate import (I think).

[jimmygchen]

Yeah I think you're right,. looking at the pending_components trace for this block
https://grafana.observability.ethpandaops.io/goto/NLNhugjHg?orgId=1

It shows that the block was first available around 09:09:13.6, which is around the time when the data column arrived, and it also showed that this block was imported many times due to the race condition (8 times...!)

With these numbers and frequency, I think it may be worth fixing the below issue properly

• Same block getting imported multiple times due to race condition #6439

And i think this can be a very easy fix after the recent refactor, I think we could just set the components to available here:

lighthouse/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs

Lines 543 to 548 in f781294

	// Explicitly drop read lock before acquiring write lock
	drop(pending_components);
	if let Some(components) = self.critical.write().get_mut(&block_root) {
	// Clean up span now that block is available
	components.span = Span::none();
	}

and before inserting, we could just check if it's already made available, similar to this: https://github.com/sigp/lighthouse/pull/7931/files#diff-08ec9c84176ae7409a04aa83dbcc45cb927cd9551f2973a2c7ed9d024d771355R490-R498

Previously my concern was

I'm worried about the case where block is available but is awaiting import / recompute head. This could be a while and we may not want to send BlockComponentProcessed event until then

But if the block is already available and awaiting import, maybe we can just do nothing and let the other thread complete the import and recompute head task? The other issue is, what do we do if we're in block lookups in the case where we actually need to wait, i.e. before processing the child of the block

[jimmygchen]

But yeah, like you said this is not as worrying as i thought, because my original concern was that if we're importing late, then we're not able to keep up with head and have to consistently switch back to lookup sync often.

[jimmygchen]

Should be addressed in #8050. Will monitor the devnet deployment

[jimmygchen]

still seeing long fork choice write locks on some supernodes on devnet-5 after the fix. need further investigation

[michaelsproul]

Let's look at the traces tomorrow

[jimmygchen]

We looked at the traces again, and the write lock time in the past 12 hours has been fine, max at around ~250 ms, but mostly pretty fast.

We suspect it was due to rayon utilising all available threads for backfilling, and it's no longer happening when backfill is not occuring.

So i believe this is fixed by #8050 and #7924 and can be closed.