Sync slow #26063

1. 
   kord1e commented at 7:02 pm on September 11, 2022: none

   Syncing blockchain is sometimes very slow. I think this has become more common in the past months.

   Here’s a screenshot from Network Traffic window in the GUI, see how there are long periods of absolutely no traffic. Also see how it only downloaded about 100 MB during the first 30minutes of syncing. It’s also often connected to just 1 or 2 peers which is weird.

   

   Internet is stable and I can easily download 10 MB/second. CPU load stays mostly low so lack of CPU resources doesn’t explain this. Memory usage is also not high. I have set the memory option in the settings menu to 4 GB.

   Sometimes it starts to work faster if you close and restart the program. But as I said this has become worse in the past months.

   Why doesn’t it download blocks faster than this? If the problem is that peers can’t provide blocks faster, why isn’t it looking for more peers?

   I’m using the latest master from git as of today.

2. kord1e added the label Bug on Sep 11, 2022
3. 
   maflcko commented at 5:53 am on September 12, 2022: member

   Please check your debug.log for possible causes; Alternatively you can upload it here.

   You can find the debug.log in your data dir.

   Please be aware that the debug log might contain personally identifying information.

4. maflcko added the label Questions and Help on Sep 12, 2022
5. maflcko removed the label Bug on Sep 12, 2022
6. 
   kord1e commented at 6:04 pm on September 12, 2022: none

   @MarcoFalke Thanks, here’s a short debug.log from today, again very little data was downloaded and there were gaps in the network traffic.

     02022-09-12T16:50:35Z Bitcoin Core version v23.99.0-2e34374bf3e1 (release build)
     12022-09-12T16:50:35Z InitParameterInteraction: parameter interaction: -listen=0 -> setting -upnp=0
     22022-09-12T16:50:35Z InitParameterInteraction: parameter interaction: -listen=0 -> setting -natpmp=0
     32022-09-12T16:50:35Z InitParameterInteraction: parameter interaction: -listen=0 -> setting -discover=0
     42022-09-12T16:50:35Z InitParameterInteraction: parameter interaction: -listen=0 -> setting -listenonion=0
     52022-09-12T16:50:35Z InitParameterInteraction: parameter interaction: -listen=0 -> setting -i2pacceptincoming=0
     62022-09-12T16:50:35Z Qt 5.15.5 (dynamic), plugin=xcb (dynamic)
     72022-09-12T16:50:35Z No static plugins.
     82022-09-12T16:50:35Z Style: fusion / QFusionStyle
     92022-09-12T16:50:35Z System: Fedora Linux 36 (Thirty Six), x86_64-little_endian-lp64
    102022-09-12T16:50:35Z redacted
    112022-09-12T16:50:35Z Using the 'sse4(1way),sse41(4way)' SHA256 implementation
    122022-09-12T16:50:35Z Default data directory /home/user/.bitcoin
    132022-09-12T16:50:35Z Using data directory /home/user/.bitcoin
    142022-09-12T16:50:35Z Config file: /home/user/.bitcoin/bitcoin.conf
    152022-09-12T16:50:35Z Setting file arg: dbcache = "4000"
    162022-09-12T16:50:35Z Setting file arg: listen = false
    172022-09-12T16:50:35Z Using at most 125 automatic connections (1024 file descriptors available)
    182022-09-12T16:50:36Z Using 16 MiB out of 16 MiB requested for signature cache, able to store 524288 elements
    192022-09-12T16:50:36Z Using 16 MiB out of 16 MiB requested for script execution cache, able to store 524288 elements
    202022-09-12T16:50:36Z Script verification uses 2 additional threads
    212022-09-12T16:50:36Z scheduler thread start
    222022-09-12T16:50:36Z Using wallet directory /home/user/.bitcoin/wallets
    232022-09-12T16:50:36Z init message: Verifying wallet(s)…
    242022-09-12T16:50:36Z Using BerkeleyDB version Berkeley DB 5.3.28: (September  9, 2013)
    252022-09-12T16:50:36Z Using wallet /home/user/.bitcoin/wallets/wallet.dat
    262022-09-12T16:50:36Z BerkeleyEnvironment::Open: LogDir=/home/user/.bitcoin/wallets/database ErrorFile=/home/user/.bitcoin/wallets/db.log
    272022-09-12T16:50:36Z Using /16 prefix for IP bucketing
    282022-09-12T16:50:36Z init message: Loading P2P addresses…
    292022-09-12T16:50:36Z Loaded 24828 addresses from peers.dat  191ms
    302022-09-12T16:50:36Z init message: Loading banlist…
    312022-09-12T16:50:36Z SetNetworkActive: true
    322022-09-12T16:50:36Z Cache configuration:
    332022-09-12T16:50:36Z * Using 2.0 MiB for block index database
    342022-09-12T16:50:36Z * Using 8.0 MiB for chain state database
    352022-09-12T16:50:36Z * Using 3990.0 MiB for in-memory UTXO set (plus up to 286.1 MiB of unused mempool space)
    362022-09-12T16:50:36Z init message: Loading block index…
    372022-09-12T16:50:36Z Assuming ancestors of block 00000000000000000009c97098b5295f7e5f183ac811fb5d1534040adb93cabd have valid signatures.
    382022-09-12T16:50:36Z Setting nMinimumChainWork=00000000000000000000000000000000000000003404ba0801921119f903495e
    392022-09-12T16:50:36Z Switching active chainstate to Chainstate [ibd] @ height -1 (null)
    402022-09-12T16:50:36Z Opening LevelDB in /home/user/.bitcoin/blocks/index
    412022-09-12T16:50:36Z Opened LevelDB successfully
    422022-09-12T16:50:36Z Using obfuscation key for /home/user/.bitcoin/blocks/index: redacted
    432022-09-12T16:50:47Z LoadBlockIndexDB: last block file = 2911
    442022-09-12T16:50:47Z LoadBlockIndexDB: last block file info: CBlockFileInfo(blocks=102, size=130710216, heights=721928...722029, time=2022-02-05...2022-02-06)
    452022-09-12T16:50:47Z Checking all blk files are present...
    462022-09-12T16:50:53Z Opening LevelDB in /home/user/.bitcoin/chainstate
    472022-09-12T16:50:53Z Opened LevelDB successfully
    482022-09-12T16:50:53Z Using obfuscation key for /home/user/.bitcoin/chainstate: redacted
    492022-09-12T16:50:54Z Loaded best chain: hashBestChain=00000000000000000003333d6eecfa33f4d3e9187c6a2b20f5f8ae0612171f43 height=722029 date=2022-02-06T10:03:36Z progress=0.927456
    502022-09-12T16:50:54Z init message: Verifying blocks…
    512022-09-12T16:50:54Z Verifying last 6 blocks at level 3
    522022-09-12T16:50:54Z [0%]...[16%]...[33%]...[50%]...[66%]...[83%]...[99%]...[DONE].
    532022-09-12T16:54:45Z No coin database inconsistencies in last 6 blocks (7131 transactions)
    542022-09-12T16:54:45Z  block index          249068ms
    552022-09-12T16:54:45Z init message: Loading wallet…
    562022-09-12T16:54:45Z BerkeleyEnvironment::Open: LogDir=/home/user/.bitcoin/wallets/database ErrorFile=/home/user/.bitcoin/wallets/db.log
    572022-09-12T16:54:45Z [default wallet] Wallet file version = 169900, last client version = 239900
    582022-09-12T16:54:45Z [default wallet] Keys: 2007 plaintext, 0 encrypted, 2007 w/ metadata, 2007 total. Unknown wallet records: 0
    592022-09-12T16:54:45Z [default wallet] Wallet completed loading in             264ms
    602022-09-12T16:54:45Z [default wallet] setKeyPool.size() = 2000
    612022-09-12T16:54:45Z [default wallet] mapWallet.size() = 5
    622022-09-12T16:54:45Z [default wallet] m_address_book.size() = 5
    632022-09-12T16:54:45Z Setting NODE_NETWORK on non-prune mode
    642022-09-12T16:54:45Z block tree size = 753687
    652022-09-12T16:54:45Z nBestHeight = 722029
    662022-09-12T16:54:45Z Loaded 0 addresses from "anchors.dat"
    672022-09-12T16:54:45Z 0 block-relay-only anchors will be tried for connections.
    682022-09-12T16:54:45Z init message: Starting network threads…
    692022-09-12T16:54:45Z init message: Done loading
    702022-09-12T16:54:45Z opencon thread start
    712022-09-12T16:54:45Z net thread start
    722022-09-12T16:54:45Z msghand thread start
    732022-09-12T16:54:45Z addcon thread start
    742022-09-12T16:54:45Z dnsseed thread start
    752022-09-12T16:54:45Z Waiting 300 seconds before querying DNS seeds.
    762022-09-12T16:54:45Z loadblk thread start
    772022-09-12T16:54:45Z GUI: Platform customization: "other"
    782022-09-12T16:54:45Z Imported mempool transactions from disk: 0 succeeded, 0 failed, 0 expired, 0 already there, 0 waiting for initial broadcast
    792022-09-12T16:54:45Z loadblk thread exit
    802022-09-12T16:54:46Z New outbound peer connected: version: 70016, blocks=753814, peer=0 (outbound-full-relay)
    812022-09-12T16:54:58Z New outbound peer connected: version: 70015, blocks=753813, peer=1 (outbound-full-relay)
    822022-09-12T16:54:59Z Synchronizing blockheaders, height: 753813 (~100.00%)
    832022-09-12T16:55:07Z P2P peers available. Skipped DNS seeding.
    842022-09-12T16:55:07Z dnsseed thread exit
    852022-09-12T16:56:27Z UpdateTip: new best=000000000000000000079a8344e3a344a39d6c626772dc777af37fecd6e538fe height=722030 version=0x20008000 log2_work=93.330571 tx=708517005 date='2022-02-06T10:07:19Z' progress=0.927456 cache=0.9MiB(6403txo)
    862022-09-12T16:56:36Z UpdateTip: new best=00000000000000000003365ca620b326a946219493654d0f050dede562a58bc4 height=722031 version=0x20000004 log2_work=93.330584 tx=708517339 date='2022-02-06T10:09:33Z' progress=0.927456 cache=1.0MiB(7707txo)
    872022-09-12T16:58:15Z UpdateTip: new best=0000000000000000000283f6dbd4007828ad3c3d2d1eab4b448640d2abcd7262 height=722032 version=0x3fffe004 log2_work=93.330598 tx=708519697 date='2022-02-06T10:27:02Z' progress=0.927459 cache=2.5MiB(18913txo)
    882022-09-12T16:58:28Z UpdateTip: new best=00000000000000000000880d0fa2f1cd4d93723c95705a6229d05be9b0ed0ed8 height=722033 version=0x20fee004 log2_work=93.330611 tx=708519969 date='2022-02-06T10:28:54Z' progress=0.927459 cache=2.7MiB(20395txo)
    892022-09-12T16:58:33Z UpdateTip: new best=000000000000000000073466612e49e878e7b36521321c7f2cb24207d26c3d77 height=722034 version=0x20008004 log2_work=93.330624 tx=708520077 date='2022-02-06T10:29:37Z' progress=0.927459 cache=2.9MiB(21140txo)
    902022-09-12T16:59:39Z UpdateTip: new best=00000000000000000004c094c5e84f7ad6e3eb2c3d85ad29076af1a79bad5db0 height=722035 version=0x20000004 log2_work=93.330637 tx=708521706 date='2022-02-06T10:41:15Z' progress=0.927461 cache=3.7MiB(27095txo)
    912022-09-12T17:00:29Z UpdateTip: new best=0000000000000000000802587b8b437f781ac7d831e5da3764556aa555171fed height=722036 version=0x20000004 log2_work=93.330651 tx=708522934 date='2022-02-06T10:49:31Z' progress=0.927463 cache=4.2MiB(31236txo)
    922022-09-12T17:00:48Z UpdateTip: new best=00000000000000000004d13f146bbb44fc6592cd5f735f9fc03ad69e230d6fcf height=722037 version=0x20000000 log2_work=93.330664 tx=708523295 date='2022-02-06T10:51:35Z' progress=0.927463 cache=4.3MiB(32391txo)
    932022-09-12T17:00:59Z UpdateTip: new best=00000000000000000002033b2ecbc50609346ba60f3fdc46a2a734e46a59a86f height=722038 version=0x3fffe000 log2_work=93.330677 tx=708523550 date='2022-02-06T10:53:37Z' progress=0.927464 cache=4.4MiB(33209txo)
    942022-09-12T17:01:02Z UpdateTip: new best=00000000000000000004f0b9d1e0cc13b7abac03e50cd5907f8f4c3e703f0558 height=722039 version=0x20006000 log2_work=93.330691 tx=708523628 date='2022-02-06T10:54:09Z' progress=0.927464 cache=4.4MiB(33426txo)
    952022-09-12T17:01:02Z New outbound peer connected: version: 70016, blocks=753815, peer=8 (outbound-full-relay)
    962022-09-12T17:01:30Z UpdateTip: new best=00000000000000000000b5b8fdcdfa009ba797857272b7222c0d614e7d03a2ae height=722040 version=0x20000004 log2_work=93.330704 tx=708523957 date='2022-02-06T10:56:27Z' progress=0.927464 cache=4.6MiB(34986txo)
    972022-09-12T17:03:30Z UpdateTip: new best=00000000000000000007526e6813259a9033a72d3f13f1601342c56fcfd8adb4 height=722041 version=0x27ffe000 log2_work=93.330717 tx=708526425 date='2022-02-06T11:13:18Z' progress=0.927467 cache=6.1MiB(43858txo)
    982022-09-12T17:03:48Z UpdateTip: new best=000000000000000000096bac7fcba611da3c77314fe99cea90efb5bc95814f0b height=722042 version=0x32752000 log2_work=93.330730 tx=708526882 date='2022-02-06T11:15:53Z' progress=0.927467 cache=6.2MiB(45135txo)
    992022-09-12T17:06:49Z UpdateTip: new best=000000000000000000008074f8efae25a37d609f2491e348628941b9aba5ee16 height=722043 version=0x20e00004 log2_work=93.330744 tx=708529583 date='2022-02-06T11:34:06Z' progress=0.927470 cache=7.4MiB(55087txo)
   1002022-09-12T17:07:19Z UpdateTip: new best=0000000000000000000141a8b9f775b2c43571fad74f67baebf79c83ea4330c0 height=722044 version=0x2000e004 log2_work=93.330757 tx=708529882 date='2022-02-06T11:36:14Z' progress=0.927470 cache=7.6MiB(56311txo)
   1012022-09-12T17:08:46Z UpdateTip: new best=00000000000000000006f9ff1c0a54e29f887d2efa399725d88642c7f07e54bf height=722045 version=0x20600004 log2_work=93.330770 tx=708531324 date='2022-02-06T11:45:19Z' progress=0.927472 cache=8.1MiB(60724txo)
   1022022-09-12T17:08:52Z UpdateTip: new best=00000000000000000007b7bf3d3e952ba5d2eec59a29ff4d5f6c33aea3644a75 height=722046 version=0x3fffe004 log2_work=93.330784 tx=708531424 date='2022-02-06T11:46:01Z' progress=0.927472 cache=8.2MiB(61006txo)
   1032022-09-12T17:09:21Z UpdateTip: new best=000000000000000000005d187be37bc3d26ce17ade1a3f14eb3bd9b9fccac98b height=722047 version=0x20000004 log2_work=93.330797 tx=708531931 date='2022-02-06T11:49:57Z' progress=0.927473 cache=8.4MiB(62543txo)
   1042022-09-12T17:09:21Z Synchronizing blockheaders, height: 753815 (~100.00%)
   1052022-09-12T17:10:36Z UpdateTip: new best=0000000000000000000632d2884a3ee1b345df5cde9afc3745a9bb53f47f7db5 height=722048 version=0x20006004 log2_work=93.330810 tx=708533027 date='2022-02-06T11:56:40Z' progress=0.927474 cache=8.8MiB(66304txo)
   1062022-09-12T17:13:54Z UpdateTip: new best=0000000000000000000843aa18304f0c7ec61648dc7186477320bb92a6e207f1 height=722049 version=0x20600004 log2_work=93.330823 tx=708534486 date='2022-02-06T12:06:21Z' progress=0.927475 cache=9.8MiB(74120txo)
   1072022-09-12T17:16:10Z UpdateTip: new best=00000000000000000000f1a5675f0d832e5896645eba4e7f9d50b8b23ee7072d height=722050 version=0x2fffe004 log2_work=93.330837 tx=708537138 date='2022-02-06T12:22:18Z' progress=0.927478 cache=11.0MiB(83747txo)
   1082022-09-12T17:17:55Z UpdateTip: new best=0000000000000000000a67199ba78b157b9f390c5cb7b9559623804f9c3e0f0b height=722051 version=0x3fff0004 log2_work=93.330850 tx=708540312 date='2022-02-06T13:04:51Z' progress=0.927482 cache=13.3MiB(97209txo)
   1092022-09-12T17:19:15Z UpdateTip: new best=00000000000000000007970781a06782962b4fa4ef596af403a46c84d8b39f11 height=722052 version=0x20c00000 log2_work=93.330863 tx=708543147 date='2022-02-06T13:14:07Z' progress=0.927485 cache=14.6MiB(107774txo)
   1102022-09-12T17:19:22Z New outbound peer connected: version: 70016, blocks=753818, peer=22 (outbound-full-relay)
   1112022-09-12T17:19:22Z Synchronizing blockheaders, height: 753818 (~100.00%)
   1122022-09-12T17:20:32Z UpdateTip: new best=00000000000000000000941e92474ee4430498bf1ff0dea90f4d5d2abd3f3671 height=722053 version=0x3fffe000 log2_work=93.330876 tx=708545523 date='2022-02-06T13:21:12Z' progress=0.927488 cache=16.5MiB(123276txo)
   1132022-09-12T17:22:08Z UpdateTip: new best=000000000000000000000b98b3f6cf52caf1a688e2b857422ee8fcf80a9838e7 height=722054 version=0x20600000 log2_work=93.330890 tx=708548600 date='2022-02-06T14:08:00Z' progress=0.927492 cache=18.2MiB(136782txo)
   1142022-09-12T17:23:41Z UpdateTip: new best=00000000000000000004aeb6468e20360f2ee668e008d89b01f03d84385a7666 height=722055 version=0x20c00004 log2_work=93.330903 tx=708550420 date='2022-02-06T14:10:58Z' progress=0.927494 cache=19.3MiB(146025txo)
   1152022-09-12T17:25:16Z UpdateTip: new best=00000000000000000007144baa6379c5f15140b2f41220db07a7f3d2ddd0e129 height=722056 version=0x20000000 log2_work=93.330916 tx=708552641 date='2022-02-06T14:26:53Z' progress=0.927496 cache=20.5MiB(155681txo)
   1162022-09-12T17:27:11Z UpdateTip: new best=00000000000000000005062f0eaf2122eb44eafdef12fdedf503ad90cd45eb54 height=722057 version=0x3fff0000 log2_work=93.330930 tx=708554781 date='2022-02-06T14:38:06Z' progress=0.927499 cache=21.6MiB(164961txo)
   1172022-09-12T17:28:51Z UpdateTip: new best=00000000000000000002fc9a934648f31b17f008f849bf28466d053a20532828 height=722058 version=0x3fffe004 log2_work=93.330943 tx=708556988 date='2022-02-06T15:00:04Z' progress=0.927501 cache=24.1MiB(173931txo)
   1182022-09-12T17:30:25Z UpdateTip: new best=00000000000000000002ac4ceee872ba40604d041f68f9591b6c61fe99516436 height=722059 version=0x31940000 log2_work=93.330956 tx=708558106 date='2022-02-06T15:07:03Z' progress=0.927502 cache=25.1MiB(182434txo)
   1192022-09-12T17:32:13Z UpdateTip: new best=00000000000000000008488c2ee78412ec655743c7fcad41b1e1a73c68ce3d04 height=722060 version=0x20600004 log2_work=93.330969 tx=708560034 date='2022-02-06T15:16:22Z' progress=0.927505 cache=26.1MiB(190271txo)
   1202022-09-12T17:35:07Z UpdateTip: new best=00000000000000000008e8cc48d4f1e39119e5a594e5bee99552c8026322bf74 height=722061 version=0x20800000 log2_work=93.330983 tx=708561454 date='2022-02-06T15:20:19Z' progress=0.927506 cache=27.1MiB(198781txo)
   1212022-09-12T17:36:45Z UpdateTip: new best=0000000000000000000926a8641b6aa8a58cd5c6c9dc41e0fd57beece9216297 height=722062 version=0x2000e000 log2_work=93.330996 tx=708563974 date='2022-02-06T15:32:16Z' progress=0.927509 cache=28.3MiB(207823txo)
   1222022-09-12T17:38:41Z UpdateTip: new best=000000000000000000002f115295e8919d9daf412e9f02227442ebc5b7a629db height=722063 version=0x20800000 log2_work=93.331009 tx=708566229 date='2022-02-06T15:41:55Z' progress=0.927511 cache=29.6MiB(218486txo)
   1232022-09-12T17:40:15Z UpdateTip: new best=00000000000000000008bfb838099e37a8130ca07014b5f76b51291c0821c39a height=722064 version=0x20c00000 log2_work=93.331023 tx=708568935 date='2022-02-06T15:43:15Z' progress=0.927515 cache=30.8MiB(228792txo)
   1242022-09-12T17:42:28Z UpdateTip: new best=00000000000000000009b2806dca2f704b28dabe9acb6fb04fbc809d8ce9c1e7 height=722065 version=0x20000000 log2_work=93.331036 tx=708571010 date='2022-02-06T15:50:18Z' progress=0.927517 cache=31.9MiB(237301txo)
   1252022-09-12T17:42:28Z addcon thread exit
   1262022-09-12T17:42:28Z opencon thread exit
   1272022-09-12T17:42:28Z Shutdown: In progress...
   1282022-09-12T17:42:28Z msghand thread exit
   1292022-09-12T17:42:28Z net thread exit
   1302022-09-12T17:42:28Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat started
   1312022-09-12T17:42:28Z DumpAnchors: Flush 0 outbound block-relay-only peer addresses to anchors.dat completed (0.01s)
   1322022-09-12T17:42:28Z scheduler thread exit
   1332022-09-12T17:42:28Z Writing 0 unbroadcast transactions to disk.
   1342022-09-12T17:42:28Z Dumped mempool: 6.593e-06s to copy, 0.0079992s to dump
   1352022-09-12T17:42:30Z [default wallet] Releasing wallet
   1362022-09-12T17:42:42Z Shutdown: done
   

