Blockchain sync - highly variable time to connect trasactions

benjamin-wilson commented at 2:30 pm on April 18, 2021: none

During initial sync, syncing becomes slow, cpu utilization is low and disk reads go high. Enabling debug=bench reveals the ‘connecting transactions’ step increases the time per tx an order of magnitude. Restarting bitcoind will fix the issure for awhile.

sudo tail -f --lines 1000 /mnt/hdd/bitcoin/debug.log | grep transactions

Proper behavior: Screenshot from 2021-04-17 14-56-24

2021-04-18T13:41:15Z - Connect 3421 transactions: 384.88ms (0.113ms/tx, 0.074ms/txin) [742.16s (632.16ms/blk)] 2021-04-18T13:41:15Z - Connect 3022 transactions: 425.70ms (0.141ms/tx, 0.078ms/txin) [742.58s (631.99ms/blk)] 2021-04-18T13:41:16Z - Connect 2190 transactions: 505.57ms (0.231ms/tx, 0.096ms/txin) [743.09s (631.88ms/blk)] 2021-04-18T13:41:16Z - Connect 3271 transactions: 349.76ms (0.107ms/tx, 0.064ms/txin) [743.44s (631.64ms/blk)] 2021-04-18T13:41:18Z - Connect 2992 transactions: 409.37ms (0.137ms/tx, 0.069ms/txin) [743.85s (631.45ms/blk)] 2021-04-18T13:41:18Z - Connect 3210 transactions: 342.55ms (0.107ms/tx, 0.062ms/txin) [744.19s (631.20ms/blk)] 2021-04-18T13:41:19Z - Connect 2274 transactions: 690.01ms (0.303ms/tx, 0.119ms/txin) [744.88s (631.25ms/blk)] 2021-04-18T13:41:20Z - Connect 2469 transactions: 797.49ms (0.323ms/tx, 0.132ms/txin) [745.68s (631.39ms/blk)] 2021-04-18T13:41:20Z - Connect 3060 transactions: 337.70ms (0.110ms/tx, 0.060ms/txin) [746.01s (631.15ms/blk)] 2021-04-18T13:41:21Z - Connect 2276 transactions: 518.23ms (0.228ms/tx, 0.089ms/txin) [746.53s (631.05ms/blk)] 2021-04-18T13:41:21Z - Connect 2703 transactions: 355.08ms (0.131ms/tx, 0.056ms/txin) [746.89s (630.82ms/blk)] 2021-04-18T13:41:22Z - Connect 2885 transactions: 507.99ms (0.176ms/tx, 0.088ms/txin) [747.40s (630.71ms/blk)] 2021-04-18T13:41:23Z - Connect 3069 transactions: 528.49ms (0.172ms/tx, 0.096ms/txin) [747.92s (630.63ms/blk)] 2021-04-18T13:41:24Z - Connect 2423 transactions: 446.64ms (0.184ms/tx, 0.074ms/txin) [748.37s (630.47ms/blk)] 2021-04-18T13:41:25Z - Connect 2337 transactions: 535.49ms (0.229ms/tx, 0.093ms/txin) [748.91s (630.39ms/blk)] 2021-04-18T13:41:25Z - Connect 3121 transactions: 469.58ms (0.150ms/tx, 0.088ms/txin) [749.38s (630.26ms/blk)]

Improper behavior after some period of time: Screenshot from 2021-04-17 12-27-19 2021-04-18T14:14:05Z - Connect 2420 transactions: 8300.56ms (3.430ms/tx, 1.496ms/txin) [2193.99s (738.22ms/blk)] 2021-04-18T14:14:11Z - Connect 2706 transactions: 6270.61ms (2.317ms/tx, 1.150ms/txin) [2200.26s (740.08ms/blk)] 2021-04-18T14:14:18Z - Connect 2839 transactions: 6572.64ms (2.315ms/tx, 1.221ms/txin) [2206.84s (742.04ms/blk)] 2021-04-18T14:14:24Z - Connect 2910 transactions: 5678.99ms (1.952ms/tx, 1.125ms/txin) [2212.51s (743.70ms/blk)] 2021-04-18T14:14:33Z - Connect 2583 transactions: 9436.20ms (3.653ms/tx, 1.444ms/txin) [2221.95s (746.62ms/blk)] 2021-04-18T14:14:56Z - Connect 521 transactions: 22822.31ms (43.805ms/tx, 2.779ms/txin) [2244.77s (754.04ms/blk)] 2021-04-18T14:15:06Z - Connect 1388 transactions: 9113.20ms (6.566ms/tx, 1.869ms/txin) [2253.89s (756.85ms/blk)] 2021-04-18T14:15:11Z - Connect 1984 transactions: 5505.65ms (2.775ms/tx, 1.154ms/txin) [2259.39s (758.44ms/blk)] 2021-04-18T14:15:16Z - Connect 1512 transactions: 4943.82ms (3.270ms/tx, 1.282ms/txin) [2264.34s (759.84ms/blk)] 2021-04-18T14:15:25Z - Connect 1936 transactions: 7980.00ms (4.122ms/tx, 1.363ms/txin) [2272.32s (762.27ms/blk)] 2021-04-18T14:15:32Z - Connect 2079 transactions: 7309.14ms (3.516ms/tx, 1.306ms/txin) [2279.62s (764.46ms/blk)] 2021-04-18T14:15:39Z - Connect 2272 transactions: 7069.39ms (3.112ms/tx, 1.204ms/txin) [2286.69s (766.58ms/blk)]

