Log detailed timing of block creation steps

CHANGELOG.md

@@ -36,6 +36,7 @@
 - Upgrade Reference Tests to 13.2 [#6854](https://github.com/hyperledger/besu/pull/6854)
 - Update Web3j dependencies [#6811](https://github.com/hyperledger/besu/pull/6811)
 - Add `tx-pool-blob-price-bump` option to configure the price bump percentage required to replace blob transactions (by default 100%) [#6874](https://github.com/hyperledger/besu/pull/6874)
+- Log detailed timing of block creation steps [#6880](https://github.com/hyperledger/besu/pull/6880)
 
 ### Bug fixes
 - Fix txpool dump/restore race condition [#6665](https://github.com/hyperledger/besu/pull/6665)

consensus/clique/src/main/java/org/hyperledger/besu/consensus/clique/blockcreation/CliqueBlockScheduler.java

@@ -68,10 +68,10 @@ public BlockCreationTimeResult getNextTimestamp(final BlockHeader parentHeader)
     final BlockCreationTimeResult result = super.getNextTimestamp(parentHeader);
 
     final long milliSecondsUntilNextBlock =
-        result.getMillisecondsUntilValid() + calculateTurnBasedDelay(parentHeader);
+        result.millisecondsUntilValid() + calculateTurnBasedDelay(parentHeader);
 
     return new BlockCreationTimeResult(
-        result.getTimestampForHeader(), Math.max(0, milliSecondsUntilNextBlock));
+        result.timestampForHeader(), Math.max(0, milliSecondsUntilNextBlock));
   }
 
   private int calculateTurnBasedDelay(final BlockHeader parentHeader) {

consensus/clique/src/test/java/org/hyperledger/besu/consensus/clique/blockcreation/CliqueBlockMinerTest.java

@@ -34,6 +34,7 @@
 import org.hyperledger.besu.crypto.SignatureAlgorithmFactory;
 import org.hyperledger.besu.datatypes.Address;
 import org.hyperledger.besu.ethereum.ProtocolContext;
+import org.hyperledger.besu.ethereum.blockcreation.BlockCreationTiming;
 import org.hyperledger.besu.ethereum.blockcreation.BlockCreator;
 import org.hyperledger.besu.ethereum.blockcreation.DefaultBlockScheduler;
 import org.hyperledger.besu.ethereum.blockcreation.txselection.TransactionSelectionResults;
@@ -93,7 +94,8 @@ void doesNotMineBlockIfNoTransactionsWhenEmptyBlocksNotAllowed() throws Interrup
         (parentHeader) -> blockCreator;
     when(blockCreator.createBlock(anyLong()))
         .thenReturn(
-            new BlockCreator.BlockCreationResult(blockToCreate, new TransactionSelectionResults()));
+            new BlockCreator.BlockCreationResult(
+                blockToCreate, new TransactionSelectionResults(), new BlockCreationTiming()));
 
     final BlockImporter blockImporter = mock(BlockImporter.class);
     final ProtocolSpec protocolSpec = mock(ProtocolSpec.class);
@@ -148,7 +150,8 @@ void minesBlockIfHasTransactionsWhenEmptyBlocksNotAllowed() throws InterruptedEx
         (parentHeader) -> blockCreator;
     when(blockCreator.createBlock(anyLong()))
         .thenReturn(
-            new BlockCreator.BlockCreationResult(blockToCreate, new TransactionSelectionResults()));
+            new BlockCreator.BlockCreationResult(
+                blockToCreate, new TransactionSelectionResults(), new BlockCreationTiming()));
 
     final BlockImporter blockImporter = mock(BlockImporter.class);
     final ProtocolSpec protocolSpec = mock(ProtocolSpec.class);

consensus/clique/src/test/java/org/hyperledger/besu/consensus/clique/blockcreation/CliqueBlockSchedulerTest.java

@@ -84,9 +84,9 @@ public void inturnValidatorWaitsExactlyBlockInterval() {
 
     final BlockCreationTimeResult result = scheduler.getNextTimestamp(parentHeader);
 
-    assertThat(result.getTimestampForHeader())
+    assertThat(result.timestampForHeader())
         .isEqualTo(currentSecondsSinceEpoch + secondsBetweenBlocks);
-    assertThat(result.getMillisecondsUntilValid()).isEqualTo(secondsBetweenBlocks * 1000);
+    assertThat(result.millisecondsUntilValid()).isEqualTo(secondsBetweenBlocks * 1000);
   }
 
   @Test
@@ -117,25 +117,25 @@ public void validatorWithTransitionForBlockTimeWaitsBlockInterval() {
     BlockHeader parentHeader =
         blockHeaderBuilder.number(2).timestamp(currentSecondsSinceEpoch).buildHeader();
     BlockCreationTimeResult result = scheduler.getNextTimestamp(parentHeader);
-    assertThat(result.getTimestampForHeader()).isEqualTo(currentSecondsSinceEpoch + 5);
-    assertThat(result.getMillisecondsUntilValid()).isGreaterThan(5 * 1000);
+    assertThat(result.timestampForHeader()).isEqualTo(currentSecondsSinceEpoch + 5);
+    assertThat(result.millisecondsUntilValid()).isGreaterThan(5 * 1000);
 
     // getNextTimestamp for transition block
     // There are 2 validators, therefore block 4 will put localAddr as the in-turn voter, therefore
     // parent block should be number 3.
     parentHeader = blockHeaderBuilder.number(3).timestamp(currentSecondsSinceEpoch).buildHeader();
     result = scheduler.getNextTimestamp(parentHeader);
-    assertThat(result.getTimestampForHeader()).isEqualTo(currentSecondsSinceEpoch + 1);
-    assertThat(result.getMillisecondsUntilValid()).isEqualTo(1000);
+    assertThat(result.timestampForHeader()).isEqualTo(currentSecondsSinceEpoch + 1);
+    assertThat(result.millisecondsUntilValid()).isEqualTo(1000);
 
     // getNextTimestamp for block after transition
     // There are 2 validators, therefore block 5 will put localAddr as the out-of-turn voter,
     // therefore
     // parent block should be number 4.
     parentHeader = blockHeaderBuilder.number(4).timestamp(currentSecondsSinceEpoch).buildHeader();
     result = scheduler.getNextTimestamp(parentHeader);
-    assertThat(result.getTimestampForHeader()).isEqualTo(currentSecondsSinceEpoch + 1);
-    assertThat(result.getMillisecondsUntilValid()).isGreaterThan(1000);
+    assertThat(result.timestampForHeader()).isEqualTo(currentSecondsSinceEpoch + 1);
+    assertThat(result.millisecondsUntilValid()).isGreaterThan(1000);
   }
 
   @Test
@@ -154,9 +154,9 @@ public void outOfTurnValidatorWaitsLongerThanBlockInterval() {
     final BlockCreationTimeResult result = scheduler.getNextTimestamp(parentHeader);
 
     long secondsBetweenBlocks = 5L;
-    assertThat(result.getTimestampForHeader())
+    assertThat(result.timestampForHeader())
         .isEqualTo(currentSecondsSinceEpoch + secondsBetweenBlocks);
-    assertThat(result.getMillisecondsUntilValid()).isGreaterThan(secondsBetweenBlocks * 1000);
+    assertThat(result.millisecondsUntilValid()).isGreaterThan(secondsBetweenBlocks * 1000);
   }
 
   @Test
@@ -178,7 +178,7 @@ public void inTurnValidatorCreatesBlockNowIFParentTimestampSufficientlyBehindNow
 
     final BlockCreationTimeResult result = scheduler.getNextTimestamp(parentHeader);
 
-    assertThat(result.getTimestampForHeader()).isEqualTo(currentSecondsSinceEpoch);
-    assertThat(result.getMillisecondsUntilValid()).isEqualTo(0);
+    assertThat(result.timestampForHeader()).isEqualTo(currentSecondsSinceEpoch);
+    assertThat(result.millisecondsUntilValid()).isEqualTo(0);
   }
 }

