fix: defer common block body production until next event loop (#8285)

**Motivation**

While going through block production logs I noticed in some rare cases
we sent header requests pretty delayed into the slot, but not if you
look at our logs, it shows that header was sent at ~100ms but mev-boost
received it at ~600ms which is a huge discrepancy. When further
analysing this I noticed that ~600ms is roughtly the time we finished
producing the common block body. This means we can't really trust the
logs here as they might be emitted but the actual HTTP request is not
sent.

Since this issue is pretty rare and most of the time we sent the
requests <100ms I think it's race condition and highly depends on I/O
timing and what other async/sync load is processed.

Another interesting side effect of this is that when these huge delays
happen (up to 500ms) I also noticed that builder HTTP requests run into
the 1 second timeout even though it looks from mev-boost perspective
that response was sent within time. My guess here is that the `fetch`
implementation sets the timer and starts it but since sending the actual
HTTP requests requires to go through poll phase it might not actually
bet sent.

Long story short, we need to wait until next evet loop iteration to
ensure I/O operations are processed before starting common block body
production as it is synchronous and blocking.

**Description**

Defer call produce common block body `produceCommonBlockBody` to next
event loop by running it in `setImmediate` callback.

Previous PR https://github.com/ChainSafe/lodestar/pull/7814
This commit is contained in:
Nico Flaig
2025-09-01 11:46:22 +01:00
committed by GitHub
parent bfd8ee3460
commit ac704f28d2

View File

@@ -75,6 +75,7 @@ import {BuilderStatus, NoBidReceived} from "../../../execution/builder/http.js";
import {validateGossipFnRetryUnknownRoot} from "../../../network/processor/gossipHandlers.js";
import {CommitteeSubscription} from "../../../network/subnets/index.js";
import {SyncState} from "../../../sync/index.js";
import {callInNextEventLoop} from "../../../util/eventLoop.js";
import {isOptimisticBlock} from "../../../util/forkChoice.js";
import {getDefaultGraffiti, toGraffitiBytes} from "../../../util/graffiti.js";
import {getLodestarClientVersion} from "../../../util/metadata.js";
@@ -678,27 +679,32 @@ export function getValidatorApi(
signal: controller.signal,
});
logger.verbose("Producing common block body", loggerContext);
const commonBlockBodyStartedAt = Date.now();
// Ensure builder and engine HTTP requests are sent before starting common block body production
// by deferring the call to next event loop iteration, allowing pending I/O operations like
// HTTP requests to be processed first and sent out early in slot.
callInNextEventLoop(() => {
logger.verbose("Producing common block body", loggerContext);
const commonBlockBodyStartedAt = Date.now();
const produceCommonBlockBodyPromise = chain
.produceCommonBlockBody({
slot,
parentBlockRoot,
parentSlot,
randaoReveal,
graffiti: graffitiBytes,
})
.then((commonBlockBody) => {
deferredCommonBlockBody.resolve(commonBlockBody);
logger.verbose("Produced common block body", {
...loggerContext,
durationMs: Date.now() - commonBlockBodyStartedAt,
});
})
.catch(deferredCommonBlockBody.reject);
chain
.produceCommonBlockBody({
slot,
parentBlockRoot,
parentSlot,
randaoReveal,
graffiti: graffitiBytes,
})
.then((commonBlockBody) => {
deferredCommonBlockBody.resolve(commonBlockBody);
logger.verbose("Produced common block body", {
...loggerContext,
durationMs: Date.now() - commonBlockBodyStartedAt,
});
})
.catch(deferredCommonBlockBody.reject);
});
const [[builder, engine]] = await Promise.all([blockProductionRacePromise, produceCommonBlockBodyPromise]);
const [builder, engine] = await blockProductionRacePromise;
if (builder.status === "pending" && engine.status === "pending") {
throw Error("Builder and engine both failed to produce the block within timeout");