Fork choice write lock held during database write

[michaelsproul]

Description

Currently we hold the fork choice write lock while writing to disk:

lighthouse/beacon_node/beacon_chain/src/beacon_chain.rs

Lines 4000 to 4002 in e5b4983

	// The fork choice write-lock is dropped *after* the on-disk database has been updated.
	// This prevents inconsistency between the two at the expense of concurrency.
	drop(fork_choice);

This poses a potential problem for fork choice lock readers, which will be blocked while waiting for this write to complete. We expect that writing to disk takes hundreds of milliseconds several seconds due to diff computation and overhead due to database I/O.

Metrics

Metrics seem to indicate that this is not a significant performance issue:

# HELP beacon_fork_choice_read_lock_aquire_seconds Time taken to aquire the fork-choice read lock
# TYPE beacon_fork_choice_read_lock_aquire_seconds histogram
beacon_fork_choice_read_lock_aquire_seconds_bucket{le="0.0001"} 1025501427
beacon_fork_choice_read_lock_aquire_seconds_bucket{le="0.0004"} 1086019739
beacon_fork_choice_read_lock_aquire_seconds_bucket{le="0.0016"} 1254510271
beacon_fork_choice_read_lock_aquire_seconds_bucket{le="0.0064"} 1313781698
beacon_fork_choice_read_lock_aquire_seconds_bucket{le="0.0256"} 1316301315
beacon_fork_choice_read_lock_aquire_seconds_bucket{le="0.1024"} 1316615602
beacon_fork_choice_read_lock_aquire_seconds_bucket{le="0.4096"} 1316673956
beacon_fork_choice_read_lock_aquire_seconds_bucket{le="+Inf"} 1316682131
beacon_fork_choice_read_lock_aquire_seconds_sum 378137.6061273879
beacon_fork_choice_read_lock_aquire_seconds_count 1316682131

TODO: more analysis here

Steps to resolve

Please describe the steps required to resolve this issue, if known.

[dapplion]

Will provide more evidence but our early conclusion is:

• The possibility of holding the write lock for long real and can slow down reads
• However, metrics show that this happens very rarely
• So we will leave the code as is. The invariants we get from making disk and fork-choice writes atomic are very nice and don't want to lose them.

[jimmygchen]

I noticed a bit of mismatch between traces and metrics on holesky nodes.

Holesky node metrics over the last 24 hours, looks pretty good

But we have quite a lot of occurrences where the acquiring write lock took more than 3s

The code that instrument the trace and metric is here, I don't see anything wrong with how we're measuring it 🤔

lighthouse/beacon_node/beacon_chain/src/canonical_head.rs

Lines 407 to 412 in 3290438

	/// Access a write-lock for fork choice.
	#[instrument(skip_all)]
	pub fn fork_choice_write_lock(&self) -> RwLockWriteGuard<'_, BeaconForkChoice<T>> {
	let _timer = metrics::start_timer(&metrics::FORK_CHOICE_WRITE_LOCK_AQUIRE_TIMES);
	self.fork_choice.write()
	}

[jimmygchen]

I noticed some state cache contention last week, 575ms here just waiting for the state cache lock:

Code:

lighthouse/beacon_node/store/src/hot_cold_store.rs

Lines 1133 to 1142 in 51321da

	#[instrument(skip_all, fields(?block_root, %max_slot), level = "debug")]
	pub fn get_advanced_hot_state_from_cache(
	&self,
	block_root: Hash256,
	max_slot: Slot,
	) -> Option<(Hash256, BeaconState<E>)> {
	self.state_cache
	.lock()
	.get_by_block_root(block_root, max_slot)
	}

Which may be contributing to this issue when persisting the block and blobs to DB, as we acquire lock on the state cache here:

lighthouse/beacon_node/store/src/hot_cold_store.rs

Lines 1469 to 1474 in 51321da

	StoreOp::DeleteBlock(block_root) => {
	self.state_cache.lock().delete_block_states(block_root);
	}
	StoreOp::DeleteState(state_root, _) => {
	self.state_cache.lock().delete_state(state_root)
	}

[jimmygchen]

This code path locks the state_cache for up to 1 second on holesky and ~500ms on mainnet:

lighthouse/beacon_node/store/src/hot_cold_store.rs

Lines 1735 to 1739 in 51321da

	fn load_hot_hdiff_buffer(&self, state_root: Hash256) -> Result<HDiffBuffer, Error> {
	if let Some(buffer) = self
	.state_cache
	.lock()
	.get_hdiff_buffer_by_state_root(state_root)

[michaelsproul]

@jimmygchen Nice find with the hdiff buffer conversion hogging the state cache. Lion and I can take a look at this on our call in the afternoon. We might be able to use a OnceCell to release that lock earlier.

[michaelsproul]

Started drafting a PR for the OnceCell here:

• Use OnceCell in HotHDiffBufferCache #8176

[michaelsproul]

Lion and I looked at the metrics, and there are quite a few occurrences per hour where the fork choice write lock takes 1s+ to obtain:

Query for this chart:

3600*(rate(beacon_fork_choice_write_lock_aquire_seconds_count{network="holesky"}[1h]) - on (instance) rate(beacon_fork_choice_write_lock_aquire_seconds_bucket{network="holesky", le="1.024"}[1h]))

However we didn't find any instances of the lock taking >4s (the top bucket). Phew!

Interestingly, if you use a 1.0 quantile in your chart (@jimmygchen) you can see the spikes:

The spikes show 4s (the top of the bucket), because they are between 1-4s. We could maybe add another bucket in there if we wanted.

This suggests that some optimisation of the fork choice write lock could be useful.

[michaelsproul]

@jimmygchen Any idea why we can't see parent spans of fork_choice_write_lock? Is it possible they're inside some span that we haven't designated as a root span? Or is this an artefact of our Tempo instance dropping spans (is that still happening?)

[jimmygchen]

Yeah that’s right, it’s called from some code paths that hasn’t been instrumented, so they become the root span.