7. 
   maflcko commented at 6:58 am on September 13, 2022: member

   It says that connecting a single block takes more than a minute. This means that your disk or CPU may be slow. Maybe retry the above debug log with -debug=bench?
8. 
   kord1e commented at 1:13 pm on September 17, 2022: none

   @MarcoFalke Thanks, here’s a new debug.log with bench option. CPU usage is not high when this slow syncing occurs. Hard disk may not be fast but it also does not explain why syncing sometimes works faster. This log was made over several hours and syncing was very slow all the time, only 500 MB or so was downloaded.

   debug.log

9. 
   maflcko commented at 1:27 pm on September 19, 2022: member

   Looks like this is reasonable performance for (let’s say) a laptop. What hardware are you on?
10. 
    sipa commented at 2:24 pm on September 19, 2022: member

    Almost all the time is spent in connecting inputs. Sounds like you’re on a high-latency disk (e.g. a slow spinning harddrive, or a network device). As the dbcache grows, and more and more of the database is in RAM, you should see some speedup (though only up to the configured dbcache value, by default 450 MB IIRC).
11. 
    maflcko commented at 2:33 pm on September 19, 2022: member

    This users has a dbcache of 4000, according to the debug log: 2022-09-12T16:50:35Z Setting file arg: dbcache = "4000"