consensus/ibft/src/test/java/org/hyperledger/besu/consensus/ibft/statemachine/IbftBlockHeightManagerTest.java

@@ -61,6 +61,7 @@
 import org.hyperledger.besu.datatypes.Address;
 import org.hyperledger.besu.datatypes.Hash;
 import org.hyperledger.besu.ethereum.ProtocolContext;
+import org.hyperledger.besu.ethereum.blockcreation.BlockCreationTiming;
 import org.hyperledger.besu.ethereum.blockcreation.BlockCreator.BlockCreationResult;
 import org.hyperledger.besu.ethereum.blockcreation.txselection.TransactionSelectionResults;
 import org.hyperledger.besu.ethereum.chain.BadBlockManager;
@@ -157,7 +158,9 @@ public void setup() {
     when(finalState.getValidatorMulticaster()).thenReturn(validatorMulticaster);
     lenient()
         .when(blockCreator.createBlock(anyLong()))
-        .thenReturn(new BlockCreationResult(createdBlock, new TransactionSelectionResults()));
+        .thenReturn(
+            new BlockCreationResult(
+                createdBlock, new TransactionSelectionResults(), new BlockCreationTiming()));
 
     lenient()
         .when(futureRoundProposalMessageValidator.validateProposalMessage(any()))

consensus/ibft/src/test/java/org/hyperledger/besu/consensus/ibft/statemachine/IbftRoundTest.java

@@ -47,6 +47,7 @@
 import org.hyperledger.besu.cryptoservices.NodeKeyUtils;
 import org.hyperledger.besu.datatypes.Hash;
 import org.hyperledger.besu.ethereum.ProtocolContext;
+import org.hyperledger.besu.ethereum.blockcreation.BlockCreationTiming;
 import org.hyperledger.besu.ethereum.blockcreation.BlockCreator.BlockCreationResult;
 import org.hyperledger.besu.ethereum.blockcreation.txselection.TransactionSelectionResults;
 import org.hyperledger.besu.ethereum.chain.BadBlockManager;
@@ -131,7 +132,9 @@ public void setup() {
 
     lenient()
         .when(blockCreator.createBlock(anyLong()))
-        .thenReturn(new BlockCreationResult(proposedBlock, new TransactionSelectionResults()));
+        .thenReturn(
+            new BlockCreationResult(
+                proposedBlock, new TransactionSelectionResults(), new BlockCreationTiming()));
 
     lenient().when(protocolSpec.getBlockImporter()).thenReturn(blockImporter);
     lenient().when(protocolSchedule.getByBlockHeader(any())).thenReturn(protocolSpec);

consensus/qbft/src/main/java/org/hyperledger/besu/consensus/qbft/blockcreation/PkiQbftBlockCreator.java

@@ -25,6 +25,7 @@
 import org.hyperledger.besu.consensus.qbft.pki.PkiQbftExtraData;
 import org.hyperledger.besu.consensus.qbft.pki.PkiQbftExtraDataCodec;
 import org.hyperledger.besu.datatypes.Hash;
+import org.hyperledger.besu.ethereum.blockcreation.BlockCreationTiming;
 import org.hyperledger.besu.ethereum.blockcreation.BlockCreator;
 import org.hyperledger.besu.ethereum.core.Block;
 import org.hyperledger.besu.ethereum.core.BlockHeader;
@@ -172,6 +173,7 @@ private BlockCreationResult replaceCmsInBlock(final BlockCreationResult blockCre
 
     return new BlockCreationResult(
         new Block(newHeader, block.getBody()),
-        blockCreationResult.getTransactionSelectionResults());
+        blockCreationResult.getTransactionSelectionResults(),
+        new BlockCreationTiming());
   }
 }

