rpc/rest/zmq: reduce LOCK(cs_main) scope: ~6 times as many requests per second #26308

andrewtoth · 2022-10-13T19:50:55Z

Picking up from #21006.

After commit ccd8ef6 it is no longer required to hold cs_main when calling ReadBlockFromDisk. This can be verified in master at https://github.com/bitcoin/bitcoin/blob/master/src/node/blockstorage.cpp#L755. Same can be seen for UndoReadFromDisk https://github.com/bitcoin/bitcoin/blob/master/src/node/blockstorage.cpp#L485.

The first commit moves ReadBlockFromDisk outside the lock scope in rest_block, where we can see a huge performance improvement when fetching blocks with multiple threads.

My test setup, on an Intel i7 with 8 cores (16 threads):

Start a fully synced bitcoind, with this bitcoin.conf:

    rest=1
    rpcthreads=16
    rpcworkqueue=64
    rpcuser=user
    rpcpassword=password

Run ApacheBench: 10000 requests, 16 parallel threads, fetching block nr. 750000 in binary:

    ab -n 10000 -c 16 "http://127.0.0.1:8332/rest/block/0000000000000000000592a974b1b9f087cb77628bb4a097d5c2c11b3476a58e.bin"

Time per request (mean)
183 ms on master
30 ms this branch

So this can process 6.1 times as many requests, and saturates all the cores instead of keeping them partly idle waiting in the lock. With 8 threads the mean times were 90 ms on master and 19 ms on this branch, a speedup of 4.7x.

Big thanks to martinus for finding this and the original PR.

The second commit is from a suggestion on the original PR by jonatack to remove the unnecessary LOCK(cs_main) in the zmq notifier's NotifyBlock.

I also found that this approach could be applied to rpcs getblock (including verbosity=3), getblockstats, and gettxoutproof with similar very good results. The above benchmarks steps need to be modified slightly for RPC. Run the following ApacheBench command with different request data in a file named data.json:

ab -p data.json -n 10000 -c 16 -A user:password "http://127.0.0.1:8332/"

For getblock, use the following in data.json:

{"jsonrpc": "1.0", "id": "curltest", "method": "getblock", "params": ["0000000000000000000592a974b1b9f087cb77628bb4a097d5c2c11b3476a58e"]}

master - 184 ms mean request time
branch - 28 ms mean request time

For getblock with verbosity level 3, use the following in data.json:

{"jsonrpc": "1.0", "id": "curltest", "method": "getblock", "params": ["0000000000000000000592a974b1b9f087cb77628bb4a097d5c2c11b3476a58e", 3]}

This verbosity level fetches an undo file from disk, so it benefits from this approach as well. However, a lot of time is spent serializing to JSON so the performance gain is not as severe.
master - 818 ms mean request time
branch - 505 ms mean request time

For getblockstats, use the following in data.json:

{"jsonrpc": "1.0", "id": "curltest", "method": "getblockstats", "params": ["0000000000000000000592a974b1b9f087cb77628bb4a097d5c2c11b3476a58e", ["minfeerate","avgfeerate"]]}

This request used a lock on reading both a block and undo file, so the results are very good.
master - 244 ms mean request time
branch - 28 ms mean request time

aureleoules

ACK 77de778

Master results

hey -n 1000 -c 16 "http://127.0.0.1:8332/rest/block/0000000000000000000592a974b1b9f087cb77628bb4a097d5c2c11b3476a58e.bin"

Summary:
  Total:	16.1675 secs
  Slowest:	0.5310 secs
  Fastest:	0.0372 secs
  Average:	0.2569 secs
  Requests/sec:	61.3578
  
  Total data:	1285175680 bytes
  Size/request:	1295540 bytes

Response time histogram:
  0.037 [1]	|
  0.087 [6]	|
  0.136 [6]	|
  0.185 [7]	|
  0.235 [168]	|■■■■■■■■■■
  0.284 [685]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.333 [92]	|■■■■■
  0.383 [3]	|
  0.432 [10]	|■
  0.482 [13]	|■
  0.531 [1]	|


