test: speed up the two slowest functional tests by 18-35% via `keypoolrefill()` #26722

kdmukai commented at 3:21 PM on December 18, 2022: contributor

Problem

wallet_fundrawtransaction.py and wallet_sendall.py are the two slowest functional tests when running without a RAM disk.

# M1 MacBook Pro timings
wallet_fundrawtransaction.py --descriptors   | ✓ Passed  | 55 s
wallet_fundrawtransaction.py --legacy-wallet | ✓ Passed  | 381 s

wallet_sendall.py --descriptors   | ✓ Passed  | 43 s
wallet_sendall.py --legacy-wallet | ✓ Passed  | 327 s

In each case, the majority of the time is spent iterating through 1500 to 1600 getnewaddress() calls. This is particularly slow in the --legacy-wallet runs.

see: https://github.com/bitcoin/bitcoin/blob/master/test/functional/wallet_fundrawtransaction.py#L986-L987 see: https://github.com/bitcoin/bitcoin/blob/master/test/functional/wallet_sendall.py#L324

Solution

Pre-fill the keypool before iterating through those getnewaddress() calls.

With this change, the execution time drops to:

wallet_fundrawtransaction.py --descriptors   | ✓ Passed  | 52 s     # -3s diff
wallet_fundrawtransaction.py --legacy-wallet | ✓ Passed  | 291 s    # -90s diff

wallet_sendall.py --descriptors   | ✓ Passed  | 27 s     # -16s diff
wallet_sendall.py --legacy-wallet | ✓ Passed  | 228 s    # -99s diff

Tagging @ Sjors as he had encouraged me to take a look at speeding up the tests.

DrahtBot commented at 3:22 PM on December 18, 2022: contributor

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	achow101
Concept ACK	theStack, brunoerg

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

DrahtBot added the label Tests on Dec 18, 2022

in test/functional/wallet_fundrawtransaction.py:980 in 857427ac62 outdated

 974 | @@ -975,6 +975,9 @@ def test_transaction_too_large(self):
 975 |          self.nodes[0].createwallet("large")
 976 |          wallet = self.nodes[0].get_wallet_rpc(self.default_wallet_name)
 977 |          recipient = self.nodes[0].get_wallet_rpc("large")
 978 | +
 979 | +        # Force the wallet to bulk-generate the addresses we'll need
 980 | +        recipient.keypoolrefill(1500)

theStack commented at 6:08 PM on December 18, 2022:

nit: Could probably move this call a few lines down, immediately before the output generation loop so it's more obvious why 1500? (The createrawtransaction call doesn't make use of the keypool, so it's okay to prefill after).

kdmukai commented at 8:06 PM on December 18, 2022:

Updated!

theStack commented at 6:11 PM on December 18, 2022: contributor

Concept ACK :rocket:

brunoerg commented at 8:00 PM on December 18, 2022: contributor

Concept ACK

kdmukai force-pushed on Dec 18, 2022

test: speed up wallet_fundrawtransaction.py and wallet_sendall.py 31fdc54dba

in test/functional/wallet_sendall.py:339 in 40056be160 outdated

 334 | @@ -331,6 +335,9 @@ def sendall_fails_with_transaction_too_large(self):
 335 |                  self.wallet.sendall,
 336 |                  recipients=[self.remainder_target])
 337 |  
 338 | +        # Reset the wallet to default
 339 | +        self.wallet.keypoolrefill(0)

maflcko commented at 9:52 AM on December 19, 2022:

Why is 0 the default and what would the call of this RPC do anyway, considering that a full keypool isn't thrown away by calling this.

kdmukai commented at 4:58 PM on December 19, 2022:

At this point in the test, self.wallet.getwalletinfo()['keypoolsize'] reports 0.

My concern was that any future tests added after this would incur a slight time penalty when calling getnewaddress on the empty keypool (~60ms slower each time for --legacy-wallet).

So my intention was to repopulate the keypool with what I thought was the default, but I misread the rpc docs. If I make the correct call (self.wallet.keypoolrefill() w/no arguments), the current config results in a new keypool size of 1. Not so helpful.