12. 
    kord1e commented at 6:43 pm on September 21, 2022: none

    @sipa @MarcoFalke Thanks, this computer is desktop, pretty old, nearly 10 years old. Blockchain is on a 2TB HDD.

    There is some disk activity going on, I can hear it. But I think disk alone shouldn’t explain this because sometimes syncing works reasonably fast, like this screenshot (unfortunately I don’t have a bench option log from this run):

    

    But often it is very slow as I posted previously, and it can be slow for hours.

13. 
    Jianfree commented at 11:39 am on September 25, 2022: none

    i have the same issue, my laptop is MacBook Pro (14-inch, 2021), Apple M1 Pro。Connect transactions is slow , CPU usage is also not high when this slow syncing occurs。 the part of debug.log is like this

     02022-09-25T11:36:16Z sending version (102 bytes) peer=18
     12022-09-25T11:36:16Z send version message: version 70016, blocks=482671, them=46.4.225.212:8333, txrelay=1, peer=18
     22022-09-25T11:36:16Z UpdatedBlockTip: new block hash=000000000000000001003cd9edda5261fbbdfdabd3c6eb37bc5faa57f1c4689c fork block hash=0000000000000000003297494b69af4d8a66bba5cb4eaea769564a9f3d730241 (in IBD=true)
     32022-09-25T11:36:16Z Feeding 308 bytes of dynamic environment data into RNG
     42022-09-25T11:36:16Z BlockConnected: block hash=000000000000000000d451ed3d5802d732d404f306d2c68f6c4952fc12b8a86f block height=482673
     52022-09-25T11:36:16Z UpdatedBlockTip: new block hash=000000000000000000d451ed3d5802d732d404f306d2c68f6c4952fc12b8a86f fork block hash=000000000000000001003cd9edda5261fbbdfdabd3c6eb37bc5faa57f1c4689c (in IBD=true)
     62022-09-25T11:36:16Z BlockConnected: block hash=00000000000000000051442f4a8d570b6fb0a4a30c5c18fa62e0e7e93ca88bd9 block height=482674
     72022-09-25T11:36:16Z UpdatedBlockTip: new block hash=00000000000000000051442f4a8d570b6fb0a4a30c5c18fa62e0e7e93ca88bd9 fork block hash=000000000000000000d451ed3d5802d732d404f306d2c68f6c4952fc12b8a86f (in IBD=true)
     82022-09-25T11:36:16Z BlockConnected: block hash=0000000000000000001011ec4d2c45a18c8eb76ae209531282b3341b0449cf42 block height=482675
     92022-09-25T11:36:16Z UpdatedBlockTip: new block hash=0000000000000000001011ec4d2c45a18c8eb76ae209531282b3341b0449cf42 fork block hash=00000000000000000051442f4a8d570b6fb0a4a30c5c18fa62e0e7e93ca88bd9 (in IBD=true)
    102022-09-25T11:36:16Z BlockConnected: block hash=0000000000000000000d041ac78f5433560381613da91f6baeff0299ec19145d block height=482676
    112022-09-25T11:36:16Z UpdatedBlockTip: new block hash=0000000000000000000d041ac78f5433560381613da91f6baeff0299ec19145d fork block hash=0000000000000000001011ec4d2c45a18c8eb76ae209531282b3341b0449cf42 (in IBD=true)
    122022-09-25T11:36:16Z BlockConnected: block hash=0000000000000000013392ec2fe989b057532c7bfa6d228c506ea3a7a64e08fd block height=482677
    132022-09-25T11:36:16Z UpdatedBlockTip: new block hash=0000000000000000013392ec2fe989b057532c7bfa6d228c506ea3a7a64e08fd fork block hash=0000000000000000000d041ac78f5433560381613da91f6baeff0299ec19145d (in IBD=true)
    142022-09-25T11:36:16Z   - Load block from disk: 31.35ms [9.61s]
    152022-09-25T11:36:16Z     - Sanity checks: 1.32ms [0.30s (2.63ms/blk)]
    162022-09-25T11:36:16Z     - Fork checks: 0.03ms [0.01s (0.07ms/blk)]
    172022-09-25T11:36:16Z socket closed for peer=18
    182022-09-25T11:36:16Z disconnecting peer=18
    192022-09-25T11:36:16Z socket no message in first 60 seconds, 0 1 peer=18
    202022-09-25T11:36:17Z Selected 24.166.214.153:8333 from tried
    212022-09-25T11:36:17Z trying connection 24.166.214.153:8333 lastseen=24.2hrs
    222022-09-25T11:36:18Z connection attempt to 24.166.214.153:8333 timed out
    232022-09-25T11:36:18Z Selected 134.209.215.174:8333 from tried
    242022-09-25T11:36:18Z trying connection 134.209.215.174:8333 lastseen=11.1hrs
    252022-09-25T11:36:19Z Added connection to 134.209.215.174:8333 peer=19
    262022-09-25T11:36:37Z       - Connect 2165 transactions: 20547.91ms (9.491ms/tx, 4.528ms/txin) [3719.65s (32065.99ms/blk)]
    272022-09-25T11:36:37Z     - Verify 4538 txins: 20548.02ms (4.528ms/txin) [3719.68s (32066.24ms/blk)]
    282022-09-25T11:36:37Z     - Index writing: 19.88ms [4.65s (40.05ms/blk)]
    292022-09-25T11:36:37Z BlockChecked: block hash=0000000000000000011ebba92f50fec98b6c1d7555cd8c25192f143a65c98111 state=Valid
    302022-09-25T11:36:37Z   - Connect total: 20569.47ms [3724.70s (32109.52ms/blk)]
    312022-09-25T11:36:37Z   - Flush: 5.85ms [1.79s (15.41ms/blk)]
    322022-09-25T11:36:37Z   - Writing chainstate: 0.01ms [0.01s (0.13ms/blk)]
    332022-09-25T11:36:37Z Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current
    342022-09-25T11:36:37Z UpdateTip: new best=0000000000000000011ebba92f50fec98b6c1d7555cd8c25192f143a65c98111 height=482678 version=0x20000002 log2_work=87.015786 tx=250621715 date='2017-08-30T18:22:13Z' progress=0.327097 cache=71.7MiB(535690txo)
    352022-09-25T11:36:37Z   - Connect postprocess: 0.26ms [0.06s (0.52ms/blk)]
    362022-09-25T11:36:37Z - Connect block: 20606.94ms [3736.18s (32208.42ms/blk)]
    372022-09-25T11:36:37Z Enqueuing BlockConnected: block hash=0000000000000000011ebba92f50fec98b6c1d7555cd8c25192f143a65c98111 block height=482678
    382022-09-25T11:36:37Z Enqueuing UpdatedBlockTip: new block hash=0000000000000000011ebba92f50fec98b6c1d7555cd8c25192f143a65c98111 fork block hash=0000000000000000013392ec2fe989b057532c7bfa6d228c506ea3a7a64e08fd (in IBD=true)
    392022-09-25T11:36:37Z BlockConnected: block hash=0000000000000000011ebba92f50fec98b6c1d7555cd8c25192f143a65c98111 block height=482678
    402022-09-25T11:36:37Z   - Load block from disk: 37.44ms [9.65s]
    412022-09-25T11:36:37Z     - Sanity checks: 1.21ms [0.31s (2.62ms/blk)]
    422022-09-25T11:36:37Z     - Fork checks: 0.02ms [0.01s (0.07ms/blk)]
    432022-09-25T11:37:01Z       - Connect 2214 transactions: 24288.43ms (10.970ms/tx, 5.284ms/txin) [3743.94s (31999.52ms/blk)]
    442022-09-25T11:37:01Z     - Verify 4597 txins: 24288.49ms (5.284ms/txin) [3743.97s (31999.76ms/blk)]
    452022-09-25T11:37:01Z     - Index writing: 18.96ms [4.66s (39.87ms/blk)]
    462022-09-25T11:37:01Z BlockChecked: block hash=0000000000000000010329cc09803e11c7b2571d0e2d4165727e07ea23523c98 state=Valid
    472022-09-25T11:37:01Z   - Connect total: 24308.83ms [3749.01s (32042.85ms/blk)]
    482022-09-25T11:37:01Z   - Flush: 6.10ms [1.79s (15.33ms/blk)]
    492022-09-25T11:37:01Z   - Writing chainstate: 0.04ms [0.01s (0.13ms/blk)]
    502022-09-25T11:37:01Z Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current
    512022-09-25T11:37:01Z UpdateTip: new best=0000000000000000010329cc09803e11c7b2571d0e2d4165727e07ea23523c98 height=482679 version=0x20000002 log2_work=87.015821 tx=250623929 date='2017-08-30T18:27:07Z' progress=0.327100 cache=72.2MiB(539731txo)
    522022-09-25T11:37:01Z   - Connect postprocess: 0.28ms [0.06s (0.52ms/blk)]
    532022-09-25T11:37:01Z - Connect block: 24352.69ms [3760.53s (32141.28ms/blk)]
    542022-09-25T11:37:01Z Enqueuing BlockConnected: block hash=0000000000000000010329cc09803e11c7b2571d0e2d4165727e07ea23523c98 block height=482679
    552022-09-25T11:37:01Z Enqueuing UpdatedBlockTip: new block hash=0000000000000000010329cc09803e11c7b2571d0e2d4165727e07ea23523c98 fork block hash=0000000000000000011ebba92f50fec98b6c1d7555cd8c25192f143a65c98111 (in IBD=true)
    562022-09-25T11:37:01Z   - Load block from disk: 37.68ms [9.68s]
    572022-09-25T11:37:01Z     - Sanity checks: 1.17ms [0.31s (2.60ms/blk)]
    582022-09-25T11:37:01Z     - Fork checks: 0.03ms [0.01s (0.07ms/blk)]
    592022-09-25T11:37:17Z       - Connect 2324 transactions: 15448.16ms (6.647ms/tx, 3.478ms/txin) [3759.39s (31859.25ms/blk)]
    602022-09-25T11:37:17Z     - Verify 4442 txins: 15448.25ms (3.478ms/txin) [3759.42s (31859.49ms/blk)]
    612022-09-25T11:37:17Z     - Index writing: 12.54ms [4.68s (39.64ms/blk)]
    622022-09-25T11:37:17Z BlockChecked: block hash=00000000000000000125ab0eb3466934f4b98f2c6dda7ef83ce98ddc85c6ffb9 state=Valid
    632022-09-25T11:37:17Z   - Connect total: 15462.18ms [3764.48s (31902.33ms/blk)]
    642022-09-25T11:37:17Z   - Flush: 15.36ms [1.81s (15.33ms/blk)]
    652022-09-25T11:37:17Z   - Writing chainstate: 0.03ms [0.01s (0.13ms/blk)]
    662022-09-25T11:37:17Z Blockpolicy estimates updated by 0 of 0 block txs, since last block 0 of 0 tracked, mempool map size 0, max target 0 from current
    672022-09-25T11:37:17Z UpdateTip: new best=00000000000000000125ab0eb3466934f4b98f2c6dda7ef83ce98ddc85c6ffb9 height=482680 version=0x20000000 log2_work=87.015856 tx=250626253 date='2017-08-30T18:37:28Z' progress=0.327103 cache=72.6MiB(542964txo)
    682022-09-25T11:37:17Z   - Connect postprocess: 0.32ms [0.06s (0.52ms/blk)]
    692022-09-25T11:37:17Z - Connect block: 15515.56ms [3776.05s (32000.38ms/blk)]
    702022-09-25T11:37:17Z Enqueuing BlockConnected: block hash=00000000000000000125ab0eb3466934f4b98f2c6dda7ef83ce98ddc85c6ffb9 block height=482680
    712022-09-25T11:37:17Z Enqueuing UpdatedBlockTip: new block hash=00000000000000000125ab0eb3466934f4b98f2c6dda7ef83ce98ddc85c6ffb9 fork block hash=0000000000000000010329cc09803e11c7b2571d0e2d4165727e07ea23523c98 (in IBD=true)
    722022-09-25T11:37:17Z   - Load block from disk: 44.31ms [9.73s]
    732022-09-25T11:37:17Z     - Sanity checks: 1.13ms [0.31s (2.59ms/blk)]
    742022-09-25T11:37:17Z     - Fork checks: 0.03ms [0.01s (0.07ms/blk)]
    