Latency distribution:
  10% in 0.2290 secs
  25% in 0.2390 secs
  50% in 0.2520 secs
  75% in 0.2671 secs
  90% in 0.2880 secs
  95% in 0.3055 secs
  99% in 0.4610 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0000 secs, 0.0372 secs, 0.5310 secs
  DNS-lookup:	0.0000 secs, 0.0000 secs, 0.0000 secs
  req write:	0.0000 secs, 0.0000 secs, 0.0003 secs
  resp wait:	0.2172 secs, 0.0197 secs, 0.4897 secs
  resp read:	0.0396 secs, 0.0005 secs, 0.0429 secs

Status code distribution:
  [200]	992 responses

PR results

hey -n 1000 -c 16 "http://127.0.0.1:8332/rest/block/0000000000000000000592a974b1b9f087cb77628bb4a097d5c2c11b3476a58e.bin"

Summary:
  Total:	5.5089 secs
  Slowest:	0.3319 secs
  Fastest:	0.0221 secs
  Average:	0.0856 secs
  Requests/sec:	180.0725
  
  Total data:	1285175680 bytes
  Size/request:	1295540 bytes

Response time histogram:
  0.022 [1]	|
  0.053 [109]	|■■■■■■■■■■
  0.084 [397]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.115 [420]	|■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■■
  0.146 [41]	|■■■■
  0.177 [3]	|
  0.208 [4]	|
  0.239 [1]	|
  0.270 [7]	|■
  0.301 [3]	|
  0.332 [6]	|■


Latency distribution:
  10% in 0.0508 secs
  25% in 0.0690 secs
  50% in 0.0831 secs
  75% in 0.0979 secs
  90% in 0.1090 secs
  95% in 0.1220 secs
  99% in 0.2890 secs

Details (average, fastest, slowest):
  DNS+dialup:	0.0000 secs, 0.0221 secs, 0.3319 secs
  DNS-lookup:	0.0000 secs, 0.0000 secs, 0.0000 secs
  req write:	0.0000 secs, 0.0000 secs, 0.0004 secs
  resp wait:	0.0486 secs, 0.0126 secs, 0.2870 secs
  resp read:	0.0369 secs, 0.0004 secs, 0.0731 secs

Status code distribution:
  [200]	992 responses

The results are consistent. The speed improvement seems to be seen only with large blocks, which is great for mainnet. I didn't notice any gains on testnet since blocks are almost empty.

andrewtoth · 2022-10-14T20:47:54Z

After reading this comment #17161 (comment) it appears it is unsafe to call ReadBlockFromDisk without holding cs_main. The block could be removed while the file is open which can cause issues on Windows.

I proposed a fix in #26316. That or another fix should be merged first before this would be safe for use with pruning I believe.

DrahtBot · 2022-10-17T01:37:57Z

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Reviews

See the guideline for information on the review process.

Type	Reviewers
ACK	MarcoFalke, hebasto
Stale ACK	aureleoules, ryanofsky

If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

Conflicts

Reviewers, this pull request conflicts with the following ones:

#26415 (rpc,rest: faster getblock and rest_block by reading raw block by andrewtoth)
#25232 (rpc: Faster getblock API by AaronDewes)
#23507 (Refactor: Improve API design of ScriptToUniv, TxToUniv etc to return the UniValue instead of mutating a parameter/reference by mjdietzx)
#21319 (RPC/Blockchain: Optimise getblock for simple disk->hex case by luke-jr)
#19888 (rpc, test: Improve getblockstats for unspendables by fjahr)

If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

ryanofsky

