Recovery from seed becomes significantly slow after a while, until a restart to the App

[Drazen-V]

Description

In the last couple of days I recovered my wallet from seed on two different computers, one running Ubuntu the other Win 10. Recovery starting date set to early-mid June 2019. The recovery starts quite fast for about the first 20%, then a small degradation of the syncing/recovery process begins. When the recovery percentage bar (equivalently the number of verified blocks) gets to 70-85% it becomes super slow.
A restart to the app makes the recovery process super fast again, though degradation also happens (and quite quickly after the restart; at one occasion I had to restart it twice during the same recovery process). I am not sure if the App is designed to support restarts, but it seems to work smoothly.

Version

V 1.4..2

Steps to reproduce

Choose recover wallet from seed, set date to early 2019, and wait...

Expected behaviour

The App should run the recovery process at the same pace (from a certain block height), or at least the pace that it gets to after a restart.

Actual behaviour

The recovery process degrades with time.

Device or machine

Win 10 and Ubuntu 20

[ripcurlx]

@oscarguindzberg Is this an expected behavior?

[wiz]

@m52go didn't you have this issue before segwit was added?

[m52go]

I did, and it fixed itself...I don't recall doing anything differently.

[oscarguindzberg]

It would be good to know whether this problem existed in 1.3.9 already. If anyone wants to try that out, I would suggest starting in parallel 2 bisq instances (one running 1.3.9 and the other running 1.4.2) on the same computer and running the recover from seed (use the same seed with the same creation date) on both instances at the same time.

Things to look at are how long they take to complete and how much cpu/ram they use.

[ghost]

I have performed the simultaneous sync test: v1.3.7 synced from seed in just under 1 hour. v1.5.0 slowed down after 20%, its log status messages said "not stalled", after an hour they said "stall disabled", at this point it was showing 50% complete and receiving 1 block per 10 seconds. I stopped and restarted it, and it picked up speed again. At this point I restarted 1.3.7 syncing fresh from seed again - it completed in 35 minutes while v1.5.0 still remained syncing, reporting "stall disabled" and receiving 1 block per 10 seconds.

[edit] The wallet start date used for syncing was 1/1/2020.
Giving up on the resync of 1.5.0 now (5.5 hours).
Memory usage does not look unusual for either version:
v1.3.7: bisq.desktop.app.BisqApp: System load: Memory (MB): 642 / No. of threads: 81
v1.5.0: bisq.common.util.Profiler: System report: Used memory: 786 MB; Free memory: 164 MB; Total memory: 950 MB; No. of threads: 69

[ghost]

Ran the same simultaneous sync with v1.4.2:

• v1.3.7 : 55 minutes, sync complete.
• v1.4.2 : 1 hour 20 minutes, 51% progress, "stall disabled", 0 blocks/second.

v1.3.7: System load: Memory (MB): 561 / No. of threads: 87
v1.4.2: System report: Used memory: 511 MB; Free memory: 513 MB; Total memory: 1024 MB; No. of threads: 68

[oscarguindzberg]

@jmacxx

• How many txs the wallet you are restoring has?
• Could you compare 1.3.9 vs 1.4.2?
• Are you using the default btc nodes and tor?
• the problem is synchronizing bitcoin blockchain or synchronizing the DAO?

thanks

[ghost]

• The wallet contains about 200 transactions.
• Comparing 1.3.9 vs 1.4.2 right now, they have not finished but I'm certain from watching the progress that it will be the same result as above with 1.3.7 vs 1.4.2. (Already 1.3.9 is 2x the progress of 1.4.2 after 30 minutes).
• Yes, using all the defaults, out of the box fresh data directory installs of bisq.
• The problem is synchronizing the bitcoin blockchain.

Some observations from watching the logs side-by-side:

• 1.3.9 does its 3 allotment of stall disconnects in the first couple of minutes.
• 1.4.2 starts off fast but soon the number of blocks received per second drops to a crawl -- however it does not stall/disconnect quickly like 1.3.9 does.
• 1.3.9 seems to maintain a steady throughput of 20 blocks per sec quite consistently.
• 1.4.2 slows to a crawl reporting 0 blocks per sec consistently, occasionally 1 block per sec.
• 1.3.9 stall threshold = 1.56 KB/sec
• 1.4.2 stall threshold = 0.78 KB/sec
• Not a memory or CPU issue, its something like a timing issue to do with the way the requests are being made seems to cause the bitcoin nodes to be non-cooperative. That's my hunch. Throttling as @cbeams mentions here.

[oscarguindzberg]

Do you get the same problem if you use a random seed with no txs associated to it and the same creation date?

…

On Thu, Nov 19, 2020, 9:47 PM James Cox ***@***.***> wrote: - The wallet contains about 200 transactions. - Comparing 1.3.9 vs 1.4.2 right now, they have not finished but I'm certain from watching the progress that it will be the same result as above with 1.3.7 vs 1.4.2. (Already 1.3.9 is 2x the progress of 1.4.2 after 30 minutes). - Yes, using all the defaults, out of the box fresh data directory installs of bisq. - The problem is synchronizing the bitcoin blockchain. Some observations from watching the logs side-by-side: - 1.3.9 does its 3 allotment of stall disconnects in the first couple of minutes. - 1.4.2 starts off fast but soon the number of blocks received per second drops to a crawl -- however it does not stall/disconnect quickly like 1.3.9 does. - 1.3.9 seems to maintain a steady throughput of 20 blocks per sec quite consistently. - 1.4.2 slows to a crawl reporting 0 blocks per sec consistently, occasionally 1 block per sec. - 1.3.9 stall threshold = 1.56 KB/sec - 1.4.2 stall threshold = 0.78 KB/sec - Not a memory or CPU issue, its something like a timing issue to do with the way the requests are being made seems to cause the bitcoin nodes to be non-cooperative. That's my hunch. Throttling as @cbeams <https://github.com/cbeams> mentions here <#4778>. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#4807 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAIXSLDPTUZ7UANVNNWXGPLSQW4AZANCNFSM4TVUCIGQ> .

[ghost]

Yes. Random seed: 1.3.9 completed in 37 minutes. 1.4.2 only at 38% after 1 hour.

[Drazen-V]

1. While already reported here, allow me to add that on my examination of this issue, I tried 3 different seeds, one for a wallet with a handful of transactions, and they all behaved the same.

Addressing @jmacxx's hunch, I have also been thinking in this direction, perhaps there was an overload on the connected peers, and they refuse the connection, but the displayed number of connected peers was stable.

I had a look at the log files, and I see a lot of conflict messages:
[JavaFX Application Thread] WARN b.c.d.m.DaoStateMonitoringService: Conflict with seed nodes: We received a block hash from peer [peer].onion:9999 which conflicts with our block hash.
Ranging over these messages, it is across different peers (not always the same peer). It shows on both of my machines.

I don't a different Bisq version to check this out, but it is worth checking whether this is the source of the problem.

2. During the week I realised that in on of my recovery attempts, the wallet balance and accounting went totally mad, resulting in a wrong balance, which was probably caused by the displayed transaction amount, for some (but not all) transactions, being totally different from the actual amounts, as well as some transactions were missing from the wallet.

I have the log files and I currently try to examine this issue.
To be clear, I see in the logs a tx id and the amount it received/sent, which is just not the real amount for this transaction.

I reported earlier that several times I restarted the App during the recovery process, though this does not seem to be the case here (seen from the log timestamps), in particular because the issue seems to be in reading values from a single tx, not an accumulated values across time.

For privacy concerns, I will (try to) do some research on my own. Would be good to know if you would like to have details under this issue, or to open a new issue.

[oscarguindzberg]

@jmacxx thanks for the info. I will try a few things on my side and I will post here when I have news.

