ThreadBlocked checking ancestorIsValidTerminalProofOfWork

[garyschulte]

Description

When fast syncing a post-merge network (fast, snap, or checkpoint) , there is a brief window where there is no finalized block. During this time besu behaves the same way it does at merge transition, verifying newPayloads and forkchoice calls by ensuring the blocks descend from a valid terminal block.

This is a problem for post-merge networks, because following the chain back to TTD is more and more time consuming the further the chain is from the TTD block. Besu will log lots of thread blocked warnings during this time while it follows the chain back to TTD:

{"@timestamp":"2022-07-16T08:43:06,287","level":"WARN","thread":"vertx-blocked-thread-checker","class":"BlockedThreadChecker","message":"Thread Thread[vert.x-worker-thread-1,5,main] has been blocked for 101820 ms, time limit is 60000 ms","throwable":" io.vertx.core.VertxException: Thread blocked\n\tat [email protected]/jdk.internal.misc.Unsafe.park(Native Method)\n\tat [email protected]/java.util.concurrent.locks.LockSupport.park(LockSupport.java:194)\n\tat [email protected]/java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1796)\n\tat [email protected]/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3128)\n\tat [email protected]/java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1823)\n\tat [email protected]/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1998)\n\tat app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.response(ExecutionEngineJsonRpcMethod.java:78)\n\tat app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.BaseJsonRpcProcessor.process(BaseJsonRpcProcessor.java:42)\n\tat app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TracedJsonRpcProcessor.process(TracedJsonRpcProcessor.java:41)\n\tat app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.TimedJsonRpcProcessor.process(TimedJsonRpcProcessor.java:45)\n\tat app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.AuthenticatedJsonRpcProcessor.process(AuthenticatedJsonRpcProcessor.java:51)\n\tat app//org.hyperledger.besu.ethereum.api.jsonrpc.execution.JsonRpcExecutor.execute(JsonRpcExecutor.java:91)\n\tat app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler.lambda$handler$6(JsonRpcExecutorHandler.java:76)\n\tat app//org.hyperledger.besu.ethereum.api.handlers.JsonRpcExecutorHandler$$Lambda$1150/0x00000008006f1c40.handle(Unknown Source)\n\tat app//io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$0(BlockingHandlerDecorator.java:48)\n\tat app//io.vertx.ext.web.impl.BlockingHandlerDecorator$$Lambda$1481/0x000000080081a840.handle(Unknown Source)\n\tat app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)\n\tat app//io.vertx.core.impl.ContextImpl$$Lambda$1357/0x00000008007a1c40.handle(Unknown Source)\n\tat app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)\n\tat app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)\n\tat app//io.vertx.core.impl.ContextImpl$$Lambda$1349/0x00000008007a3c40.run(Unknown Source)\n\tat app//io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)\n\tat app//io.vertx.core.impl.TaskQueue$$Lambda$726/0x0000000800594c40.run(Unknown Source)\n\tat [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)\n\tat [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)\n\tat app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat [email protected]/java.lang.Thread.run(Thread.java:829)\n"}

Acceptance Criteria

• besu should be able to quickly determine that a fast sync pivot descends from a valid TTD block
• besu should not log excessive thread blocked errors

Steps to Reproduce (Bug)

1. snap, fast or checkpoint sync ropsten

Expected behavior: [What you expect to happen] fast sync completes, backward sync completes, and besu is immediately ready to serve CL requests

Actual behavior: [What actually happens] On ropsten, besu will emit blocked thread exceptions for ~ 2 minutes while it walks the chain back to TTD

Frequency: [What percentage of the time does it occur?]

Versions (Add all that apply)

• Software version: 22.7.0-RC2-SNAPSHOT