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

issue hebasto openend this issue on April 6, 2020
  1. hebasto commented at 3:32 pm on April 6, 2020: member

    UPDATE: see #18538 (comment)

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

     0$ time bitcoin-cli -rpcclienttimeout=3600 gettxoutsetinfo
 1{
 2  "height": 624598,
 3  "bestblock": "0000000000000000001366754ef0fb1b483f1d7d64e3f561c262fdf5978ffbc0",
 4  "transactions": 39618423,
 5  "txouts": 66517746,
 6  "bogosize": 4997008193,
 7  "hash_serialized_2": "53f16a7e24542b3079eb7246660126392107fe87b2233ec27070386d333de708",
 8  "disk_size": 4009464235,
 9  "total_amount": 18307304.82089071
10}
11
12real	6m33.513s
13user	0m0.004s
14sys	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:

     0$ time bitcoin-cli -rpcclienttimeout=3600 gettxoutsetinfo
 1{
 2  "height": 624679,
 3  "bestblock": "000000000000000000117e2b43965e568b5d50004f347f8b6ee642191c2895a8",
 4  "transactions": 39645155,
 5  "txouts": 66579180,
 6  "bogosize": 5001532788,
 7  "hash_serialized_2": "8adbf6e32f931eea9cc2cbcbd44c25b06ab0f1f564c6b75174ad60dc8b48f496",
 8  "disk_size": 4009243803,
 9  "total_amount": 18308317.32089071
10}
11
12real	56m23.878s
13user	0m0.004s
14sys	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:

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

    Please note that this issue differs from #16979.

  2. MarcoFalke commented at 3:35 pm on April 6, 2020: member
    If you compile boost and libevent from depends, does it match the gitian behavior?
  3. hebasto commented at 3:38 pm on April 6, 2020: member

    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.

  4. hebasto commented at 9:05 pm on April 6, 2020: member
    Using Clang instead of GCC did not help.
  5. sipa commented at 9:08 pm on April 6, 2020: member
    Those two gettxoutsetinfo outputs are for different blocks; their output isn’t expected to be the same.
  6. MarcoFalke commented at 9:25 pm on April 6, 2020: member
    I think the bug is about how long it takes to compute them
  7. sipa commented at 9:31 pm on April 6, 2020: member
    Oh!
  8. hebasto commented at 8:45 pm on April 16, 2020: member

    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)”.

  9. hebasto closed this on Apr 16, 2020
  10. MarcoFalke commented at 9:11 pm on April 16, 2020: member
    @hebasto Can you check if he RPC calls are faster when you run with -nodebuglogfile -nodebug?
  11. hebasto commented at 12:06 pm on April 17, 2020: member

    @MarcoFalke

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

    Checked. Yes, they are faster:

     0hebasto@odroid:~/bitcoin$ date; time bitcoin-cli -rpcclienttimeout=10000 gettxoutsetinfo
 1Fri Apr 17 11:30:16 UTC 2020
 2{
 3  "height": 626399,
 4  "bestblock": "000000000000000000103db782701e6747a0bf98bcc7933f92800d0b38e089f8",
 5  "transactions": 39781990,
 6  "txouts": 66615480,
 7  "bogosize": 5004515507,
 8  "hash_serialized_2": "27264fac620c60137ed79feecde0876174d3ca66dc5abebd6e480fe31f03cf09",
 9  "disk_size": 4013644842,
10  "total_amount": 18329817.32081895
11}
12
13real	10m41.300s
14user	0m0.004s
15sys	0m0.026s
16hebasto@odroid:~/bitcoin$ date; time bitcoin-cli -rpcclienttimeout=10000 gettxoutsetinfo
17Fri Apr 17 11:47:04 UTC 2020
18{
19  "height": 626400,
20  "bestblock": "0000000000000000000ad754a8c9860880d015f552d52976ff10cce5004321c5",
21  "transactions": 39782745,
22  "txouts": 66617426,
23  "bogosize": 5004659160,
24  "hash_serialized_2": "d696936443fe99a1aa796f9146968a68ca61c35641338f33343848bfbf54470a",
25  "disk_size": 4017378717,
26  "total_amount": 18329829.82081895
27}
28
29real	7m23.625s
30user	0m0.009s
31sys	0m0.032s
  12. MarcoFalke commented at 3:38 pm on April 30, 2020: member
    Did you have -debug=1 enabled, which includes leveldb debug logs?
  13. hebasto commented at 0:53 am on May 3, 2020: member

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

    The excerpt from my bitcoin.con:

    0debug=rpc
