From 8064da02178f6863923ac906be5def3126554fd8 Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Mon, 8 Apr 2024 13:34:20 +0200 Subject: [PATCH] Log detailed timing of block creation steps (#6880) Signed-off-by: Fabio Di Fabio --- CHANGELOG.md | 1 + .../blockcreation/CliqueBlockScheduler.java | 4 +- .../blockcreation/CliqueBlockMinerTest.java | 7 +- .../CliqueBlockSchedulerTest.java | 24 +++---- .../IbftBlockHeightManagerTest.java | 5 +- .../ibft/statemachine/IbftRoundTest.java | 5 +- .../blockcreation/PkiQbftBlockCreator.java | 4 +- .../PkiQbftBlockCreatorTest.java | 9 ++- .../QbftBlockHeightManagerTest.java | 5 +- .../qbft/statemachine/QbftRoundTest.java | 5 +- .../blockcreation/AbstractBlockCreator.java | 12 ++-- .../blockcreation/AbstractBlockScheduler.java | 20 +----- .../blockcreation/BlockCreationTiming.java | 66 +++++++++++++++++++ .../ethereum/blockcreation/BlockCreator.java | 10 ++- .../ethereum/blockcreation/BlockMiner.java | 48 +++++++++----- .../blockcreation/DefaultBlockScheduler.java | 4 +- .../blockcreation/BlockMinerTest.java | 12 +++- .../DefaultBlockSchedulerTest.java | 10 +-- 18 files changed, 176 insertions(+), 75 deletions(-) create mode 100644 ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockCreationTiming.java diff --git a/CHANGELOG.md b/CHANGELOG.md index ed7d0aa12f8..506de63a077 100644 --- a/CHANGELOG.md +++ b/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) diff --git a/consensus/clique/src/main/java/org/hyperledger/besu/consensus/clique/blockcreation/CliqueBlockScheduler.java b/consensus/clique/src/main/java/org/hyperledger/besu/consensus/clique/blockcreation/CliqueBlockScheduler.java index 994b8fed137..5ffa78e09f1 100644 --- a/consensus/clique/src/main/java/org/hyperledger/besu/consensus/clique/blockcreation/CliqueBlockScheduler.java +++ b/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) { diff --git a/consensus/clique/src/test/java/org/hyperledger/besu/consensus/clique/blockcreation/CliqueBlockMinerTest.java b/consensus/clique/src/test/java/org/hyperledger/besu/consensus/clique/blockcreation/CliqueBlockMinerTest.java index a29a20d14d6..cfd4270d8df 100644 --- a/consensus/clique/src/test/java/org/hyperledger/besu/consensus/clique/blockcreation/CliqueBlockMinerTest.java +++ b/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); diff --git a/consensus/clique/src/test/java/org/hyperledger/besu/consensus/clique/blockcreation/CliqueBlockSchedulerTest.java b/consensus/clique/src/test/java/org/hyperledger/besu/consensus/clique/blockcreation/CliqueBlockSchedulerTest.java index fddcce39091..ed973306dc3 100644 --- a/consensus/clique/src/test/java/org/hyperledger/besu/consensus/clique/blockcreation/CliqueBlockSchedulerTest.java +++ b/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,16 +117,16 @@ 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, @@ -134,8 +134,8 @@ public void validatorWithTransitionForBlockTimeWaitsBlockInterval() { // 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); } } diff --git a/consensus/ibft/src/test/java/org/hyperledger/besu/consensus/ibft/statemachine/IbftBlockHeightManagerTest.java b/consensus/ibft/src/test/java/org/hyperledger/besu/consensus/ibft/statemachine/IbftBlockHeightManagerTest.java index feb5bbc97d7..68e0ee5efe5 100644 --- a/consensus/ibft/src/test/java/org/hyperledger/besu/consensus/ibft/statemachine/IbftBlockHeightManagerTest.java +++ b/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())) diff --git a/consensus/ibft/src/test/java/org/hyperledger/besu/consensus/ibft/statemachine/IbftRoundTest.java b/consensus/ibft/src/test/java/org/hyperledger/besu/consensus/ibft/statemachine/IbftRoundTest.java index e93f2f9f40c..e948f43f3bf 100644 --- a/consensus/ibft/src/test/java/org/hyperledger/besu/consensus/ibft/statemachine/IbftRoundTest.java +++ b/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); diff --git a/consensus/qbft/src/main/java/org/hyperledger/besu/consensus/qbft/blockcreation/PkiQbftBlockCreator.java b/consensus/qbft/src/main/java/org/hyperledger/besu/consensus/qbft/blockcreation/PkiQbftBlockCreator.java index ea4c851b7f2..b3811a8aa34 100644 --- a/consensus/qbft/src/main/java/org/hyperledger/besu/consensus/qbft/blockcreation/PkiQbftBlockCreator.java +++ b/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()); } } diff --git a/consensus/qbft/src/test/java/org/hyperledger/besu/consensus/qbft/blockcreation/PkiQbftBlockCreatorTest.java b/consensus/qbft/src/test/java/org/hyperledger/besu/consensus/qbft/blockcreation/PkiQbftBlockCreatorTest.java index 1a597b790e6..e8282f9de9b 100644 --- a/consensus/qbft/src/test/java/org/hyperledger/besu/consensus/qbft/blockcreation/PkiQbftBlockCreatorTest.java +++ b/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; } diff --git a/consensus/qbft/src/test/java/org/hyperledger/besu/consensus/qbft/statemachine/QbftBlockHeightManagerTest.java b/consensus/qbft/src/test/java/org/hyperledger/besu/consensus/qbft/statemachine/QbftBlockHeightManagerTest.java index 4a2dd5b9b86..a0479860845 100644 --- a/consensus/qbft/src/test/java/org/hyperledger/besu/consensus/qbft/statemachine/QbftBlockHeightManagerTest.java +++ b/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())) diff --git a/consensus/qbft/src/test/java/org/hyperledger/besu/consensus/qbft/statemachine/QbftRoundTest.java b/consensus/qbft/src/test/java/org/hyperledger/besu/consensus/qbft/statemachine/QbftRoundTest.java index bf730bbf7e6..838ec71e0dd 100644 --- a/consensus/qbft/src/test/java/org/hyperledger/besu/consensus/qbft/statemachine/QbftRoundTest.java +++ b/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); diff --git a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockCreator.java b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockCreator.java index 4da6b3970a6..a1fec9475d1 100644 --- a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockCreator.java +++ b/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 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) { diff --git a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockScheduler.java b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockScheduler.java index bce8d480e5b..12246be0016 100644 --- a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockScheduler.java +++ b/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) {} } diff --git a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockCreationTiming.java b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockCreationTiming.java new file mode 100644 index 00000000000..71c649bbff6 --- /dev/null +++ b/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 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(); + } +} diff --git a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockCreator.java b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockCreator.java index 389c0c16f81..24bff4c47ee 100644 --- a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockCreator.java +++ b/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); diff --git a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockMiner.java b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockMiner.java index 34ac04bf880..96ba91ab86a 100644 --- a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockMiner.java +++ b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockMiner.java @@ -29,10 +29,8 @@ 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 BlockCreationResult createBlock( final List transactions, final List 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 @@ protected boolean shouldImportBlock(final Block block) throws InterruptedExcepti 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 @@ protected boolean mineBlock() throws InterruptedException { 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(); } diff --git a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/DefaultBlockScheduler.java b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/DefaultBlockScheduler.java index 1e0830d3e4e..327cba4a85a 100644 --- a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/DefaultBlockScheduler.java +++ b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/DefaultBlockScheduler.java @@ -54,8 +54,8 @@ public BlockCreationTimeResult getNextTimestamp(final BlockHeader parentHeader) 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)); } } diff --git a/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/BlockMinerTest.java b/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/BlockMinerTest.java index 066fe5b2be3..3910d899d96 100644 --- a/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/BlockMinerTest.java +++ b/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/BlockMinerTest.java @@ -64,7 +64,9 @@ public void blockCreatedIsAddedToBlockChain() throws InterruptedException { final Function 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 void failureToImportDoesNotTriggerObservers() throws InterruptedException final Function 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 void blockValidationFailureBeforeImportDoesNotImportBlock() throws Interr final Function 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); diff --git a/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/DefaultBlockSchedulerTest.java b/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/DefaultBlockSchedulerTest.java index 0bb0ba1dd1a..a31f1cacf94 100644 --- a/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/DefaultBlockSchedulerTest.java +++ b/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/DefaultBlockSchedulerTest.java @@ -47,8 +47,8 @@ public void canMineBlockOnLimitOfClockDrift() { 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 void childBlockWithinClockDriftReportsTimeToValidOfZero() { final AbstractBlockScheduler.BlockCreationTimeResult result = scheduler.getNextTimestamp(parentBlock); - assertThat(result.getMillisecondsUntilValid()).isEqualTo(0); + assertThat(result.millisecondsUntilValid()).isEqualTo(0); } @Test @@ -81,7 +81,7 @@ public void mustWaitForNextBlockIfTooFarAheadOfSystemTime() { 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 void ifParentTimestampIsBehindCurrentTimeChildUsesCurrentTime() { final AbstractBlockScheduler.BlockCreationTimeResult result = scheduler.getNextTimestamp(parentBlock); - assertThat(result.getTimestampForHeader()).isEqualTo(secondsSinceEpoch); + assertThat(result.timestampForHeader()).isEqualTo(secondsSinceEpoch); } }