lighthouse
lighthouse copied to clipboard
sigp
Too many `Searching for block components`
TLDR: Not actively harmful, just wasted CPU cycles while block and blobs are in the da_checker and we keep getting attestations
- Introduced in https://github.com/sigp/lighthouse/pull/5583
17,901 hits on ho-h-bn-suit during 1 hour after 2024 May 2, @ 18:26:30.000 all of them for block 0xf26fcf6a6985185172b27782fda904a25c83a637e7268f0fd878fb9b55e12b7e
May 02 09:26:38.901 DEBG Received unknown block hash message block_root: 0xf26f…2b7e, service: sync
May 02 09:26:38.902 DEBG Dropping completed lookup block: 0xf26f…2b7e, service: sync
May 02 09:26:38.902 DEBG Searching for block components block: 0xf26fcf6a6985185172b27782fda904a25c83a637e7268f0fd878fb9b55e12b7e, peer_ids: [PeerId("16Uiu2HAmUyPcQeJ123zf7RzhqxRd9Berjj9m7x4bNecmQMj2sUQ1")], service: sync
The condition to complete the lookup early is hit and it is dropped immediately. Then another unknown block event is processed and repeat
Block and blobs received in time, all 6 blobs. However, execution verification was very slow 4.7 sec.
May 02 09:26:37.701 DEBG Successfully verified gossip blob commitment: 0xb1ce…5bab, index: 0, root: 0xf26f…2b7e, slot: 1561633
May 02 09:26:37.939 INFO New block received root: 0xf26fcf6a6985185172b27782fda904a25c83a637e7268f0fd878fb9b55e12b7e, slot: 1561633
May 02 09:26:42.980 DEBG Delayed head block set_as_head_time_ms: 32, imported_time_ms: 289, attestable_delay_ms: 6779, available_delay_ms: 6658, execution_time_ms: 4726, blob_delay_ms: 1838, observed_delay_ms: 1931, total_delay_ms: 6979, slot: 1561633, proposer_index: 788787, block_root: 0xf26fcf6a6985185172b27782fda904a25c83a637e7268f0fd878fb9b55e12b7e, service: beacon
May 02 09:26:42.948 DEBG Beacon block imported block_slot: 1561633, block_root: 0xf26fcf6a6985185172b27782fda904a25c83a637e7268f0fd878fb9b55e12b7e, service: beacon
While the block + blobs are in the da_checker we get lots of attestations referencing the block. For each attestation we create and drop a lookup.
May 02 09:26:38.902 DEBG Searching for block components block: 0xf26fcf6a6985185172b27782fda904a25c83a637e7268f0fd878fb9b55e12b7e, peer_ids: [PeerId("16Uiu2HAmUyPcQeJ123zf7RzhqxRd9Berjj9m7x4bNecmQMj2sUQ1")], service: sync
May 02 09:26:42.661 DEBG Searching for block components block: 0xf26fcf6a6985185172b27782fda904a25c83a637e7268f0fd878fb9b55e12b7e, peer_ids: [PeerId("16Uiu2HAmVt2q6mBeuPHstXtSH6minp1brK5BprKq7LTF4xCCsHeV")], service: sync
I'm confused where this log is coming from:
May 02 09:26:38.901 DEBG Received unknown block hash message block_root: 0xf26f…2b7e, service: sync
suit would have been on a version where I deleted it at that time. It was so spammy it was causing us to drop logs:
https://github.com/sigp/lighthouse/pull/5672/files
Either way I don't think that changes the analysis
