Transactions that takes too long to evaluate, during block creation, …

…are dropped from the txpool (hyperledger#6163)


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

CHANGELOG.md

@@ -8,6 +8,7 @@
 
 ### Additions and Improvements
 - Implement debug_traceCall [#5885](https://github.com/hyperledger/besu/pull/5885)
+- Transactions that takes too long to evaluate, during block creation, are dropped from the txpool [#6163](https://github.com/hyperledger/besu/pull/6163)
 
 ## 23.10.2
 

ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java

@@ -16,6 +16,7 @@
 
 import static org.hyperledger.besu.plugin.data.TransactionSelectionResult.BLOCK_SELECTION_TIMEOUT;
 import static org.hyperledger.besu.plugin.data.TransactionSelectionResult.SELECTED;
+import static org.hyperledger.besu.plugin.data.TransactionSelectionResult.TX_EVALUATION_TOO_LONG;
 
 import org.hyperledger.besu.datatypes.Address;
 import org.hyperledger.besu.datatypes.Wei;
@@ -95,6 +96,7 @@ public class BlockTransactionSelector {
   private final BlockAwareOperationTracer pluginOperationTracer;
   private final EthScheduler ethScheduler;
   private final AtomicBoolean isTimeout = new AtomicBoolean(false);
+  private final long blockTxsSelectionMaxTime;
   private WorldUpdater blockWorldStateUpdater;
 
   public BlockTransactionSelector(
@@ -133,6 +135,7 @@ public BlockTransactionSelector(
     this.pluginTransactionSelector = pluginTransactionSelector;
     this.pluginOperationTracer = pluginTransactionSelector.getOperationTracer();
     blockWorldStateUpdater = worldState.updater();
+    blockTxsSelectionMaxTime = miningParameters.getUnstable().getBlockTxsSelectionMaxTime();
   }
 
   private List<AbstractTransactionSelector> createTransactionSelectors(
@@ -168,8 +171,6 @@ public TransactionSelectionResults buildTransactionListForBlock() {
   }
 
   private void timeLimitedSelection() {
-    final long blockTxsSelectionMaxTime =
-        blockSelectionContext.miningParameters().getUnstable().getBlockTxsSelectionMaxTime();
     final var txSelection =
         ethScheduler.scheduleBlockCreationTask(
             () ->
@@ -226,9 +227,11 @@ private TransactionSelectionResult evaluateTransaction(
       final PendingTransaction pendingTransaction) {
     checkCancellation();
 
+    final long evaluationStartedAt = System.currentTimeMillis();
+
     TransactionSelectionResult selectionResult = evaluatePreProcessing(pendingTransaction);
     if (!selectionResult.selected()) {
-      return handleTransactionNotSelected(pendingTransaction, selectionResult);
+      return handleTransactionNotSelected(pendingTransaction, selectionResult, evaluationStartedAt);
     }
 
     final WorldUpdater txWorldStateUpdater = blockWorldStateUpdater.updater();
@@ -239,10 +242,14 @@ private TransactionSelectionResult evaluateTransaction(
         evaluatePostProcessing(pendingTransaction, processingResult);
 
     if (postProcessingSelectionResult.selected()) {
-      return handleTransactionSelected(pendingTransaction, processingResult, txWorldStateUpdater);
+      return handleTransactionSelected(
+          pendingTransaction, processingResult, txWorldStateUpdater, evaluationStartedAt);
     }
     return handleTransactionNotSelected(
-        pendingTransaction, postProcessingSelectionResult, txWorldStateUpdater);
+        pendingTransaction,
+        postProcessingSelectionResult,
+        txWorldStateUpdater,
+        evaluationStartedAt);
   }
 
   /**
@@ -326,12 +333,14 @@ private TransactionProcessingResult processTransaction(
    * @param pendingTransaction The pending transaction.
    * @param processingResult The result of the transaction processing.
    * @param txWorldStateUpdater The world state updater.
+   * @param evaluationStartedAt when the evaluation of this tx started
    * @return The result of the transaction selection process.
    */
   private TransactionSelectionResult handleTransactionSelected(
       final PendingTransaction pendingTransaction,
       final TransactionProcessingResult processingResult,
-      final WorldUpdater txWorldStateUpdater) {
+      final WorldUpdater txWorldStateUpdater,
+      final long evaluationStartedAt) {
     final Transaction transaction = pendingTransaction.getTransaction();
 
     final long gasUsedByTransaction =
@@ -347,7 +356,8 @@ private TransactionSelectionResult handleTransactionSelected(
     // this need to be done synchronously to avoid that a concurrent timeout
     // could start packing a block while we are updating the state here
     synchronized (isTimeout) {
-      if (!isTimeout.get()) {
+      tooLate = isTimeout.get();
+      if (!tooLate) {
         txWorldStateUpdater.commit();
         blockWorldStateUpdater.commit();
         final TransactionReceipt receipt =
@@ -356,30 +366,47 @@ private TransactionSelectionResult handleTransactionSelected(
 
         transactionSelectionResults.updateSelected(
             pendingTransaction.getTransaction(), receipt, gasUsedByTransaction, blobGasUsed);
-        tooLate = false;
-      } else {
-        tooLate = true;
       }
     }
 
+    final long evaluationTime = System.currentTimeMillis() - evaluationStartedAt;
     if (tooLate) {
       // even if this tx passed all the checks, it is too late to include it in this block,
       // so we need to treat it as not selected
-      LOG.atTrace()
-          .setMessage("{} processed too late for block creation")
-          .addArgument(transaction::toTraceLog)
-          .log();
+
+      // check if this tx took too much to evaluate, and in case remove it from the pool
+      final TransactionSelectionResult timeoutSelectionResult;
+      if (evaluationTime > blockTxsSelectionMaxTime) {
+        LOG.atWarn()
+            .setMessage(
+                "Transaction {} is too late for inclusion, evaluated in {}ms that is over the max limit of {}"
+                    + ", removing it from the pool")
+            .addArgument(transaction::toTraceLog)
+            .addArgument(evaluationTime)
+            .addArgument(blockTxsSelectionMaxTime)
+            .log();
+        timeoutSelectionResult = TX_EVALUATION_TOO_LONG;
+      } else {
+        LOG.atTrace()
+            .setMessage("Transaction {} is too late for inclusion")
+            .addArgument(transaction::toTraceLog)
+            .addArgument(evaluationTime)
+            .log();
+        timeoutSelectionResult = BLOCK_SELECTION_TIMEOUT;
+      }
+
       // do not rely on the presence of this result, since by the time it is added, the code
       // reading it could have been already executed by another thread
       return handleTransactionNotSelected(
-          pendingTransaction, BLOCK_SELECTION_TIMEOUT, txWorldStateUpdater);
+          pendingTransaction, timeoutSelectionResult, txWorldStateUpdater, evaluationStartedAt);
     }
 
     pluginTransactionSelector.onTransactionSelected(pendingTransaction, processingResult);
     blockWorldStateUpdater = worldState.updater();
     LOG.atTrace()
-        .setMessage("Selected {} for block creation")
+        .setMessage("Selected {} for block creation, evaluated in {}ms")
         .addArgument(transaction::toTraceLog)
+        .addArgument(evaluationTime)
         .log();
     return SELECTED;
   }
@@ -391,24 +418,34 @@ private TransactionSelectionResult handleTransactionSelected(
    *
    * @param pendingTransaction The unselected pending transaction.
    * @param selectionResult The result of the transaction selection process.
+   * @param evaluationStartedAt when the evaluation of this tx started
    * @return The result of the transaction selection process.
    */
   private TransactionSelectionResult handleTransactionNotSelected(
       final PendingTransaction pendingTransaction,
-      final TransactionSelectionResult selectionResult) {
+      final TransactionSelectionResult selectionResult,
+      final long evaluationStartedAt) {
 
     transactionSelectionResults.updateNotSelected(
         pendingTransaction.getTransaction(), selectionResult);
     pluginTransactionSelector.onTransactionNotSelected(pendingTransaction, selectionResult);
+    LOG.atTrace()
+        .setMessage("Not selected {} for block creation with result {}, evaluated in {}ms")
+        .addArgument(pendingTransaction::toTraceLog)
+        .addArgument(selectionResult)
+        .addArgument(() -> System.currentTimeMillis() - evaluationStartedAt)
+        .log();
+
     return selectionResult;
   }
 
   private TransactionSelectionResult handleTransactionNotSelected(
       final PendingTransaction pendingTransaction,
       final TransactionSelectionResult selectionResult,
-      final WorldUpdater txWorldStateUpdater) {
+      final WorldUpdater txWorldStateUpdater,
+      final long evaluationStartedAt) {
     txWorldStateUpdater.revert();
-    return handleTransactionNotSelected(pendingTransaction, selectionResult);
+    return handleTransactionNotSelected(pendingTransaction, selectionResult, evaluationStartedAt);
   }
 
   private void checkCancellation() {

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

@@ -18,6 +18,10 @@
 import static org.assertj.core.api.Assertions.entry;
 import static org.awaitility.Awaitility.await;
 import static org.hyperledger.besu.ethereum.core.MiningParameters.Unstable.DEFAULT_NON_POA_BLOCK_TXS_SELECTION_MAX_TIME;
+import static org.hyperledger.besu.plugin.data.TransactionSelectionResult.BLOCK_SELECTION_TIMEOUT;
+import static org.hyperledger.besu.plugin.data.TransactionSelectionResult.PRIORITY_FEE_PER_GAS_BELOW_CURRENT_MIN;
+import static org.hyperledger.besu.plugin.data.TransactionSelectionResult.SELECTED;
+import static org.hyperledger.besu.plugin.data.TransactionSelectionResult.TX_EVALUATION_TOO_LONG;
 import static org.mockito.ArgumentMatchers.any;
 import static org.mockito.ArgumentMatchers.anyBoolean;
 import static org.mockito.ArgumentMatchers.eq;
@@ -582,15 +586,15 @@ public TransactionSelectionResult evaluateTransactionPreProcessing(
                   return TransactionSelectionResult.invalidTransient("transient");
                 if (pendingTransaction.getTransaction().equals(notSelectedInvalid))
                   return TransactionSelectionResult.invalid("invalid");
-                return TransactionSelectionResult.SELECTED;
+                return SELECTED;
               }
 
               @Override
               public TransactionSelectionResult evaluateTransactionPostProcessing(
                   final PendingTransaction pendingTransaction,
                   final org.hyperledger.besu.plugin.data.TransactionProcessingResult
                       processingResult) {
-                return TransactionSelectionResult.SELECTED;
+                return SELECTED;
               }
             };
 
@@ -640,7 +644,7 @@ public void transactionSelectionPluginShouldWork_PostProcessing() {
               @Override
               public TransactionSelectionResult evaluateTransactionPreProcessing(
                   final PendingTransaction pendingTransaction) {
-                return TransactionSelectionResult.SELECTED;
+                return SELECTED;
               }
 
               @Override
@@ -652,7 +656,7 @@ public TransactionSelectionResult evaluateTransactionPostProcessing(
                 if (processingResult.getEstimateGasUsedByTransaction() > maxGasUsedByTransaction) {
                   return TransactionSelectionResult.invalidTransient("Invalid");
                 }
-                return TransactionSelectionResult.SELECTED;
+                return SELECTED;
               }
             };
 
@@ -869,9 +873,7 @@ public void shouldNotSelectTransactionsWithPriorityFeeLessThanConfig() {
 
     assertThat(results.getSelectedTransactions()).containsOnly(txSelected);
     assertThat(results.getNotSelectedTransactions())
-        .containsOnly(
-            entry(
-                txNotSelected, TransactionSelectionResult.PRIORITY_FEE_PER_GAS_BELOW_CURRENT_MIN));
+        .containsOnly(entry(txNotSelected, PRIORITY_FEE_PER_GAS_BELOW_CURRENT_MIN));
   }
 
   @ParameterizedTest
@@ -882,47 +884,84 @@ public void subsetOfPendingTransactionsIncludedWhenTxSelectionMaxTimeIsOver(
       final boolean processingTooLate,
       final boolean postProcessingTooLate) {
 
-    final Supplier<Answer<TransactionSelectionResult>> inTime =
-        () -> invocation -> TransactionSelectionResult.SELECTED;
+    internalBlockSelectionTimeoutSimulation(
+        isPoa,
+        preProcessingTooLate,
+        processingTooLate,
+        postProcessingTooLate,
+        500,
+        BLOCK_SELECTION_TIMEOUT,
+        false);
+  }
+
+  @ParameterizedTest
+  @MethodSource("subsetOfPendingTransactionsIncludedWhenTxSelectionMaxTimeIsOver")
+  public void pendingTransactionsThatTakesTooLongToEvaluateIsDroppedFromThePool(
+      final boolean isPoa,
+      final boolean preProcessingTooLate,
+      final boolean processingTooLate,
+      final boolean postProcessingTooLate) {
+
+    internalBlockSelectionTimeoutSimulation(
+        isPoa,
+        preProcessingTooLate,
+        processingTooLate,
+        postProcessingTooLate,
+        900,
+        TX_EVALUATION_TOO_LONG,
+        true);
+  }
+
+  private void internalBlockSelectionTimeoutSimulation(
+      final boolean isPoa,
+      final boolean preProcessingTooLate,
+      final boolean processingTooLate,
+      final boolean postProcessingTooLate,
+      final long longProcessingTxTime,
+      final TransactionSelectionResult longProcessingTxResult,
+      final boolean isLongProcessingTxDropped) {
+
+    final long fastProcessingTxTime = 200;
+
+    final Supplier<Answer<TransactionSelectionResult>> inTime = () -> invocation -> SELECTED;
+
     final BiFunction<Transaction, Long, Answer<TransactionSelectionResult>> tooLate =
         (p, t) ->
             invocation -> {
-              if (((PendingTransaction) invocation.getArgument(0)).getTransaction().equals(p)) {
+              final org.hyperledger.besu.ethereum.eth.transactions.PendingTransaction ptx =
+                  invocation.getArgument(0);
+              if (ptx.getTransaction().equals(p)) {
                 Thread.sleep(t);
+              } else {
+                Thread.sleep(fastProcessingTxTime);
               }
-              return TransactionSelectionResult.SELECTED;
+              return SELECTED;
             };
 
     final ProcessableBlockHeader blockHeader = createBlock(301_000);
     final Address miningBeneficiary = AddressHelpers.ofValue(1);
     final int poaMinBlockTime = 1;
     final long blockTxsSelectionMaxTime = 750;
-    final long longProcessingTxTime = 500;
 
     final List<Transaction> transactionsToInject = new ArrayList<>(3);
     for (int i = 0; i < 2; i++) {
       final Transaction tx = createTransaction(i, Wei.of(7), 100_000);
       transactionsToInject.add(tx);
-      ensureTransactionIsValid(tx);
+      ensureTransactionIsValid(tx, 0, 0, processingTooLate ? fastProcessingTxTime : 0);
     }
 
     final Transaction lateTx = createTransaction(2, Wei.of(7), 100_000);
     transactionsToInject.add(lateTx);
-    ensureTransactionIsValid(
-        lateTx, 0, 0, processingTooLate ? blockTxsSelectionMaxTime + longProcessingTxTime : 0);
+    ensureTransactionIsValid(lateTx, 0, 0, processingTooLate ? longProcessingTxTime : 0);
 
     PluginTransactionSelector transactionSelector = mock(PluginTransactionSelector.class);
     when(transactionSelector.evaluateTransactionPreProcessing(any()))
         .thenAnswer(
-            preProcessingTooLate
-                ? inTime.get()
-                : tooLate.apply(lateTx, blockTxsSelectionMaxTime + longProcessingTxTime));
+            preProcessingTooLate ? tooLate.apply(lateTx, longProcessingTxTime) : inTime.get());
 
     when(transactionSelector.evaluateTransactionPostProcessing(any(), any()))
         .thenAnswer(
-            postProcessingTooLate
-                ? inTime.get()
-                : tooLate.apply(lateTx, blockTxsSelectionMaxTime + longProcessingTxTime));
+            postProcessingTooLate ? tooLate.apply(lateTx, longProcessingTxTime) : inTime.get());
 
     final PluginTransactionSelectorFactory transactionSelectorFactory =
         mock(PluginTransactionSelectorFactory.class);
@@ -962,7 +1001,9 @@ public void subsetOfPendingTransactionsIncludedWhenTxSelectionMaxTimeIsOver(
     // given enough time we can check the not selected tx
     await().until(() -> !results.getNotSelectedTransactions().isEmpty());
     assertThat(results.getNotSelectedTransactions())
-        .containsOnly(entry(lateTx, TransactionSelectionResult.BLOCK_SELECTION_TIMEOUT));
+        .containsOnly(entry(lateTx, longProcessingTxResult));
+    assertThat(transactionPool.getTransactionByHash(lateTx.getHash()).isEmpty())
+        .isEqualTo(isLongProcessingTxDropped ? true : false);
   }
 
   private static Stream<Arguments>

plugin-api/build.gradle

@@ -69,7 +69,7 @@ Calculated : ${currentHash}
 tasks.register('checkAPIChanges', FileStateChecker) {
   description = "Checks that the API for the Plugin-API project does not change without deliberate thought"
   files = sourceSets.main.allJava.files
-  knownHash = '7Aj0APsKs1wBVqaWQFdEs85/MNKxTiVzyjIeZ+zCWlw='
+  knownHash = 'gKRXd2Ow7wYKSgeGrDMRj0+2LdCzjOhLx8UEno9btGw='
 }
 check.dependsOn('checkAPIChanges')
 

plugin-api/src/main/java/org/hyperledger/besu/plugin/data/TransactionSelectionResult.java

@@ -29,6 +29,7 @@ private enum Status {
     BLOCK_FULL(true, false),
     BLOCK_OCCUPANCY_ABOVE_THRESHOLD(true, false),
     BLOCK_SELECTION_TIMEOUT(true, false),
+    TX_EVALUATION_TOO_LONG(false, true),
     INVALID_TRANSIENT(false, false),
     INVALID(false, true);
 
@@ -60,8 +61,9 @@ public String toString() {
   /** There was no more time to add transaction to the block */
   public static final TransactionSelectionResult BLOCK_SELECTION_TIMEOUT =
       new TransactionSelectionResult(Status.BLOCK_SELECTION_TIMEOUT);
-  ;
-
+  /** Transaction took too much to evaluate */
+  public static final TransactionSelectionResult TX_EVALUATION_TOO_LONG =
+      new TransactionSelectionResult(Status.TX_EVALUATION_TOO_LONG);
   /**
    * The transaction has not been selected since too large and the occupancy of the block is enough
    * to stop the selection.