From a4397f66b9333d165c6a8f76598125fd0e0dcb47 Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Fri, 10 Nov 2023 19:48:53 +0100 Subject: [PATCH 1/4] Drop tx that takes too long to evaluate during block selection Signed-off-by: Fabio Di Fabio --- .../txselection/BlockTransactionSelector.java | 78 ++++++++++++++----- .../data/TransactionSelectionResult.java | 6 +- 2 files changed, 63 insertions(+), 21 deletions(-) diff --git a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java index 595bcb74332..22fc69e5b3b 100644 --- a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java +++ b/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,8 @@ public class BlockTransactionSelector { private final BlockAwareOperationTracer pluginOperationTracer; private final EthScheduler ethScheduler; private final AtomicBoolean isTimeout = new AtomicBoolean(false); + private final long blockTxsSelectionMaxTime; + private final long txEvaluationMaxTime; private WorldUpdater blockWorldStateUpdater; public BlockTransactionSelector( @@ -133,6 +136,8 @@ public BlockTransactionSelector( this.pluginTransactionSelector = pluginTransactionSelector; this.pluginOperationTracer = pluginTransactionSelector.getOperationTracer(); blockWorldStateUpdater = worldState.updater(); + blockTxsSelectionMaxTime = miningParameters.getUnstable().getBlockTxsSelectionMaxTime(); + txEvaluationMaxTime = 10; } private List createTransactionSelectors( @@ -168,8 +173,6 @@ public TransactionSelectionResults buildTransactionListForBlock() { } private void timeLimitedSelection() { - final long blockTxsSelectionMaxTime = - blockSelectionContext.miningParameters().getUnstable().getBlockTxsSelectionMaxTime(); final var txSelection = ethScheduler.scheduleBlockCreationTask( () -> @@ -226,9 +229,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 +244,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 +335,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 +358,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 +368,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 > txEvaluationMaxTime) { + 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(txEvaluationMaxTime) + .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 +420,35 @@ 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, txWorldStateUpdater, evaluationStartedAt); } private void checkCancellation() { diff --git a/plugin-api/src/main/java/org/hyperledger/besu/plugin/data/TransactionSelectionResult.java b/plugin-api/src/main/java/org/hyperledger/besu/plugin/data/TransactionSelectionResult.java index 1a397259e6e..2bbf04649ba 100644 --- a/plugin-api/src/main/java/org/hyperledger/besu/plugin/data/TransactionSelectionResult.java +++ b/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. From 618e3fdc8f45127b4ed9fc9122b705342bb06b3d Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Mon, 13 Nov 2023 14:00:15 +0100 Subject: [PATCH 2/4] Unit test Signed-off-by: Fabio Di Fabio --- .../txselection/BlockTransactionSelector.java | 9 +- .../AbstractBlockTransactionSelectorTest.java | 85 ++++++++++++++----- 2 files changed, 66 insertions(+), 28 deletions(-) diff --git a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java index 22fc69e5b3b..fc8ee0bd6c1 100644 --- a/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java +++ b/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/txselection/BlockTransactionSelector.java @@ -97,7 +97,6 @@ public class BlockTransactionSelector { private final EthScheduler ethScheduler; private final AtomicBoolean isTimeout = new AtomicBoolean(false); private final long blockTxsSelectionMaxTime; - private final long txEvaluationMaxTime; private WorldUpdater blockWorldStateUpdater; public BlockTransactionSelector( @@ -137,7 +136,6 @@ public BlockTransactionSelector( this.pluginOperationTracer = pluginTransactionSelector.getOperationTracer(); blockWorldStateUpdater = worldState.updater(); blockTxsSelectionMaxTime = miningParameters.getUnstable().getBlockTxsSelectionMaxTime(); - txEvaluationMaxTime = 10; } private List createTransactionSelectors( @@ -378,14 +376,14 @@ private TransactionSelectionResult handleTransactionSelected( // check if this tx took too much to evaluate, and in case remove it from the pool final TransactionSelectionResult timeoutSelectionResult; - if (evaluationTime > txEvaluationMaxTime) { + 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(txEvaluationMaxTime) + .addArgument(blockTxsSelectionMaxTime) .log(); timeoutSelectionResult = TX_EVALUATION_TOO_LONG; } else { @@ -447,8 +445,7 @@ private TransactionSelectionResult handleTransactionNotSelected( final WorldUpdater txWorldStateUpdater, final long evaluationStartedAt) { txWorldStateUpdater.revert(); - return handleTransactionNotSelected( - pendingTransaction, selectionResult, txWorldStateUpdater, evaluationStartedAt); + return handleTransactionNotSelected(pendingTransaction, selectionResult, evaluationStartedAt); } private void checkCancellation() { diff --git a/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockTransactionSelectorTest.java b/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockTransactionSelectorTest.java index ae16f34d078..9858893f017 100644 --- a/ethereum/blockcreation/src/test/java/org/hyperledger/besu/ethereum/blockcreation/AbstractBlockTransactionSelectorTest.java +++ b/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,7 +586,7 @@ public TransactionSelectionResult evaluateTransactionPreProcessing( return TransactionSelectionResult.invalidTransient("transient"); if (pendingTransaction.getTransaction().equals(notSelectedInvalid)) return TransactionSelectionResult.invalid("invalid"); - return TransactionSelectionResult.SELECTED; + return SELECTED; } @Override @@ -590,7 +594,7 @@ 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> 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> inTime = () -> invocation -> SELECTED; + final BiFunction> 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 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 From 80c71cf602f2c9aba393983459153939752ecd8f Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Mon, 13 Nov 2023 15:07:09 +0100 Subject: [PATCH 3/4] Update CHANGELOG Signed-off-by: Fabio Di Fabio --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3d2e517ba37..1edf6bb0c8b 100644 --- a/CHANGELOG.md +++ b/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 From 3e3e1ebb8231856743b352b90fd0fe1953e94aec Mon Sep 17 00:00:00 2001 From: Fabio Di Fabio Date: Mon, 13 Nov 2023 15:17:57 +0100 Subject: [PATCH 4/4] Update API checksum Signed-off-by: Fabio Di Fabio --- plugin-api/build.gradle | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/plugin-api/build.gradle b/plugin-api/build.gradle index 6db2af92a14..493cd744590 100644 --- a/plugin-api/build.gradle +++ b/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')