14. 
    kord1e commented at 12:56 pm on November 27, 2022: none

    I used the “iotop” utility to check disk usage and I’m seeing constant high disk reads when this problem occurs. 40 to 50 MB/s reads maybe. CPU usage is not very high. This continues for hours and hours.

    Sometimes it downloads 1 GB or so, then this behavior continues again.

    Why does it spend so much time reading from the disk?

    Also, the GUI is often extremely unresponsive when this happens, and has been so for years, but that’s another issue (https://github.com/bitcoin/bitcoin/issues/10504)

15. 
    willcl-ark commented at 10:09 am on November 28, 2022: contributor

    • @kord1e what are your hardware specs? Specifically CPU and HDD.
    • Is your HDD attached via network or as a NAS or anything else non-standard?
    • How much free space does your HDD have as a %?
    • Can you confirm that you only see this behaviour in IBD or also when synced to the tip and when a new block arrives?

    When you say you see a 50MB/s read, is this for a sustained period of time and if so how long roughly? If this is just for a few milliseconds (or a single iotop refresh period, as it doesn’t update live) then this could be the expected speed for your system (reflecting HDD read speed, usually 30 - 150 MB/s).

    Do you have enough RAM on the system to increase the dbcache from 4000 during IBD, as high as you can afford towards its max value of 16384? If you do perhaps you can measure a performance increase. After IBD this option can be removed as this size of dbcache is no longer necessary for performance.

    For reference my 11700k with 970 EVO SSD connects blocks in ~ 30 - 200ms vs 20000 - 70000ms on your system:

    02022-11-28T08:39:15Z [bench]   - Connect total: 187.58ms [28.90s (244.88ms/blk)]
    12022-11-28T08:48:40Z [bench]   - Connect total: 155.08ms [29.05s (244.13ms/blk)]
    22022-11-28T08:50:55Z [bench]   - Connect total: 117.53ms [29.17s (243.07ms/blk)]
    32022-11-28T08:52:50Z [bench]   - Connect total: 74.45ms [29.24s (241.68ms/blk)]
    42022-11-28T08:55:46Z [bench]   - Connect total: 77.34ms [29.32s (240.33ms/blk)]
    52022-11-28T08:56:40Z [bench]   - Connect total: 73.66ms [29.39s (238.97ms/blk)]
    62022-11-28T09:04:31Z [bench]   - Connect total: 72.36ms [29.47s (237.63ms/blk)]
    72022-11-28T09:10:53Z [bench]   - Connect total: 75.09ms [29.54s (236.33ms/blk)]
    82022-11-28T09:18:26Z [bench]   - Connect total: 39.28ms [29.58s (234.77ms/blk)]
    92022-11-28T09:37:31Z [bench]   - Connect total: 69.91ms [29.65s (233.47ms/blk)]
    

    vs

     02022-09-16T20:01:34Z [bench]   - Connect total: 50590.96ms [11477.21s (33363.98ms/blk)]
     12022-09-16T20:01:54Z [bench]   - Connect total: 19201.96ms [11496.41s (33322.93ms/blk)]
     22022-09-16T20:02:16Z [bench]   - Connect total: 22065.72ms [11518.48s (33290.40ms/blk)]
     32022-09-16T20:02:49Z [bench]   - Connect total: 32213.59ms [11550.69s (33287.29ms/blk)]
     42022-09-16T20:03:27Z [bench]   - Connect total: 38662.26ms [11589.35s (33302.74ms/blk)]
     52022-09-16T20:03:54Z [bench]   - Connect total: 26702.07ms [11616.06s (33283.83ms/blk)]
     62022-09-16T20:04:27Z [bench]   - Connect total: 32737.16ms [11648.79s (33282.27ms/blk)]
     72022-09-16T20:04:57Z [bench]   - Connect total: 29466.07ms [11678.26s (33271.39ms/blk)]
     82022-09-16T20:05:26Z [bench]   - Connect total: 28619.46ms [11706.88s (33258.18ms/blk)]
     92022-09-16T20:05:39Z [bench]   - Connect total: 12864.00ms [11719.74s (33200.40ms/blk)]
    102022-09-16T20:06:04Z [bench]   - Connect total: 23847.28ms [11743.59s (33173.98ms/blk)]
    112022-09-16T20:06:25Z [bench]   - Connect total: 21557.35ms [11765.15s (33141.26ms/blk)]
    122022-09-16T20:06:46Z [bench]   - Connect total: 20445.31ms [11785.59s (33105.60ms/blk)]
    132022-09-16T20:07:00Z [bench]   - Connect total: 13537.34ms [11799.13s (33050.78ms/blk)]
    142022-09-16T20:07:24Z [bench]   - Connect total: 23659.23ms [11822.79s (33024.55ms/blk)]
    152022-09-16T20:08:07Z [bench]   - Connect total: 43326.17ms [11866.12s (33053.25ms/blk)]
    162022-09-16T20:08:36Z [bench]   - Connect total: 28623.18ms [11894.74s (33040.94ms/blk)]
    172022-09-16T20:08:56Z [bench]   - Connect total: 19072.78ms [11913.81s (33002.25ms/blk)]
    182022-09-16T20:09:39Z [bench]   - Connect total: 43177.82ms [11956.99s (33030.36ms/blk)]
    192022-09-16T20:10:49Z [bench]   - Connect total: 69207.65ms [12026.20s (33130.02ms/blk)]
    

    I don’t have a spinning disk to test expected performance against myself I’m afraid.

16. 
    kord1e commented at 10:14 am on December 6, 2022: none

    @willcl-ark CPU is a 4-core Xeon about 10 years old, HDD is a 2TB standard HDD with more than 50% free space. Connected via SATA, no network or other slow/non-standard stuff.

    CPU usage stays low when this disk reading is in progress and Bitcoin-Qt doesn’t even seem to use much memory, much less than the 4000 MB in the settings.

    I’m currently syncing, Bitcoin-Qt says it’s 6 weeks behind and it’s doing this disk reading for hours and hours.

    iotop shows constant disk activity about 50 MB/sec, occasionally it may drop to a smaller value but in general this 50 MB/sec activity continues for very long periods of time. I don’t know how iotop measures it, is it average over the screen update period or what. But it’s constantly showing this activity and I can also hear the disk crunching.

    I’m pretty sure it was not at all like this many years ago, I remember using an older and slower laptop with slower HDD for Bitcoin maybe 5 to 7 years ago, no issues, fast syncing. It feels like this issue is getting worse and worse.

17. 
    willcl-ark commented at 2:38 pm on January 26, 2023: contributor

    In my opinion this issue might be considered stale now and could be closed?

    It appears not to have a root cause in the codebase and is likely a function of the hardware/setup being used. Additionally, aside from jianfree, there have been no other reports of this behaviour from users in 4 months.

18. 
    maflcko commented at 2:46 pm on January 26, 2023: member

    Is this still an issue with a recent version of Bitcoin Core? If yes, what are the steps to reproduce?
19. maflcko closed this on Jan 26, 2023

    ---

20. 
    maflcko commented at 2:42 pm on January 30, 2023: member

    Another thing to look out for would be to check if anything is connected over RPC to the node, or if the debug log has any more details with full debug logging enabled (e.g. lock contention).
21. 
    jonatack commented at 5:11 pm on January 30, 2023: contributor

    with full debug logging enabled (e.g. lock contention)

    If useful, the steps to take are described in https://github.com/bitcoin/bitcoin/blob/master/doc/developer-notes.md#debug_lockcontention (and in the debugging section of that doc, in general).

22. 
    popkian commented at 10:58 pm on February 20, 2023: none

    I am having the same exact issue, if anyone has any suggestion on how to solve this would be great.
23. 
    willcl-ark commented at 1:31 pm on February 21, 2023: contributor

    @popkian, see this previous comment on what you can do to help us diagnose the issue.
24. 
    helpau commented at 7:34 pm on November 14, 2023: none

    I found the same problem, and started looking for the causes. I found a large block connection time [bench] - Connect total: 16234.98ms . My configuration: Windows 10 22H2 x64, Bitcoin Core 25.1.0, Xeon E5-2670, 16 GB RAM, 1TB HDD SATA III drive with 64 MB cache, 90% free, NTFS with 4 KB cluster size Bitcoin Core configuration: prune 2 GB, dbcache 12000 MB, -1 threads My steps: 1)Wait for IBD to complete 2)Shut down Bitcoin Core 3)Defragment the disc 4)Turn on Bitcoin Core 5)Wait an hour Disc fragmentation went from 0 to 10%, most of it was chainstate files (over 80% of chainstate files were fragmented). Synchronization speed around 0.04% per hour. slow sync.tar.gz

    

