tests: Running with –usecli ~5x slower than without #15309

1. 
   fanquake commented at 3:42 am on February 1, 2019: member

   Bought up in IRC here (line 603). More discussion here (line 10).

   master @ cb35f1d305d88934df64c2e7fb80700b673360e6 with --usecli:

   0test/functional/test_runner.py --usecli wallet_disableprivatekeys.py
   1Temporary test directory at /var/folders/z2/cn877pxd3czdfh47mfkmbwgm0000gn/T/test_runner_₿_🏃_20190201_113059
   21/1 - wallet_disableprivatekeys.py passed, Duration: 35 s             
   3
   4TEST                         | STATUS    | DURATION
   5
   6wallet_disableprivatekeys.py | ✓ Passed  | 35 s
   7
   8ALL                          | ✓ Passed  | 35 s (accumulated) 
   9Runtime: 35 s
   

   without --usecli:

   0test/functional/test_runner.py wallet_disableprivatekeys.py
   1Temporary test directory at /var/folders/z2/cn877pxd3czdfh47mfkmbwgm0000gn/T/test_runner_₿_🏃_20190201_113144
   21/1 - wallet_disableprivatekeys.py passed, Duration: 7 s
   3
   4TEST                         | STATUS    | DURATION
   5
   6wallet_disableprivatekeys.py | ✓ Passed  | 7 s
   7
   8ALL                          | ✓ Passed  | 7 s (accumulated) 
   9Runtime: 7 s
   

2. fanquake added the label Tests on Feb 1, 2019
3. 
   laanwj commented at 9:31 am on February 1, 2019: member

   It’s expected to be somewhat slower due to the process creation overhead, this overhead counts in tests that do a lot of RPC calls. But agree even then 5× is much slower than expected.
4. 
   MarcoFalke commented at 4:14 pm on February 1, 2019: member

   This happens because there is a 30 second overhead to exit the http event loop:

   0 node0 ...:09.423988Z Flushed wallet.dat 0ms 
   1 node0 ...:37.123147Z Exited http event loop 
   

5. MarcoFalke added the label RPC/REST/ZMQ on Feb 1, 2019
6. MarcoFalke added this to the milestone 0.18.0 on Feb 1, 2019
7. 
   ryanofsky commented at 4:53 pm on February 1, 2019: member

   Is this related to #14670?
8. 
   ryanofsky commented at 4:57 pm on February 1, 2019: member

   From IRC, it might be related to #14993:

   [00:53:49] <aj> i’d seen it in december, as at cb52cee2 fwiw

9. 
   sdaftuar commented at 5:58 pm on February 5, 2019: member

   PR #14670 seems to have slowed down tests considerably, particularly when using –usecli.

   I bisected this and commit e98a9eede2fb48ff33a020acc888cbcd83e24bbf is the first one I see that consistently slows down performance (I was running test/functional/wallet_multiwallet.py --usecli, and prior that commit it consistently takes 20 seconds on my machine, while after that commit it takes more than 40 seconds). The following commit 8d3f46ec3938e2ba17654fecacd1d2629f9915fd slows things down considerably more – that same test takes over 5 minutes after that commit.

   I’m not familiar with the changes in #14670 so perhaps the reviewers from that PR can comment further?

   ping @promag

10. 
    promag commented at 6:14 pm on February 5, 2019: member

    @sdaftuar thanks, looks like the client is not closing the connection and the server is allowing the connection to persist, this leads to the connection timeout (by default 60sec 30sec).

    Do you observe slow down only with --usecli?. It’s strange because bitcoin-cli sends Connection: close header and libevent should close the connection after it - unless there are other events in the event base.

    I’ll revisit this along with #14993.

11. MarcoFalke removed this from the milestone 0.18.0 on Feb 13, 2019
12. 
    fanquake commented at 7:14 pm on November 25, 2019: member

    Going to close this, as I am no longer seeing any significant difference, i.e only 1-2s on applicable tests, with or without --usecli. Using master at 89a1f7a250ef70ff2d65701564f1e24bb9280d90.
13. fanquake closed this on Nov 25, 2019

    ---

14. deadalnix referenced this in commit 35f2c83fa6 on Feb 6, 2020
15. MarcoFalke locked this on Dec 16, 2021

Contributors
fanquake laanwj MarcoFalke ryanofsky sdaftuar promag

Labels
Tests RPC/REST/ZMQ