rpc: Worker threads still run after timeout error for two gettxoutsetinfo RPC calls

hebasto commented at 12:55 pm on September 28, 2019: member

Having a default number (DEFAULT_HTTP_THREADS=4;) of HTTP worker threads.

A single gettxoutsetinfo RPC call returns:

 0hebasto@odroid:~$ time bitcoin-cli gettxoutsetinfo
 1{
 2  "height": 596966,
 3  "bestblock": "0000000000000000000016b72d77ce09ff1ffd98824e671e92c4e6b536e05b2c",
 4  "transactions": 36147771,
 5  "txouts": 62227414,
 6  "bogosize": 4681101424,
 7  "hash_serialized_2": "5523a667c0b00094c104b37f85d469b8db9c7615d861e17a22bbdef36717f3e1",
 8  "disk_size": 3761251169,
 9  "total_amount": 17961904.82206827
10}
11
12real	6m36.365s
13user	0m0.006s
14sys	0m0.012s

… and a worker thread gets the “sleeping” status (from the top output).

When running two gettxoutsetinfo RPC calls from two terminals (nearly) simultaneously, each of them returns with a timeout error:

0hebasto@odroid:~$ time bitcoin-cli gettxoutsetinfo
1error: Could not connect to the server 127.0.0.1:8332 (error code 0 - "timeout reached")
2
3Make sure the bitcoind server is running and that you are connecting to the correct RPC port.
4
5real	15m0.120s
6user	0m0.008s
7sys	0m0.012s

… and two worker threads do not sleep and still consume CPU cycles ~until bitcoind is stopped~ too long.

System information

0hebasto@odroid:~$ bitcoind -version | head -n 1
1Bitcoin Core Daemon version v0.18.0
2hebasto@odroid:~$ lsb_release -ds
3Ubuntu 18.04.3 LTS

Hardware: ODROID-HC1

hebasto added the label Bug on Sep 28, 2019

hebasto renamed this:
~~rpc: Worker threads still run endlessly for two gettxoutsetinfo RPC calls~~
rpc: Worker threads still run after timeout error for two gettxoutsetinfo RPC calls
on Sep 28, 2019

fanquake added the label RPC/REST/ZMQ on Sep 28, 2019

promag commented at 0:46 am on October 2, 2019: member

Have you tried with other RPC? Looks like a bug in the HTTP server (?).

0bitcoin-cli gettxoutsetinfo
1error: Could not connect to the server 127.0.0.1:8332 (error code 0 - "timeout reached")

How long until the 2nd line is printed?

hebasto commented at 7:03 pm on October 2, 2019: member

How long until the 2nd line is printed?

15 minutes.

MarcoFalke removed the label Bug on Oct 11, 2019

MarcoFalke commented at 8:02 pm on October 11, 2019: member

It might take longer when two threads fight over disk access on a slow disk.

15 minutes

That is the rpc timeout (900s), have you tried increasing it?

0  -rpcclienttimeout=<n>
1       Timeout in seconds during HTTP requests, or 0 for no timeout. (default:
2       900)

hebasto commented at 2:49 pm on October 12, 2019: member

That is the rpc timeout (900s), have you tried increasing it?

With increased value of -rpcclienttimeout it takes about 74 min to finish two concurrent gettxoutsetinfo RPC calls instead of about 6 min for a single one.

MarcoFalke commented at 3:11 pm on October 12, 2019: member

Did they report the correct result?

hebasto commented at 3:17 pm on October 12, 2019: member

Did they report the correct result?

Yes.

MarcoFalke commented at 3:21 pm on October 12, 2019: member

I presume the issue is just disk access. If you feel like digging, you can try running through /usr/bin/time -v ... or similar.

MarcoFalke added the label Resource usage on Oct 12, 2019

hebasto commented at 4:53 pm on October 12, 2019: member

I presume the issue is just disk access. If you feel like digging, you can try running through /usr/bin/time -v ... or similar.

 0$ date; /usr/bin/time -v bitcoin-cli -rpcclienttimeout=86400 gettxoutsetinfo
 1Sat Oct 12 15:40:47 UTC 2019
 2{
 3  "height": 599069,
 4  "bestblock": "00000000000000000003c798f8dfe68ff0d813b5ee3126376385cf289643f62b",
 5  "transactions": 36735954,
 6  "txouts": 63065683,
 7  "bogosize": 4743358939,
 8  "hash_serialized_2": "63a6e567364f0143fb795d0ab9d0caa150dbb023b3d42e42792918e169aaa647",
 9  "disk_size": 3774113243,
10  "total_amount": 17988192.32195437
11}
12	Command being timed: "bitcoin-cli -rpcclienttimeout=86400 gettxoutsetinfo"
13	User time (seconds): 0.00
14	System time (seconds): 0.01
15	Percent of CPU this job got: 0%
16	Elapsed (wall clock) time (h:mm:ss or m:ss): 1:09:44
17	Average shared text size (kbytes): 0
18	Average unshared data size (kbytes): 0
19	Average stack size (kbytes): 0
20	Average total size (kbytes): 0
21	Maximum resident set size (kbytes): 2316
22	Average resident set size (kbytes): 0
23	Major (requiring I/O) page faults: 18
24	Minor (reclaiming a frame) page faults: 265
25	Voluntary context switches: 39
26	Involuntary context switches: 1
27	Swaps: 0
28	File system inputs: 3128
29	File system outputs: 0
30	Socket messages sent: 0
31	Socket messages received: 0
32	Signals delivered: 0
33	Page size (bytes): 4096
34	Exit status: 0

hebasto commented at 7:35 am on October 13, 2019: member

ARM big.LITTLE architecture could be the root of issue. How can I find out which core, big or LITTLE, runs a particular thread?

MarcoFalke commented at 8:07 pm on July 2, 2020: member

I think the cli simply disconnects, but the server doesn’t know that, so the thread keeps running?

promag commented at 9:22 pm on July 2, 2020: member

I think the cli simply disconnects, but the server doesn’t know that, so the thread keeps running?

Yes, only thing “interrupting” requests ATM is shutdown.

hebasto commented at 4:57 am on July 3, 2020: member

My ODROID-HC1 is out of order now (I hope this is a temporary problem); and I couldn’t make more tests.

So closing for now.

hebasto closed this on Jul 3, 2020

hebasto commented at 10:07 pm on August 16, 2020: member

Cheap hardware (SD card) and trash software (stock OS) were the root of this issue.

The same ODROID-HC1 with a new good & reliable SD card, powered by Armbian Focal OS – all issues are gone.

DrahtBot locked this on Feb 15, 2022

rpc: Worker threads still run after timeout error for two gettxoutsetinfo RPC calls #16979