gitian vs self-compiled on ARM 32-bit gettxoutsetinfo #18538

UPDATE: see #18538 (comment)

Having the low-end system ODROID-HC1. The downloaded binaries 0.19.1 behave as expected:

$ time bitcoin-cli -rpcclienttimeout=3600 gettxoutsetinfo
{
  "height": 624598,
  "bestblock": "0000000000000000001366754ef0fb1b483f1d7d64e3f561c262fdf5978ffbc0",
  "transactions": 39618423,
  "txouts": 66517746,
  "bogosize": 4997008193,
  "hash_serialized_2": "53f16a7e24542b3079eb7246660126392107fe87b2233ec27070386d333de708",
  "disk_size": 4009464235,
  "total_amount": 18307304.82089071
}

real	6m33.513s
user	0m0.004s
sys	0m0.023s

Monitoring the b-httpworker.0 thread via htop shows that it is running almost all the time.

The similar results I've received from other downloaded versions: 0.19.0.1 and 0.18.0.

The built locally binaries (with and without depends) show very different results:

$ time bitcoin-cli -rpcclienttimeout=3600 gettxoutsetinfo
{
  "height": 624679,
  "bestblock": "000000000000000000117e2b43965e568b5d50004f347f8b6ee642191c2895a8",
  "transactions": 39645155,
  "txouts": 66579180,
  "bogosize": 5001532788,
  "hash_serialized_2": "8adbf6e32f931eea9cc2cbcbd44c25b06ab0f1f564c6b75174ad60dc8b48f496",
  "disk_size": 4009243803,
  "total_amount": 18308317.32089071
}

real	56m23.878s
user	0m0.004s
sys	0m0.030s

Monitoring the b-httpworker.0 thread via htop shows that it is blocked very often.

This difference in behavior is so strange, I'm not sure how to debug it...

The compiler on machine:

$ g++ --version | head -1
g++ (Ubuntu/Linaro 7.5.0-3ubuntu1~18.04) 7.5.0

Please note that this issue differs from #16979.

If you compile boost and libevent from depends, does it match the gitian behavior?

If you compile boost and libevent from depends, does it match the gitian behavior?

No, it doesn't. FWIW, I compiled depends with NO_QT=1 only.

Using Clang instead of GCC did not help.

Those two gettxoutsetinfo outputs are for different blocks; their output isn't expected to be the same.

I think the bug is about how long it takes to compute them

Oh!

Just discovered:

To make the binary, which is compiled on ODROID-HC1, as fast as a gitian build it is required to configure with the --disable-threadlocal option. Don't know the reasons though...

Also such binary, compiled with --disable-threadlocal configure option, has debug.log file clear from massive messages "socket recv error Connection reset by peer (104)".

@hebasto Can you check if he RPC calls are faster when you run with -nodebuglogfile -nodebug?

@MarcoFalke

@hebasto Can you check if he RPC calls are faster when you run with -nodebuglogfile -nodebug?

Checked. Yes, they are faster:

hebasto@odroid:~/bitcoin$ date; time bitcoin-cli -rpcclienttimeout=10000 gettxoutsetinfo
Fri Apr 17 11:30:16 UTC 2020
{
  "height": 626399,
  "bestblock": "000000000000000000103db782701e6747a0bf98bcc7933f92800d0b38e089f8",
  "transactions": 39781990,
  "txouts": 66615480,
  "bogosize": 5004515507,
  "hash_serialized_2": "27264fac620c60137ed79feecde0876174d3ca66dc5abebd6e480fe31f03cf09",
  "disk_size": 4013644842,
  "total_amount": 18329817.32081895
}

real	10m41.300s
user	0m0.004s
sys	0m0.026s
hebasto@odroid:~/bitcoin$ date; time bitcoin-cli -rpcclienttimeout=10000 gettxoutsetinfo
Fri Apr 17 11:47:04 UTC 2020
{
  "height": 626400,
  "bestblock": "0000000000000000000ad754a8c9860880d015f552d52976ff10cce5004321c5",
  "transactions": 39782745,
  "txouts": 66617426,
  "bogosize": 5004659160,
  "hash_serialized_2": "d696936443fe99a1aa796f9146968a68ca61c35641338f33343848bfbf54470a",
  "disk_size": 4017378717,
  "total_amount": 18329829.82081895
}

real	7m23.625s
user	0m0.009s
sys	0m0.032s

Did you have -debug=1 enabled, which includes leveldb debug logs?

Did you have -debug=1 enabled, which includes leveldb debug logs?

The excerpt from my bitcoin.con:

debug=rpc
logthreadnames=1

I have to re-open this issue.

While testing #18851 on my ODROID-HC1 (ARM 32-bit) I discovered very strange things: the performance of the gettxoutsetinfo RPC call degrades by 10..15 times over time, if it is made several times consequentially (not concurrently). More details for different cases:

• binary compiled without --disable-threadlocal -- performance degradation at the first gettxoutsetinfo RPC call
• gitian 0.20rc1 and #18851 -- performance degradation starts from the 3rd gettxoutsetinfo RPC call in a row

It seems the root of the problem lies somewhere in the resource management rather in thread_local.

Hope someone could reproduce my test results on similar hardware.

@hebasto This sounds like maybe memory fragmentation, perhaps in conjunction with swap space being used?

@sipa In fact, no swap is used on the test node:

$ free
              total        used        free      shared  buff/cache   available
Mem:        2042436      424220       51416        5964     1566800     1555208
Swap:             0           0           0

I can't reproduce bitcoind running with -noconnect and config:

root@odroid:~# cat ~/Downloads/bm/bitcoin.conf 
#mintxfee=0.00001011
dbcache=100
checkblocks=6
checklevel=2
prune=5500
txindex=0
#walletrbf=1
#assumevalid=0
checkpoints=0
disablewallet=1
server=1
logthreadnames=1

debug=1
debugexclude=libevent
debugexclude=leveldb
[main]
rpcport=44333

root@odroid:~# while /usr/bin/time ./workspace/bitcoin-core/src/bitcoin-cli -datadir=/root/Downloads/bm/ -rpcclienttimeout=999999 gettxoutsetinfo ; do true ; done 
2020-07-02T19:20:20Z [http] Received a POST request for / from 127.0.0.1:48860
2020-07-02T19:20:20Z [httpworker.2] ThreadRPCServer method=gettxoutsetinfo user=__cookie__
2020-07-02T19:20:20Z [httpworker.2] FlushStateToDisk: write block and undo data to disk started
2020-07-02T19:20:20Z [httpworker.2] FlushStateToDisk: write block and undo data to disk completed (0.83ms)
2020-07-02T19:20:20Z [httpworker.2] FlushStateToDisk: write block index to disk started
2020-07-02T19:20:20Z [httpworker.2] FlushStateToDisk: write block index to disk completed (5.71ms)
2020-07-02T19:20:20Z [httpworker.2] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
2020-07-02T19:20:20Z [httpworker.2] Writing final batch of 0.00 MiB
2020-07-02T19:20:20Z [httpworker.2] Committed 0 changed transaction outputs (out of 0) to coin database...
2020-07-02T19:20:20Z [httpworker.2] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
2020-07-02T19:20:20Z [httpworker.2] Enqueuing ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
2020-07-02T19:20:20Z [scheduler] ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
2020-07-02T19:20:46Z [scheduler] Feeding 10721 bytes of dynamic environment data into RNG
2020-07-02T19:21:09Z [scheduler] Flushed 62430 addresses to peers.dat  3400ms
2020-07-02T19:21:46Z [scheduler] Feeding 10718 bytes of dynamic environment data into RNG
2020-07-02T19:22:46Z [scheduler] Feeding 10710 bytes of dynamic environment data into RNG
2020-07-02T19:23:46Z [scheduler] Feeding 10710 bytes of dynamic environment data into RNG
2020-07-02T19:24:46Z [scheduler] Feeding 10716 bytes of dynamic environment data into RNG
2020-07-02T19:25:46Z [scheduler] Feeding 10711 bytes of dynamic environment data into RNG
2020-07-02T19:26:46Z [scheduler] Feeding 10712 bytes of dynamic environment data into RNG
2020-07-02T19:27:46Z [scheduler] Feeding 10712 bytes of dynamic environment data into RNG
{
  "height": 637366,
  "bestblock": "0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03",
  "transactions": 40131521,
  "txouts": 65847359,
  "bogosize": 4946880515,
  "hash_serialized_2": "8485ca2bb1b7d504e6801febb61ec04aa62d584f3962311ecacfbca8e95b45ee",
  "disk_size": 3997489055,
  "total_amount": 18420861.07048077
}
0.01user 0.00system 8:13.85elapsed 0%CPU (0avgtext+0avgdata 4152maxresident)k
256inputs+0outputs (1major+459minor)pagefaults 0swaps
2020-07-02T19:28:34Z [http] Received a POST request for / from 127.0.0.1:48861
2020-07-02T19:28:34Z [httpworker.0] ThreadRPCServer method=gettxoutsetinfo user=__cookie__
2020-07-02T19:28:34Z [httpworker.0] FlushStateToDisk: write block and undo data to disk started
2020-07-02T19:28:34Z [httpworker.0] FlushStateToDisk: write block and undo data to disk completed (0.89ms)
2020-07-02T19:28:34Z [httpworker.0] FlushStateToDisk: write block index to disk started
2020-07-02T19:28:34Z [httpworker.0] FlushStateToDisk: write block index to disk completed (9.95ms)
2020-07-02T19:28:34Z [httpworker.0] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
2020-07-02T19:28:34Z [httpworker.0] Writing final batch of 0.00 MiB
2020-07-02T19:28:34Z [httpworker.0] Committed 0 changed transaction outputs (out of 0) to coin database...
2020-07-02T19:28:34Z [httpworker.0] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
2020-07-02T19:28:34Z [httpworker.0] Enqueuing ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
2020-07-02T19:28:34Z [scheduler] ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
2020-07-02T19:28:46Z [scheduler] Feeding 10713 bytes of dynamic environment data into RNG
2020-07-02T19:29:46Z [scheduler] Feeding 10710 bytes of dynamic environment data into RNG
2020-07-02T19:30:46Z [scheduler] Feeding 10711 bytes of dynamic environment data into RNG
2020-07-02T19:31:46Z [scheduler] Feeding 10714 bytes of dynamic environment data into RNG
2020-07-02T19:32:46Z [scheduler] Feeding 10712 bytes of dynamic environment data into RNG
2020-07-02T19:33:46Z [scheduler] Feeding 10714 bytes of dynamic environment data into RNG
2020-07-02T19:34:46Z [scheduler] Feeding 10711 bytes of dynamic environment data into RNG
{
  "height": 637366,
  "bestblock": "0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03",
  "transactions": 40131521,
  "txouts": 65847359,
  "bogosize": 4946880515,
  "hash_serialized_2": "8485ca2bb1b7d504e6801febb61ec04aa62d584f3962311ecacfbca8e95b45ee",
  "disk_size": 3995613631,
  "total_amount": 18420861.07048077
}
0.01user 0.01system 6:30.41elapsed 0%CPU (0avgtext+0avgdata 4192maxresident)k
3104inputs+0outputs (23major+199minor)pagefaults 0swaps
2020-07-02T19:35:05Z [http] Received a POST request for / from 127.0.0.1:48862
2020-07-02T19:35:05Z [httpworker.3] ThreadRPCServer method=gettxoutsetinfo user=__cookie__
2020-07-02T19:35:05Z [httpworker.3] FlushStateToDisk: write block and undo data to disk started
2020-07-02T19:35:05Z [httpworker.3] FlushStateToDisk: write block and undo data to disk completed (0.20ms)
2020-07-02T19:35:05Z [httpworker.3] FlushStateToDisk: write block index to disk started
2020-07-02T19:35:05Z [httpworker.3] FlushStateToDisk: write block index to disk completed (3.72ms)
2020-07-02T19:35:05Z [httpworker.3] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
2020-07-02T19:35:05Z [httpworker.3] Writing final batch of 0.00 MiB
2020-07-02T19:35:05Z [httpworker.3] Committed 0 changed transaction outputs (out of 0) to coin database...
2020-07-02T19:35:05Z [httpworker.3] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
2020-07-02T19:35:05Z [httpworker.3] Enqueuing ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
2020-07-02T19:35:05Z [scheduler] ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
2020-07-02T19:35:46Z [scheduler] Feeding 10711 bytes of dynamic environment data into RNG
2020-07-02T19:36:10Z [scheduler] Flushed 62430 addresses to peers.dat  693ms
2020-07-02T19:36:46Z [scheduler] Feeding 10707 bytes of dynamic environment data into RNG
2020-07-02T19:37:46Z [scheduler] Feeding 10710 bytes of dynamic environment data into RNG
2020-07-02T19:38:46Z [scheduler] Feeding 10709 bytes of dynamic environment data into RNG
2020-07-02T19:39:46Z [scheduler] Feeding 10719 bytes of dynamic environment data into RNG
2020-07-02T19:40:46Z [scheduler] Feeding 10707 bytes of dynamic environment data into RNG
2020-07-02T19:41:46Z [scheduler] Feeding 10715 bytes of dynamic environment data into RNG
{
  "height": 637366,
  "bestblock": "0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03",
  "transactions": 40131521,
  "txouts": 65847359,
  "bogosize": 4946880515,
  "hash_serialized_2": "8485ca2bb1b7d504e6801febb61ec04aa62d584f3962311ecacfbca8e95b45ee",
  "disk_size": 3992207693,
  "total_amount": 18420861.07048077
}
0.01user 0.00system 7:18.58elapsed 0%CPU (0avgtext+0avgdata 4376maxresident)k
744inputs+0outputs (9major+275minor)pagefaults 0swaps
2020-07-02T19:42:23Z [http] Received a POST request for / from 127.0.0.1:48863
2020-07-02T19:42:23Z [httpworker.1] ThreadRPCServer method=gettxoutsetinfo user=__cookie__
2020-07-02T19:42:23Z [httpworker.1] FlushStateToDisk: write block and undo data to disk started
2020-07-02T19:42:23Z [httpworker.1] FlushStateToDisk: write block and undo data to disk completed (0.21ms)
2020-07-02T19:42:23Z [httpworker.1] FlushStateToDisk: write block index to disk started
2020-07-02T19:42:24Z [httpworker.1] FlushStateToDisk: write block index to disk completed (220.57ms)
2020-07-02T19:42:24Z [httpworker.1] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
2020-07-02T19:42:24Z [httpworker.1] Writing final batch of 0.00 MiB
2020-07-02T19:42:24Z [httpworker.1] Committed 0 changed transaction outputs (out of 0) to coin database...
2020-07-02T19:42:24Z [httpworker.1] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
2020-07-02T19:42:24Z [httpworker.1] Enqueuing ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
2020-07-02T19:42:24Z [scheduler] ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
2020-07-02T19:42:46Z [scheduler] Feeding 10708 bytes of dynamic environment data into RNG
2020-07-02T19:43:46Z [scheduler] Feeding 10716 bytes of dynamic environment data into RNG
2020-07-02T19:44:46Z [scheduler] Feeding 10714 bytes of dynamic environment data into RNG
2020-07-02T19:45:46Z [scheduler] Feeding 10710 bytes of dynamic environment data into RNG
2020-07-02T19:46:46Z [scheduler] Feeding 10714 bytes of dynamic environment data into RNG
2020-07-02T19:47:46Z [scheduler] Feeding 10717 bytes of dynamic environment data into RNG
{
  "height": 637366,
  "bestblock": "0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03",
  "transactions": 40131521,
  "txouts": 65847359,
  "bogosize": 4946880515,
  "hash_serialized_2": "8485ca2bb1b7d504e6801febb61ec04aa62d584f3962311ecacfbca8e95b45ee",
  "disk_size": 3990051228,
  "total_amount": 18420861.07048077
}
0.01user 0.00system 6:20.46elapsed 0%CPU (0avgtext+0avgdata 4064maxresident)k
656inputs+0outputs (9major+392minor)pagefaults 0swaps
2020-07-02T19:48:44Z [http] Received a POST request for / from 127.0.0.1:48864
2020-07-02T19:48:44Z [httpworker.2] ThreadRPCServer method=gettxoutsetinfo user=__cookie__
2020-07-02T19:48:44Z [httpworker.2] FlushStateToDisk: write block and undo data to disk started
2020-07-02T19:48:44Z [httpworker.2] FlushStateToDisk: write block and undo data to disk completed (0.91ms)
2020-07-02T19:48:44Z [httpworker.2] FlushStateToDisk: write block index to disk started
2020-07-02T19:48:44Z [httpworker.2] FlushStateToDisk: write block index to disk completed (7.61ms)
2020-07-02T19:48:44Z [httpworker.2] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
2020-07-02T19:48:44Z [httpworker.2] Writing final batch of 0.00 MiB
2020-07-02T19:48:44Z [httpworker.2] Committed 0 changed transaction outputs (out of 0) to coin database...
2020-07-02T19:48:44Z [httpworker.2] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
2020-07-02T19:48:44Z [httpworker.2] Enqueuing ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
2020-07-02T19:48:44Z [scheduler] ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
2020-07-02T19:48:46Z [scheduler] Feeding 10717 bytes of dynamic environment data into RNG
2020-07-02T19:49:46Z [scheduler] Feeding 10712 bytes of dynamic environment data into RNG
2020-07-02T19:50:46Z [scheduler] Feeding 10712 bytes of dynamic environment data into RNG
2020-07-02T19:51:11Z [scheduler] Flushed 62430 addresses to peers.dat  707ms
2020-07-02T19:51:46Z [scheduler] Feeding 10713 bytes of dynamic environment data into RNG
2020-07-02T19:52:46Z [scheduler] Feeding 10715 bytes of dynamic environment data into RNG
2020-07-02T19:53:46Z [scheduler] Feeding 10711 bytes of dynamic environment data into RNG
{
  "height": 637366,
  "bestblock": "0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03",
  "transactions": 40131521,
  "txouts": 65847359,
  "bogosize": 4946880515,
  "hash_serialized_2": "8485ca2bb1b7d504e6801febb61ec04aa62d584f3962311ecacfbca8e95b45ee",
  "disk_size": 3989952740,
  "total_amount": 18420861.07048077
}
0.01user 0.00system 5:42.70elapsed 0%CPU (0avgtext+0avgdata 4188maxresident)k
1448inputs+0outputs (21major+202minor)pagefaults 0swaps

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.

I've fixed hardware problems (a microSD-card issue) with my ODROID-HC1. @MarcoFalke Mind providing more info about your test system? ARM version, CPU, storage type (HDD/SSD), bitness, OS etc

Could you try to test with -rpcthreads=1 ?

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.