Thread Blocked When Added Transaction #1585

RatanRSur · 2020-11-18T16:13:34Z

2020-11-16 07:14:15.738+00:00 | vertx-blocked-thread-checker | WARN  | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-2,5,main]=Thread[vert.x-worker-thread-2,5,main] has been blocked for 69863 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
	at app//org.hyperledger.besu.ethereum.eth.transactions.PendingTransactions.addTransaction(PendingTransactions.java:245)
	at app//org.hyperledger.besu.ethereum.eth.transactions.PendingTransactions.addLocalTransaction(PendingTransactions.java:170)
	at app//org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.addLocalTransaction(TransactionPool.java:168)
	at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.EthSendRawTransaction.response(EthSendRawTransaction.java:79)
	at app//org.hyperledger.besu.ethereum.api.jsonrpc.websocket.WebSocketRequestHandler.lambda$executeHandler$0(WebSocketRequestHandler.java:105)
	at app//org.hyperledger.besu.ethereum.api.jsonrpc.websocket.WebSocketRequestHandler$$Lambda$1140/0x0000000800712440.handle(Unknown Source)
	at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:313)
	at app//io.vertx.core.impl.ContextImpl$$Lambda$627/0x00000008005b5040.run(Unknown Source)
	at java.base@11.0.6/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base@11.0.6/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base@11.0.6/java.lang.Thread.run(Thread.java:834)

The text was updated successfully, but these errors were encountered:

NicolasMassart · 2020-11-19T08:02:31Z

When it happens, TPS falls to 1. It's usually around 300/400 otherwise.

matkt · 2020-12-04T16:19:41Z

Result of a quick investigation of this bug :

If we look at the logs we notice that when the thread block messages arrive we have just after a block with many transactions

vertx-blocked-thread-checker | WARN | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-7,5,main]=Thread[vert.x-worker-thread-7,5,main] has been blocked for 70874 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
at app//org.hyperledger.besu.ethereum.eth.transactions.PendingTransactions.addTransaction(PendingTransactions.java:245)
at app//org.hyperledger.besu.ethereum.eth.transactions.PendingTransactions.addLocalTransaction(PendingTransactions.java:170)
at app//org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.addLocalTransaction(TransactionPool.java:168)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.EthSendRawTransaction.response(EthSendRawTransaction.java:79)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.websocket.WebSocketRequestHandler.lambda$executeHandler$0(WebSocketRequestHandler.java:105)
at app//org.hyperledger.besu.ethereum.api.jsonrpc.websocket.WebSocketRequestHandler$$Lambda$1140/0x0000000800712440.handle(Unknown Source)
at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:313)
at app//io.vertx.core.impl.ContextImpl$$Lambda$627/0x00000008005b5040.run(Unknown Source)
at java.base@11.0.6/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base@11.0.6/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.base@11.0.6/java.lang.Thread.run(Thread.java:834)

IbftRound | Importing block to chain. round=ConsensusRoundIdentifier{Sequence=4358961, Round=3}, hash=0x9a46b8a05e2c2e103edb481d299cf9403e1937f3e720d96d6ede348f4782d03b
PersistBlockTask | Imported #4,358,961 / 1003 tx / 0 om / 38,381,621 (17.0%) gas / (0x9a46b8a05e2c2e103edb481d299cf9403e1937f3e720d96d6ede348f4782d03b) in 0.212s. Peers: 3

When blocks with 0 transaction are created we dont have any thread block message

This meant that more than 1,000 transactions had to be evaluated. The process of selecting transactions can be something quite big (especially because of the evaluation of each transaction)

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

Line 154 in 021ce8e

    
             This function iterates over (potentially) all transactions in the PendingTransactions, this is a

This method, which can be long, is synchronized with the method that allows adding transactions (synchronized (prioritizedTransactions))

Select transaction

besu/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/PendingTransactions.java

Line 207 in 9062140

