How does a Besu validator exactly select transactions from txpool to generate a block?

[CaixiangFan]

Description

I am researching the performance of Besu with PoA consensus. I created a free gas private network and set the block gas limit to the max. Expected all submitted txs to be selected and wrapped into a block under a moderate tx load. But, from the logs, I found that Besu proposer didn't selected as many txs as expected.

Acceptance Criteria

• Under low tx rate (tx/s), all txs in the pool should be selected.
• Under high tx rate (tx/s), Besu should include as many txs as possible into the next block.

Steps to Reproduce (Bug)

1. Create a 4-node (validator) private QBFT Besu network on cloud with min-gas-price=0 and block gas limit to "0x1fffffffffffff".
2. Use Nginx to connect to 4 validators for load balancing.
3. Use Caliper to benchmark Besu with varying TPS (100 to 1000).
4. Collect DEBUG logs for all benchmarks.

Expected behavior: [What you expect to happen] Under low workload, e.g., 100TPS, Besu validator includes all txs in pool into the next block.

Actual behavior: [What actually happens] There are many transactions left pending and the number of txs in a block is not always the same as the number of txs submitted.

Frequency: [What percentage of the time does it occur?] Always

Versions (Add all that apply)

• Software version: [besu --version] v22.4
• OS Name & Version: [cat /etc/*release] Ubuntu 20.04
• Kernel Version: [uname -a] Linux cc 5.4.0-107-generic
• Docker Version: [docker version] 20.10.14
• Cloud VM, type, size: [Amazon Web Services I3-large] Openstack, 2vCPU, 7.5GB RAM, 36GB HDD
• Benchamrking senario: Simple contract (Open, Query, Transfer)
• Have you reproduced the issue on other eth clients: NO

Additional Information (Add any of the following or anything else that may be relevant)

• Besu setup info - genesis file, config options ibftConfigFile-template.json file:

{
    "genesis": {
      "config": {
         "chainId": 1337,
         "muirglacierblock": 0,
         "qbft": {
           "blockperiodseconds": 1,
           "epochlength": 30000,
           "requesttimeoutseconds": 2
         }
       },
       "nonce": "0x0",
       "timestamp": "0x58ee40ba",
       "gasLimit": "0x1fffffffffffff",
       "contractSizeLimit": 2147483647,
       "difficulty": "0x1",
       "mixHash": "0x63746963616c2062797a616e74696e65206661756c7420746f6c6572616e6365",
       "coinbase": "0x0000000000000000000000000000000000000000",
       "alloc": {
          "fe3b557e8fb62b89f4916b721be55ceb828dbd73": {
             "privateKey": "8f2a55949038a9610f50fb23b5883af3b4ecb3c3bb792cbcefbd1542c692be63",
             "comment": "private key and this comment are ignored.  In a real chain, the private key should NOT be stored",
             "balance": "10000000000000000000000"
          },
          "627306090abaB3A6e1400e9345bC60c78a8BEf57": {
            "privateKey": "c87509a1c067bbde78beb793e6fa76530b6382a4c0241e5e4a9ec0a0f44dc0d3",
            "comment": "private key and this comment are ignored.  In a real chain, the private key should NOT be stored",
            "balance": "20000000000000000000000"
         }
    },
    "blockchain": {
      "nodes": {
        "generate": true,
          "count": 4
      }
    }
   }

• logs

2022-04-13 03:40:11.365+00:00 | EthScheduler-Workers-3 | INFO  | PersistBlockTask | Imported #9,843 / 100 tx / 0 om / 4,179,560 (0.0%) gas / (0xb899ac56726babf18cd4609139391eae405f4cd44fbc03dbb06c645beb6a28f9) in 0.051s. Peers: 3
2022-04-13 03:40:11.367+00:00 | BftProcessorExecutor-QBFT-0 | INFO  | QbftBesuControllerBuilder | Imported #9,843 / 100 tx / 35 pending / 4,179,560 (0.0%) gas / (0xb899ac56726babf18cd4609139391eae405f4cd44fbc03dbb06c645beb6a28f9)
2022-04-13 03:40:11.367+00:00 | vert.x-worker-thread-7 | DEBUG | WebSocketRequestHandler | WS-RPC request -> eth_getTransactionReceipt
....
2022-04-13 03:40:15.215+00:00 | BftProcessorExecutor-QBFT-0 | INFO  | QbftBesuControllerBuilder | Imported #9,847 / 97 tx / 21 pending / 4,052,747 (0.0%) gas / (0xfd5d424df386fe1e800d86c2db005ea00eda4b56b2703d1ae6f64ea754050d76)
...
2022-04-13 03:40:57.224+00:00 | BftProcessorExecutor-QBFT-0 | INFO  | QbftBesuControllerBuilder | Produced #9,889 / 100 tx / 20 pending / 3,516,520 (0.0%) gas / (0x9570fc0548d2bb85ef2fc4077213a88d590bddd1e34cbb64bf21f1b021649ad0)
2022-04-13 03:40:57.224+00:00 | EthScheduler-Workers-1 | INFO  | PersistBlockTask | Imported #9,889 / 100 tx / 0 om / 3,516,520 (0.0%) gas / (0x9570fc0548d2bb85ef2fc4077213a88d590bddd1e34cbb64bf21f1b021649ad0) in 0.020s. Peers: 3

Any docs or codebase references on how exactly a validator selects txs from local txpool are appreciated. Thank you.

[matkt]

@NicolasMassart

[NicolasMassart]

Validator selects tx that have a fees over the minimum. So as you set zero, all tx should match that. Then it fills the block up to the max block size, here 0x1fffffffffffff, so it probably depends on the amount of transactions. Can you tell us more about the cumulated fees for all the txs in the pool?

[CaixiangFan]

@NicolasMassart Hi, I set up a free gas network, so there should be no gas fees in the pool. As you mentioned, validator should select all txs in the pool until the number reaches the max gas limit (0x1fffffffffffff). I kept the transaction pool queue size to the default 4096, which was big enough to prevent any tx discarding. So, I expect all txs in the pool to be included in the next block. But, logs tell a different story. Validator left some txs pending in both low (100tx/s) and high (1,000tx/s) tx load, as shown below.

2022-04-13 03:36:28.970+00:00 | EthScheduler-Workers-1 | INFO  | PersistBlockTask | Imported #9,635 / 702 tx / 0 om / 24,728,094 (0.0%) gas / (0xfa8624f7017ea99454936348a8b72e5bda968ac0d2dce7a9a525039c5658caa3) in 0.122s. Peers: 3
2022-04-13 03:36:28.971+00:00 | BftProcessorExecutor-QBFT-0 | INFO  | QbftBesuControllerBuilder | Imported #9,635 / 702 tx / 298 pending / 24,728,094 (0.0%) gas / (0xfa8624f7017ea99454936348a8b72e5bda968ac0d2dce7a9a525039c5658caa3)

Any suggestions on how to explain this phenomenon?

[gfukushima]

Hi @CaixiangFan, it's been a while since the last interaction in this issue. Have you been able to test this scenario with a more recent version of Besu? We've had some improvements on the transaction pool. Would you please let us know if this still requires further investigation?

[gfukushima]

Closing due to inactivity. Feel free to reopen the issue if necessary.

[chenqping]

I seem to run into the same issue in 23.1.3 version

| INFO  | QbftBesuControllerBuilder | Produced #89 / 0 tx / 2 pending / 0 (0.0%) gas / (0x67119faf511857e1010a5c5f40ece171886b231094dda0890fcceb89ee10fc48)

| INFO  | QbftBesuControllerBuilder | Produced #90 / 0 tx / 2 pending / 0 (0.0%) gas / (0x3a91f84316c2573472e421b7ae04f744827c7b8f40990389101d40e018e68bf6)

| INFO  | QbftBesuControllerBuilder | Produced #91 / 0 tx / 2 pending / 0 (0.0%) gas / (0x89776779789ad736c05852355a6b714c9c4b9f2aae9ebcd38cd117751ea366a3)

the two pending transafer transactions from the same account as following

    "result": {
        "blockHash": null,
        "blockNumber": null,
        "from": "0xfe3b557e8fb62b89f4916b721be55ceb828dbd73",
        "gas": "0x5208",
        "gasPrice": "0x44c",
        "hash": "0x09f7b2ccbe8d8ce64f4a06c6d3db7fb26cc647f4c8466d98600dc815376671f2",
        "input": "0x",
        "nonce": "0x1",
        "to": "0xfe3b557e8fb62b89f4916b721be55ceb828dbd73",
        "transactionIndex": null,
        "value": "0x0",
        "v": "0xa95",
        "r": "0x8eabd5e6b7cbb26e96234426e4d0f8162dbdac5c6332fa8a3189bbcf205ca24a",
        "s": "0x701d8e759c78d6114328ca937b026c7743ecaec823c0e21f02b665e520b75423",
        "chainId": "0x539",
        "publicKey": "0x09b02f8a5fddd222ade4ea4528faefc399623af3f736be3c44f03e2df22fb792f3931a4d9573d333ca74343305762a753388c3422a86d98b713fc91c1ea04842",
        "raw": "0xf8630182044c82520894fe3b557e8fb62b89f4916b721be55ceb828dbd738080820a95a08eabd5e6b7cbb26e96234426e4d0f8162dbdac5c6332fa8a3189bbcf205ca24aa0701d8e759c78d6114328ca937b026c7743ecaec823c0e21f02b665e520b75423",
        "type": "0x0"
    }

        "blockHash": null,
        "blockNumber": null,
        "from": "0xfe3b557e8fb62b89f4916b721be55ceb828dbd73",
        "gas": "0x5208",
        "gasPrice": "0x3e8",
        "hash": "0x3d5bd158372f80a48252b22847f34f74fbc8c586b42d5b846ef371217a140bf8",
        "input": "0x",
        "nonce": "0x2",
        "to": "0x7028fca215e4970933fd64f066462f7498c14014",
        "transactionIndex": null,
        "value": "0x8ac7230489e80000",
        "v": "0xa95",
        "r": "0xcb6c78bf1c2246ee8c844b98347f84edbea3151361b77125dbfc88dba213b930",
        "s": "0x1622e21862d8e2382bb2cccfbbe4e27b1872551c872cebd3bce437d2d54768d0",
        "chainId": "0x539",
        "publicKey": "0x09b02f8a5fddd222ade4ea4528faefc399623af3f736be3c44f03e2df22fb792f3931a4d9573d333ca74343305762a753388c3422a86d98b713fc91c1ea04842",
        "raw": "0xf86b028203e8825208947028fca215e4970933fd64f066462f7498c14014888ac7230489e8000080820a95a0cb6c78bf1c2246ee8c844b98347f84edbea3151361b77125dbfc88dba213b930a01622e21862d8e2382bb2cccfbbe4e27b1872551c872cebd3bce437d2d54768d0",
        "type": "0x0"

anyone can explain this?

[chenqping]

@CaixiangFan hi you met any issues benchmarking with caliper? I always ran into nonce too high problem even sending not too high tps

[CaixiangFan]

Hi no I didn't have this problem. Nonce too high might be caused by the previous txs not being processed. You can refer to my benchmarking setup from our paper and its associated GitHub repo. Hope this helps.

[chenqping]

Hi no I didn't have this problem. Nonce too high might be caused by the previous txs not being processed. You can refer to my benchmarking setup from our paper and its associated GitHub repo. Hope this helps.

Yes hv read your paper, but I didn't even cross 100 tps with 4 qbft nodes yet, caliper couldn't run more, don't if you ran into these issues or it's a version problem, I tested against 23.1.3

[CaixiangFan]

No; I didn't run into these issues. If the Caliper couldn't generate more than 100TPS, it should be a config problem on the Caliper side. Not sure how you set up your Caliper. Try launching it on a stronger machine and config more workers (aka processes) in the config.yaml file, and make sure your TPS is more than 100TPS.

[chenqping]

No; I didn't run into these issues. If the Caliper couldn't generate more than 100TPS, it should be a config problem on the Caliper side. Not sure how you set up your Caliper. Try launching it on a stronger machine and config more workers (aka processes) in the config.yaml file, and make sure your TPS is more than 100TPS. You seem to use many addresses to build the benchmark workloads?

[CaixiangFan]

Yes, otherwise you will get the nonce issue.

[chenqping]

Yes, otherwise you will get the nonce issue.

did you modify caliper or use many worker processes?