unexplainable slow startup pause

[blckbx]

Hi there,

first things first, the setup:

• lnd-0.17.1-beta
• bitcoind 25.1
• Ubuntu 22.04.3 LTS
• Linux 5.15.0-88-generic 98-Ubuntu SMP Mon Oct 2 15:18:56 UTC 2023 x86_64 GNU/Linux
• Postgresql 14

Since quite a while ago (I can't really tell when this started to show up), I've experienced longer startup times. As far as I can remember this wasn't an issue with bbolt db and also on a new node with PostgreSQL (at least in the beginning). There is an unexplainable pause of 4 and a half-something minutes visible in lnd.log that seems off to me:

2023-11-14 13:10:40.459 [INF] LNWL: Started rescan from block 000000000000000000030499e05ce007819dd6ef62886d2396a9b4b7a2d0a4b3 (height 816730) for 521 addresses
2023-11-14 13:10:40.467 [INF] LNWL: Catching up block hashes to height 816730, this might take a while
2023-11-14 13:10:40.468 [INF] LNWL: Done catching up block hashes
2023-11-14 13:10:40.468 [INF] LNWL: Finished rescan for 521 addresses (synced to block 000000000000000000030499e05ce007819dd6ef62886d2396a9b4b7a2d0a4b3, height 816730)
...
pause of 4+ minutes with occasional rpc errors "rpc server is in process of starting up"
....
2023-11-14 13:15:07.101 [INF] ATPL: Instantiating autopilot with active=false, max_channels=5, allocation=0.600000, min_chan_size=20000, max_chan_size=16777215, private=false, min_confs=1, conf_target=3
2023-11-14 13:15:07.103 [INF] LTND: Systemd was notified about our readiness
2023-11-14 13:15:07.104 [INF] LTND: Waiting for chain backend to finish sync, start_height=816730
2023-11-14 13:15:07.107 [INF] LTND: Chain backend is fully synced (end_height=816730)!
2023-11-14 13:15:07.107 [INF] NANN: HostAnnouncer starting
2023-11-14 13:15:07.107 [WRN] HLCK: check: disk space configured with 0 attempts, skipping it
2023-11-14 13:15:07.107 [WRN] HLCK: check: tls configured with 0 attempts, skipping it
2023-11-14 13:15:07.107 [INF] LNWL: SigPool starting
2023-11-14 13:15:07.113 [INF] CHNF: ChannelNotifier starting
2023-11-14 13:15:07.113 [INF] PRNF: PeerNotifier starting
2023-11-14 13:15:07.113 [INF] HSWC: HtlcNotifier starting

I captured two pprof goroutine dumps (debug=0 and debug=2) for further investigation:
goroutines.tar.gz

Thanks in advance for any hints on how to make restarts fast again.

[blckbx]

Probably related issue: #6646

[blckbx]

I could pin it down to wtclient.
Running wtclient.active=false removes this pause completely.

[ellemouton]

@blckbx - does the issue re-appear after starting with wtclient.active=true again?
just want to make 100% sure that it is wtclient related cause I dont think the wtclient should affect LND startup

[ellemouton]

and if it does re-appear, could you maybe post the logs prefixed with [WTCL] so that we can see if there is anything fishy there?

[blckbx]

@blckbx - does the issue re-appear after starting with wtclient.active=true again? just want to make 100% sure that it is wtclient related cause I dont think the wtclient should affect LND startup

Did some more tests. The pause reappears while a watchtower is actively connected. wtclient.active=true without an active watchtower doesn't pause startup. Debug level on WTCL does not give more infos, here's all there is:

2023-11-22 14:09:11.567 [INF] WTCL: (legacy) Using private watchtower XXX, offering policy (blob-type=10 max-updates=1024 reward-rate=0 sweep-fee-rate=75000)
2023-11-22 14:09:19.699 [ERR] RPCS: [/walletrpc.WalletKit/DeriveKey]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-11-22 14:09:19.708 [ERR] RPCS: [/lnrpc.Lightning/GetInfo]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-11-22 14:09:22.192 [ERR] RPCS: [/lnrpc.Lightning/PendingChannels]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-11-22 14:12:21.564 [ERR] RPCS: [/lnrpc.Lightning/GetInfo]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-11-22 14:12:21.566 [ERR] RPCS: [/walletrpc.WalletKit/DeriveKey]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-11-22 14:12:21.568 [ERR] RPCS: [/lnrpc.Lightning/GetInfo]: the RPC server is in the process of starting up, but not yet ready to accept calls
2023-11-22 14:13:38.009 [INF] WTCL: (anchor) Using private watchtower XXX, offering policy (blob-type=110 max-updates=1024 reward-rate=0 sweep-fee-rate=75000)

[ellemouton]

also, do you have an idea of how many watchtower sessions you have?

[blckbx]

the logs appear right after start up or only after the long wait?

those logs appear after the pause.

also, do you have an idea of how many watchtower sessions you have?

            "active_session_candidate":  true,
            "num_sessions":  9156,
            "sessions":  [],
            "session_info":  [
                {
                    "active_session_candidate":  true,
                    "num_sessions":  9156,
                    "sessions":  [],
                    "policy_type":  "ANCHOR"
                },
                {
                    "active_session_candidate":  true,
                    "num_sessions":  739,
                    "sessions":  [],
                    "policy_type":  "LEGACY"
                }
            ]

and also 6203 sessions from an old, borked WT connection LND is trying to remove (after the pause) but failing

[ERR] WTCL: (legacy) error deleting session 03324e39a28231524f55f51d8140ce50554382662eaed3a15bf750aa4fa37a260f from tower: failed to dial tower(YYY) at any available addresses

which I cannot get rid of if not truncating towerclientdb_kv entirely (I guess).

[ellemouton]

alright cool yeah then the issue is the slow start up of the tower client due to the number of sessions.

I'll dig into this tomorrow to see if there is something we can do to improve the performance here 👍 thanks for reporting this!

[blckbx]

Thanks for looking into this, Elle! 🚀

[ellemouton]

opened an issue to track this: #8221

1st PR incoming asap

[ellemouton]

Hi @blckbx - just letting you know that #8222 has been merged. So once that is included in a release then: when you start LND with wtclient active, the very very first time your startup, it will be just as slow since it is now doing a migration to make the slow query fast in future. Then once that first start up is over, any start up after that should be much much faster again

[blckbx]

Thanks so much, Elle! I'm looking forward to this.