[Drazen-V]

I dug a bit deeper into my logs.

I see the log output:
14:42:13.901 [BlockingClient network thread for c6ac4jdfyeiakex2.onion:8333] INFO o.b.core.Peer: Bloom filter exhausted whilst processing block 0000000000000000000051898eb1f0f4dc69a34e1f18ee3c2044b31a24004c17, discarding

followed by several of these:
14:42:13.901 [PeerGroup Thread] INFO o.b.core.Peer: Peer{[2pj2o2mrawj7yotg.onion]:8333, version=70016, subVer=/Satoshi:0.20.1/, services=1037 (NETWORK, BLOOM, WITNESS, NETWORK_LIMITED), time=2020-11-13 14:38:07, height=656745}: Sending Bloom filter and querying mempool

[Note the block height, 656745, which seems to be the actual tip at the time of the recovery, while the syncing process is at block height 621705, as I see the message:
14:42:14.405 [JavaFX Application Thread] INFO b.c.d.n.l.LiteNode: New block at height 621705 from bsqWalletService ]

Afterwards, I see plenty of these:
14:42:13.935 [BlockingClient network thread for c6ac4jdfyeiakex2.onion:8333] INFO o.b.core.Peer: Discarding block 00000000000000000002b441b5ed88807124e0a46f4df0fa9653a535153a1878 because we're still waiting for a fresh filter
....
14:42:21.734 [BlockingClient network thread for c6ac4jdfyeiakex2.onion:8333] INFO o.b.core.Peer: Discarding block 000000000000000000050c06c99eea9aaed654a68c5191300c8de74c2b469d0b because we're still waiting for a fresh filter
14:42:21.773 [PeerGroup Thread] INFO o.b.c.PeerGroup$ChainDownloadSpeedCalculator: 0 blocks/sec, 0 tx/sec, 0 pre-filtered tx/sec, avg/last 4.37/0.00 kilobytes per sec, chain/common height 621705/656745, not stalled (threshold <0.78 KB/sec for 10 seconds)
14:42:22.156 [BlockingClient network thread for c6ac4jdfyeiakex2.onion:8333] INFO o.b.core.Peer: Restarting chain download
14:42:22.404 [BlockingClient network thread for c6ac4jdfyeiakex2.onion:8333] WARN o.b.c.AbstractBlockChain: Block does not connect: 0000000000000000000067e6d980f1618847efa149882748989dc060a58fc02f prev 0000000000000000000518e169b29521f39bffe2a667b7fe8468e5e3eb4be2c2

In between, this kind of messages also appear several times:
14:42:16.956 [Wallet autosave thread] INFO o.b.w.WalletFiles: Background saving wallet; last seen block is height 621705, date 2020-03-15T09:26:32Z, hash 000000000000000000070374e624e2ee04cf56515d80d5b484ca9a1ab7472e70

And finally it progresses into the next block:
14:42:23.728 [JavaFX Application Thread] INFO b.c.d.n.l.LiteNode: New block at height 621706 from bsqWalletService

Note how long - 8 seconds - it is stuck on one block, with height 621705.

I have seen this behavior at least at 3 different times in my logs -- for all of them, my wallet actually had a transaction in the following block; in the above example I have an outgoing tx in block height 621706.

Since we see the same issue with wallets with no transactions, it won't explain the entire behaviour, but it may explain some.

[oscarguindzberg]

@jmacxx @Drazen-V could you share with me the logs of 1.4.2 where sync gets too slow?
Options:

• send me an email (find my email address on my github profile)
• I am oscarguindzberg2 on keybase
• upload it somewhere and post the link here

[ghost]

Emailed it to you.

[oscarguindzberg]

I found something. Created an issue on bitcoinj upstream bitcoinj/bitcoinj#2069
Working on a solution.

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

[stale]

This issue has been automatically closed because of inactivity. Feel free to reopen it if you think it is still relevant.