25. 
    helpau commented at 7:40 pm on November 14, 2023: none

    Please reopen the issue, I will try to give logs with lock conflicts later. Probably related #776
26. 
    helpau commented at 8:24 am on November 19, 2023: none

    Here’s what I did to get logs with [lock] entries 1)Downloaded the release 25.1 source code, installed VS 2022 2)Installed qt with the -debug-and-release parameter 3)Installed the dependencies via vcpkg 4)Specified DEBUG_LOCKCONTENTION parameter for libbitcoin_utul project, started Debug solution build, ran bitcoin-qt.exe with -debug=1, didn’t get [lock]’s 5)Tried to add DEBUG_LOCKORDER parameter, but with it the build failed (bug?). If I can’t build the solution, I will try to reproduce the bug in a Linux virtual machine or in WSL.
27. maflcko reopened this on Nov 19, 2023

    ---

28. 
    hebasto commented at 3:06 pm on November 20, 2023: member

    Please reopen the issue, I will try to give logs with lock conflicts later. Probably related #776

    Windows and Fedora, which was mentioned by this issue author, are quite different systems.

    The rule of thumb for Bitcoin Core users on Windows is to add the data and block directories into Windows Security exclusions.

29. 
    maflcko commented at 3:11 pm on November 20, 2023: member

    Windows and Fedora, which was mentioned by this issue author, are quite different systems.

    Ok, closing again. Feel free to file a new issue if this happens again. Make sure to include details, as explained above. You may reference this issue, if you want.

30. maflcko closed this on Nov 20, 2023

    ---

Contributors
kord1e maflcko sipa Jianfree willcl-ark jonatack popkian helpau hebasto

Labels
Questions and Help