Restarting bitcoind will fix the issue and speed up sync times for awhile (anywhere from 1min to a few hours) before slowing down.

To reproduce I’m running raspiblitz 1.7RC2, fresh install. Sandisk 1TB ssd, Rasperry pi 4 model B, 4GB.

benjamin-wilson added the label Bug on Apr 18, 2021

benjamin-wilson renamed this:
~~Blockchain sync highly variable time to connect trasactions~~
Blockchain sync - highly variable time to connect trasactions
on Apr 18, 2021

jonatack commented at 3:09 pm on April 18, 2021: contributor

Hi @benjamin-wilson, which version of bitcoin core are you running (bitcoind -version)? Default configuration options?

benjamin-wilson commented at 4:46 pm on April 18, 2021: none

version .21 bitcoin.conf:

 0# bitcoind configuration
 1# mainnet/testnet
 2testnet=0
 3# Bitcoind options
 4server=1
 5daemon=1
 6txindex=0
 7disablewallet=1
 8peerbloomfilters=1
 9# Connection settings
10rpcuser=raspibolt
11rpcpassword=c4w0Mh2q
12rpcport=8332
13rpcallowip=127.0.0.1
14rpcbind=127.0.0.1:8332
15zmqpubrawblock=tcp://127.0.0.1:28332
16zmqpubrawtx=tcp://127.0.0.1:28333
17# Raspberry Pi optimizations
18dbcache=512
19maxorphantx=10
20maxmempool=300
21maxconnections=40
22maxuploadtarget=5000
23datadir=/mnt/hdd/bitcoin
24debug=bench

sipa commented at 4:49 pm on April 18, 2021: member

Can you report the corresponding cache= values on the “UpdateTip” lines? It’s expected that I/O is higher when the cache is small.

benjamin-wilson commented at 4:58 pm on April 18, 2021: none

The cache value increases from nothing to just above the dbcache config value and then dumps to disk. I’ve tried from 512mb to 3072. Doesn’t seem to make a difference. The slowness doesn’t seem to correlate to the size of the current cache.

sipa commented at 5:02 pm on April 18, 2021: member

I see you have swap space configured. Could it be that your whole system memory usage goes too high and starts needing swap? Have you tried without swap?

Other than that, perhaps your system is overheating?

benjamin-wilson commented at 5:11 pm on April 18, 2021: none

Hmm might be right with the swap, I saw I had free memory so I didn’t think if it. I’ll poke around and see.

benjamin-wilson commented at 5:34 pm on April 18, 2021: none

Ok looks like bitcoind was using swap (non-zero from vmstat) even when I turned swappiness down to 10.

I ran sudo swapoff -a and free is showing 2.9G available.

0admin@raspberrypi:~ $ free -m
1              total        used        free      shared  buff/cache   available
2Mem:           3845         824          51           8        2968        2937
3Swap:             0           0           0

I’m still seeingsiand so from vmstat though and a lot of disk reads?

0
1admin@raspberrypi:~ $ vmstat
2procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
3 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
4 1  1      0  52608    936 3015432   95   95 42789  1962 1705  770 15 19 57  9  0

benjamin-wilson commented at 7:47 pm on April 18, 2021: none

I confirmed swap is off but still experiencing the same issue.

sipa commented at 7:58 pm on April 18, 2021: member

Is it all of a sudden that it becomes significantly slower, or is it gradual?

benjamin-wilson commented at 8:37 pm on April 18, 2021: none

