Tests: speed up fundrawtransaction test #17340

jnewbery commented at 2:27 PM on November 1, 2019: member

Speed up rpc_fundrawtransaction.py

Most of the time in rpc_fundrawtransaction.py is spent waiting for unconfirmed transactions to propagate. Net processing adds a poisson random delay to the time it will INV transactions with a mean interval of 5 seconds. Calls like the following:

self.nodes[2].sendrawtransaction(signedTx['hex'])
self.sync_all()
self.nodes[1].generate(1)

will therefore introduce a delay waiting for the mempools to sync. Instead just generate the block on the node that sent the transaction:

self.nodes[2].sendrawtransaction(signedTx['hex'])
self.nodes[2].generate(1)

rpc_fundrawtransaction.py is not intended to be a test for transaction relay, so it's ok to do this.

jnewbery commented at 2:28 PM on November 1, 2019: member

h/t to @jonatack for adding logging in #17327. It wouldn't have been obvious where the delays were being introduced without that PR.

jnewbery commented at 2:29 PM on November 1, 2019: member

Sample run before this PR:

 ./rpc_fundrawtransaction.py 
2019-11-01T14:11:43.898000Z TestFramework (INFO): Initializing test directory /tmp/user/1000/bitcoin_func_test__37epvjg
2019-11-01T14:11:45.270000Z TestFramework (INFO): Connect nodes, set fees, generate blocks, and sync
...
2019-11-01T14:12:41.473000Z TestFramework (INFO): Tests successful

(58 seconds)

after:

→ ./rpc_fundrawtransaction.py 
2019-11-01T14:20:14.757000Z TestFramework (INFO): Initializing test directory /tmp/user/1000/bitcoin_func_test_sel5qr1p
2019-11-01T14:20:15.609000Z TestFramework (INFO): Connect nodes, set fees, generate blocks, and sync
...
2019-11-01T14:20:27.072000Z TestFramework (INFO): Tests successful

(12 seconds)

jonatack commented at 2:59 PM on November 1, 2019: member

Run times in seconds for me:

ff22751417c6fbbd22f4eefd0e23431a83335c13: 62, 61, 52, 56, 61, 64

a8f7497a2335842dd357fa16ce1b38962a718b2a: 20, 22, 21, 21, 20, 22

fanquake added the label Tests on Nov 1, 2019

promag commented at 3:55 PM on November 1, 2019: member

rpc_fundrawtransaction.py is not intended to be a test for transaction relay

Concept ACK, nice speedup!

jonatack commented at 4:50 PM on November 1, 2019: member

In test_runner.py::BASE_SCRIPTS, rpc_fundrawtransaction.py could be moved down 3 groups to the upper part of Tests less than 30s.

achow101 commented at 4:53 PM on November 1, 2019: member

Are there other tests where we could make a similar improvement?

jnewbery commented at 4:58 PM on November 1, 2019: member

Are there other tests where we could make a similar improvement?

Yes. Anything that is sped up by #15881 could be individually sped up by changing how txs are relayed in that test. Alternatively, running the tests under a python profiler and checking which ones spend a lot of time in sync_mempools would show places that could be optimized.

MarcoFalke commented at 5:02 PM on November 1, 2019: member

If you decide to re-sort the tests, could also include the ones that have been made faster here: #16613 (comment)

jnewbery commented at 9:40 PM on November 1, 2019: member

Made it faster

jnewbery commented at 9:40 PM on November 1, 2019: member

If you decide to re-sort the tests, could also include the ones that have been made faster here: #16613 (comment)

I think that could be done separately

MarcoFalke commented at 9:44 PM on November 1, 2019: member

Rebase or force push to work around the GitHub bug?

jnewbery force-pushed on Nov 1, 2019

jnewbery commented at 9:45 PM on November 1, 2019: member

Rebase or force push to work around the GitHub bug?

Done. Thanks!

jonatack commented at 8:02 AM on November 4, 2019: member

Run times in seconds for me:

ff22751: 62, 61, 52, 56, 61, 64

a8f7497: 20, 22, 21, 21, 20, 22

2919ad318a723c7b90147298d93dd95458c7715f: 20, 21, 22, 24, 21, 21 -> I'm not seeing improvement over a8f7497a2335842dd357fa16ce1b38962a718b2a

in test/functional/rpc_fundrawtransaction.py:33 in 2919ad318a outdated

  27 | @@ -28,6 +28,9 @@ class RawTransactionsTest(BitcoinTestFramework):
  28 |      def set_test_params(self):
  29 |          self.num_nodes = 4
  30 |          self.setup_clean_chain = True
  31 | +        # This test isn't testing tx relay. Set whitelist on the peers for
  32 | +        # instant tx relay.
  33 | +        self.extra_args = [['-whitelist=127.0.01']] * 4

jonatack commented at 9:49 AM on November 4, 2019:

s/127.0.01/127.0.0.1/ ?

