Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
Impa10r opened this issue Sep 4, 2024 · 9 comments
Closed

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

Impa10r opened this issue Sep 4, 2024 · 9 comments
Assignees
@rustyrussell
Milestone
v24.11

Comments

@Impa10r
Copy link

Impa10r commented Sep 4, 2024 •
edited
Loading

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
@rustyrussell rustyrussell added this to the v24.11 milestone Sep 4, 2024
@rustyrussell rustyrussell self-assigned this Sep 4, 2024
@Impa10r Impa10r changed the title v24.08 listhtlcs is 10x slower vs v24.05 v24.08 API calls are 10x slower vs v24.05 Sep 4, 2024
@Impa10r Impa10r changed the title v24.08 API calls are 10x slower vs v24.05 v24.08 JSON-RPC calls are 10x slower vs v24.05 Sep 4, 2024
@Impa10r
Copy link
Author

Impa10r commented Sep 4, 2024 •
edited
Loading

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
Copy link
Author

Impa10r commented Sep 4, 2024 •
edited
Loading

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
Copy link
Contributor

grubles commented Sep 4, 2024 •
edited
Loading

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

@Impa10r
Copy link
Author

Impa10r commented Sep 4, 2024

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
Copy link
Contributor

grubles commented Sep 5, 2024

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
Copy link
Author

Impa10r commented Sep 5, 2024 •
edited
Loading

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
Copy link
Contributor

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 rustyrussell added bug and removed bug labels Sep 6, 2024
@rustyrussell
Copy link
Contributor

Closing for now since no reproduce...

@Impa10r
Copy link
Author

Impa10r commented Sep 6, 2024 •
edited
Loading

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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@rustyrussell rustyrussell

Labels
None yet
Projects
None yet
Milestone
v24.11
Development

No branches or pull requests
3 participants
@rustyrussell @grubles @Impa10r