Happens over 30 sec to 1 min? It’s really weird because yesterday it ran for hours really well then I woke up and it was slow. Today it seems to get slow just a few minutes after I start it. Here’s some logs showing the transition. It’s very apparent when I watch nmon, cpu dropps and disk reads go to 100% with little writes.

  0admin@raspberrypi:~ $ cat slowSync.txt | grep ms/tx,
  12021-04-18T20:17:44Z       - Connect 3411 transactions: 2110.59ms (0.619ms/tx, 0.351ms/txin) [2.11s (2110.59ms/blk)]
  22021-04-18T20:17:46Z       - Connect 2165 transactions: 1906.96ms (0.881ms/tx, 0.303ms/txin) [4.02s (2008.78ms/blk)]
  32021-04-18T20:17:48Z       - Connect 3130 transactions: 1668.59ms (0.533ms/tx, 0.293ms/txin) [5.69s (1895.38ms/blk)]
  42021-04-18T20:17:51Z       - Connect 3021 transactions: 2412.81ms (0.799ms/tx, 0.420ms/txin) [8.10s (2024.74ms/blk)]
  52021-04-18T20:17:52Z       - Connect 2963 transactions: 1642.81ms (0.554ms/tx, 0.292ms/txin) [9.74s (1948.35ms/blk)]
  62021-04-18T20:17:55Z       - Connect 1986 transactions: 2747.87ms (1.384ms/tx, 0.437ms/txin) [12.49s (2081.61ms/blk)]
  72021-04-18T20:17:58Z       - Connect 2572 transactions: 2536.87ms (0.986ms/tx, 0.449ms/txin) [15.03s (2146.64ms/blk)]
  82021-04-18T20:17:59Z       - Connect 3213 transactions: 1009.24ms (0.314ms/tx, 0.176ms/txin) [16.04s (2004.47ms/blk)]
  92021-04-18T20:18:02Z       - Connect 2934 transactions: 1399.44ms (0.477ms/tx, 0.236ms/txin) [17.44s (1937.24ms/blk)]
 102021-04-18T20:18:08Z       - Connect 1773 transactions: 6487.73ms (3.659ms/tx, 0.919ms/txin) [23.92s (2392.29ms/blk)]
 112021-04-18T20:18:10Z       - Connect 2585 transactions: 1998.43ms (0.773ms/tx, 0.337ms/txin) [25.92s (2356.49ms/blk)]
 122021-04-18T20:18:13Z       - Connect 3004 transactions: 2428.78ms (0.809ms/tx, 0.388ms/txin) [28.35s (2362.51ms/blk)]
 132021-04-18T20:18:15Z       - Connect 2820 transactions: 2120.29ms (0.752ms/tx, 0.289ms/txin) [30.47s (2343.88ms/blk)]
 142021-04-18T20:18:17Z       - Connect 3324 transactions: 1543.56ms (0.464ms/tx, 0.256ms/txin) [32.01s (2286.71ms/blk)]
 152021-04-18T20:18:19Z       - Connect 2649 transactions: 2219.77ms (0.838ms/tx, 0.382ms/txin) [34.23s (2282.25ms/blk)]
 162021-04-18T20:18:21Z       - Connect 3161 transactions: 1480.20ms (0.468ms/tx, 0.255ms/txin) [35.71s (2232.12ms/blk)]
 172021-04-18T20:18:24Z       - Connect 3131 transactions: 2092.61ms (0.668ms/tx, 0.371ms/txin) [37.81s (2223.91ms/blk)]
 182021-04-18T20:18:25Z       - Connect 3236 transactions: 1652.83ms (0.511ms/tx, 0.272ms/txin) [39.46s (2192.19ms/blk)]
 192021-04-18T20:18:27Z       - Connect 2904 transactions: 1413.78ms (0.487ms/tx, 0.244ms/txin) [40.87s (2151.22ms/blk)]
 202021-04-18T20:18:29Z       - Connect 3138 transactions: 1842.17ms (0.587ms/tx, 0.326ms/txin) [42.72s (2135.77ms/blk)]
 212021-04-18T20:18:31Z       - Connect 1856 transactions: 1747.31ms (0.941ms/tx, 0.240ms/txin) [44.46s (2117.27ms/blk)]
 222021-04-18T20:18:34Z       - Connect 2884 transactions: 2449.43ms (0.849ms/tx, 0.420ms/txin) [46.91s (2132.37ms/blk)]
 232021-04-18T20:18:37Z       - Connect 2469 transactions: 2729.06ms (1.105ms/tx, 0.376ms/txin) [49.64s (2158.31ms/blk)]
 242021-04-18T20:18:38Z       - Connect 2034 transactions: 1610.65ms (0.792ms/tx, 0.258ms/txin) [51.25s (2135.49ms/blk)]
 252021-04-18T20:18:41Z       - Connect 2024 transactions: 2790.59ms (1.379ms/tx, 0.458ms/txin) [54.04s (2161.69ms/blk)]
 262021-04-18T20:18:44Z       - Connect 2897 transactions: 2303.47ms (0.795ms/tx, 0.452ms/txin) [56.35s (2167.15ms/blk)]
 272021-04-18T20:18:46Z       - Connect 3469 transactions: 1523.53ms (0.439ms/tx, 0.237ms/txin) [57.87s (2143.31ms/blk)]
 282021-04-18T20:18:47Z       - Connect 3206 transactions: 1319.88ms (0.412ms/tx, 0.200ms/txin) [59.19s (2113.90ms/blk)]
 292021-04-18T20:18:49Z       - Connect 3348 transactions: 1814.68ms (0.542ms/tx, 0.301ms/txin) [61.00s (2103.58ms/blk)]
 302021-04-18T20:18:51Z       - Connect 2971 transactions: 1390.08ms (0.468ms/tx, 0.231ms/txin) [62.39s (2079.80ms/blk)]
 312021-04-18T20:18:53Z       - Connect 3370 transactions: 1743.69ms (0.517ms/tx, 0.308ms/txin) [64.14s (2068.96ms/blk)]
 322021-04-18T20:18:56Z       - Connect 3194 transactions: 2387.95ms (0.748ms/tx, 0.378ms/txin) [66.53s (2078.93ms/blk)]
 332021-04-18T20:18:59Z       - Connect 3370 transactions: 2169.06ms (0.644ms/tx, 0.362ms/txin) [68.69s (2081.66ms/blk)]
 342021-04-18T20:19:02Z       - Connect 2739 transactions: 3031.24ms (1.107ms/tx, 0.511ms/txin) [71.73s (2109.59ms/blk)]
 352021-04-18T20:19:05Z       - Connect 2668 transactions: 2557.99ms (0.959ms/tx, 0.451ms/txin) [74.28s (2122.40ms/blk)]
 362021-04-18T20:19:07Z       - Connect 2169 transactions: 2384.08ms (1.099ms/tx, 0.450ms/txin) [76.67s (2129.67ms/blk)]
 372021-04-18T20:19:09Z       - Connect 2303 transactions: 1706.62ms (0.741ms/tx, 0.323ms/txin) [78.37s (2118.23ms/blk)]
 382021-04-18T20:19:12Z       - Connect 2575 transactions: 2361.26ms (0.917ms/tx, 0.455ms/txin) [80.74s (2124.63ms/blk)]
 392021-04-18T20:19:14Z       - Connect 2830 transactions: 1327.27ms (0.469ms/tx, 0.238ms/txin) [82.06s (2104.18ms/blk)]
 402021-04-18T20:19:17Z       - Connect 2243 transactions: 2785.61ms (1.242ms/tx, 0.466ms/txin) [84.85s (2121.22ms/blk)]
 412021-04-18T20:19:20Z       - Connect 2541 transactions: 3101.56ms (1.221ms/tx, 0.524ms/txin) [87.95s (2145.13ms/blk)]
 422021-04-18T20:19:25Z       - Connect 2096 transactions: 4340.73ms (2.071ms/tx, 0.678ms/txin) [92.29s (2197.41ms/blk)]
 432021-04-18T20:19:29Z       - Connect 1998 transactions: 4165.73ms (2.085ms/tx, 0.651ms/txin) [96.46s (2243.18ms/blk)]
 442021-04-18T20:19:36Z       - Connect 2108 transactions: 7060.30ms (3.349ms/tx, 1.134ms/txin) [103.52s (2352.66ms/blk)]
 452021-04-18T20:19:41Z       - Connect 1562 transactions: 4255.10ms (2.724ms/tx, 0.707ms/txin) [107.77s (2394.94ms/blk)]
 462021-04-18T20:19:44Z       - Connect 2290 transactions: 3010.00ms (1.314ms/tx, 0.549ms/txin) [110.78s (2408.31ms/blk)]
 472021-04-18T20:19:47Z       - Connect 2707 transactions: 3101.85ms (1.146ms/tx, 0.534ms/txin) [113.88s (2423.06ms/blk)]
 482021-04-18T20:19:51Z       - Connect 2231 transactions: 3869.96ms (1.735ms/tx, 0.664ms/txin) [117.75s (2453.21ms/blk)]
 492021-04-18T20:19:57Z       - Connect 801 transactions: 5703.79ms (7.121ms/tx, 0.692ms/txin) [123.46s (2519.55ms/blk)]
 502021-04-18T20:19:58Z       - Connect 1186 transactions: 1446.30ms (1.219ms/tx, 0.519ms/txin) [124.90s (2498.08ms/blk)]
 512021-04-18T20:20:00Z       - Connect 3269 transactions: 1841.58ms (0.563ms/tx, 0.334ms/txin) [126.75s (2485.21ms/blk)]
 522021-04-18T20:20:03Z       - Connect 2516 transactions: 2524.03ms (1.003ms/tx, 0.428ms/txin) [129.27s (2485.96ms/blk)]
 532021-04-18T20:20:04Z       - Connect 3016 transactions: 1216.11ms (0.403ms/tx, 0.281ms/txin) [130.49s (2462.00ms/blk)]
 542021-04-18T20:20:06Z       - Connect 675 transactions: 1155.74ms (1.712ms/tx, 0.844ms/txin) [131.64s (2437.81ms/blk)]
 552021-04-18T20:20:06Z       - Connect 1032 transactions: 442.28ms (0.429ms/tx, 0.240ms/txin) [132.08s (2401.52ms/blk)]
 562021-04-18T20:20:07Z       - Connect 2645 transactions: 1170.11ms (0.442ms/tx, 0.231ms/txin) [133.25s (2379.53ms/blk)]
 572021-04-18T20:20:08Z       - Connect 2734 transactions: 853.01ms (0.312ms/tx, 0.129ms/txin) [134.11s (2352.75ms/blk)]
 582021-04-18T20:20:09Z       - Connect 112 transactions: 64.51ms (0.576ms/tx, 0.318ms/txin) [134.17s (2313.30ms/blk)]
 592021-04-18T20:20:11Z       - Connect 2322 transactions: 1577.71ms (0.679ms/tx, 0.225ms/txin) [135.75s (2300.83ms/blk)]
 602021-04-18T20:20:12Z       - Connect 2630 transactions: 1020.75ms (0.388ms/tx, 0.157ms/txin) [136.77s (2279.50ms/blk)]
 612021-04-18T20:20:13Z       - Connect 2306 transactions: 1264.74ms (0.548ms/tx, 0.215ms/txin) [138.03s (2262.86ms/blk)]
 622021-04-18T20:20:15Z       - Connect 2535 transactions: 1383.99ms (0.546ms/tx, 0.322ms/txin) [139.42s (2248.69ms/blk)]
 632021-04-18T20:20:17Z       - Connect 2645 transactions: 2231.81ms (0.844ms/tx, 0.387ms/txin) [141.65s (2248.42ms/blk)]
 642021-04-18T20:20:20Z       - Connect 2882 transactions: 2494.08ms (0.865ms/tx, 0.410ms/txin) [144.14s (2252.26ms/blk)]
 652021-04-18T20:20:22Z       - Connect 2548 transactions: 2238.70ms (0.879ms/tx, 0.386ms/txin) [146.38s (2252.05ms/blk)]
 662021-04-18T20:20:24Z       - Connect 3112 transactions: 1831.04ms (0.588ms/tx, 0.321ms/txin) [148.21s (2245.67ms/blk)]
 672021-04-18T20:20:26Z       - Connect 2309 transactions: 2227.45ms (0.965ms/tx, 0.417ms/txin) [150.44s (2245.40ms/blk)]
 682021-04-18T20:20:28Z       - Connect 2976 transactions: 1640.56ms (0.551ms/tx, 0.252ms/txin) [152.08s (2236.50ms/blk)]
 692021-04-18T20:20:30Z       - Connect 3460 transactions: 1975.86ms (0.571ms/tx, 0.308ms/txin) [154.06s (2232.73ms/blk)]
 702021-04-18T20:20:32Z       - Connect 2810 transactions: 1788.16ms (0.636ms/tx, 0.310ms/txin) [155.85s (2226.38ms/blk)]
 712021-04-18T20:20:35Z       - Connect 1946 transactions: 2336.92ms (1.201ms/tx, 0.346ms/txin) [158.18s (2227.93ms/blk)]
 722021-04-18T20:20:37Z       - Connect 2550 transactions: 1917.07ms (0.752ms/tx, 0.331ms/txin) [160.10s (2223.62ms/blk)]
 732021-04-18T20:20:39Z       - Connect 2987 transactions: 1859.71ms (0.623ms/tx, 0.337ms/txin) [161.96s (2218.63ms/blk)]
 742021-04-18T20:20:40Z       - Connect 2340 transactions: 874.91ms (0.374ms/tx, 0.226ms/txin) [162.83s (2200.47ms/blk)]
 752021-04-18T20:20:41Z       - Connect 2252 transactions: 1046.04ms (0.464ms/tx, 0.278ms/txin) [163.88s (2185.08ms/blk)]
 762021-04-18T20:20:41Z       - Connect 122 transactions: 18.24ms (0.150ms/tx, 0.083ms/txin) [163.90s (2156.57ms/blk)]
 772021-04-18T20:20:42Z       - Connect 3706 transactions: 1380.28ms (0.372ms/tx, 0.225ms/txin) [165.28s (2146.49ms/blk)]
 782021-04-18T20:20:44Z       - Connect 3655 transactions: 1621.39ms (0.444ms/tx, 0.263ms/txin) [166.90s (2139.75ms/blk)]
 792021-04-18T20:20:45Z       - Connect 1699 transactions: 1017.33ms (0.599ms/tx, 0.320ms/txin) [167.92s (2125.55ms/blk)]
 802021-04-18T20:20:46Z       - Connect 955 transactions: 582.12ms (0.610ms/tx, 0.344ms/txin) [168.50s (2106.25ms/blk)]
 812021-04-18T20:20:48Z       - Connect 3008 transactions: 1968.70ms (0.654ms/tx, 0.337ms/txin) [170.47s (2104.56ms/blk)]
 822021-04-18T20:20:49Z       - Connect 1812 transactions: 1241.09ms (0.685ms/tx, 0.351ms/txin) [171.71s (2094.03ms/blk)]
 832021-04-18T20:20:50Z       - Connect 2703 transactions: 1019.05ms (0.377ms/tx, 0.179ms/txin) [172.73s (2081.07ms/blk)]
 842021-04-18T20:20:51Z       - Connect 844 transactions: 251.48ms (0.298ms/tx, 0.153ms/txin) [172.98s (2059.29ms/blk)]
 852021-04-18T20:20:52Z       - Connect 1823 transactions: 607.73ms (0.333ms/tx, 0.135ms/txin) [173.59s (2042.22ms/blk)]
 862021-04-18T20:20:52Z       - Connect 1196 transactions: 589.84ms (0.493ms/tx, 0.251ms/txin) [174.18s (2025.33ms/blk)]
 872021-04-18T20:20:52Z       - Connect 258 transactions: 89.26ms (0.346ms/tx, 0.247ms/txin) [174.27s (2003.07ms/blk)]
 882021-04-18T20:20:53Z       - Connect 157 transactions: 74.30ms (0.473ms/tx, 0.324ms/txin) [174.34s (1981.16ms/blk)]
 892021-04-18T20:20:55Z       - Connect 2882 transactions: 1979.44ms (0.687ms/tx, 0.330ms/txin) [176.32s (1981.14ms/blk)]
 902021-04-18T20:20:57Z       - Connect 2773 transactions: 2096.94ms (0.756ms/tx, 0.368ms/txin) [178.42s (1982.42ms/blk)]
 912021-04-18T20:20:59Z       - Connect 2663 transactions: 1453.42ms (0.546ms/tx, 0.238ms/txin) [179.87s (1976.61ms/blk)]
 922021-04-18T20:21:01Z       - Connect 2690 transactions: 2088.57ms (0.776ms/tx, 0.377ms/txin) [181.96s (1977.83ms/blk)]
 932021-04-18T20:21:03Z       - Connect 2812 transactions: 1411.26ms (0.502ms/tx, 0.254ms/txin) [183.37s (1971.74ms/blk)]
 942021-04-18T20:21:05Z       - Connect 2492 transactions: 2104.33ms (0.844ms/tx, 0.371ms/txin) [185.48s (1973.15ms/blk)]
 952021-04-18T20:21:06Z       - Connect 2859 transactions: 1320.79ms (0.462ms/tx, 0.215ms/txin) [186.80s (1966.28ms/blk)]
 962021-04-18T20:21:08Z       - Connect 3025 transactions: 1300.72ms (0.430ms/tx, 0.214ms/txin) [188.10s (1959.35ms/blk)]
 972021-04-18T20:21:10Z       - Connect 2072 transactions: 2208.83ms (1.066ms/tx, 0.345ms/txin) [190.31s (1961.92ms/blk)]
 982021-04-18T20:21:12Z       - Connect 2362 transactions: 1888.25ms (0.799ms/tx, 0.308ms/txin) [192.19s (1961.17ms/blk)]
 992021-04-18T20:21:14Z       - Connect 2419 transactions: 1916.64ms (0.792ms/tx, 0.316ms/txin) [194.11s (1960.72ms/blk)]
