Import of locally mined block takes more than 3 seconds

[peterbitfly]

I'm running:

• Which Parity version?: 1.10.9
• Which operating system?: Linux
• How installed?: binaries
• Are you fully synchronized?: yes
• Which network are you connected to?: ethereum mainnet
• Did you try to restart the node?: yes

Given the current Ethereum network conditions we observed that it takes Parity sometimes up to 3 second to import a locally mined block and propagate it to other nodes.

We managed to capture a full timeline of one such example:

2018-07-08T18:29:38+02:00 --> Valid PoW solution of block 5928241 was found and an HTTP eth_submitWork call was issues to the local parity node
2018-07-08T18:29:41+02:00 (3 seconds later) --> The local notify work http handler was called (defined via --notify-work)
2018-07-08T18:29:41+02:00 --> The eth_submitWork call returned with the result of the call (true)

Log from the block import from the local parity node:

2018-07-08 18:29:41  Imported #5928241 a4b9…a114 (158 txs, 7.96 Mgas, 3647.12 ms, 26.53 KiB)
2018-07-08 18:29:41  Submitted block imported OK. #5928241: a4b911fab46a88dbb1db760352a48527bd1421b85c565df85b9ee5636373a114

Log from the block import from a remote parity node (with a direct connection to the node that mined the block):

2018-07-08 18:29:41  Imported #5928241 a4b9…a114 (158 txs, 7.96 Mgas, 74.20 ms, 26.53 KiB)

Which means that more than 3 seconds were spent between a block solution being found an the block being propagated to other nodes. This represents over 20% of the normal Ethereum block time and might be an explanation for the high uncle rate we are currently observing.

The parity node is running on a dedicated server with a local NVMe disk, 32 GB of RAM and a 4GHz CPU and the following settings: --cache-size=20000 --notify-work= --relay-set strict --force-sealing --reseal-on-txs "none" --reseal-on-uncle --tx-queue-gas=auto

I admit, this is an extrem example, but generally we see from our logs that locally submitted block take ~ 10 times more to be imported compared to the normal block import speed (while a remote block gets imported in around ~50-100ms a locally mined block takes between 300-1000ms).

Ideally the new block should be propagated to the network before any other local work is done. Also the import time seem to be directly correlated with the amount of transactions in the block / pool as we see nearly instant import times on Ethereum Classic blocks.

[Tbaut]

There was a lot of work involved in the Tx queue in the 1.11 branch. It's about to be stable so I'd suggest you give it a try and tell us if you see a difference.

[peterbitfly]

Unfortunately we observed another issue with the 1.11 branch (#8974) that prevented us from upgrading up to now.

[Tbaut]

Seems to be fixed in later releases as of #8974 (comment) Let us know.

[peterbitfly]

The issue has not been fixed for us, we are still seeing occasional weird Syncing behavior with 1.11.5 like for example:

2018-07-10 04:20:37  Imported #5936503 0xa122…1486 (51 txs, 6.08 Mgas, 44 ms, 13.71 KiB)
2018-07-10 04:20:41  Imported #5936503 0x67d9…f783 (73 txs, 7.99 Mgas, 47 ms, 19.17 KiB)
2018-07-10 04:20:47    91/100 peers    221 MiB chain  122 MiB db  0 bytes queue   51 KiB sync  RPC:  0 conn,  2 req/s, 139 µs
2018-07-10 04:20:59  Imported #5936504 0x4576…cd5f (30 txs, 6.18 Mgas, 41 ms, 9.70 KiB)
2018-07-10 04:21:02  Syncing #5936504 0x4576…cd5f     0 blk/s   18 tx/s   0 Mgas/s      0+    0 Qed  #5936490   89/100 peers    221 MiB chain  123 MiB db  0 bytes queue   51 KiB sync  RPC:  0 conn,  2 req/s, 124 µs
2018-07-10 04:21:03  Imported #5936503 0x6a8f…96b8 (139 txs, 7.98 Mgas, 35 ms, 26.02 KiB) + another 1 block(s) containing 248 tx(s)
2018-07-10 04:21:37    91/100 peers    221 MiB chain  123 MiB db  0 bytes queue   51 KiB sync  RPC:  0 conn,  2 req/s, 120 µs
2018-07-10 04:21:51  Reorg to #5936505 0x1baf…b96e (0x4576…cd5f #5936503 0xa122…1486 0xd9ff…5e6c)
2018-07-10 04:21:51  Imported #5936505 0x1baf…b96e (189 txs, 7.99 Mgas, 37 ms, 31.20 KiB)

I have provided additional logs in the other ticket.

[peterbitfly]

I can confirm that the issue seems to be solved by the recent tx queue optimizations. We will continue to monitor the issue and re-open the ticket in case it appears again.