Code review ACK d7f358b, and I think I disagree with (or don't understand) the comment that this change should require #26316. In all of the cases here, the ReadBlock or UndoRead return value is checked so if reading data fails on windows, the RPC and rest requests should still do the right thing.

Or is the concern not that this change would cause RPC and rest calls to do the wrong thing, but that this change would cause unlink calls to fail on windows and result in a wasted disk space? If that is the bug, and I think a more minimal and elegant fix might just be to make the pruning code resilient to files temporarily being unlinkable because they are in-use, and to just retry and delete them later on the next round of pruning.

andrewtoth · 2022-11-18T16:06:28Z

Or is the concern not that this change would cause RPC and rest calls to do the wrong thing, but that this change would cause unlink calls to fail on windows and result in a wasted disk space? If that is the bug, and I think a more minimal and elegant fix might just be to make the pruning code resilient to files temporarily being unlinkable because they are in-use, and to just retry and delete them later on the next round of pruning.

@ryanofsky yes, thank you for the suggestion. I've implemented that in #26533. I think that's a better/less invasive solution than what I have proposed in #26316.

andrewtoth · 2022-12-06T14:28:38Z

Rebased

src/zmq/zmqpublishnotifier.cpp

maflcko · 2022-12-06T19:51:44Z

Happy to re-ACK for the nit

review ACK 2cd94da 🔗

Show signature

Signature:

andrewtoth · 2022-12-06T20:07:30Z

@MarcoFalke addressed the nit.

maflcko · 2022-12-07T08:48:17Z

re-ACK d7f61e7 💫

Show signature

Signature:

hebasto · 2022-12-07T10:52:21Z

Concept ACK.

hebasto · 2022-12-07T11:18:09Z

src/rpc/blockchain.cpp

    }

    if (!ReadBlockFromDisk(block, pblockindex, Params().GetConsensus())) {
        // Block not found on disk. This could be because we have the block
        // header in our index but not yet have the block or did not accept the
-        // block.
+        // block. Or if the block was pruned right after we released the lock above.


Do we have a test for such a case?

I don't think it it possible to write a test for this deletion race, unless you want to modify the source code as well?

It might be easier to write a functional test for lack of deletion (on Windows) in #26533 by holding a open file handle to the block file

The way I could see a test for this case would be to have a long sleep above the if statement, then call PruneBlockFilesManual in the test and it should fail here, but that would require modifying the source as pointed out by MarcoFalke. Is there another way to introduce an arbitrary delay or block the thread in tests?

hebasto

ACK d7f61e7, I have reviewed the code and it looks OK. Did not make benchmarking though.

hebasto · 2022-12-07T11:59:13Z

src/rpc/blockchain.cpp

+            const bool is_not_pruned{WITH_LOCK(::cs_main, return !blockman.IsBlockPruned(blockindex))};
+            const bool have_undo{is_not_pruned && UndoReadFromDisk(blockUndo, blockindex)};


efd82ae

nit: Less negations:

Suggested change

const bool is_not_pruned{WITH_LOCK(::cs_main, return !blockman.IsBlockPruned(blockindex))};

const bool have_undo{is_not_pruned && UndoReadFromDisk(blockUndo, blockindex)};

const bool is_pruned{WITH_LOCK(::cs_main, return blockman.IsBlockPruned(blockindex))};

const bool have_undo{!is_pruned && UndoReadFromDisk(blockUndo, blockindex)};

?

How is this less negations? You're swapping a negation on one line, for a negation on a different line.

How is this less negations?

line 184: is_not_pruned
line 184: !blockman.IsBlockPruned(blockindex)
line 185: is_not_pruned
total = 3 cases

--

in suggestion
line 185: !is_pruned
total =1 case

I wouldn't consider variable names describing a state "negations", and I'm not sure why there is a need to avoid them.

Can also keep everything in one line as-is, and reduce the diff to a one-char diff.

const bool have_undo{WITH_LOCK(::cs_main, return !blockman.IsBlockPruned(blockindex)) && UndoReadFromDisk(blockUndo, blockindex)};

I wouldn't consider variable names describing a state "negations", and I'm not sure why there is a need to avoid them.

nm, I agree with the current code.

…es as m…

Summary: > After commit ccd8ef6 (D2979) it is no longer required to hold cs_main when calling ReadBlockFromDisk. > > The first commit moves ReadBlockFromDisk outside the lock scope in rest_block, where we can see a huge performance improvement when fetching blocks with multiple threads. This is a partial backport of [[bitcoin/bitcoin#26308 | core#26308]] bitcoin/bitcoin@c75e3d2 Test Plan: With Clang and DEBUG: `ninja all check-all` Reviewers: #bitcoin_abc, sdulfari Reviewed By: #bitcoin_abc, sdulfari Subscribers: sdulfari Differential Revision: https://reviews.bitcoinabc.org/D13052

Summary: > The second commit is from a suggestion on the original PR by jonatack to remove the unnecessary LOCK(cs_main) in the zmq notifier's NotifyBlock. This is a partial backport of [[bitcoin/bitcoin#26308 | core#26308]] bitcoin/bitcoin@7d253c9 Depends on D13052 Test Plan: With Clang and DEBUG: `ninja all check-all` Reviewers: #bitcoin_abc, sdulfari Reviewed By: #bitcoin_abc, sdulfari Differential Revision: https://reviews.bitcoinabc.org/D13053

Summary: This is a partial backport of [[bitcoin/bitcoin#26308 | core#26308]] bitcoin/bitcoin@f00808e Depends on D13053 Test Plan: With Clang and DEBUG: `ninja all check-all` Reviewers: #bitcoin_abc, sdulfari Reviewed By: #bitcoin_abc, sdulfari Differential Revision: https://reviews.bitcoinabc.org/D13054

Summary: This is a partial backport of [[bitcoin/bitcoin#26308 | core#26308]] bitcoin/bitcoin@efd82ae Depends on D13054 Test Plan: With Clang and DEBUG: `ninja all check-all` Reviewers: #bitcoin_abc, sdulfari Reviewed By: #bitcoin_abc, sdulfari Differential Revision: https://reviews.bitcoinabc.org/D13055

Summary: This is a partial backport of [[bitcoin/bitcoin#26308 | core#26308]] bitcoin/bitcoin@4d92b5a Depends on D13055 Test Plan: With Clang and DEBUG: `ninja all check-all` Reviewers: #bitcoin_abc, sdulfari Reviewed By: #bitcoin_abc, sdulfari Differential Revision: https://reviews.bitcoinabc.org/D13056

Summary: This concludes backport of [[bitcoin/bitcoin#26308 | core#26308]] bitcoin/bitcoin@d7f61e7 Depends on D13055 Test Plan: With Clang and DEBUG: `ninja all check-all` Reviewers: #bitcoin_abc, sdulfari Reviewed By: #bitcoin_abc, sdulfari Differential Revision: https://reviews.bitcoinabc.org/D13057

DrahtBot added the RPC/REST/ZMQ label Oct 13, 2022

fanquake mentioned this pull request Oct 14, 2022

rpc: reduce LOCK(cs_min) scope in rest_block: ~5 times as many requests per second #21006

Closed

andrewtoth force-pushed the no-lock-for-read-block branch from ad30672 to 77de778 Compare October 14, 2022 01:13

aureleoules approved these changes Oct 14, 2022

View reviewed changes

andrewtoth mentioned this pull request Oct 15, 2022

use shared mutex to guard against block files being removed before read #26316

Closed

andrewtoth marked this pull request as draft October 15, 2022 00:39

andrewtoth changed the title ~~rest: reduce LOCK(cs_main) scope in rest_block: ~6 times as many requests per second~~ rpc/rest/zmq: reduce LOCK(cs_main) scope: ~6 times as many requests per second Oct 17, 2022

andrewtoth force-pushed the no-lock-for-read-block branch 3 times, most recently from 0f882ec to bfa9663 Compare October 17, 2022 01:27

andrewtoth marked this pull request as ready for review October 17, 2022 02:15

andrewtoth force-pushed the no-lock-for-read-block branch from bfa9663 to d7f358b Compare October 17, 2022 13:13

andrewtoth mentioned this pull request Oct 17, 2022

net: don't lock cs_main while reading blocks in net processing #26326

Merged

This was referenced Oct 17, 2022

rpc: Faster getblock API #25232

Closed

Refactor: Improve API design of ScriptToUniv, TxToUniv etc to return the UniValue instead of mutating a parameter/reference #23507

Closed

andrewtoth marked this pull request as draft October 19, 2022 00:21

DrahtBot mentioned this pull request Nov 7, 2022

RPC/Blockchain: Optimise getblock for simple disk->hex case #21319

Closed

ryanofsky approved these changes Nov 17, 2022

View reviewed changes

andrewtoth marked this pull request as ready for review November 18, 2022 16:06

DrahtBot added the Needs rebase label Dec 6, 2022

andrewtoth force-pushed the no-lock-for-read-block branch from d7f358b to 2cd94da Compare December 6, 2022 14:27

maflcko reviewed Dec 6, 2022

View reviewed changes

src/zmq/zmqpublishnotifier.cpp Outdated Show resolved Hide resolved

DrahtBot removed the Needs rebase label Dec 6, 2022

andrewtoth mentioned this pull request Dec 6, 2022

rpc: Return accurate results for scanblocks #26325

Merged

andrewtoth added 6 commits December 6, 2022 15:07

rest: reduce LOCK(cs_main) scope in rest_block

c75e3d2

zmq: remove LOCK(cs_main) from NotifyBlock

7d253c9

rpc: reduce LOCK(cs_main) scope in GetBlockChecked and getblock

f00808e

rpc: reduce LOCK(cs_main) scope in blockToJSON

efd82ae

rpc: reduce LOCK(cs_main) scope in GetUndoChecked and getblockstats

4d92b5a

rpc: reduce LOCK(cs_main) scope in gettxoutproof

d7f61e7

andrewtoth force-pushed the no-lock-for-read-block branch from 2cd94da to d7f61e7 Compare December 6, 2022 20:07

hebasto reviewed Dec 7, 2022

View reviewed changes

hebasto approved these changes Dec 7, 2022

View reviewed changes

maflcko merged commit 1801d8c into bitcoin:master Dec 8, 2022

sidhujag pushed a commit to syscoin/syscoin that referenced this pull request Dec 8, 2022

Merge bitcoin#26308: rpc/rest/zmq: reduce LOCK(cs_main) scope: ~6 tim…

ef0b52a

…es as m…

andrewtoth deleted the no-lock-for-read-block branch December 8, 2022 22:55

maflcko mentioned this pull request Dec 21, 2022

clang-tidy: Add more performance-* checks and related fixes #26642

Merged

bitcoin locked and limited conversation to collaborators Dec 8, 2023

		const bool is_not_pruned{WITH_LOCK(::cs_main, return !blockman.IsBlockPruned(blockindex))};
		const bool have_undo{is_not_pruned && UndoReadFromDisk(blockUndo, blockindex)};

rpc/rest/zmq: reduce LOCK(cs_main) scope: ~6 times as many requests per second #26308

rpc/rest/zmq: reduce LOCK(cs_main) scope: ~6 times as many requests per second #26308

Uh oh!

Conversation

andrewtoth commented Oct 13, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

aureleoules left a comment

Choose a reason for hiding this comment

Uh oh!

andrewtoth commented Oct 14, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

DrahtBot commented Oct 17, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Reviews

Conflicts

Uh oh!

ryanofsky left a comment

Choose a reason for hiding this comment

Uh oh!

andrewtoth commented Nov 18, 2022

Uh oh!

andrewtoth commented Dec 6, 2022

Uh oh!

Uh oh!

maflcko commented Dec 6, 2022

Uh oh!

andrewtoth commented Dec 6, 2022

Uh oh!

maflcko commented Dec 7, 2022

Uh oh!

hebasto commented Dec 7, 2022

Uh oh!

hebasto Dec 7, 2022

Choose a reason for hiding this comment

Uh oh!

maflcko Dec 7, 2022

Choose a reason for hiding this comment

Uh oh!

andrewtoth Dec 7, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

hebasto left a comment

Choose a reason for hiding this comment

Uh oh!

hebasto Dec 7, 2022

Choose a reason for hiding this comment

Uh oh!

fanquake Dec 7, 2022

Choose a reason for hiding this comment

Uh oh!

hebasto Dec 7, 2022

Choose a reason for hiding this comment

Uh oh!

fanquake Dec 7, 2022

Choose a reason for hiding this comment

Uh oh!

maflcko Dec 7, 2022

Choose a reason for hiding this comment

Uh oh!

hebasto Dec 7, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

andrewtoth commented Oct 13, 2022 •

edited

Loading

andrewtoth commented Oct 14, 2022 •

edited

Loading

DrahtBot commented Oct 17, 2022 •

edited

Loading

andrewtoth Dec 7, 2022 •

edited

Loading

hebasto Dec 7, 2022 •

edited

Loading