Lnd: Slow startup times

[hsjoberg]

Background

Hi everyone.
Since recent commits in master, lnd startup time is very slow compared to before.
This issue appears for me compiling lnd to Android (using the in-mem gRPC), but the same probably applies to just running it on a computer.

I'm compiling with go 1.13 and latest gomobile.
I've tested it on 2 different computers and I've tried on an isolated android app running only lnd.

I did some simple benchmark testing giving the following results:

For starting up + unlock wallet, the startup time before was around:
1.03-4s (avg 1.13s)

Now on latest master, the startup times is around:
3.59-10.71s (avg 5.03)

These high startup times basically make mobile wallets infeasible.
I've seen it going even higher than 10.71s.

Your environment

• lnd master (as of writing 7fcac54)
• Linux compiling aar file for Android
• go 1.13 and latest gomobile

Steps to reproduce

Compile latest master, run lnd on testnet/mainnet with Neutrino.

The last known commit I'm absolutely certain works* without the slowdown regression is f60e4b1e14547a76747a012cff663e828c9da313

*) Unfortunately unless you have it in your go cache, compiling lnd at that commit doesn't seem to work anymore because of some revision issue with btcwallet, giving the following error when compiling:

github.com/btcsuite/btcwallet@v0.0.0-20180904010540-284e2e0e696e33d5be388f7f3d9a26db703e0c06: invalid pseudo-version: revision is longer than canonical (284e2e0e696e)

I've been conducting my own testing and I have found out that one of the following dependencies causes the regression:
btcsuite/btcwallet or lightninglabs/neutrino.

These two commits caused the regression

According to my tests, these two commits caused the regression:
5fc003d6 and 5ecde6d5.

5fc003d6 updates btcd, neutrino and btcwallet.
5ecde6d5 makes use of new neutrino APIs.

Presumably there's a regression in neutrino.

[halseth]

Seems to be happening because of freelist disable in btcwallet: https://github.com/btcsuite/btcwallet/commit/e809748b1e5563ef90ec04246762e7b67f283706

[hsjoberg]

Yes, as discussed on the lnd slack, reverting btcsuite/btcwallet@e809748 puts startup times back to normal.

[halseth]

I did some testing with this, and it is definitely slower with disabled free list sync. A run with the freelist sync disabled (current master) looks like this:

2019-09-30 13:35:29.322 [INF] CHDB: Checking for schema update: latest_version=11, min_upgrade_version=9, db_version=11
2019-09-30 13:35:31.318 [INF] BTCN: Loaded 110 addresses from file '/root/.lnd/data/chain/bitcoin/testnet/peers.json'

while reverting the above mentioned btcwallet commit results in runs like this:

2019-09-30 13:37:41.144 [INF] CHDB: Checking for schema update: latest_version=11, min_upgrade_version=9, db_version=11
2019-09-30 13:37:41.165 [INF] BTCN: Loaded 110 addresses from file '/root/.lnd/data/chain/bitcoin/testnet/peers.json'

So opening the database goes from a few milliseconds to ~2 seconds in my case (testing on $5 DigitalOcean box), so I can definitely see it being a problem on slower hardware.

@hsjoberg Do you consistently get increased startup (look at the two log lines I posted above) up to 10s? I experienced this on first restart after switching between freelist/nofreelist, but next restart after the db was updated to the new setting was usually faster for me.

[halseth]

Also inspected the logs from Lightning App running on Pixel 2 XL, seeing about 5s to open db:

2019-09-30 13:48:02.290 [INF] CHDB: Checking for schema update: latest_version=11, min_upgrade_version=9, db_version=11
2019-09-30 13:48:07.008 [INF] BTCN: Loaded 112 addresses from file '/data/user/0/engineering.lightning.LightningMainnet/files/data/chain/bitcoin/mainnet/peers.json'

[hsjoberg]

Do you consistently get increased startup (look at the two log lines I posted above) up to 10s? I experienced this on first restart after switching between freelist/nofreelist, but next restart after the db was updated to the new setting was usually faster for me.

@halseth Yes I consistently* get increased startup time. I haven't seen it go down to levels it was before (~1.5s).

*) It is not always up to 10s though, it seems like every time I restart my phone (OnePlus 6), the startup time will be around 8s (for mainnet, ~12s testnet) for some reason.
After that for the next startup, it goes down to around 2.5s mainnet and 4s testnet.
But I've also seen it going up to 10s occasionally after that as well, seemingly at random.

[cfromknecht]

@hsjoberg are you seeing this with a new database or with an existing wallet?

[hsjoberg]

@cfromknecht I started noticing it on an existing wallet, but I've checked and it happens from a complete clean install as well with no previous data.

[halseth]

Immediately after restart of my DO node, opening the db goes to ~9s. On the phone I couldn't see this jump after a restart.

[halseth]

compacting the db didn't make a difference either.

[halseth]

Most of the increased startup time comes from opening the neutrino db, according to my testing.

[Crypt-iQ]

@hsjoberg Could you get a cpu & heap profile?

[hsjoberg]

@Crypt-iQ I have mostly tested this on Android (compiled with gomobile) so far, where profiling probably will be more difficult.

I'll set up a proper dev environment for Go when I get my new computer (I not so familiar with Go yet btw).