consensus/qbft/src/test/java/org/hyperledger/besu/consensus/qbft/blockcreation/PkiQbftBlockCreatorTest.java

@@ -32,6 +32,7 @@
 import org.hyperledger.besu.consensus.qbft.pki.PkiQbftExtraData;
 import org.hyperledger.besu.consensus.qbft.pki.PkiQbftExtraDataCodec;
 import org.hyperledger.besu.datatypes.Hash;
+import org.hyperledger.besu.ethereum.blockcreation.BlockCreationTiming;
 import org.hyperledger.besu.ethereum.blockcreation.BlockCreator;
 import org.hyperledger.besu.ethereum.blockcreation.BlockCreator.BlockCreationResult;
 import org.hyperledger.besu.ethereum.blockcreation.txselection.TransactionSelectionResults;
@@ -148,9 +149,13 @@ private Block createBlockBeingProposed() {
             blockHeaderWithExtraData,
             new BlockBody(Collections.emptyList(), Collections.emptyList()));
     when(blockCreator.createBlock(eq(1L)))
-        .thenReturn(new BlockCreationResult(block, new TransactionSelectionResults()));
+        .thenReturn(
+            new BlockCreationResult(
+                block, new TransactionSelectionResults(), new BlockCreationTiming()));
     when(blockCreator.createEmptyWithdrawalsBlock(anyLong()))
