Skip to content

Commit

Permalink
Log detailed timing of block creation steps (#6880)
Browse files Browse the repository at this point in the history
Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>
  • Loading branch information
fab-10 authored Apr 8, 2024
1 parent 6208f8f commit 8064da0
Show file tree
Hide file tree
Showing 18 changed files with 176 additions and 75 deletions.
1 change: 1 addition & 0 deletions CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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()))
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -172,6 +173,7 @@ private BlockCreationResult replaceCmsInBlock(final BlockCreationResult blockCre

return new BlockCreationResult(
new Block(newHeader, block.getBody()),
blockCreationResult.getTransactionSelectionResults());
blockCreationResult.getTransactionSelectionResults(),
new BlockCreationTiming());
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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()))
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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);

Expand Down Expand Up @@ -218,7 +221,7 @@ protected BlockCreationResult createBlock(
pluginTransactionSelector.getOperationTracer();

operationTracer.traceStartBlock(processableBlockHeader);

timings.register("preTxsSelection");
final TransactionSelectionResults transactionResults =
selectTransactions(
processableBlockHeader,
Expand All @@ -227,9 +230,8 @@ protected BlockCreationResult createBlock(
miningBeneficiary,
newProtocolSpec,
pluginTransactionSelector);

transactionResults.logSelectionStats();

timings.register("txsSelection");
throwIfStopped();

final Optional<WithdrawalsProcessor> maybeWithdrawalsProcessor =
Expand Down Expand Up @@ -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) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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) {}
}
Original file line number Diff line number Diff line change
@@ -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();
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand All @@ -40,6 +44,10 @@ public Block getBlock() {
public TransactionSelectionResults getTransactionSelectionResults() {
return transactionSelectionResults;
}

public BlockCreationTiming getBlockCreationTimings() {
return blockCreationTiming;
}
}

BlockCreationResult createBlock(final long timestamp);
Expand Down
Loading

0 comments on commit 8064da0

Please sign in to comment.