synchronized (prioritizedTransactions) {
Add transaction

besu/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/PendingTransactions.java

Line 245 in 9062140

synchronized (prioritizedTransactions) {

This means that the creation of a block can impact the addition of pending transactions

sudo1991 · 2022-01-27T05:17:35Z

I got the same problem during the performance test. Is it resolved?
I sent 190 transactions per second to the Besu network.

If a transaction used 337,472 gas in the log, multiple transactions were stored in one block,

Block Gas Limit = 9,007,199,254,740,991(genesis.json "gasLimit" : "0x1fffffffffffff")
Transaction Gas Limit = 1,000,000,000

but a problem occurred when a transaction used 1,222,986 gas in the log.

Block Gas Limit = 9,007,199,254,740,991(genesis.json "gasLimit" : "0x1fffffffffffff")
Transaction Gas Limit = 9,007,199,254,740,991

Transactions are written to the block only if this is the case.
A block is created approximately every 3 minutes and 30 seconds, and only one transaction is recorded in the block.

If the Transaction Gas Limit is less than that value, the following exception occurs.

2022-01-25 14:25:53.191+09:00 | vertx-blocked-thread-checker | WARN  | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-18,5,main]=Thread[vert.x-worker-thread-18,5,main] has been blocked for 666461 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
        at app//org.hyperledger.besu.ethereum.eth.transactions.sorter.GasPricePendingTransactionsSorter.addTransaction(GasPricePendingTransactionsSorter.java:92)
        at app//org.hyperledger.besu.ethereum.eth.transactions.sorter.AbstractPendingTransactionsSorter.addLocalTransaction(AbstractPendingTransactionsSorter.java:179)
        at app//org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.addLocalTransaction(TransactionPool.java:142)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.EthSendRawTransaction.response(EthSendRawTransaction.java:79)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.JsonRpcHttpService.process(JsonRpcHttpService.java:725)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.JsonRpcHttpService.lambda$handleJsonSingleRequest$13(JsonRpcHttpService.java:579)
        at app//org.hyperledger.besu.ethereum.api.jsonrpc.JsonRpcHttpService$$Lambda$1201/0x0000000840621440.handle(Unknown Source)
        at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:313)
        at app//io.vertx.core.impl.ContextImpl$$Lambda$729/0x0000000840515c40.run(Unknown Source)
        at java.base@11.0.13/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base@11.0.13/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base@11.0.13/java.lang.Thread.run(Thread.java:829)

My ibftConfigFile is

{
  "genesis": {
    "alloc": {
      "6f8e4674c80c76833daa6fc1f19343c7a4909de8" : {
        "balance" : "1000000000000000000000000000"
      },
      ...
    },
    "coinbase": "0x0000000000000000000000000000000000000000",
    "config": {
      "chainId": 20211221,
      "muirglacierblock": 0,
      "ibft2": {
        "blockperiodseconds": 1,
        "epochlength": 30000,
        "requesttimeoutseconds": 2
      },
      "contractSizeLimit" : 2147483647
    },
    "messageQueueLimit": 5000000,
    "difficulty": "0x1",
    "gasLimit" : "0x1fffffffffffff",
    "mixHash": "0x63746963616c2062797a616e74696e65206661756c7420746f6c6572616e6365",
    "nonce": "0x0",
    "timestamp": "0x00"
  },
  "blockchain": {
    "nodes": {
      "generate": true,
      "count": 4
    }
  }
}

My bootnode options are

nohup $APP_HOME/bin/besu \
  --genesis-file=$GENESIS_PATH \
  --logging=INFO \
  --data-path=$DATA_DIR \
  --network-id=$NETWORK_ID \
  --rpc-http-host=0.0.0.0 \
  --rpc-http-enabled \
  --rpc-http-port=$RPC_PORT \
  --rpc-http-cors-origins="all" \
  --rpc-http-api=ADMIN,ETH,DEBUG,MINER,NET,TXPOOL,WEB3,IBFT \
  --host-allowlist="*" \
  --p2p-port=$P2P_PORT \
  --tx-pool-max-size=5000000 \
  --min-gas-price=0 \
>> $LOG_FILE 2>&1 &

My other nodes options are

nohup $APP_HOME/bin/besu \
  --genesis-file=$GENESIS_PATH \
  --logging=INFO \
  --data-path=$DATA_DIR \
  --network-id=$NETWORK_ID \
  --rpc-http-host=0.0.0.0 \
  --rpc-http-enabled \
  --rpc-http-port=$RPC_PORT \
  --rpc-http-cors-origins="all" \
  --rpc-http-api=ADMIN,ETH,DEBUG,MINER,NET,TXPOOL,WEB3,IBFT \
  --host-allowlist="*" \
  --p2p-port=$P2P_PORT \
  --min-gas-price=0 \
  --tx-pool-max-size=5000000 \
  --bootnodes=enode://INSERT_ENODE@$BOOTNODE_HOSTNAME:$P2P_PORT \
  --tx-pool-retention-hours=24 \
>> $LOG_FILE 2>&1 &