-        .thenReturn(new BlockCreationResult(block, new TransactionSelectionResults()));
+        .thenReturn(
+            new BlockCreationResult(
+                block, new TransactionSelectionResults(), new BlockCreationTiming()));
 
     return block;
   }

consensus/qbft/src/test/java/org/hyperledger/besu/consensus/qbft/statemachine/QbftBlockHeightManagerTest.java

@@ -60,6 +60,7 @@
 import org.hyperledger.besu.datatypes.Address;
 import org.hyperledger.besu.datatypes.Hash;
 import org.hyperledger.besu.ethereum.ProtocolContext;
+import org.hyperledger.besu.ethereum.blockcreation.BlockCreationTiming;
 import org.hyperledger.besu.ethereum.blockcreation.BlockCreator.BlockCreationResult;
 import org.hyperledger.besu.ethereum.blockcreation.txselection.TransactionSelectionResults;
 import org.hyperledger.besu.ethereum.chain.BadBlockManager;
@@ -157,7 +158,9 @@ public void setup() {
     when(finalState.getQuorum()).thenReturn(3);
     when(finalState.getValidatorMulticaster()).thenReturn(validatorMulticaster);
     when(blockCreator.createBlock(anyLong()))
-        .thenReturn(new BlockCreationResult(createdBlock, new TransactionSelectionResults()));
+        .thenReturn(
+            new BlockCreationResult(
+                createdBlock, new TransactionSelectionResults(), new BlockCreationTiming()));
 
     when(futureRoundProposalMessageValidator.validateProposalMessage(any())).thenReturn(true);
     when(messageValidatorFactory.createFutureRoundProposalMessageValidator(anyLong(), any()))

consensus/qbft/src/test/java/org/hyperledger/besu/consensus/qbft/statemachine/QbftRoundTest.java

@@ -50,6 +50,7 @@
 import org.hyperledger.besu.cryptoservices.NodeKeyUtils;
 import org.hyperledger.besu.datatypes.Hash;
 import org.hyperledger.besu.ethereum.ProtocolContext;
+import org.hyperledger.besu.ethereum.blockcreation.BlockCreationTiming;
 import org.hyperledger.besu.ethereum.blockcreation.BlockCreator.BlockCreationResult;
 import org.hyperledger.besu.ethereum.blockcreation.txselection.TransactionSelectionResults;
 import org.hyperledger.besu.ethereum.chain.BadBlockManager;
@@ -139,7 +140,9 @@ QbftContext.class, emptyList(), new QbftExtraDataCodec()),
     proposedBlock = new Block(header, new BlockBody(emptyList(), emptyList()));
 
     when(blockCreator.createBlock(anyLong()))
-        .thenReturn(new BlockCreationResult(proposedBlock, new TransactionSelectionResults()));
+        .thenReturn(
+            new BlockCreationResult(
+                proposedBlock, new TransactionSelectionResults(), new BlockCreationTiming()));
 
     when(protocolSchedule.getByBlockHeader(any())).thenReturn(protocolSpec);
     when(protocolSpec.getBlockImporter()).thenReturn(blockImporter);

ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockCreator.java