1logthreadnames=1
  14. hebasto commented at 9:03 am on May 3, 2020: member

    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.

  15. hebasto reopened this on May 3, 2020
  16. sipa commented at 9:19 pm on May 3, 2020: member
    @hebasto This sounds like maybe memory fragmentation, perhaps in conjunction with swap space being used?
  17. hebasto commented at 10:46 pm on May 3, 2020: member

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

    0$ free
1              total        used        free      shared  buff/cache   available
2Mem:        2042436      424220       51416        5964     1566800     1555208
3Swap:             0           0           0
  18. MarcoFalke commented at 8:10 pm on July 2, 2020: member

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

     0root@odroid:~# cat ~/Downloads/bm/bitcoin.conf 
 1#mintxfee=0.00001011
 2dbcache=100
 3checkblocks=6
 4checklevel=2
 5prune=5500
 6txindex=0
 7#walletrbf=1
 8#assumevalid=0
 9checkpoints=0
10disablewallet=1
11server=1
12logthreadnames=1
13
14debug=1
15debugexclude=libevent
16debugexclude=leveldb
17[main]
18rpcport=44333

      0root@odroid:~# while /usr/bin/time ./workspace/bitcoin-core/src/bitcoin-cli -datadir=/root/Downloads/bm/ -rpcclienttimeout=999999 gettxoutsetinfo ; do true ; done 
  12020-07-02T19:20:20Z [http] Received a POST request for / from 127.0.0.1:48860
  22020-07-02T19:20:20Z [httpworker.2] ThreadRPCServer method=gettxoutsetinfo user=__cookie__
  32020-07-02T19:20:20Z [httpworker.2] FlushStateToDisk: write block and undo data to disk started
  42020-07-02T19:20:20Z [httpworker.2] FlushStateToDisk: write block and undo data to disk completed (0.83ms)
  52020-07-02T19:20:20Z [httpworker.2] FlushStateToDisk: write block index to disk started
  62020-07-02T19:20:20Z [httpworker.2] FlushStateToDisk: write block index to disk completed (5.71ms)
  72020-07-02T19:20:20Z [httpworker.2] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
  82020-07-02T19:20:20Z [httpworker.2] Writing final batch of 0.00 MiB
  92020-07-02T19:20:20Z [httpworker.2] Committed 0 changed transaction outputs (out of 0) to coin database...
 102020-07-02T19:20:20Z [httpworker.2] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
 112020-07-02T19:20:20Z [httpworker.2] Enqueuing ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
 122020-07-02T19:20:20Z [scheduler] ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
 132020-07-02T19:20:46Z [scheduler] Feeding 10721 bytes of dynamic environment data into RNG
 142020-07-02T19:21:09Z [scheduler] Flushed 62430 addresses to peers.dat  3400ms
 152020-07-02T19:21:46Z [scheduler] Feeding 10718 bytes of dynamic environment data into RNG
 162020-07-02T19:22:46Z [scheduler] Feeding 10710 bytes of dynamic environment data into RNG
 172020-07-02T19:23:46Z [scheduler] Feeding 10710 bytes of dynamic environment data into RNG
 182020-07-02T19:24:46Z [scheduler] Feeding 10716 bytes of dynamic environment data into RNG
 192020-07-02T19:25:46Z [scheduler] Feeding 10711 bytes of dynamic environment data into RNG
 202020-07-02T19:26:46Z [scheduler] Feeding 10712 bytes of dynamic environment data into RNG
 212020-07-02T19:27:46Z [scheduler] Feeding 10712 bytes of dynamic environment data into RNG
 22{
 23  "height": 637366,
 24  "bestblock": "0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03",
 25  "transactions": 40131521,
 26  "txouts": 65847359,
 27  "bogosize": 4946880515,
 28  "hash_serialized_2": "8485ca2bb1b7d504e6801febb61ec04aa62d584f3962311ecacfbca8e95b45ee",
 29  "disk_size": 3997489055,
 30  "total_amount": 18420861.07048077
 31}
 320.01user 0.00system 8:13.85elapsed 0%CPU (0avgtext+0avgdata 4152maxresident)k
 33256inputs+0outputs (1major+459minor)pagefaults 0swaps
 342020-07-02T19:28:34Z [http] Received a POST request for / from 127.0.0.1:48861
 352020-07-02T19:28:34Z [httpworker.0] ThreadRPCServer method=gettxoutsetinfo user=__cookie__
 362020-07-02T19:28:34Z [httpworker.0] FlushStateToDisk: write block and undo data to disk started
 372020-07-02T19:28:34Z [httpworker.0] FlushStateToDisk: write block and undo data to disk completed (0.89ms)
 382020-07-02T19:28:34Z [httpworker.0] FlushStateToDisk: write block index to disk started
 392020-07-02T19:28:34Z [httpworker.0] FlushStateToDisk: write block index to disk completed (9.95ms)
 402020-07-02T19:28:34Z [httpworker.0] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
 412020-07-02T19:28:34Z [httpworker.0] Writing final batch of 0.00 MiB
 422020-07-02T19:28:34Z [httpworker.0] Committed 0 changed transaction outputs (out of 0) to coin database...
 432020-07-02T19:28:34Z [httpworker.0] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
 442020-07-02T19:28:34Z [httpworker.0] Enqueuing ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
 452020-07-02T19:28:34Z [scheduler] ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
 462020-07-02T19:28:46Z [scheduler] Feeding 10713 bytes of dynamic environment data into RNG
 472020-07-02T19:29:46Z [scheduler] Feeding 10710 bytes of dynamic environment data into RNG
 482020-07-02T19:30:46Z [scheduler] Feeding 10711 bytes of dynamic environment data into RNG
 492020-07-02T19:31:46Z [scheduler] Feeding 10714 bytes of dynamic environment data into RNG
 502020-07-02T19:32:46Z [scheduler] Feeding 10712 bytes of dynamic environment data into RNG
 512020-07-02T19:33:46Z [scheduler] Feeding 10714 bytes of dynamic environment data into RNG
 522020-07-02T19:34:46Z [scheduler] Feeding 10711 bytes of dynamic environment data into RNG
 53{
 54  "height": 637366,
 55  "bestblock": "0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03",
 56  "transactions": 40131521,
 57  "txouts": 65847359,
 58  "bogosize": 4946880515,
 59  "hash_serialized_2": "8485ca2bb1b7d504e6801febb61ec04aa62d584f3962311ecacfbca8e95b45ee",
 60  "disk_size": 3995613631,
 61  "total_amount": 18420861.07048077
 62}
 630.01user 0.01system 6:30.41elapsed 0%CPU (0avgtext+0avgdata 4192maxresident)k
 643104inputs+0outputs (23major+199minor)pagefaults 0swaps
 652020-07-02T19:35:05Z [http] Received a POST request for / from 127.0.0.1:48862
 662020-07-02T19:35:05Z [httpworker.3] ThreadRPCServer method=gettxoutsetinfo user=__cookie__
 672020-07-02T19:35:05Z [httpworker.3] FlushStateToDisk: write block and undo data to disk started
 682020-07-02T19:35:05Z [httpworker.3] FlushStateToDisk: write block and undo data to disk completed (0.20ms)
 692020-07-02T19:35:05Z [httpworker.3] FlushStateToDisk: write block index to disk started
 702020-07-02T19:35:05Z [httpworker.3] FlushStateToDisk: write block index to disk completed (3.72ms)
 712020-07-02T19:35:05Z [httpworker.3] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
 722020-07-02T19:35:05Z [httpworker.3] Writing final batch of 0.00 MiB
 732020-07-02T19:35:05Z [httpworker.3] Committed 0 changed transaction outputs (out of 0) to coin database...
 742020-07-02T19:35:05Z [httpworker.3] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
 752020-07-02T19:35:05Z [httpworker.3] Enqueuing ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
 762020-07-02T19:35:05Z [scheduler] ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
 772020-07-02T19:35:46Z [scheduler] Feeding 10711 bytes of dynamic environment data into RNG
 782020-07-02T19:36:10Z [scheduler] Flushed 62430 addresses to peers.dat  693ms
 792020-07-02T19:36:46Z [scheduler] Feeding 10707 bytes of dynamic environment data into RNG
 802020-07-02T19:37:46Z [scheduler] Feeding 10710 bytes of dynamic environment data into RNG
 812020-07-02T19:38:46Z [scheduler] Feeding 10709 bytes of dynamic environment data into RNG
 822020-07-02T19:39:46Z [scheduler] Feeding 10719 bytes of dynamic environment data into RNG
 832020-07-02T19:40:46Z [scheduler] Feeding 10707 bytes of dynamic environment data into RNG
 842020-07-02T19:41:46Z [scheduler] Feeding 10715 bytes of dynamic environment data into RNG
 85{
 86  "height": 637366,
 87  "bestblock": "0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03",
 88  "transactions": 40131521,
 89  "txouts": 65847359,
 90  "bogosize": 4946880515,
 91  "hash_serialized_2": "8485ca2bb1b7d504e6801febb61ec04aa62d584f3962311ecacfbca8e95b45ee",
 92  "disk_size": 3992207693,
 93  "total_amount": 18420861.07048077
 94}
 950.01user 0.00system 7:18.58elapsed 0%CPU (0avgtext+0avgdata 4376maxresident)k
 96744inputs+0outputs (9major+275minor)pagefaults 0swaps
 972020-07-02T19:42:23Z [http] Received a POST request for / from 127.0.0.1:48863
 982020-07-02T19:42:23Z [httpworker.1] ThreadRPCServer method=gettxoutsetinfo user=__cookie__
 992020-07-02T19:42:23Z [httpworker.1] FlushStateToDisk: write block and undo data to disk started