software version: [ besu --version ]
- besu/v21.10.5/linux-x86_64/openjdk-java-11
java version: [ java -version ]
- openjdk version "11.0.13" 2021-10-19 LTS
OS 이름 및 버전: [ cat /etc/*release ]
- CentOS Linux release 8.5.2111
kernel커널 버전: [ uname -a]
- Linux ppelblk01 4.18.0-305.25.1.el8_4.x86_64 '#'1 SMP Wed Nov 3 10:29:07 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

non-fungible-nelson · 2022-07-19T17:33:22Z

@matkt - OK to close?

matkt · 2022-07-19T17:41:39Z

I don't think we have a fix for that. i think we can keep it open

Ayo91 · 2022-10-15T22:09:43Z

I have the same issue, any solution?

eth1_1           | 2022-10-15 22:06:24.965+00:00 | vertx-blocked-thread-checker | WARN  | BlockedThreadChecker | Thread Thread[vert.x-worker-thread-0,5,main] has been blocked for 64058 ms, time limit is 60000 ms
eth1_1           | io.vertx.core.VertxException: Thread blocked
eth1_1           | 	at java.base@17.0.4/sun.nio.cs.StreamEncoder.write(StreamEncoder.java:118)
eth1_1           | 	at java.base@17.0.4/java.io.OutputStreamWriter.write(OutputStreamWriter.java:187)
eth1_1           | 	at java.base@17.0.4/java.io.Writer.append(Writer.java:389)
eth1_1           | 	at app//io.prometheus.client.exporter.common.TextFormat.writeEscapedLabelValue(TextFormat.java:88)
eth1_1           | 	at app//io.prometheus.client.exporter.common.TextFormat.write004(TextFormat.java:42)
eth1_1           | 	at app//org.hyperledger.besu.metrics.prometheus.MetricsHttpService.lambda$metricsRequest$4(MetricsHttpService.java:205)
eth1_1           | 	at app//org.hyperledger.besu.metrics.prometheus.MetricsHttpService$$Lambda$1353/0x0000000801216c40.handle(Unknown Source)
eth1_1           | 	at app//io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
eth1_1           | 	at app//io.vertx.core.impl.ContextImpl$$Lambda$1006/0x000000080114df10.handle(Unknown Source)
eth1_1           | 	at app//io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
eth1_1           | 	at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
eth1_1           | 	at app//io.vertx.core.impl.ContextImpl$$Lambda$1005/0x000000080114dce8.run(Unknown Source)
eth1_1           | 	at java.base@17.0.4/java.util.concurrent.Thread

linuxninja39 · 2023-05-23T01:06:03Z

Well 2.5 years after this was reported, it's still open. I'm getting this same error with the 23.4.0 release. Any hints?

non-fungible-nelson · 2023-11-14T16:51:41Z

Considering as stale - @fab-10 is checking

lakshay-zeeve · 2024-01-20T19:50:02Z

We're getting the same issue with 1000 transactions in a block. And it only starts to occur if the node is connected to blockscout.

fab-10 · 2024-02-19T16:45:33Z

@lakshay-zeeve is it possible that Blockscout is using too many resources and it is interfering with other Besu tasks, that could mean that you need to dedicate more resources to the instance using Blockscout

jflo · 2024-10-21T22:32:24Z

We'd like to close this issue as out of date. Please come back with more info if you have any.

timbeiko added the bug Something isn't working label Nov 30, 2020

matkt self-assigned this Dec 4, 2020

matkt removed their assignment Mar 10, 2021

vmichalik added the P3 Medium (ex: JSON-RPC request not working with a specific client library due to loose spec assumtion) label Sep 20, 2021

non-fungible-nelson added the icebox items that need more consideration, time, or can wait label May 24, 2022

iamhsk added the TeamChupa GH issues worked on by Chupacabara Team label Jul 14, 2022

non-fungible-nelson closed this as completed Nov 14, 2023

non-fungible-nelson reopened this Nov 14, 2023

jflo removed the TeamChupa GH issues worked on by Chupacabara Team label Oct 15, 2024

jflo closed this as completed Oct 21, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Thread Blocked When Added Transaction #1585

Thread Blocked When Added Transaction #1585

RatanRSur commented Nov 18, 2020

NicolasMassart commented Nov 19, 2020

matkt commented Dec 4, 2020 •

edited

Loading

sudo1991 commented Jan 27, 2022 •

edited

Loading

non-fungible-nelson commented Jul 19, 2022

matkt commented Jul 19, 2022

Ayo91 commented Oct 15, 2022

linuxninja39 commented May 23, 2023

non-fungible-nelson commented Nov 14, 2023 •

edited

Loading

lakshay-zeeve commented Jan 20, 2024

fab-10 commented Feb 19, 2024

jflo commented Oct 21, 2024

Thread Blocked When Added Transaction #1585

Thread Blocked When Added Transaction #1585

Comments

RatanRSur commented Nov 18, 2020

NicolasMassart commented Nov 19, 2020

matkt commented Dec 4, 2020 • edited Loading

sudo1991 commented Jan 27, 2022 • edited Loading

non-fungible-nelson commented Jul 19, 2022

matkt commented Jul 19, 2022

Ayo91 commented Oct 15, 2022

linuxninja39 commented May 23, 2023

non-fungible-nelson commented Nov 14, 2023 • edited Loading

lakshay-zeeve commented Jan 20, 2024

fab-10 commented Feb 19, 2024

jflo commented Oct 21, 2024

matkt commented Dec 4, 2020 •

edited

Loading

sudo1991 commented Jan 27, 2022 •

edited

Loading

non-fungible-nelson commented Nov 14, 2023 •

edited

Loading