But this all strikes me now as unnecessary premature optimization.

Can either:

Not worry about future tests.
Slightly increase the first keypoolrefill call to have some leftover (+10? +100?).

Either way, my second keypoolrefill that you point out here is unnecessary and will be removed.

kdmukai force-pushed on Dec 19, 2022

achow101 commented at 6:00 PM on December 19, 2022: member

ACK 31fdc54dba92fe9d7d8289f1e4380082838a74a9

I'm not seeing a significant time delta on my system, but I can see why it might for some systems.

brunoerg commented at 10:45 PM on December 19, 2022: contributor

Some tests on my Macbook Air M1:

master:

./test/functional/wallet_fundrawtransaction.py --descriptors  3.36s user 0.88s system 17% cpu 23.551 total
./test/functional/wallet_fundrawtransaction.py --legacy-wallet  11.14s user 3.62s system 17% cpu 1:23.17 total

./test/functional/wallet_sendall.py --descriptors  1.13s user 0.30s system 61% cpu 2.323 total
./test/functional/wallet_sendall.py --legacy-wallet  7.65s user 2.57s system 16% cpu 1:03.60 total

this branch:

./test/functional/wallet_fundrawtransaction.py --descriptors  3.66s user 
0.84s system 19% cpu 22.843 total
./test/functional/wallet_fundrawtransaction.py --legacy-wallet  9.11s user 3.05s system 18% cpu 1:04.39 total

./test/functional/wallet_sendall.py --descriptors  1.53s user 0.30s system 66% cpu 2.737 total
./test/functional/wallet_sendall.py --legacy-wallet  5.61s user 2.15s system 17% cpu 44.872 total

kdmukai commented at 4:36 PM on December 20, 2022: contributor

Figured out how to get a RAM disk set up for Mac and finally seeing similar (blazing!) performance as @brunoerg's numbers (albeit still a bit slower).

So this PR ends up being a massive time saver IF you aren't running a RAM disk, but basically unnoticeable if you are running a RAM disk. The RAM disk runs are pretty inconsistent so any time impact seems to get lost in the run-to-run random variation.

For example, on an old 2014 8GB Intel MacBook Air:

# Master, no RAM disk
wallet_fundrawtransaction.py --descriptors   | ✓ Passed  | 66 s
wallet_fundrawtransaction.py --legacy-wallet | ✓ Passed  | 711 s

# PR, no RAM disk
wallet_fundrawtransaction.py --descriptors   | ✓ Passed  | 53 s   # -13 s
wallet_fundrawtransaction.py --legacy-wallet | ✓ Passed  | 455 s  # -256 s

# Master, w/1GB RAM disk
wallet_fundrawtransaction.py --descriptors   | ✓ Passed  | 19-33 s (3 runs)
wallet_fundrawtransaction.py --legacy-wallet | ✓ Passed  | 23-32 s (3 runs)

# PR, w/1GB RAM disk
wallet_fundrawtransaction.py --descriptors   | ✓ Passed  | 27-32 s (3 runs)
wallet_fundrawtransaction.py --legacy-wallet | ✓ Passed  | 21-30 s (3 runs)

So I can't say if this PR is a worthwhile change or not.

Are there machines/OSes that can't allocate a sufficient RAM disk? Like, I don't know, a 2GB Raspberry Pi? Is it possible that there are global devs out there trying to work on such an underpowered device?

achow101 commented at 6:58 PM on December 20, 2022: member

So I can't say if this PR is a worthwhile change or not.

Are there machines/OSes that can't allocate a sufficient RAM disk? Like, I don't know, a 2GB Raspberry Pi? Is it possible that there are global devs out there trying to work on such an underpowered device?

It isn't so much as what computers developers use are capable of, but rather what are new developers most likely to encounter. Many OSes have default configurations that do not use ramdisks for /tmp, so we should do things that make it easier for those using such default configurations.

maflcko merged this on Dec 21, 2022

maflcko closed this on Dec 21, 2022

sidhujag referenced this in commit fb9c7574f0 on Dec 21, 2022

bitcoin locked this on Dec 21, 2023