RPC performance problems

[jnorthco]

I'm having some problems with RPC performance with Bitcoin Core v0.17.1 .

My wallet is a reasonable size, with around 100K addresses and 400K transactions, at first I though it was related to this, but even basic RPC calls that do not use the wallet are taking a very long time:

root@no:~# date; time bitcoin-cli uptime; date
Wed 19 Jun 13:55:13 EDT 2019
2606

real   0m26.249s
user   0m0.000s
sys   0m0.000s
Wed 19 Jun 13:55:39 EDT 2019


It seems that the time is all taken before the call is actually processed.  In debug.log, I see this for example:

2019-06-19T17:55:39Z ThreadRPCServer method=uptime

So, the LogPrint in the parse function was not reached until the very end of the 26 second processing time, confirming that it's not the uptime function itself that takes the time, but something that happens before this.

I currently have 4 RPC threads enabled.  top shows that one of them is generally busy with 100% CPU use (a single core).  Once one finishes, the next one will use 100% CPU, so it would seem that only one request at a time is actually processed despite the 4 threads, although this is hard to verify.  strace shows that threads are normally waiting for a futex when they are not using the CPU:

root@no:~# strace -p 22451
strace: Process 22451 attached
futex(0x555b6d8b6260, FUTEX_WAKE_PRIVATE, 1) = 1
write(8, "\1\0\0\0\0\0\0\0",         = 8
futex(0x555b6f63b000, FUTEX_WAKE_PRIVATE, 1) = 1
write(1, "2019-06-19T20:33:27Z ThreadRPCSe"..., 71) = 71
write(4, "2019-06-19T20:33:27Z ThreadRPCSe"..., 71) = 71
futex(0x555b6d8b6260, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x555b6d8b6260, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x555b6d8b6260, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x555b6d8b6260, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x555b6d8b6260, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x555b6d8b6260, FUTEX_WAKE_PRIVATE, 1) = 1
write(8, "\1\0\0\0\0\0\0\0",         = 8
write(1, "2019-06-19T20:33:42Z ThreadRPCSe"..., 75) = 75
write(4, "2019-06-19T20:33:42Z ThreadRPCSe"..., 75) = 75
futex(0x555b6d8b6260, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x555b6d8b6260, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x555b6d8b6260, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x555b6d8b6260, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x555b6d8b6260, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x555b6d8b6260, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x555b6d8b6260, FUTEX_WAKE_PRIVATE, 1) = 1
write(8, "\1\0\0\0\0\0\0\0",         = 8
futex(0x555b6f63b000, FUTEX_WAKE_PRIVATE, 1) = 1
write(1, "2019-06-19T20:33:43Z ThreadRPCSe"..., 75) = 75
write(4, "2019-06-19T20:33:43Z ThreadRPCSe"..., 75) = 75
futex(0x555b6d8b6260, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x555b6d8b6260, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0x555b6d8b6260, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x555b6d8b6260, FUTEX_WAIT_PRIVATE, 2, NULL^Cstrace: Process 22451 detached
 <detached ...>

Timing is a little hard to judge, but watching top at the same time seems to bear out that each httpworker is stuck in a futex until it grabs the CPU, writes the log entry, and processes a request, then it stops in a futex again.

The RPC sever is fairly busy, here is the call breakdown over a typical 60-minute period:

root@no:~# grep 2019-06-19T19 debug.log | grep ThreadRPC | cut -d '=' -f 2 | cut -d ' ' -f 1 | sort | uniq -c
    662 getbalance
    997 getblockcount
   3646 getreceivedbyaddress
    876 gettransaction
    254 getwalletinfo
    107 listsinceblock
      5 sendfrom
      4 settxfee

So, just under 2 RPC calls per second on average.

I'm not sure how to determine if the slowness is based on the wallet size, the overall RPC volume, or some other factor, but it seems like at least the 4 threads should be able to work in parallel rather than in sequence as they currently seem to.

I've attempted increasing rpcthreads to 64, but this just results in 63 idle httpworker threads and one active using 100% of one core.

Anybody have any suggestions?

[1714140953]

1714140953

[1714140953]

1714140953

[1714140953]

1714140953

[achow101]

Bitcoin Core uses a lot of locks internally in order to keep data structures sane with concurrency. A lot of RPCs tend to take the same locks, e.g. many take the main lock cs_main. Wallet ones almost always take cs_wallet. So if you are doing a lot of different RPCs, it's likely that something is grabbing a lock and thus forcing the next call to have to wait for the same lock so it takes a long time.

Are you running something in the background that is doing a lot of RPC calls? If you stop that, does it become faster?

[jnorthco]

The RPC call count I posted is always happening.  It's a production wallet, so it's hard to reduce traffic, but I'll see if I can reduce the frequency of these calls and see if it impacts performance.  I cannot duplicate the poor performance by importing the same wallet into a separate instance of Core, although my test Core is not yet synchronized, so I'm not sure if this is due to reduced RPC traffic or due to the near-empty block database.

Thanks for confirming that there are locks in the RPC code, that would definitely explain what we're seeing.  Do you have any guidance on which RPC calls might be more expensive, and thus hold the lock longer?  Would any options to Core (txindex maybe?) be expected to improve performance for any of the calls that we're making?

[achow101]

Do you have any guidance on which RPC calls might be more expensive, and thus hold the lock longer? 

getbalance and getreceivedbyaddress are both pretty expensive and equally expensive (they both loop over all transactions in the wallet).

listsinceblock can be fairly expensive, depending on how far back you are looking.

sendfrom can also be pretty expensive depending on the distribution of the values of your UTXOs.

Would any options to Core (txindex maybe?) be expected to improve performance for any of the calls that we're making?

No.

[DaveF]

Although many people will disagree with me on this. The speed / performance issue can be fixed by throwing hardware at the problem.
You just need a lot of it at the moment. Can you move the blocks to faster disks or a raid with better performance? Can you put in enough ram to carve out a 256gb ramdrive so you can move the blockchain there?

Yeah, we're talking $1000s, you just have to figure out if it's better to spend time optimizing or just spend some money and kick the problem down the road till you outgrow it again.

-Dave

[linenoise]

You do not mention your machine specs. Do you have a lot of memory? As noted better equipment has better performance and I have seen too little memory cause a lot of high CPU usage with crypto.  Also memory is usually the easiest thing to add to a system to improve performance.