1002021-04-18T20:21:16Z       - Connect 1061 transactions: 1894.87ms (1.786ms/tx, 0.611ms/txin) [196.01s (1960.06ms/blk)]
1012021-04-18T20:21:17Z       - Connect 2466 transactions: 1050.97ms (0.426ms/tx, 0.215ms/txin) [197.06s (1951.06ms/blk)]
1022021-04-18T20:21:19Z       - Connect 2412 transactions: 1514.51ms (0.628ms/tx, 0.293ms/txin) [198.57s (1946.78ms/blk)]
1032021-04-18T20:21:21Z       - Connect 1860 transactions: 1662.13ms (0.894ms/tx, 0.343ms/txin) [200.23s (1944.01ms/blk)]
1042021-04-18T20:21:22Z       - Connect 2762 transactions: 1373.57ms (0.497ms/tx, 0.301ms/txin) [201.61s (1938.53ms/blk)]
1052021-04-18T20:21:23Z       - Connect 1926 transactions: 1218.18ms (0.632ms/tx, 0.293ms/txin) [202.83s (1931.67ms/blk)]
1062021-04-18T20:21:34Z       - Connect 1820 transactions: 4735.39ms (2.602ms/tx, 1.158ms/txin) [207.56s (1958.12ms/blk)]
1072021-04-18T20:21:39Z       - Connect 2571 transactions: 5260.94ms (2.046ms/tx, 0.962ms/txin) [212.82s (1988.99ms/blk)]
1082021-04-18T20:21:47Z       - Connect 2040 transactions: 8046.29ms (3.944ms/tx, 1.335ms/txin) [220.87s (2045.07ms/blk)]
1092021-04-18T20:21:51Z       - Connect 2883 transactions: 3962.96ms (1.375ms/tx, 0.621ms/txin) [224.83s (2062.67ms/blk)]
1102021-04-18T20:21:56Z       - Connect 1228 transactions: 4069.92ms (3.314ms/tx, 1.271ms/txin) [228.90s (2080.92ms/blk)]
1112021-04-18T20:21:58Z       - Connect 2131 transactions: 2554.95ms (1.199ms/tx, 0.560ms/txin) [231.46s (2085.19ms/blk)]
1122021-04-18T20:21:59Z       - Connect 416 transactions: 558.67ms (1.343ms/tx, 0.667ms/txin) [232.01s (2071.56ms/blk)]
1132021-04-18T20:22:03Z       - Connect 2932 transactions: 3614.21ms (1.233ms/tx, 0.603ms/txin) [235.63s (2085.21ms/blk)]
1142021-04-18T20:22:07Z       - Connect 2900 transactions: 4354.95ms (1.502ms/tx, 0.737ms/txin) [239.98s (2105.12ms/blk)]
1152021-04-18T20:22:14Z       - Connect 2559 transactions: 6662.96ms (2.604ms/tx, 1.120ms/txin) [246.65s (2144.75ms/blk)]
1162021-04-18T20:22:22Z       - Connect 1982 transactions: 8284.58ms (4.180ms/tx, 1.534ms/txin) [254.93s (2197.68ms/blk)]
1172021-04-18T20:22:24Z       - Connect 1011 transactions: 2014.99ms (1.993ms/tx, 0.971ms/txin) [256.95s (2196.12ms/blk)]
1182021-04-18T20:22:30Z       - Connect 2926 transactions: 5595.99ms (1.913ms/tx, 0.944ms/txin) [262.54s (2224.93ms/blk)]
1192021-04-18T20:22:36Z       - Connect 3273 transactions: 5317.79ms (1.625ms/tx, 0.956ms/txin) [267.86s (2250.92ms/blk)]
1202021-04-18T20:22:40Z       - Connect 2423 transactions: 3889.90ms (1.605ms/tx, 0.910ms/txin) [271.75s (2264.58ms/blk)]
1212021-04-18T20:22:44Z       - Connect 2625 transactions: 3773.33ms (1.437ms/tx, 0.517ms/txin) [275.52s (2277.05ms/blk)]
1222021-04-18T20:22:48Z       - Connect 2867 transactions: 4136.41ms (1.443ms/tx, 0.588ms/txin) [279.66s (2292.29ms/blk)]
1232021-04-18T20:22:56Z       - Connect 2624 transactions: 4846.28ms (1.847ms/tx, 0.772ms/txin) [284.51s (2313.05ms/blk)]
1242021-04-18T20:23:01Z       - Connect 2940 transactions: 4587.29ms (1.560ms/tx, 0.767ms/txin) [289.09s (2331.40ms/blk)]
1252021-04-18T20:23:10Z       - Connect 2413 transactions: 9130.11ms (3.784ms/tx, 1.588ms/txin) [298.22s (2385.78ms/blk)]
1262021-04-18T20:23:15Z       - Connect 3164 transactions: 4830.58ms (1.527ms/tx, 0.815ms/txin) [303.05s (2405.19ms/blk)]
1272021-04-18T20:23:20Z       - Connect 2709 transactions: 4438.76ms (1.639ms/tx, 0.691ms/txin) [307.49s (2421.20ms/blk)]
1282021-04-18T20:23:26Z       - Connect 2911 transactions: 6138.68ms (2.109ms/tx, 1.032ms/txin) [313.63s (2450.24ms/blk)]
1292021-04-18T20:23:32Z       - Connect 2962 transactions: 5419.45ms (1.830ms/tx, 0.954ms/txin) [319.05s (2473.26ms/blk)]
1302021-04-18T20:23:37Z       - Connect 2680 transactions: 4754.63ms (1.774ms/tx, 0.800ms/txin) [323.81s (2490.81ms/blk)]
1312021-04-18T20:23:42Z       - Connect 3183 transactions: 5548.45ms (1.743ms/tx, 0.969ms/txin) [329.35s (2514.15ms/blk)]
1322021-04-18T20:23:48Z       - Connect 2497 transactions: 5579.94ms (2.235ms/tx, 0.972ms/txin) [334.93s (2537.38ms/blk)]
1332021-04-18T20:23:53Z       - Connect 3258 transactions: 5309.56ms (1.630ms/tx, 0.890ms/txin) [340.24s (2558.22ms/blk)]
1342021-04-18T20:24:00Z       - Connect 2066 transactions: 6662.37ms (3.225ms/tx, 1.101ms/txin) [346.91s (2588.85ms/blk)]
1352021-04-18T20:24:09Z       - Connect 2101 transactions: 8424.53ms (4.010ms/tx, 1.273ms/txin) [355.33s (2632.07ms/blk)]
1362021-04-18T20:24:25Z       - Connect 726 transactions: 16045.19ms (22.101ms/tx, 2.406ms/txin) [371.38s (2730.70ms/blk)]

