Optimize against ValidatorPubkeyCache timeouts

[paulhauner]

Description

A user in Discord recently posted the following log:

Apr 28 19:09:08.447 CRIT Beacon block processing error           error: ValidatorPubkeyCacheLockTimeout, service: beacon
Apr 28 19:09:08.447 WARN BlockProcessingFailure                  outcome: ValidatorPubkeyCacheLockTimeout, msg: unexpected condition in processing block.

This user was not the first one, I've personally seen quite a few users report this same rror.

The validator_pubkey_cache is protected by a TimeoutRwLock. This means there can only be lock contention when something holds the write lock.

I think (it's worth confirming) this is the only place we take a write-lock on the pubkey cache:

lighthouse/beacon_node/beacon_chain/src/beacon_chain.rs

Lines 1633 to 1641 in 3a24ca5

	// If there are new validators in this block, update our pubkey cache.
	//
	// We perform this _before_ adding the block to fork choice because the pubkey cache is
	// used by attestation processing which will only process an attestation if the block is
	// known to fork choice. This ordering ensure that the pubkey cache is always up-to-date.
	self.validator_pubkey_cache
	.try_write_for(VALIDATOR_PUBKEY_CACHE_LOCK_TIMEOUT)
	.ok_or(Error::ValidatorPubkeyCacheLockTimeout)?
	.import_new_pubkeys(&state)?;

I think (also worth confirming) that bulk of the time holding the write-lock is spent inside this function:

lighthouse/beacon_node/beacon_chain/src/validator_pubkey_cache.rs

Lines 124 to 169 in 3a24ca5

	/// Adds zero or more validators to `self`.
	fn import<I>(&mut self, validator_keys: I) -> Result<(), BeaconChainError>
	where
	I: Iterator<Item = PublicKeyBytes> + ExactSizeIterator,
	{
	self.pubkey_bytes.reserve(validator_keys.len());
	self.pubkeys.reserve(validator_keys.len());
	self.indices.reserve(validator_keys.len());
	for pubkey in validator_keys {
	let i = self.pubkeys.len();
	if self.indices.contains_key(&pubkey) {
	return Err(BeaconChainError::DuplicateValidatorPublicKey);
	}
	// The item is written to disk _before_ it is written into
	// the local struct.
	//
	// This means that a pubkey cache read from disk will always be equivalent to or
	// _later than_ the cache that was running in the previous instance of Lighthouse.
	//
	// The motivation behind this ordering is that we do not want to have states that
	// reference a pubkey that is not in our cache. However, it's fine to have pubkeys
	// that are never referenced in a state.
	match &mut self.backing {
	PubkeyCacheBacking::File(persistence_file) => {
	persistence_file.append(i, &pubkey)?;
	}
	PubkeyCacheBacking::Database(store) => {
	store.put_item(&DatabasePubkey::key_for_index(i), &DatabasePubkey(pubkey))?;
	}
	}
	self.pubkeys.push(
	(&pubkey)
	.try_into()
	.map_err(BeaconChainError::InvalidValidatorPubkeyBytes)?,
	);
	self.pubkey_bytes.push(pubkey);
	self.indices.insert(pubkey, i);
	}
	Ok(())
	}

So, it stands to reason that if we can optimize out some time spent in ValidatorPubkeyCache::import then we can avoid ValidatorPubkeyCacheLockTimeout errors.

I think the first step should be to add metrics to ValidatorPubkeyCache::import and determine what's taking the longest.

Potential Optimization

I'm guessing that the write-to-disk part is taking the longest.

It's really important that we retain the current behaviour where the on-disk "backing" is updated somewhat-atomically with the internal Vecs and HashMap.

One potential option is to have a "prepare" step where we can copy the backing to a new random file and add the new keys to it. Then, we have a "commit" phase where we replace the old backing with the new (only a single file copy operation) and update the internal structures.

The "prepare" step only needs a read-lock, whist the "commit" still needs a write-lock (but is hopefully much faster).

Once we determine it is indeed writing to disk that's slow we can expand upon this.

[michaelsproul]

The default backing is the DB now (since #2234), so we can't use an intermediate file per se, although I agree we can probably do a prepare/commit step with a read lock initially during the DB write, and then a write lock during the mutation.

[paulhauner]

The default backing is the DB now

Oh yeah, I forgot about this.

I agree we can probably do a prepare/commit step with a read lock initially during the DB write, and then a write lock during the mutation.

We just need to maintain some sort of mechanism to ensure we mutate the DB and in-memory cache in lock-step. That might involve moving the locks inside ValidatorPubkeyCache.

[michaelsproul]

It took me ages to find, but an upgrade-able lock might be useful for this: https://docs.rs/lock_api/0.4.2/lock_api/struct.RwLockUpgradableReadGuard.html#method.upgrade

https://docs.rs/lock_api/0.4.2/lock_api/struct.RwLock.html#method.upgradable_read

[noslav]

Hi lighthouse team, we're currently experiencing issues related to this please find the following log

Sep 09 21:41:21 cqt-operator-p1 systemd[1]: Started lighthouse eth2 service.
Sep 11 02:00:38 cqt-operator-p1 lighthouse[179796]: Sep 11 02:00:38.094 CRIT Beacon block processing error           error: ValidatorPubkeyCacheLockTimeout, service: beacon
Sep 11 02:25:18 cqt-operator-p1 lighthouse[179796]: Sep 11 02:25:18.922 CRIT Chain removed                           op: batch processing result, reason: WrongBatchState("Validation failed for batch in wrong state: AwaitingProcessing(16Uiu2HAm8HcQWjTmpEeqW96nDeYRs5c9bYV7SMPYSyeVGbEdPExU, 63 blocks)"), id: 12382284213649068281, from: 60234, to: 145933, end_root: 0x8093…fac2, current_target: 60238, batches: 7, peers: 4, validated_batches: 0, state: Syncing, sync_type: Finalized, service: sync
Sep 11 09:22:16 cqt-operator-p1 lighthouse[179796]: Sep 11 09:22:16.746 CRIT Beacon block processing error           error: ValidatorPubkeyCacheLockTimeout, service: beacon
Sep 11 10:44:41 cqt-operator-p1 lighthouse[179796]: Sep 11 10:44:41.898 CRIT Beacon block processing error           error: ValidatorPubkeyCacheLockTimeout, service: beacon
Sep 11 16:18:41 cqt-operator-p1 lighthouse[179796]: Sep 11 16:18:41.779 CRIT Beacon block processing error           error: ValidatorPubkeyCacheLockTimeout, service: beacon

The bn is running with the following config -

lighthouse \
--network mainnet \
beacon_node \
--datadir /scratch/lighthouse \
--debug-level crit \
--http \
--checkpoint-sync-url https://beaconstate.ethstaker.cc \
--execution-endpoint http://localhost:8551 \
--execution-jwt /scratch/node/eth-mainnet/geth/jwtsecret

To add we've no idea of the status of the beacon node sync from the above log but a quick size scan of the datadir gave me the following -

root@cqt-operator-p1:/scratch/lighthouse/beacon# sudo du -sh *
42G	chain_db
6.3G	freezer_db
590M	logs
16K	network

the running CL version -

lighthouse --version
Lighthouse v3.1.0-aa022f4
BLS library: blst
SHA256 hardware acceleration: true
Specs: mainnet (true), minimal (false), gnosis (false)

in conjunction with EL version -

Geth
Version: 1.10.23-stable
Git Commit: 5774d758f4f1e45c23ff6c81b957445b6bfcc5e8
Git Commit Date: 20220910
Architecture: amd64
Go Version: go1.18.1
Operating System: linux

OS -

Linux cqt-operator-p1 #15-Ubuntu SMP Fri Jun 10 11:30:24 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

Kindly advise on how to proceed!

[michaelsproul]

@noslav Try turning on the --disable-lock-timeouts flag. It will silence the error and prevent spurious retries but will not make the node process blocks any faster (the fundamental reason for the timeout). You might want to look into improving the CPU and or I/O performance of your hardware as well.

This issue is about improving our handling of the cache, which will not be available until a future release.

[noslav]

@noslav Try turning on the --disable-lock-timeouts flag. It will silence the error and prevent spurious retries but will not make the node process blocks any faster (the fundamental reason for the timeout). You might want to look into improving the CPU and or I/O performance of your hardware as well.

This issue is about improving our handling of the cache, which will not be available until a future release.

thank you for the quick turnaround!

[noslav]

@michaelsproul your suggestion helped, thank you! However, I'm wondering why in my logs I don't get the mentioned line here in the faq section on the merge migration page

INFO Ready for the merge, current_difficulty: 10789363, terminal_total_difficulty: 10790000

logs currently only show the following

Sep 12 00:19:41 cqt-operator-p1 systemd[1]: Stopped lighthouse eth2 service.
Sep 12 00:19:41 cqt-operator-p1 systemd[1]: lighthouse.service: Consumed 12h 27min 57.266s CPU time.
Sep 12 00:19:41 cqt-operator-p1 systemd[1]: Started lighthouse eth2 service.
|

has this anything to do with my EL configuration?

[michaelsproul]

@noslav Remove the flag --debug-level crit, that flag is causing your node to only log critical errors, which is quite a strange configuration and probably not what you want!

[michaelsproul]

I've overhauled the pubkey cache on the tree-states branch by making it into a generic cache for all validator information. I might try a new approach there using a CoW map for the data so that we can clone it when reading, and then mutate a copy while writing to disk, which then gets swapped into place.