Log detailed timing of block creation steps (#6880)

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

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 class CliqueBlockScheduler extends DefaultBlockScheduler {
     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.KeyPair;
 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 @@ class CliqueBlockMinerTest {
         (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 @@ class CliqueBlockMinerTest {
         (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 class CliqueBlockSchedulerTest {
 
     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,16 +117,16 @@ public class CliqueBlockSchedulerTest {
     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,
@@ -134,8 +134,8 @@ public class CliqueBlockSchedulerTest {
     // 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 class CliqueBlockSchedulerTest {
     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 class CliqueBlockSchedulerTest {
 
     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.cryptoservices.NodeKeyUtils;
 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 class IbftBlockHeightManagerTest {
     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.NodeKey;
 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 class IbftRoundTest {
 
     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.PkiQbftBlockHeaderFunctions;
 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 @@ public class PkiQbftBlockCreator implements BlockCreator {
 
     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.PkiQbftBlockHeaderFunctions;
 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 @@ public class PkiQbftBlockCreatorTest {
             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.cryptoservices.NodeKeyUtils;
 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 class QbftBlockHeightManagerTest {
     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.NodeKey;
 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 @@ public class QbftRoundTest {
     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 @@ public abstract class AbstractBlockCreator implements AsyncBlockCreator {
       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 @@ public abstract class AbstractBlockCreator implements AsyncBlockCreator {
           pluginTransactionSelector.getOperationTracer();
 
       operationTracer.traceStartBlock(processableBlockHeader);
-
+      timings.register("preTxsSelection");
       final TransactionSelectionResults transactionResults =
           selectTransactions(
               processableBlockHeader,
@@ -227,9 +230,8 @@ public abstract class AbstractBlockCreator implements AsyncBlockCreator {
               miningBeneficiary,
               newProtocolSpec,
               pluginTransactionSelector);
-
       transactionResults.logSelectionStats();
-
+      timings.register("txsSelection");
       throwIfStopped();
 
       final Optional<WithdrawalsProcessor> maybeWithdrawalsProcessor =
@@ -319,8 +321,8 @@ public abstract class AbstractBlockCreator implements AsyncBlockCreator {
       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 abstract class AbstractBlockScheduler {
 
   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 interface BlockCreator {
     public TransactionSelectionResults getTransactionSelectionResults() {
       return transactionSelectionResults;
     }
+
+    public BlockCreationTiming getBlockCreationTimings() {
+      return blockCreationTiming;
+    }
   }
 
   BlockCreationResult createBlock(final long timestamp);

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

@@ -29,10 +29,8 @@ import org.hyperledger.besu.util.Subscribers;
 import java.util.List;
 import java.util.Optional;
 import java.util.concurrent.CancellationException;
-import java.util.concurrent.TimeUnit;
 import java.util.function.Function;
 
-import com.google.common.base.Stopwatch;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
@@ -110,7 +108,7 @@ public class BlockMiner<M extends AbstractBlockCreator> implements Runnable {
       final List<Transaction> transactions,
       final List<BlockHeader> ommers) {
     final BlockCreator blockCreator = this.blockCreatorFactory.apply(parentHeader);
-    final long timestamp = scheduler.getNextTimestamp(parentHeader).getTimestampForHeader();
+    final long timestamp = scheduler.getNextTimestamp(parentHeader).timestampForHeader();
     return blockCreator.createBlock(transactions, ommers, timestamp);
   }
 
@@ -133,13 +131,19 @@ public class BlockMiner<M extends AbstractBlockCreator> implements Runnable {
   protected boolean mineBlock() throws InterruptedException {
     // Ensure the block is allowed to be mined - i.e. the timestamp on the new block is sufficiently
     // ahead of the parent, and still within allowable clock tolerance.
+    final var timing = new BlockCreationTiming();
+
     LOG.trace("Started a mining operation.");
 
     final long newBlockTimestamp = scheduler.waitUntilNextBlockCanBeMined(parentHeader);
+    timing.register("protocolWait");
 
-    final Stopwatch stopwatch = Stopwatch.createStarted();
     LOG.trace("Mining a new block with timestamp {}", newBlockTimestamp);
-    final Block block = minerBlockCreator.createBlock(newBlockTimestamp).getBlock();
+
+    final var blockCreationResult = minerBlockCreator.createBlock(newBlockTimestamp);
+    timing.registerAll(blockCreationResult.getBlockCreationTimings());
+
+    final Block block = blockCreationResult.getBlock();
     LOG.trace(
         "Block created, importing to local chain, block includes {} transactions",
         block.getBody().getTransactions().size());
@@ -152,26 +156,36 @@ public class BlockMiner<M extends AbstractBlockCreator> implements Runnable {
         protocolSchedule.getByBlockHeader(block.getHeader()).getBlockImporter();
     final BlockImportResult blockImportResult =
         importer.importBlock(protocolContext, block, HeaderValidationMode.FULL);
+    timing.register("importingBlock");
     if (blockImportResult.isImported()) {
       notifyNewBlockListeners(block);
-      final double taskTimeInSec = stopwatch.elapsed(TimeUnit.MILLISECONDS) / 1000.0;
-      LOG.info(
-          String.format(
-              "Produced #%,d / %d tx / %d om / %,d (%01.1f%%) gas / (%s) in %01.3fs",
-              block.getHeader().getNumber(),
-              block.getBody().getTransactions().size(),
-              block.getBody().getOmmers().size(),
-              block.getHeader().getGasUsed(),
-              (block.getHeader().getGasUsed() * 100.0) / block.getHeader().getGasLimit(),
-              block.getHash(),
-              taskTimeInSec));
+      timing.register("notifyListeners");
+      logProducedBlock(block, timing);
     } else {
       LOG.error("Illegal block mined, could not be imported to local chain.");
     }
-
     return blockImportResult.isImported();
   }
 
+  private void logProducedBlock(final Block block, final BlockCreationTiming blockCreationTiming) {
+    String log =
+        String.format(
+            "Produced #%,d / %d tx / %d om / %,d (%01.1f%%) gas / (%s) in %01.3fs",
+            block.getHeader().getNumber(),
+            block.getBody().getTransactions().size(),
+            block.getBody().getOmmers().size(),
+            block.getHeader().getGasUsed(),
+            (block.getHeader().getGasUsed() * 100.0) / block.getHeader().getGasLimit(),
+            block.getHash(),
+            blockCreationTiming.end("log").getSeconds() / 1000.0);
+
+    if (LOG.isDebugEnabled()) {
+      log = log + ", timing [" + blockCreationTiming + "]";
+    }
+
+    LOG.info(log);
+  }
+
   public void cancel() {
     minerBlockCreator.cancel();
   }

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

@@ -54,8 +54,8 @@ public class DefaultBlockScheduler extends AbstractBlockScheduler {
     final long nextHeaderTimestamp = Long.max(parentTimestamp + minSecondsSinceParent, now);
 
     final long earliestBlockTransmissionTime = nextHeaderTimestamp - acceptableClockDriftSeconds;
-    final long msUntilBlocKTransmission = (earliestBlockTransmissionTime * 1000) - msSinceEpoch;
+    final long msUntilBlockTransmission = (earliestBlockTransmissionTime * 1000) - msSinceEpoch;
 
-    return new BlockCreationTimeResult(nextHeaderTimestamp, Math.max(0, msUntilBlocKTransmission));
+    return new BlockCreationTimeResult(nextHeaderTimestamp, Math.max(0, msUntilBlockTransmission));
   }
 }

ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/BlockMinerTest.java

@@ -64,7 +64,9 @@ public class BlockMinerTest {
     final Function<BlockHeader, PoWBlockCreator> blockCreatorSupplier =
         (parentHeader) -> blockCreator;
     when(blockCreator.createBlock(anyLong()))
-        .thenReturn(new BlockCreationResult(blockToCreate, new TransactionSelectionResults()));
+        .thenReturn(
+            new BlockCreationResult(
+                blockToCreate, new TransactionSelectionResults(), new BlockCreationTiming()));
 
     final BlockImporter blockImporter = mock(BlockImporter.class);
     final ProtocolSpec protocolSpec = mock(ProtocolSpec.class);
@@ -106,7 +108,9 @@ public class BlockMinerTest {
     final Function<BlockHeader, PoWBlockCreator> blockCreatorSupplier =
         (parentHeader) -> blockCreator;
     when(blockCreator.createBlock(anyLong()))
-        .thenReturn(new BlockCreationResult(blockToCreate, new TransactionSelectionResults()));
+        .thenReturn(
+            new BlockCreationResult(
+                blockToCreate, new TransactionSelectionResults(), new BlockCreationTiming()));
 
     final BlockImporter blockImporter = mock(BlockImporter.class);
     final ProtocolSpec protocolSpec = mock(ProtocolSpec.class);
@@ -152,7 +156,9 @@ public class BlockMinerTest {
     final Function<BlockHeader, PoWBlockCreator> blockCreatorSupplier =
         (parentHeader) -> blockCreator;
     when(blockCreator.createBlock(anyLong()))
-        .thenReturn(new BlockCreationResult(blockToCreate, new TransactionSelectionResults()));
+        .thenReturn(
+            new BlockCreationResult(
+                blockToCreate, new TransactionSelectionResults(), new BlockCreationTiming()));
 
     final BlockImporter blockImporter = mock(BlockImporter.class);
     final ProtocolSpec protocolSpec = mock(ProtocolSpec.class);

ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/DefaultBlockSchedulerTest.java

@@ -47,8 +47,8 @@ public class DefaultBlockSchedulerTest {
     final AbstractBlockScheduler.BlockCreationTimeResult result =
         scheduler.getNextTimestamp(parentBlock);
 
-    assertThat(result.getTimestampForHeader()).isEqualTo(parentTimeStamp + interBlockSeconds);
-    assertThat(result.getMillisecondsUntilValid()).isEqualTo(0);
+    assertThat(result.timestampForHeader()).isEqualTo(parentTimeStamp + interBlockSeconds);
+    assertThat(result.millisecondsUntilValid()).isEqualTo(0);
   }
 
   @Test
@@ -64,7 +64,7 @@ public class DefaultBlockSchedulerTest {
     final AbstractBlockScheduler.BlockCreationTimeResult result =
         scheduler.getNextTimestamp(parentBlock);
 
-    assertThat(result.getMillisecondsUntilValid()).isEqualTo(0);
+    assertThat(result.millisecondsUntilValid()).isEqualTo(0);
   }
 
   @Test
@@ -81,7 +81,7 @@ public class DefaultBlockSchedulerTest {
     final AbstractBlockScheduler.BlockCreationTimeResult result =
         scheduler.getNextTimestamp(parentBlock);
 
-    assertThat(result.getMillisecondsUntilValid()).isEqualTo(interBlockSeconds * 1000);
+    assertThat(result.millisecondsUntilValid()).isEqualTo(interBlockSeconds * 1000);
   }
 
   @Test
@@ -99,6 +99,6 @@ public class DefaultBlockSchedulerTest {
     final AbstractBlockScheduler.BlockCreationTimeResult result =
         scheduler.getNextTimestamp(parentBlock);
 
-    assertThat(result.getTimestampForHeader()).isEqualTo(secondsSinceEpoch);
+    assertThat(result.timestampForHeader()).isEqualTo(secondsSinceEpoch);
   }
 }