Core 0.18.0 occasionally semi-stalling during IBD

[jnano]

I'm encountering IBD getting semi-stuck, without any errors in the log.

It's something I've noticed a few times in the past, and it was usually resolved by quitting and restarting Core.

But now that doesn't help. I'm hitting consecutive cases where Core just sits idle 10-15 minutes, downloading continuously at 150KB/sec (slow for normal sync), but with practically no CPU usage, no disk I/O except occasional flushing (I'm guessing), and no special log messages.

Running v0.18.0 on Windows, pruned mode. The first time I noticed this behavior now was after block 561672. Don't know if that's significant.

Here's Core's CPU and disk I/O graph for about 10 minutes:

[jackg]

What's in the log? Is it just doing nothing?

You could probably try deleting the last block if it is just idling and doing nothing.

[jnano]

Nothing special in the log. It looks like a normal IBD, except that some blocks take 1 minute or so. It could be back to normal syncing for a bit, then back to waiting.

Network Traffic tab (faster than the idling before I restarted, slower than usual, but continuous):


CPU and disk I/O during the above transfer graph:


A bit of the log:

Code:

2019-06-25T19:44:55Z UpdateTip: new best=000000000000000000217676b59165f3374cc14e2e37a28697fdb640de375a40 height=562185 version=0x20000000 log2_work=90.326807 tx=381070270 date='2019-02-08T18:50:35Z' progress=0.897254 cache=47.6MiB(361000txo)
2019-06-25T19:44:56Z UpdateTip: new best=0000000000000000001a85df8c4a78199a550ce73a100384f28827d7cb60f989 height=562186 version=0x20000000 log2_work=90.326831 tx=381071466 date='2019-02-08T18:50:53Z' progress=0.897257 cache=48.1MiB(365061txo)
2019-06-25T19:44:57Z UpdateTip: new best=00000000000000000015d468c15f436af4645c3001cd4ee69ea218f746755596 height=562187 version=0x3fffe000 log2_work=90.326854 tx=381073901 date='2019-02-08T19:01:08Z' progress=0.897263 cache=48.5MiB(369080txo)
2019-06-25T19:44:57Z UpdateTip: new best=000000000000000000062a22c6b9b74328dcbabee23748c6979fbb8d16c29d1e height=562188 version=0x20000000 log2_work=90.326877 tx=381076875 date='2019-02-08T19:14:00Z' progress=0.897270 cache=49.1MiB(373603txo)
2019-06-25T19:44:57Z UpdateTip: new best=00000000000000000028271c0e727d4dce8eada472be9e1084ddb427c00f794c height=562189 version=0x20000000 log2_work=90.3269 tx=381080072 date='2019-02-08T19:34:47Z' progress=0.897278 cache=49.7MiB(378699txo)
2019-06-25T19:44:58Z UpdateTip: new best=00000000000000000028372fa021e5a29c7f1f55bccd1c7f334d00fb6c2e7b43 height=562190 version=0x2fff4000 log2_work=90.326923 tx=381083063 date='2019-02-08T19:58:13Z' progress=0.897285 cache=50.1MiB(381898txo)
2019-06-25T19:44:58Z UpdateTip: new best=00000000000000000012d880afc8da50e195958dbb2795e3c73253f1687e1af2 height=562191 version=0x20000000 log2_work=90.326947 tx=381085440 date='2019-02-08T20:04:44Z' progress=0.897290 cache=50.6MiB(385973txo)
2019-06-25T19:44:59Z Pre-allocating up to position 0xf00000 in rev01521.dat
2019-06-25T19:44:59Z UpdateTip: new best=0000000000000000001ea068fe7ac7837632ef3c57c7b04c52f1393b5c10ba9d height=562192 version=0x20800000 log2_work=90.32697 tx=381087581 date='2019-02-08T20:15:02Z' progress=0.897295 cache=51.2MiB(390759txo)
2019-06-25T19:44:59Z UpdateTip: new best=00000000000000000008a4be49799ee5066ff0482e9005ec614cbca6cb53693d height=562193 version=0x20000000 log2_work=90.326993 tx=381090100 date='2019-02-08T20:15:49Z' progress=0.897301 cache=51.6MiB(393946txo)
2019-06-25T19:44:59Z Leaving block file 1523: CBlockFileInfo(blocks=137, size=134014563, heights=562154...562572, time=2019-02-08...2019-02-11)
2019-06-25T19:45:00Z Pre-allocating up to position 0x1000000 in blk01524.dat
2019-06-25T19:45:31Z Pre-allocating up to position 0x2000000 in blk01524.dat
2019-06-25T19:45:54Z Pre-allocating up to position 0x100000 in rev01524.dat
2019-06-25T19:45:54Z UpdateTip: new best=000000000000000000004e84053d492c86458ccf032cef77e3eb1fc3677763cf height=562194 version=0x20c00000 log2_work=90.327016 tx=381092733 date='2019-02-08T20:29:44Z' progress=0.897307 cache=52.2MiB(398800txo)
2019-06-25T19:46:15Z Pre-allocating up to position 0x3000000 in blk01524.dat
2019-06-25T19:46:51Z UpdateTip: new best=00000000000000000018ecafe45151df9fe0fc4e0c40206019f13e3d2eca9075 height=562195 version=0x20000000 log2_work=90.327039 tx=381095681 date='2019-02-08T20:43:04Z' progress=0.897313 cache=52.7MiB(402916txo)
2019-06-25T19:46:51Z Pre-allocating up to position 0x4000000 in blk01524.dat
2019-06-25T19:47:35Z Pre-allocating up to position 0x5000000 in blk01524.dat
2019-06-25T19:47:46Z UpdateTip: new best=0000000000000000002b737bca3fbd0dcc307095319e3145e0d5b3fa53efc800 height=562196 version=0x20000000 log2_work=90.327063 tx=381098652 date='2019-02-08T21:15:56Z' progress=0.897320 cache=53.2MiB(407195txo)
2019-06-25T19:48:16Z Pre-allocating up to position 0x6000000 in blk01524.dat
2019-06-25T19:48:17Z Prune: UnlinkPrunedFiles deleted blk/rev (01514)
2019-06-25T19:48:17Z Prune: UnlinkPrunedFiles deleted blk/rev (01515)
2019-06-25T19:48:44Z UpdateTip: new best=00000000000000000025d5b35e578d8eeb291f2ade6d024846f2c6aa37d6b6e9 height=562197 version=0x20000000 log2_work=90.327086 tx=381101968 date='2019-02-08T21:20:25Z' progress=0.897327 cache=4.9MiB(12233txo)
2019-06-25T19:48:45Z UpdateTip: new best=0000000000000000001193a93b013cfa0ebd1051ef9d3c70cd9eda952b3dbb87 height=562198 version=0x3fffe000 log2_work=90.327109 tx=381103904 date='2019-02-08T21:23:29Z' progress=0.897332 cache=6.0MiB(21515txo)
2019-06-25T19:48:52Z Pre-allocating up to position 0x7000000 in blk01524.dat
2019-06-25T19:49:37Z Pre-allocating up to position 0x8000000 in blk01524.dat
2019-06-25T19:49:51Z UpdateTip: new best=000000000000000000274781bff23556d78d774739b12d4cb72da89af277b41d height=562199 version=0x20000000 log2_work=90.327132 tx=381106223 date='2019-02-08T21:30:01Z' progress=0.897337 cache=7.1MiB(30108txo)

[jackg]

It might just be an instability of either your hardware or Internet connection. If its something that's heppened more recently, I'd just ignore it and see if time fixes it. Since it's a prunes node, deleting the last block will probably cause more damage (afaik).

[jnano]

There isn't anything special or taxing running on the computer, so I don't think it could be another program interfering.
The connection is fine too. In the last graph above there's constant downloading at 400KB/s, so I thought an expected processing rate of one block per 3-4 seconds.

Anyway, now, after a few more minutes, it suddenly unclogged itself. At least partially. Compare the right side of the graphs (normal IBD) to the left side (semi-stuck IBD).

CPU/disk (click to expand):


Network:

[jackg]

It might have been an upgrade in the operating system. Or a sort out of something... If you have AV that can sometimes cause an issue with stuff too and it might not use much cpu power but it might use it for a while if it tries to quarenteen something...

[jnano]

There was no high CPU or disk activity from other software. I don't use an AV in the background, nor automatic OS updates.

Just another mystery in Core's not always logical behavior.

Anyway, thanks!

[jnano]

It's unlikely that all 8 peers are stalling at the same time, but I'll check it in more detail when I get time to analyze the log.

And the network graph did show activity. Slower, but enough for a block every few seconds, rather than the one roughly per minute it was doing.