Improve newPayload and FCU logs (#7961)

* Change the output log on newPayload and FCU executions Signed-off-by: Ameziane H. <[email protected]> Co-authored-by: Fabio Di Fabio <[email protected]> Co-authored-by: Simon Dudley <[email protected]>
hyperledger · Dec 5, 2024 · d595eee · d595eee
1 parent cdfbe46
commit d595eee
Show file tree

Hide file tree

Showing 11 changed files with 149 additions and 18 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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/...er/besu/ethereum/api/jsonrpc/internal/methods/engine/AbstractEngineForkchoiceUpdated.java b/...er/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/...perledger/besu/ethereum/api/jsonrpc/internal/methods/engine/AbstractEngineNewPayload.java b/...perledger/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<List<Request>> extractRequests(final Optional<List<String>> 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<Integer> 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<Object> 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
@@ -26,6 +26,7 @@ public class BlockProcessingResult extends BlockValidationResult {
 
   private final Optional<BlockProcessingOutputs> yield;
   private final boolean isPartial;
+  private Optional<Integer> 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<BlockProcessingOutputs> 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<BlockProcessingOutputs> yield,
+      final Optional<Integer> 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<TransactionReceipt> getReceipts() {
   public Optional<List<Request>> 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<Integer> 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
@@ -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/...reum/core/src/main/java/org/hyperledger/besu/ethereum/mainnet/AbstractBlockProcessor.java b/...reum/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<PreprocessingContext> runBlockPreProcessing(

diff --git a/...ger/besu/ethereum/mainnet/parallelization/ParallelizedConcurrentTransactionProcessor.java b/...ger/besu/ethereum/mainnet/parallelization/ParallelizedConcurrentTransactionProcessor.java
@@ -251,8 +251,10 @@ public Optional<TransactionProcessingResult> 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/...e/src/main/java/org/hyperledger/besu/ethereum/processing/TransactionProcessingResult.java b/...e/src/main/java/org/hyperledger/besu/ethereum/processing/TransactionProcessingResult.java
@@ -49,6 +49,8 @@ public enum Status {
 
   private final Bytes output;
 
+  private Optional<Boolean> isProcessedInParallel = Optional.empty();
+
   private final ValidationResult<TransactionInvalidReason> validationResult;
   private final Optional<Bytes> revertReason;
 
@@ -194,6 +196,25 @@ public ValidationResult<TransactionInvalidReason> getValidationResult() {
     return validationResult;
   }
 
+  /**
+   * Set isProcessedInParallel to the value in parameter
+   *
+   * @param isProcessedInParallel new value of isProcessedInParallel
+   */
+  public void setIsProcessedInParallel(final Optional<Boolean> 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<Boolean> getIsProcessedInParallel() {
+    return isProcessedInParallel;
+  }
+
   /**
    * Returns the reason why a transaction was reverted (if applicable).
    *