1002020-07-02T19:42:23Z [httpworker.1] FlushStateToDisk: write block and undo data to disk completed (0.21ms)
1012020-07-02T19:42:23Z [httpworker.1] FlushStateToDisk: write block index to disk started
1022020-07-02T19:42:24Z [httpworker.1] FlushStateToDisk: write block index to disk completed (220.57ms)
1032020-07-02T19:42:24Z [httpworker.1] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
1042020-07-02T19:42:24Z [httpworker.1] Writing final batch of 0.00 MiB
1052020-07-02T19:42:24Z [httpworker.1] Committed 0 changed transaction outputs (out of 0) to coin database...
1062020-07-02T19:42:24Z [httpworker.1] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
1072020-07-02T19:42:24Z [httpworker.1] Enqueuing ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
1082020-07-02T19:42:24Z [scheduler] ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
1092020-07-02T19:42:46Z [scheduler] Feeding 10708 bytes of dynamic environment data into RNG
1102020-07-02T19:43:46Z [scheduler] Feeding 10716 bytes of dynamic environment data into RNG
1112020-07-02T19:44:46Z [scheduler] Feeding 10714 bytes of dynamic environment data into RNG
1122020-07-02T19:45:46Z [scheduler] Feeding 10710 bytes of dynamic environment data into RNG
1132020-07-02T19:46:46Z [scheduler] Feeding 10714 bytes of dynamic environment data into RNG
1142020-07-02T19:47:46Z [scheduler] Feeding 10717 bytes of dynamic environment data into RNG
115{
116  "height": 637366,
117  "bestblock": "0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03",
118  "transactions": 40131521,
119  "txouts": 65847359,
120  "bogosize": 4946880515,
121  "hash_serialized_2": "8485ca2bb1b7d504e6801febb61ec04aa62d584f3962311ecacfbca8e95b45ee",
122  "disk_size": 3990051228,
123  "total_amount": 18420861.07048077
124}
1250.01user 0.00system 6:20.46elapsed 0%CPU (0avgtext+0avgdata 4064maxresident)k
126656inputs+0outputs (9major+392minor)pagefaults 0swaps
1272020-07-02T19:48:44Z [http] Received a POST request for / from 127.0.0.1:48864
1282020-07-02T19:48:44Z [httpworker.2] ThreadRPCServer method=gettxoutsetinfo user=__cookie__
1292020-07-02T19:48:44Z [httpworker.2] FlushStateToDisk: write block and undo data to disk started
1302020-07-02T19:48:44Z [httpworker.2] FlushStateToDisk: write block and undo data to disk completed (0.91ms)
1312020-07-02T19:48:44Z [httpworker.2] FlushStateToDisk: write block index to disk started
1322020-07-02T19:48:44Z [httpworker.2] FlushStateToDisk: write block index to disk completed (7.61ms)
1332020-07-02T19:48:44Z [httpworker.2] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) started
1342020-07-02T19:48:44Z [httpworker.2] Writing final batch of 0.00 MiB
1352020-07-02T19:48:44Z [httpworker.2] Committed 0 changed transaction outputs (out of 0) to coin database...
1362020-07-02T19:48:44Z [httpworker.2] FlushStateToDisk: write coins cache to disk (0 coins, 0kB) completed (0.00s)
1372020-07-02T19:48:44Z [httpworker.2] Enqueuing ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
1382020-07-02T19:48:44Z [scheduler] ChainStateFlushed: block hash=0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03
1392020-07-02T19:48:46Z [scheduler] Feeding 10717 bytes of dynamic environment data into RNG
1402020-07-02T19:49:46Z [scheduler] Feeding 10712 bytes of dynamic environment data into RNG
1412020-07-02T19:50:46Z [scheduler] Feeding 10712 bytes of dynamic environment data into RNG
1422020-07-02T19:51:11Z [scheduler] Flushed 62430 addresses to peers.dat  707ms
1432020-07-02T19:51:46Z [scheduler] Feeding 10713 bytes of dynamic environment data into RNG
1442020-07-02T19:52:46Z [scheduler] Feeding 10715 bytes of dynamic environment data into RNG
1452020-07-02T19:53:46Z [scheduler] Feeding 10711 bytes of dynamic environment data into RNG
146{
147  "height": 637366,
148  "bestblock": "0000000000000000000083f435bb8d5fda03cea0da827fd8e2b71d691a926d03",
149  "transactions": 40131521,
150  "txouts": 65847359,
151  "bogosize": 4946880515,
152  "hash_serialized_2": "8485ca2bb1b7d504e6801febb61ec04aa62d584f3962311ecacfbca8e95b45ee",
153  "disk_size": 3989952740,
154  "total_amount": 18420861.07048077
155}
1560.01user 0.00system 5:42.70elapsed 0%CPU (0avgtext+0avgdata 4188maxresident)k
1571448inputs+0outputs (21major+202minor)pagefaults 0swaps
  19. MarcoFalke renamed this:
    gitian vs self-compiled on ARM 32-bit
    gitian vs self-compiled on ARM 32-bit gettxoutsetinfo
    on Jul 2, 2020
  20. hebasto commented at 4:52 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.

  21. hebasto closed this on Jul 3, 2020
  22. hebasto commented at 10:26 am on July 6, 2020: member

    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 ?

  23. hebasto reopened this on Jul 6, 2020
  24. hebasto commented at 10:06 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.

  25. hebasto closed this on Aug 16, 2020
  26. DrahtBot locked this on Feb 15, 2022


hebasto MarcoFalke sipa

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-07-05 22:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me