v24.08 JSON-RPC calls are 10x slower vs v24.05

Impa10r commented 2 months ago

I have a testnode with only 3 channels and 5 rebalances between two of them. Calling listhtlcs in a loop for each channel used to take 200 ms, now 2 sec. I have to do this every time user refreshes to track balance changes. This was too slow already, now completely unsustainable for a production node.

listhtlcs cannot be polled incrementally like listforwards, and there are no hooks or subscriptions to monitor sent payments without invoices. I am stuck ((

I don't ask to poll the database faster, I ask for subscription to outbound HTLCs event.

Edit: I use glightning in Go. All API endpoints seem very slow, so actually I do ask to fix that.

`getinfo` output

24.08 Ubuntu-22.04

Impa10r commented 2 months ago

Update.

24.08 also does not shutdown cleanly and causes Ubutnu to hang on shutdown. In short: a disaster release!

Sep  4 13:53:58 vlad-VirtualBox systemd[1]: Stopping Core Lightning daemon...
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Deactivated successfully.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18447 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18472 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18539 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18564 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18590 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18614 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18615 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18639 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18662 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18663 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18784 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18851 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18856 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18936 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18959 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 18982 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19006 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19007 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19064 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19089 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19090 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19181 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19270 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19274 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19343 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19365 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19366 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19417 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19441 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19628 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19739 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 19784 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 29117 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 29243 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 29318 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 29377 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 29402 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 29425 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 29483 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 29640 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 29656 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 29745 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 29863 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 29993 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 30607 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 40975 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41065 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41069 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41130 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41155 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41157 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41239 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41380 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41417 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41437 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41438 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41498 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41606 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41622 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41739 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41760 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41761 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41787 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 41857 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 52016 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 52038 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 52041 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 52100 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 52300 (lightning_conne) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 52383 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 52497 (lightning_gossi) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 99981 (lightning_hsmd) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 139787 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 140812 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 140893 (peerswap) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 140947 (bcli) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 140948 (commando) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 140949 (fetchinvoice) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 140950 (funder) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 140951 (topology) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 140952 (keysend) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 140953 (offers) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 140954 (pay) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 140956 (txprepare) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Unit process 140957 (cln-renepay) remains running after unit stopped.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: Stopped Core Lightning daemon.
Sep  4 13:53:59 vlad-VirtualBox systemd[1]: lightningd.service: Consumed 37.782s CPU time.

Rolling back to 24.05 is not possible:

**BROKEN** plugin-bookkeeper: Refusing to migrate down from version 17 to 15

Impa10r commented 2 months ago

Update 2. After unsuccessfully rolling back to 24.05, I installed 24.08 again with this command (as before):

sudo tar --overwrite -xvf clightning-v24.08-Ubuntu-22.04.tar.xz -C /

RPC calls are now fast again! Nothing else changed, compare this:

Before reinstall: 2024/09/04 13:13:56 fetchPaymentsStats took 10.125399611s to execute

After reinstall: 2024/09/04 14:29:39 fetchPaymentsStats took 8.293982ms to execute

I do not know what to make of it or if the problem will return in the future.

grubles commented 2 months ago

Just adding a bit of data: on a medium sized node, listhtlcs took 6m35s to run.

Impa10r commented 2 months ago

Just adding a bit of data: on a medium sized node, listhtlcs took 6m35s to run.

how long does this take? lightning-cli sql -k query="SELECT * FROM htlcs;"

grubles commented 2 months ago

Just adding a bit of data: on a medium sized node, listhtlcs took 6m35s to run.

how long does this take? lightning-cli sql -k query="SELECT * FROM htlcs;"

That takes 6m46s.

Impa10r commented 2 months ago

cli sql -k query="SELECT * FROM htlcs;"

horrible. could you also try this please? lightning-cli sql -k query="SELECT * FROM htlcs WHERE expiry > 833622;"

It would be nice if the last 6 months of HTLCs were loading faster.

But, unfortunately, such a query fails in glightning!

rustyrussell commented 2 months ago

Well, sql just calls listhtlcs underneath, so it won't be faster. It could be accelerated, but it hasn't yet, esp since listhtlcs doesn't support the wait/pagination APIs, which would be the first step (along with delete and autocleaning of old HTLCs).

Without profiling, it's hard to know where it's going wrong, or why it's now "fixed". If it happens again, see if something is consuming a strange amount of CPU time? If something is flooding lightningd, it could get backed up...

rustyrussell commented 2 months ago

Closing for now since no reproduce...

Impa10r commented 2 months ago

Well, sql just calls listhtlcs underneath, so it won't be faster.

Wait, are you saying SQL query "SELECT * FROM htlcs WHERE payment_hash=x'payment_hash'" will also take 6+ minutes to run? This is just unacceptable! My code relies on this query being fast.

listhtlcs doesn't support the wait/pagination APIs, which would be the first step

ETA?

ElementsProject / lightning