Slow eth_sendRawTransaction response time. jsonrpc-eventloop thread does txqueue processing.

[ghost]

Before filing a new issue, please provide the following information.

• Parity Ethereum version: 2.3.5
• Operating system: Linux
• Installation: one-line installer
• Fully synchronized: yes
• Network: ethereum
• Restarted: yes

I've been observing occasional bad performance of the eth_sendRawTransaction and parity_nextNonce endpoints JSON RPC. Both HTTP and WebSocket response times can reach up to 4-5s, whereas the same node usually takes around 10-20ms to respond to eth_call, eth_getTransactionCount etc.

While debugging it I noticed that when handling eth_sendRawTransaction, jsonrpc-eventloop-N threads tend to do some suspicious txqueue processing, which I would expect to happen asynchronously.

Attaching an example log snippet:

2019-03-20 17:16:38 UTC  TRACE rpc  Request: {"jsonrpc": "2.0", "method": "eth_sendRawTransaction", "params": ["0x..."], "id": 14}.
2019-03-20 17:16:38 UTC jsonrpc-eventloop-2 TRACE own_tx  Importing transaction: PendingTransaction { transaction: SignedTransaction { transaction: UnverifiedTransaction { unsigned: Transaction { nonce: CENSORED, gas_price: CENSORED, gas: CENSORED, action: Call(CENSORED), value: 0, data: [CENSORED] }, v: 27, r: CENSORED s: CENSORED, hash: 0xTRANSACTIONHASHWASHERE }, sender: 0xADDRESSWASHERE, public: Some(0xCENSORED) }, condition: None }
2019-03-20 17:16:38 UTC IO Worker #1 DEBUG txqueue  [0x3128b023fe578c9fd6c19fe6b43222df9fa11a1bc0ffc8967b77d3001c4c7e76] Rejected tx with not enough balance: 0 < 36000000000000000
2019-03-20 17:16:38 UTC IO Worker #0 DEBUG txqueue  [0xaf6d067bf5cea56bac5ef21acdedfd2d64ba66f5f766b7bda5997e917f33bb46] Rejected tx with not enough balance: 8845750000000000 < 80067200000000000
2019-03-20 17:16:39 UTC IO Worker #1 DEBUG txqueue  [0x715cf1e62b386b20b84e659eaa4b9018a8adb71724a58f57a277baeea7b6f9aa] Rejected tx with not enough balance: 0 < 38000000000000000
2019-03-20 17:16:39 UTC IO Worker #0 TRACE txqueue  [0xedb054430e43aed879215a9d9f39edb9ad3a00b425dcf60e18aa5c4f363f4df3] Rejected tx already in the blockchain
2019-03-20 17:16:39 UTC IO Worker #1 DEBUG txqueue  [0xb814767870b8fed406d47231dde1a4daebca0abacc05b5f1f65035b29007db61] Rejected tx with not enough balance: 0 < 95000000000000000
2019-03-20 17:16:40 UTC IO Worker #0 TRACE txqueue  [0xc8b84998b92c8397a7d1fb5818644a9b2b484591df01f78ab99621fe340b9b75] Rejected tx already in the blockchain
2019-03-20 17:16:40 UTC IO Worker #1 DEBUG txqueue  [0xf3e99af3773055abd92efbe4073f074871d3d4c5047660bb185caefc3301bb01] Rejected tx with not enough balance: 0 < 36000000000000000
2019-03-20 17:16:40 UTC IO Worker #0 DEBUG txqueue  Re-computing pending set for block: 7407015
2019-03-20 17:16:41 UTC IO Worker #0 TRACE txqueue  [0xc6e6d6af3bdd9875d7962c1ff7ba0d3c827f9dabc88bf2be9f466d2e9417c372] Rejected tx already in the blockchain
2019-03-20 17:16:41 UTC IO Worker #1 DEBUG txqueue  [0xb6e6e98f59b06b6b9f1be60c1f93b908f6681935ad708dab461d060dc9e180f6] Rejected tx with not enough balance: 0 < 36000000000000000
[...]
2019-03-20 17:16:42 UTC IO Worker #3 DEBUG txqueue  [0x1408652e365fa17a62ca14154590179a912474586220b83e435e81d033145488] Sender: 0x5209…9288, nonce: 11, gasPrice: 111000000, gas: 91000, value: 0, dataLen: 0))
2019-03-20 17:16:42 UTC IO Worker #1 DEBUG txqueue  [0x44feb0011c4f3cdbf40378ecb4543dac074b71959ff0a7990fe1971b62e1c8b2] Rejected tx with not enough balance: 1 < 43999999999999999
2019-03-20 17:16:42 UTC Verifier #2 DEBUG txqueue  [0x695eaaab80d4cdfb80034ffd57cca99f6d5f81f381cc4c84d47bfc8affec8373] Marking as invalid: Error(Execution(NotEnoughCash { required: 70077700000000000, got: 9766900000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC Verifier #2 DEBUG txqueue  [0xf5f6aaea68cf06ae0dd519cf4c19bf31c13050c77f0b4b799f2dd7f7895ed6dd] Marking as invalid: Error(Execution(NotEnoughCash { required: 80077700000000000, got: 79689200000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC IO Worker #3 DEBUG txqueue  [0x0c9f1c50120f70d80129dbff39f99cefba51650f04b9027612d21950b97ebf1a] Added to the pool.
2019-03-20 17:16:42 UTC IO Worker #3 DEBUG txqueue  [0x0c9f1c50120f70d80129dbff39f99cefba51650f04b9027612d21950b97ebf1a] Sender: 0xebab…48cf, nonce: 7, gasPrice: 47619047, gas: 21000, value: 1000000013000, dataLen: 0))
2019-03-20 17:16:42 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0x695eaaab80d4cdfb80034ffd57cca99f6d5f81f381cc4c84d47bfc8affec8373] Marking as invalid: Error(Execution(NotEnoughCash { required: 70077700000000000, got: 9766900000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC Verifier #2 DEBUG txqueue  [0xfc4b875283a535d50627fc8428c1bf684b0945797469e4ded4afb1cf9074dc97] Marking as invalid: Error(Execution(NotEnoughCash { required: 80075600000000000, got: 79924400000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0xf5f6aaea68cf06ae0dd519cf4c19bf31c13050c77f0b4b799f2dd7f7895ed6dd] Marking as invalid: Error(Execution(NotEnoughCash { required: 80077700000000000, got: 79689200000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC Verifier #2 DEBUG txqueue  [0x837ca4e0f780a435791b77f30b92db236b02bbee4fbdb8ebc6246442e6cc1c95] Marking as invalid: Error(Execution(NotEnoughCash { required: 70073500000000000, got: 69706000000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0xfc4b875283a535d50627fc8428c1bf684b0945797469e4ded4afb1cf9074dc97] Marking as invalid: Error(Execution(NotEnoughCash { required: 80075600000000000, got: 79924400000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0x837ca4e0f780a435791b77f30b92db236b02bbee4fbdb8ebc6246442e6cc1c95] Marking as invalid: Error(Execution(NotEnoughCash { required: 70073500000000000, got: 69706000000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC Verifier #2 DEBUG txqueue  [0xb523ae194ac3b21f43f15bd1cc8749271aaf9f9f57bb77e7f79bcf311d7e811e] Marking as invalid: Error(Execution(NotEnoughCash { required: 100073500000000000, got: 89779500000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0xb523ae194ac3b21f43f15bd1cc8749271aaf9f9f57bb77e7f79bcf311d7e811e] Marking as invalid: Error(Execution(NotEnoughCash { required: 100073500000000000, got: 89779500000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC Verifier #2 DEBUG txqueue  [0x868de865b3f553f83227cde91ce9ae90afe83628bd4298657de762f7ff28169f] Marking as invalid: Error(Execution(NotEnoughCash { required: 90071400000000000, got: 19714400000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0x868de865b3f553f83227cde91ce9ae90afe83628bd4298657de762f7ff28169f] Marking as invalid: Error(Execution(NotEnoughCash { required: 90071400000000000, got: 19714400000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC Verifier #2 DEBUG txqueue  [0x8c4a4a2d04bee13133b352a324f67236219a7f4f600547f17881a751316c6c66] Marking as invalid: Error(Execution(NotEnoughCash { required: 100067200000000000, got: 19462400000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0x8c4a4a2d04bee13133b352a324f67236219a7f4f600547f17881a751316c6c66] Marking as invalid: Error(Execution(NotEnoughCash { required: 100067200000000000, got: 19462400000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC Verifier #2 DEBUG txqueue  [0x9409a4c4a0d45cd1557d604a2febeb5ed81309aec1431faafcfec662aa002591] Marking as invalid: Error(Execution(NotEnoughCash { required: 60065100000000000, got: 29804700000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC IO Worker #1 DEBUG txqueue  [0x4a84c9696bc353ebcc31726be6dd841960d23adaac9a323fcad962a50af09582] Rejected tx with not enough balance: 1 < 43999999999999999
2019-03-20 17:16:42 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0x9409a4c4a0d45cd1557d604a2febeb5ed81309aec1431faafcfec662aa002591] Marking as invalid: Error(Execution(NotEnoughCash { required: 60065100000000000, got: 29804700000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC Verifier #2 DEBUG txqueue  [0x5197d85a323f817e85c27a6afd810113dceee0a555c07f18732cbb3030392f07] Marking as invalid: Error(Execution(NotEnoughCash { required: 50065100000000000, got: 29804700000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0x5197d85a323f817e85c27a6afd810113dceee0a555c07f18732cbb3030392f07] Marking as invalid: Error(Execution(NotEnoughCash { required: 50065100000000000, got: 29804700000000000 }), State { next_error: None, backtrace: InternalBacktrace { backtrace: None } }).
2019-03-20 17:16:42 UTC IO Worker #1 DEBUG txqueue  [0x20fab82b91dad7273932def02f5eff428db079335bb533d6829bd91aa3574d93] Rejected tx with not enough balance: 1 < 43999999999999999
2019-03-20 17:16:42 UTC IO Worker #3 TRACE txqueue  [0xa05923fba6f308e6245955d0f556f1947d9bfa33c97cf07bfe4ec0dd4bb27eaa] Rejected tx already in the blockchain
2019-03-20 17:16:42 UTC IO Worker #3 TRACE txqueue  [0xc0712812d14f7645aa531c14e4cfcaccac1d0d3add73a33366181891ca02d550] Rejected tx already in the blockchain
2019-03-20 17:16:42 UTC IO Worker #1 DEBUG txqueue  [0x904a7abba1c8ff14c6719c9cdbb8b261eb96a1d1bd82e2051a4138d80356af41] Rejected tx with not enough balance: 1 < 43999999999999999
[...]
2019-03-20 17:16:43 UTC IO Worker #2 TRACE txqueue  [0x22781357107eae3cf0981ef8dc59af0e0b77026e112d038fe1e131ea369e0551] Rejecting recently rejected: AlreadyImported
2019-03-20 17:16:43 UTC IO Worker #2 TRACE txqueue  [0x567a984290a3d7c908d1ceea83e5814153e069ee0df16970ed0d88d317ada3a4] Rejecting recently rejected: AlreadyImported
2019-03-20 17:16:43 UTC IO Worker #2 TRACE txqueue  [0xe0cc2589a9c1d61b227f946b8717cbfac9d956b0e57f545a985617c85c7f1500] Rejecting recently rejected: AlreadyImported
2019-03-20 17:16:43 UTC IO Worker #2 TRACE txqueue  [0x5088f6ef2035eb7c7dd68ee5567cafbea66a72904af3afd5a5e46a2ad912270a] Rejecting recently rejected: AlreadyImported
2019-03-20 17:16:43 UTC IO Worker #3 TRACE txqueue  [0x2233b2586a8abaadba83898abb82b1056e0ef0a4ad42f3afb0ef4d6464f7c97e] Rejecting recently rejected: AlreadyImported
2019-03-20 17:16:43 UTC IO Worker #2 TRACE txqueue  [0x14df91cfcfc1439141208cf1f761fd923c6988b27afa8ef7f586677917ff9be1] Rejecting recently rejected: AlreadyImported
2019-03-20 17:16:43 UTC IO Worker #0 DEBUG txqueue  [0x55410d860ca4d12062111bc472e2b5b2fb1f25aff1a18cae8f7a69107b2a292f] Rejected tx with not enough balance: 44958000000000000 < 250021000000000000
2019-03-20 17:16:43 UTC IO Worker #1 DEBUG txqueue  [0x0c8961a549a7ca217dd7b5a585d457c5300e173d80f6eaba798f25fce26c0bb1] Rejected tx with not enough balance: 15080000000000 < 1499984920000000000
2019-03-20 17:16:43 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0xfc4b875283a535d50627fc8428c1bf684b0945797469e4ded4afb1cf9074dc97] Marked as invalid by executor.
2019-03-20 17:16:43 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0x8c4a4a2d04bee13133b352a324f67236219a7f4f600547f17881a751316c6c66] Marked as invalid by executor.
2019-03-20 17:16:43 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0x9409a4c4a0d45cd1557d604a2febeb5ed81309aec1431faafcfec662aa002591] Marked as invalid by executor.
2019-03-20 17:16:43 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0xb523ae194ac3b21f43f15bd1cc8749271aaf9f9f57bb77e7f79bcf311d7e811e] Marked as invalid by executor.
2019-03-20 17:16:43 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0xf5f6aaea68cf06ae0dd519cf4c19bf31c13050c77f0b4b799f2dd7f7895ed6dd] Marked as invalid by executor.
2019-03-20 17:16:43 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0x695eaaab80d4cdfb80034ffd57cca99f6d5f81f381cc4c84d47bfc8affec8373] Marked as invalid by executor.
2019-03-20 17:16:43 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0x868de865b3f553f83227cde91ce9ae90afe83628bd4298657de762f7ff28169f] Marked as invalid by executor.
2019-03-20 17:16:43 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0x837ca4e0f780a435791b77f30b92db236b02bbee4fbdb8ebc6246442e6cc1c95] Marked as invalid by executor.
2019-03-20 17:16:43 UTC jsonrpc-eventloop-2 DEBUG txqueue  [0x5197d85a323f817e85c27a6afd810113dceee0a555c07f18732cbb3030392f07] Marked as invalid by executor.
2019-03-20 17:16:43 UTC IO Worker #3 TRACE txqueue  [0x28036de946280db428effd942992a04c03711eb8af9dc53889062497e5936102] Rejecting recently rejected: AlreadyImported
2019-03-20 17:16:43 UTC IO Worker #3 TRACE txqueue  [0x9327330e296fffd470d4cf1df51e5dc22c16648fd479204418b1a92e55441e8d] Rejecting recently rejected: AlreadyImported
2019-03-20 17:16:43 UTC IO Worker #3 TRACE txqueue  [0x76524ed7705a37cd77fd961b4c0fa8a8817bb58485cb57d60eaa8142bfce3e62] Rejecting recently rejected: AlreadyImported
2019-03-20 17:16:43 UTC IO Worker #3 TRACE txqueue  [0x36d9b64e41cdcfc1fe77f1d30c9f1fcb3e32b5beb24cf8c9ec6bb5aa15939031] Rejecting recently rejected: AlreadyImported
2019-03-20 17:16:43 UTC IO Worker #3 TRACE txqueue  [0xa05923fba6f308e6245955d0f556f1947d9bfa33c97cf07bfe4ec0dd4bb27eaa] Rejecting recently rejected: AlreadyImported
2019-03-20 17:16:43 UTC IO Worker #3 TRACE txqueue  [0xc0712812d14f7645aa531c14e4cfcaccac1d0d3add73a33366181891ca02d550] Rejecting recently rejected: AlreadyImported
2019-03-20 17:16:43 UTC IO Worker #3 TRACE txqueue  [0x567a984290a3d7c908d1ceea83e5814153e069ee0df16970ed0d88d317ada3a4] Rejecting recently rejected: AlreadyImported
[...]
2019-03-20 17:16:43 UTC IO Worker #0 DEBUG txqueue  [0x8b25daeedf2b542a26909511b22e9f0bde1d30a5300319060a05f571cbab83a7] Rejected tx with not enough balance: 0 < 15091111470000000000
2019-03-20 17:16:43 UTC IO Worker #1 DEBUG txqueue  [0xc2d10b0c2f7714e3821bf60f10c725f89c33b64b275580fa57feef02b88a69ee] Rejected tx with not enough balance: 15080000000000 < 7500000000000000640
2019-03-20 17:16:43 UTC jsonrpc-eventloop-2 DEBUG rpc  [Some(Num(14))] Took 4856ms
2019-03-20 17:16:43 UTC jsonrpc-eventloop-2 DEBUG rpc  Response: {"jsonrpc":"2.0","result":"0xTRANSACTIONHASHWASHERE","id":14}.

[tomusdrw]

It seems that pending block is being created inside the RPC thread, might be better to just schedule pending block creation asynchronously instead.

Note it's also semi-related to my comment here: #10382 (comment)

Down at the bottom I suggest that batch-sending of transactions/raw transactions would be a really good thing to have (And I'm not talking about RPC batch request, cause in such case all requests are processed independently anyway, but rather use of existing optimizations when importing multiple transactions to the pool at once).

[adria0]

Closing issue due to its stale state.