ironfish icon indicating copy to clipboard operation
ironfish copied to clipboard

Accounts sync lags Blockchain sync in Ironfish Status - by up to 2000 blocks

Open crProductGuy opened this issue 2 years ago • 2 comments

What happened?

On 0.1.47 (perhaps before, but definitely on that), and on 0.1.49 in the first 24 hours of node runtime, ironfish status -f shows the Accounts block count lagging the Blockchain current height.

Just before upgrading from 1.47 to 1.48/9 my node was 2000 behind in Accounts. After upgrading to 1.49, within 4 hours, the Node itself (Blockchain) had fully sync'd (yay, fast!), and Accounts had caught up by 1000 block to "only" 1000 blocks behind the Blockchain.

But 23 hours later, Accounts is now about 1300 blocks behind Head and Blockchain.

See log output below.

A few other users have noticed this also recently (on 0.1.49).

I believe I'm the first one who reported it in #report-bugs and here in Issues. Jason was aware of my noticing it before the release of Wallet 2.0 and recommended waiting to see if it persisted after it was released. Still present, so reporting it now. He said he'd look into it.


Could this also be responsible for my accounts:balance continuously showing 0 recently?

In mid-late Sept, I had 17. In July I had 24 IRON, but they've all recently disappeared or become "invisible" despite the Node saying Sync'd in Status.

A rescan (without reset) while the node was running restored my balance a couple of weeks ago. Will try a rescan --reset now.

Version

0.1.49

Debug output

Iron Fish version               0.1.49 @ ec57ed3
Iron Fish library               0.0.26 @ ec57ed3
Operating system                Windows_NT x64
CPU model(s)                    AMD Athlon Silver 3050U with Radeon Graphics
CPU threads                     2
RAM total                       5.88 GiB
Heap total                      2.01 GiB
Node version                    v16.16.0
ironfish in PATH                true
Garbage Collector Exposed       false
Telemetry enabled               true
Node name                       ProductGuy
Block graffiti                  ProductGuy

Relevant log output

Version              0.1.49 @ ec57ed3
Node                 STARTED
Node Name            ProductGuy
Block Graffiti       ProductGuy
Memory               Heap: 188.84 MiB -> 260.63 MiB / 2.01 GiB (9.2%), RSS: 1.04 GiB (17.7%), Free: 1.18 GiB
(79.8%)
CPU                  Cores: 2, Current: 159.8%
P2P Network          CONNECTED - In: 75.40 KB/s, Out: 95.24 KB/s, peers 49
Mining               STARTED - 0 miners, 0 mined
Mem Pool             Size: 2565 tx, Bytes: 3.81 MiB
Syncer               SYNCING - 0.02 blocks per seconds, avg time to add block 28293.28 ms
Blockchain           000000000000369477134033bc633ac9d711a397c2c7e036caf7de6a9877ce25 (216117), Since HEAD: 5m
47s (SYNCED)
Accounts             0000000000000efd2c0c894119c3113a9d2131bb2d9cbf080a458a92c323e7ae (214820)
Telemetry            STARTED - 35900 <- 154 pending
Workers              STARTED - 511 -> 1 / 1 - 4.01 jobs Δ, 16.29 jobs/s

Graffiti

ProductGuy

crProductGuy avatar Oct 06 '22 17:10 crProductGuy

Started a node over the past few days. Used a snapshot to get my block count to around 86%. Used the snapshot last night to get my blocks all synced up. However my account blocks were lagging. I was at ~55K and was adding about 10 blocks/minute. Currently running accounts:rescan --reset which is going faster, but still slow. Generally averaging 3-5 blocks/second. Running on 1.49

airj1012 avatar Oct 06 '22 18:10 airj1012

Found how to fix this on my little 2-core / 2-thread Athlon Silver.

Ironfish Config change: ironfish config:set nodeWorkersMax 2

Note that this exactly matches my core & hyperthread count: this is a non-hyperthreaded CPU, so it can only do 2 things at once.

That completely fixes the Account lag on v0.1.49!

This still leaves the question of "why" this makes a difference.

I recommend a doc enhancement in the Config section and maybe the Getting Started guide:

"Set nodeWorkersMax to no more than the number of hyperthreads on your CPU.

Consider limiting it to the number of physical cores. The default value is 6. Lowering it for low-core CPUs seems to prevent Accounts block height from falling behind Blockchain height in ironfish status -f. "

This may have additional benefit of more accurate ironfish accounts:balance and a higher likelihood of being able to reliably make deposits, but I'm speculating now.

Details:

Now ironfish status -f shows Accounts Block Height = Blockchain Height, or sometimes 1 less. But it's not dropping behind after the node has been running for a few hours, like it was even with nodeWorkersMax 5 yesterday, when it got as much as 400 blocks behind again, or like when it was 10, and Accounts was as much as 2000 behind the Blockchain block height while syncing or sync'd.

I had nodeWorkersMax set to 10 for a long time over the summer, as an experiment to see if more workers would soak up more idle CPU time in between the 100% periods. Apparently not, and apparently it had a bad effect of allowing the "account-management workers" to lose out on their fair and necessary share of CPU cycles.

I had an intuition to pull it down to 5 on Friday, which helped. 2 is even better and "fixes the lag" completely!

crProductGuy avatar Oct 09 '22 23:10 crProductGuy

Looking really good in V0.1.51.

I say close it as Fixed!

Accounts track Blockchain very well now. Longest lag I've seen in the last week is 12 blocks behind, which is almost nothing, and catches up pretty fast.

I've tried both nodeWorkersMax = 2 (to match my 2-core 2-thread CPU as well as increasing it to 6 for a couple of days, and in almost all cases, Accounts is current or maybe 1 block behind.

I also don't have to do "tricks" like running a low-priority dummy compute task to get my CPU utilization up enough to get full boost clockrate of 3.2 GHz.

Syncing is very fast now, waaaayyy better on 1.51. Well done!

crProductGuy avatar Nov 11 '22 20:11 crProductGuy

Solved per my experience! Thanks, great work Dev Team! 1.51 is awesome and a huge leap!

crProductGuy avatar Nov 11 '22 22:11 crProductGuy

Glad to hear it!

danield9tqh avatar Nov 12 '22 04:11 danield9tqh