@@ -190,7 +190,10 @@ protected BlockCreationResult createBlock(
       final long timestamp,
       boolean rewardCoinbase) {
 
+    final var timings = new BlockCreationTiming();
+
     try (final MutableWorldState disposableWorldState = duplicateWorldStateAtParent()) {
+      timings.register("duplicateWorldState");
       final ProtocolSpec newProtocolSpec =
           protocolSchedule.getForNextBlockHeader(parentHeader, timestamp);
 
@@ -218,7 +221,7 @@ protected BlockCreationResult createBlock(
           pluginTransactionSelector.getOperationTracer();
 
       operationTracer.traceStartBlock(processableBlockHeader);
-
+      timings.register("preTxsSelection");
       final TransactionSelectionResults transactionResults =
           selectTransactions(
               processableBlockHeader,
@@ -227,9 +230,8 @@ protected BlockCreationResult createBlock(
               miningBeneficiary,
               newProtocolSpec,
               pluginTransactionSelector);
-
       transactionResults.logSelectionStats();
-
+      timings.register("txsSelection");
       throwIfStopped();
 
       final Optional<WithdrawalsProcessor> maybeWithdrawalsProcessor =
@@ -319,8 +321,8 @@ protected BlockCreationResult createBlock(
       final Block block = new Block(blockHeader, blockBody);
 
       operationTracer.traceEndBlock(blockHeader, blockBody);
-
-      return new BlockCreationResult(block, transactionResults);
+      timings.register("blockAssembled");
+      return new BlockCreationResult(block, transactionResults, timings);
     } catch (final SecurityModuleException ex) {
       throw new IllegalStateException("Failed to create block signature", ex);
     } catch (final CancellationException | StorageException ex) {

ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockScheduler.java

@@ -37,23 +37,5 @@ public long waitUntilNextBlockCanBeMined(final BlockHeader parentHeader)
 
   public abstract BlockCreationTimeResult getNextTimestamp(final BlockHeader parentHeader);
 
-  public static class BlockCreationTimeResult {
-
-    private final long timestampForHeader;
-    private final long millisecondsUntilValid;
-
-    public BlockCreationTimeResult(
-        final long timestampForHeader, final long millisecondsUntilValid) {
-      this.timestampForHeader = timestampForHeader;
-      this.millisecondsUntilValid = millisecondsUntilValid;
-    }
-
-    public long getTimestampForHeader() {
-      return timestampForHeader;
-    }
-
-    public long getMillisecondsUntilValid() {
-      return millisecondsUntilValid;
-    }
-  }
+  public record BlockCreationTimeResult(long timestampForHeader, long millisecondsUntilValid) {}
 }

ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockCreationTiming.java

@@ -0,0 +1,66 @@
+/*
+ * Copyright Hyperledger Besu Contributors.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on
+ * an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the
+ * specific language governing permissions and limitations under the License.
+ *
+ * SPDX-License-Identifier: Apache-2.0
+ */
+package org.hyperledger.besu.ethereum.blockcreation;
+
+import java.time.Duration;
+import java.time.Instant;
+import java.util.LinkedHashMap;
+import java.util.Map;
+
+import com.google.common.base.Stopwatch;
+
+public class BlockCreationTiming {
+  private final Map<String, Duration> timing = new LinkedHashMap<>();
+  private final Stopwatch stopwatch;
+  private final Instant startedAt = Instant.now();
+
+  public BlockCreationTiming() {
+    this.stopwatch = Stopwatch.createStarted();
+  }
+
+  public void register(final String step) {
+    timing.put(step, stopwatch.elapsed());
+  }
+
+  public void registerAll(final BlockCreationTiming subTiming) {
+    final var offset = Duration.between(startedAt, subTiming.startedAt);
+    for (final var entry : subTiming.timing.entrySet()) {
+      timing.put(entry.getKey(), offset.plus(entry.getValue()));
+    }
+  }
+
+  public Duration end(final String step) {
+    final var elapsed = stopwatch.stop().elapsed();
+    timing.put(step, elapsed);
+    return elapsed;
+  }
+
+  @Override
+  public String toString() {
+    final var sb = new StringBuilder("Started at " + startedAt + ", ");
+
+    var prevDuration = Duration.ZERO;
+    for (final var entry : timing.entrySet()) {
+      sb.append(entry.getKey())
+          .append("=")
+          .append(entry.getValue().minus(prevDuration).toMillis())
+          .append("ms, ");
+      prevDuration = entry.getValue();
+    }
+    sb.delete(sb.length() - 2, sb.length());
+
+    return sb.toString();
+  }
+}

ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockCreator.java

@@ -26,11 +26,15 @@ public interface BlockCreator {
   class BlockCreationResult {
     private final Block block;
     private final TransactionSelectionResults transactionSelectionResults;
+    private final BlockCreationTiming blockCreationTiming;
 
     public BlockCreationResult(
-        final Block block, final TransactionSelectionResults transactionSelectionResults) {
+        final Block block,
+        final TransactionSelectionResults transactionSelectionResults,
+        final BlockCreationTiming timings) {
       this.block = block;
       this.transactionSelectionResults = transactionSelectionResults;
+      this.blockCreationTiming = timings;
     }
 
     public Block getBlock() {
@@ -40,6 +44,10 @@ public Block getBlock() {
     public TransactionSelectionResults getTransactionSelectionResults() {
       return transactionSelectionResults;
     }
+
+    public BlockCreationTiming getBlockCreationTimings() {
+      return blockCreationTiming;
+    }
   }
 
   BlockCreationResult createBlock(final long timestamp);