Credit to @practicalswift who caught it in my PR ;)

Sjors commented at 5:28 PM on November 4, 2019:

Maybe also make it more specific: -whitelist=relay@127.0.0.1.

~You could also add -whitebind to cover both inbound and outbound, however for some reason this requires you to specify a port, so you'd have to tweak the test suite for that.~

Afaik whitelist only works for inbound connections. Not sure if that matters here.

jnewbery commented at 6:39 PM on November 4, 2019:

Fixed. Thanks!

Sjors approved

Sjors commented at 5:29 PM on November 4, 2019: member

ACK 2919ad3 modulo IP typo (I ran with that corrected).

Tested on macOS 10.15 with --enable-debug. Before: 72 seconds. After: 38 seconds.

[tests] Speed up rpc_fundrawtransaction.py

Most of the time in rpc_fundrawtransaction.py is spent waiting for
unconfirmed transactions to propagate. Net processing adds a poisson
random delay to the time it will INV transactions with a mean interval
of 5 seconds. Calls like the following:

```
self.nodes[2].sendrawtransaction(signedTx['hex'])
self.sync_all()
self.nodes[1].generate(1)
````

will therefore introduce a delay waiting for the mempools to sync.
Instead just generate the block on the node that sent the transaction:

```
self.nodes[2].sendrawtransaction(signedTx['hex'])
self.nodes[2].generate(1)
```

rpc_fundrawtransaction.py is not intended to be a test for transaction
relay, so it's ok to do this.

646b593bbd

jnewbery force-pushed on Nov 4, 2019

jnewbery commented at 6:41 PM on November 4, 2019: member

I'm not seeing improvement over a8f7497

I see at least a second saved on average from not having to stop-start the nodes. I think not stop-starting when unnecessary makes a cleaner test in any case.

in test/functional/rpc_fundrawtransaction.py:33 in ae6fd926d0 outdated

  27 | @@ -28,6 +28,9 @@ class RawTransactionsTest(BitcoinTestFramework):
  28 |      def set_test_params(self):
  29 |          self.num_nodes = 4
  30 |          self.setup_clean_chain = True
  31 | +        # This test isn't testing tx relay. Set whitelist on the peers for
  32 | +        # instant tx relay.
  33 | +        self.extra_args = [['-whitelist=127.0.0.1']] * 4

jonatack commented at 10:43 AM on November 6, 2019:

Could do

     def set_test_params(self):
-        self.num_nodes = 4
+        num_nodes = 4
+        self.num_nodes = num_nodes
         self.setup_clean_chain = True
         # This test isn't testing tx relay. Set whitelist on the peers for
         # instant tx relay.
-        self.extra_args = [['-whitelist=127.0.0.1']] * 4
+        self.extra_args = [['-whitelist=127.0.0.1']] * num_nodes

jnewbery commented at 7:57 PM on November 6, 2019:

even better, just:

        self.extra_args = [['-whitelist=127.0.0.1']] * self.num_nodes

which I've now done.

jonatack commented at 9:16 AM on November 7, 2019:

Yes, even better; doing the same in wallet_avoidreuse.py

jonatack commented at 10:46 AM on November 6, 2019: member

ACK ae6fd926d0b49f69dec4b63e0d5cc2a639408892 happy to re-ACK for the simple change below

[tests] Use -whitelist in rpc_fundrawtransaction.py

Makes tx relay faster

9a8505299b

[tests] Don't stop-start unnecessarily in rpc_fundrawtransaction.py

This was only added in c1dde3a949b36ce9c2155777b3fa1372e7ed97d8 to match
behaviour when `encryptwallet` would restart the node. It's not required
for the test (and slows things down).

af7bae7340

jnewbery force-pushed on Nov 6, 2019

MarcoFalke commented at 8:16 PM on November 6, 2019: member

ACK af7bae734089f6af0029b0887932ccd9a469e12e 🛴

<details><summary>Show signature and timestamp</summary>

Signature:

Timestamp of file with hash 1ecd30be3396a80fa3c5142b61bd557f16f7db00e6f86414f9df50183d6462cf -

</details>

MarcoFalke referenced this in commit e65b4160e9 on Nov 6, 2019

MarcoFalke merged this on Nov 6, 2019

MarcoFalke closed this on Nov 6, 2019

jnewbery deleted the branch on Nov 6, 2019

promag commented at 8:42 PM on November 6, 2019: member

Here we go :owl:

sidhujag referenced this in commit a8f50b80a5 on Nov 7, 2019

fanquake referenced this in commit 270616228b on Nov 7, 2019

MarcoFalke referenced this in commit a57af897ec on Aug 16, 2020

sidhujag referenced this in commit 9f7e4e2bb0 on Aug 16, 2020

jasonbcox referenced this in commit 3687ad6dbc on Nov 4, 2020

sidhujag referenced this in commit 1395875031 on Nov 10, 2020

DrahtBot locked this on Dec 16, 2021