sipa commented at 8:39 pm on April 18, 2021: member

My best guess is that this is your CPU being throttled because of overheating.

benjamin-wilson commented at 8:41 pm on April 18, 2021: none

It’s sitting at 43C, I’ve checked the frequency and it’s boosting correctly to 1.5Ghz

0admin@raspberrypi:~ $ sudo vcgencmd measure_clock arm
1frequency(48)=1500345728
2admin@raspberrypi:~ $ sudo vcgencmd measure_temp
3temp=43.3'C

In addition I don’t think that would explain the disk reads going higher when cpu utilization goes lower.

sipa commented at 8:47 pm on April 18, 2021: member

Is it possible that the I/O or memory or SATA controller is throttled independently from the CPU?

benjamin-wilson commented at 9:10 pm on April 18, 2021: none

Well I just put the whole thing outside on the windowsill for 10min, it’s 11C outside, same symptoms.

sipa commented at 9:46 pm on April 18, 2021: member

I have no explanation anymore in that case!

benjamin-wilson commented at 0:12 am on April 19, 2021: none

Working at this from another angle, I don’t understand why there’s so much reading from the disk, event when things are working ‘correctly’. It’s my understanding that TL;DR blocks would be downloaded from peers, validated in memory and then written to disk. Looking at the validation logic we’ve been talking about I’m not seeing a lot of reason for i/o but I’m not familiar with some of those function calls and my c++ is more than rusty. Not sure I understand why there’s 200+ mbps disk read to process less than 1, 1mb block per second? There’s the previous block load but according to the bench logs that’s pretty fast.

sipa commented at 0:13 am on April 19, 2021: member

It’s reading UTXOs from disk, not blocks.

benjamin-wilson commented at 0:16 am on April 19, 2021: none

Ah that makes sense, i suppose checking the balance is part of the validation…

pinheadmz commented at 3:25 pm on March 8, 2023: member

Ah that makes sense, i suppose checking the balance is part of the validation…

Not just balance but the UTXOs store the output script needed for any spending validation. Have you been able to reproduce this issue with the latest release of Bitcoin Core @benjamin-wilson ?

maflcko commented at 9:55 am on March 9, 2023: member

Closing for now, but please let us know if there are more details available.

maflcko closed this on Mar 9, 2023

maflcko added the label UTXO Db and Indexes on Mar 9, 2023

maflcko added the label Resource usage on Mar 9, 2023

bitcoin locked this on Mar 8, 2024

Blockchain sync - highly variable time to connect trasactions #21722