besu
besu copied to clipboard
hyperledger
Thread Blocked When Added Transaction
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 [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at [email protected]/java.lang.Thread.run(Thread.java:834)
When it happens, TPS falls to 1. It's usually around 300/400 otherwise.
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 [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at [email protected]/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) https://github.com/hyperledger/besu/blob/021ce8ee040427d804c69bd7ecb3ed893a948124/ethereum/blockcreation/src/main/java/org/hyperledger/besu/ethereum/blockcreation/BlockTransactionSelector.java#L154
This method, which can be long, is synchronized with the method that allows adding transactions (synchronized (prioritizedTransactions))
- Select transaction https://github.com/hyperledger/besu/blob/9062140452fb054f2487a9096395fee7132a6a0b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/PendingTransactions.java#L207
- Add transaction https://github.com/hyperledger/besu/blob/9062140452fb054f2487a9096395fee7132a6a0b/ethereum/eth/src/main/java/org/hyperledger/besu/ethereum/eth/transactions/PendingTransactions.java#L245
This means that the creation of a block can impact the addition of pending transactions
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 [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at [email protected]/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
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 [email protected]/sun.nio.cs.StreamEncoder.write(StreamEncoder.java:118)
eth1_1 | at [email protected]/java.io.OutputStreamWriter.write(OutputStreamWriter.java:187)
eth1_1 | at [email protected]/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 [email protected]/java.util.concurrent.Thread
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?
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.
@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
