diff --git a/CHANGELOG.md b/CHANGELOG.md index 4ee0947a31e..629ef8e18c2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -46,6 +46,7 @@ - Add RPC WS options to specify password file for keystore and truststore [#7970](https://github.com/hyperledger/besu/pull/7970) - Prometheus Java Metrics library upgraded to version 1.3.3 [#7880](https://github.com/hyperledger/besu/pull/7880) - Add histogram to Prometheus metrics system [#7944](https://github.com/hyperledger/besu/pull/7944) +- Improve newPayload and FCU logs [#7961](https://github.com/hyperledger/besu/pull/7961) ### Bug fixes diff --git a/datatypes/src/main/java/org/hyperledger/besu/datatypes/Hash.java b/datatypes/src/main/java/org/hyperledger/besu/datatypes/Hash.java index 3777169ed4d..53a19399a97 100644 --- a/datatypes/src/main/java/org/hyperledger/besu/datatypes/Hash.java +++ b/datatypes/src/main/java/org/hyperledger/besu/datatypes/Hash.java @@ -118,4 +118,16 @@ public static Hash fromHexString(final String str) { public static Hash fromHexStringLenient(final String str) { return new Hash(Bytes32.fromHexStringLenient(str)); } + + /*** + * For logging purposes, this method returns a shortened hex representation + * + * @return shortened string with only the beginning and the end of the hex representation + */ + public String toShortLogString() { + final var hexRepresentation = toFastHex(false); + String firstPart = hexRepresentation.substring(0, 5); + String lastPart = hexRepresentation.substring(hexRepresentation.length() - 5); + return firstPart + "....." + lastPart; + } } diff --git a/datatypes/src/main/java/org/hyperledger/besu/datatypes/Wei.java b/datatypes/src/main/java/org/hyperledger/besu/datatypes/Wei.java index 7b097a9dd1a..1fe2a5ffea5 100644 --- a/datatypes/src/main/java/org/hyperledger/besu/datatypes/Wei.java +++ b/datatypes/src/main/java/org/hyperledger/besu/datatypes/Wei.java @@ -161,11 +161,31 @@ public static Wei fromQuantity(final Quantity quantity) { * @return the string */ public String toHumanReadableString() { + return toHumanReadableStringWithPadding(1); + } + + /** + * Wei to human-readable string, with padding + * + * @return the string + */ + public String toHumanReadablePaddedString() { + return toHumanReadableStringWithPadding(6); + } + + /** + * Returns a human-readable String, the number of returned characters depends on the width + * parameter + * + * @param width the number of digits to use + * @return a human-readable String + */ + private String toHumanReadableStringWithPadding(final int width) { final BigInteger amount = toBigInteger(); final int numOfDigits = amount.toString().length(); final Unit preferredUnit = Unit.getPreferred(numOfDigits); final double res = amount.doubleValue() / preferredUnit.divisor; - return String.format("%1." + preferredUnit.decimals + "f %s", res, preferredUnit); + return String.format("%" + width + "." + preferredUnit.decimals + "f %s", res, preferredUnit); } /** The enum Unit. */ diff --git a/datatypes/src/test/java/org/hyperledger/besu/datatypes/WeiTest.java b/datatypes/src/test/java/org/hyperledger/besu/datatypes/WeiTest.java index 7162f98b026..39162fd2cfd 100644 --- a/datatypes/src/test/java/org/hyperledger/besu/datatypes/WeiTest.java +++ b/datatypes/src/test/java/org/hyperledger/besu/datatypes/WeiTest.java @@ -44,4 +44,28 @@ public void toHumanReadableString() { assertThat(Wei.of(new BigInteger("1" + String.valueOf(manyZeros))).toHumanReadableString()) .isEqualTo("100.00 tether"); } + + @Test + public void toHumanReadablePaddedString() { + assertThat(Wei.ZERO.toHumanReadablePaddedString()).isEqualTo(" 0 wei"); + assertThat(Wei.ONE.toHumanReadablePaddedString()).isEqualTo(" 1 wei"); + + assertThat(Wei.of(999).toHumanReadablePaddedString()).isEqualTo(" 999 wei"); + assertThat(Wei.of(1000).toHumanReadablePaddedString()).isEqualTo(" 1.00 kwei"); + + assertThat(Wei.of(1009).toHumanReadablePaddedString()).isEqualTo(" 1.01 kwei"); + assertThat(Wei.of(1011).toHumanReadablePaddedString()).isEqualTo(" 1.01 kwei"); + + assertThat(Wei.of(new BigInteger("1000000000")).toHumanReadablePaddedString()) + .isEqualTo(" 1.00 gwei"); + + assertThat(Wei.of(new BigInteger("1000000000000000000")).toHumanReadablePaddedString()) + .isEqualTo(" 1.00 ether"); + + final char[] manyZeros = new char[32]; + Arrays.fill(manyZeros, '0'); + assertThat( + Wei.of(new BigInteger("1" + String.valueOf(manyZeros))).toHumanReadablePaddedString()) + .isEqualTo("100.00 tether"); + } } diff --git a/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/AbstractEngineForkchoiceUpdated.java b/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/AbstractEngineForkchoiceUpdated.java index 11ec3d04c59..727677aa8ed 100644 --- a/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/AbstractEngineForkchoiceUpdated.java +++ b/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/AbstractEngineForkchoiceUpdated.java @@ -389,8 +389,7 @@ protected RpcErrorType getInvalidPayloadAttributesError() { // fcU calls are synchronous, no need to make volatile private long lastFcuInfoLog = System.currentTimeMillis(); - private static final String logMessage = - "{} for fork-choice-update: head: {}, finalized: {}, safeBlockHash: {}"; + private static final String logMessage = "FCU({}) | head: {} | finalized: {} | safeBlockHash: {}"; private void logForkchoiceUpdatedCall( final EngineStatus status, final EngineForkchoiceUpdatedParameter forkChoice) { @@ -413,9 +412,9 @@ private void logAtInfo( LOG.info( logMessage, status.name(), - forkChoice.getHeadBlockHash(), - forkChoice.getFinalizedBlockHash(), - forkChoice.getSafeBlockHash()); + forkChoice.getHeadBlockHash().toShortLogString(), + forkChoice.getFinalizedBlockHash().toShortLogString(), + forkChoice.getSafeBlockHash().toShortLogString()); } private void logAtDebug( diff --git a/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/AbstractEngineNewPayload.java b/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/AbstractEngineNewPayload.java index 8562e140f56..ac9dfe221e6 100644 --- a/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/AbstractEngineNewPayload.java +++ b/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/AbstractEngineNewPayload.java @@ -370,7 +370,8 @@ public JsonRpcResponse syncResponse(final JsonRpcRequestContext requestContext) .flatMap(Optional::stream) .mapToInt(List::size) .sum(), - (System.currentTimeMillis() - startTimeMs) / 1000.0); + (System.currentTimeMillis() - startTimeMs) / 1000.0, + executionResult.getNbParallelizedTransations()); return respondWith(reqId, blockParam, newBlockHeader.getHash(), VALID); } else { if (executionResult.causedBy().isPresent()) { @@ -564,26 +565,41 @@ private Optional> extractRequests(final Optional> may .collect(Collectors.toList())); } - private void logImportedBlockInfo(final Block block, final int blobCount, final double timeInS) { + private void logImportedBlockInfo( + final Block block, + final int blobCount, + final double timeInS, + final Optional nbParallelizedTransations) { final StringBuilder message = new StringBuilder(); - message.append("Imported #%,d / %d tx"); + final int nbTransactions = block.getBody().getTransactions().size(); + message.append("Imported #%,d (%s)|%5d tx"); final List messageArgs = new ArrayList<>( - List.of(block.getHeader().getNumber(), block.getBody().getTransactions().size())); + List.of( + block.getHeader().getNumber(), block.getHash().toShortLogString(), nbTransactions)); if (block.getBody().getWithdrawals().isPresent()) { - message.append(" / %d ws"); + message.append("|%3d ws"); messageArgs.add(block.getBody().getWithdrawals().get().size()); } - message.append(" / %d blobs / base fee %s / %,d (%01.1f%%) gas / (%s) in %01.3fs. Peers: %d"); + double mgasPerSec = (timeInS != 0) ? block.getHeader().getGasUsed() / (timeInS * 1_000_000) : 0; + message.append( + "|%2d blobs| base fee %s| gas used %,11d (%5.1f%%)| exec time %01.3fs| mgas/s %6.2f"); messageArgs.addAll( List.of( blobCount, - block.getHeader().getBaseFee().map(Wei::toHumanReadableString).orElse("N/A"), + block.getHeader().getBaseFee().map(Wei::toHumanReadablePaddedString).orElse("N/A"), block.getHeader().getGasUsed(), (block.getHeader().getGasUsed() * 100.0) / block.getHeader().getGasLimit(), - block.getHash().toHexString(), timeInS, - ethPeers.peerCount())); + mgasPerSec)); + if (nbParallelizedTransations.isPresent()) { + double parallelizedTxPercentage = + (double) (nbParallelizedTransations.get() * 100) / nbTransactions; + message.append("| parallel txs %5.1f%%"); + messageArgs.add(parallelizedTxPercentage); + } + message.append("| peers: %2d"); + messageArgs.add(ethPeers.peerCount()); LOG.info(String.format(message.toString(), messageArgs.toArray())); } } diff --git a/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/BlockProcessingResult.java b/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/BlockProcessingResult.java index f34bd056c64..77276caecde 100644 --- a/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/BlockProcessingResult.java +++ b/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/BlockProcessingResult.java @@ -26,6 +26,7 @@ public class BlockProcessingResult extends BlockValidationResult { private final Optional yield; private final boolean isPartial; + private Optional nbParallelizedTransations = Optional.empty(); /** A result indicating that processing failed. */ public static final BlockProcessingResult FAILED = new BlockProcessingResult("processing failed"); @@ -40,6 +41,21 @@ public BlockProcessingResult(final Optional yield) { this.isPartial = false; } + /** + * A result indicating that processing was successful but incomplete. + * + * @param yield the outputs of processing a block + * @param nbParallelizedTransations potential number of parallelized transactions during block + * processing + */ + public BlockProcessingResult( + final Optional yield, + final Optional nbParallelizedTransations) { + this.yield = yield; + this.isPartial = false; + this.nbParallelizedTransations = nbParallelizedTransations; + } + /** * A result indicating that processing was successful but incomplete. * @@ -144,4 +160,13 @@ public List getReceipts() { public Optional> getRequests() { return yield.flatMap(BlockProcessingOutputs::getRequests); } + + /** + * Returns an optional that contains the number of parallelized transactions (if there is any) + * + * @return Optional of parallelized transactions during the block execution + */ + public Optional getNbParallelizedTransations() { + return nbParallelizedTransations; + } } diff --git a/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/MainnetBlockValidator.java b/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/MainnetBlockValidator.java index 00766cdf574..c2925d651bd 100644 --- a/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/MainnetBlockValidator.java +++ b/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/MainnetBlockValidator.java @@ -183,7 +183,8 @@ public BlockProcessingResult validateAndProcessBlock( } return new BlockProcessingResult( - Optional.of(new BlockProcessingOutputs(worldState, receipts, maybeRequests))); + Optional.of(new BlockProcessingOutputs(worldState, receipts, maybeRequests)), + result.getNbParallelizedTransations()); } } catch (MerkleTrieException ex) { context.getWorldStateArchive().heal(ex.getMaybeAddress(), ex.getLocation()); diff --git a/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/mainnet/AbstractBlockProcessor.java b/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/mainnet/AbstractBlockProcessor.java index 496652cdf66..d6a483a955f 100644 --- a/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/mainnet/AbstractBlockProcessor.java +++ b/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/mainnet/AbstractBlockProcessor.java @@ -135,6 +135,8 @@ public BlockProcessingResult processBlock( blockHashLookup, blobGasPrice); + boolean parallelizedTxFound = false; + int nbParallelTx = 0; for (int i = 0; i < transactions.size(); i++) { final Transaction transaction = transactions.get(i); if (!hasAvailableBlockBudget(blockHeader, transaction, currentGasUsed)) { @@ -181,6 +183,13 @@ public BlockProcessingResult processBlock( transactionReceiptFactory.create( transaction.getType(), transactionProcessingResult, worldState, currentGasUsed); receipts.add(transactionReceipt); + if (!parallelizedTxFound + && transactionProcessingResult.getIsProcessedInParallel().isPresent()) { + parallelizedTxFound = true; + nbParallelTx = 1; + } else if (transactionProcessingResult.getIsProcessedInParallel().isPresent()) { + nbParallelTx++; + } } if (blockHeader.getBlobGasUsed().isPresent() && currentBlobGasUsed != blockHeader.getBlobGasUsed().get()) { @@ -243,7 +252,8 @@ public BlockProcessingResult processBlock( } return new BlockProcessingResult( - Optional.of(new BlockProcessingOutputs(worldState, receipts, maybeRequests))); + Optional.of(new BlockProcessingOutputs(worldState, receipts, maybeRequests)), + parallelizedTxFound ? Optional.of(nbParallelTx) : Optional.empty()); } protected Optional runBlockPreProcessing( diff --git a/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/mainnet/parallelization/ParallelizedConcurrentTransactionProcessor.java b/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/mainnet/parallelization/ParallelizedConcurrentTransactionProcessor.java index c6beaa2f40e..a62cc1fffa5 100644 --- a/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/mainnet/parallelization/ParallelizedConcurrentTransactionProcessor.java +++ b/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/mainnet/parallelization/ParallelizedConcurrentTransactionProcessor.java @@ -251,8 +251,10 @@ public Optional applyParallelizedTransactionResult( blockAccumulator.importStateChangesFromSource(transactionAccumulator); - if (confirmedParallelizedTransactionCounter.isPresent()) + if (confirmedParallelizedTransactionCounter.isPresent()) { confirmedParallelizedTransactionCounter.get().inc(); + transactionProcessingResult.setIsProcessedInParallel(Optional.of(Boolean.TRUE)); + } return Optional.of(transactionProcessingResult); } else { blockAccumulator.importPriorStateFromSource(transactionAccumulator); diff --git a/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/processing/TransactionProcessingResult.java b/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/processing/TransactionProcessingResult.java index eca28927bdd..a05ecf3d8fb 100644 --- a/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/processing/TransactionProcessingResult.java +++ b/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/processing/TransactionProcessingResult.java @@ -49,6 +49,8 @@ public enum Status { private final Bytes output; + private Optional isProcessedInParallel = Optional.empty(); + private final ValidationResult validationResult; private final Optional revertReason; @@ -194,6 +196,25 @@ public ValidationResult getValidationResult() { return validationResult; } + /** + * Set isProcessedInParallel to the value in parameter + * + * @param isProcessedInParallel new value of isProcessedInParallel + */ + public void setIsProcessedInParallel(final Optional isProcessedInParallel) { + this.isProcessedInParallel = isProcessedInParallel; + } + + /** + * Returns a flag that indicates if the transaction was executed in parallel + * + * @return Optional of Boolean, the value of the boolean is true if the transaction was executed + * in parallel + */ + public Optional getIsProcessedInParallel() { + return isProcessedInParallel; + } + /** * Returns the reason why a transaction was reverted (if applicable). *