Core Lightning

plugins/sql: use modern data style, not globals.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

lightningd: don't process more than 100 commands from a plugin at once.

Now that ccan/io rotates through callbacks, we can call io_always() to
yield.

We're now fast enough that this doesn't have any effect on this test,
bit it's still good to have.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

lightningd: don't process more than 100 commands from a JSONRPC at once.

Now that ccan/io rotates through callbacks, we can call io_always() to yield.

Though it doesn't fire on our benchmark, it's a good thing to do.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

ccan: update to get io_loop fairness.

This rotates through fds explicitly, to avoid unfairness.
This doesn't really make a difference until we start using it.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

common: optimize json parsing.

We would keep parsing if we were out of tokens, even if we had actually
finished one object!

These are comparison against the "xpay: use filtering on rpc_command
so we only get called on "pay"." not the disasterous previous one!

tests/test_coinmoves.py::test_generate_coinmoves (2,000,000, sqlite3):
Time (from start to end of l2 node): 126 seconds (was 135)
Worst latency: 5.1 seconds **WAS 12.1**

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

commando, chanbackup: use custommsg hooks.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

libplugin: don't wait for clean_tmpctx() to free requests as we process them.

xpay is relying on the destructor to send another request. This means
that it doesn't actually submit the request until *next time* we wake.

This has been in xpay from the start, but it is not noticeable until
xpay stops subscribing to every command on the rpc_command hook.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

libplugin: allow plugins to register optional filters for each hook they want.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

lightningd: add support for filters on "rpc_command" hook.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Added: Plugins: the `rpc_command` hook can now specify a "filter" on what commands it is interested in.

Revert "bookkeeper: don't flood logs if we have many channelmoves all at once."

This reverts commit 1dda0c07530d01dfa50f6121ba30530659a1475b so we can test
what its like to be flooded with logs again.

This benefits from other improvements we've made this release, to handling
plugin input (i.e. converting to use common/jsonrpc_io), so this doesn't
make much difference.

tests/test_coinmoves.py::test_generate_coinmoves (100,000, sqlite3):
Time (from start to end of l2 node): 211 seconds
Worst latency: 108 seconds

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

JSONRPC: use a bigger default buffer.

This potentially saves us some reads (not measurably though), at cost
of less fairness. It's important to measure though, because a single
large request will increase buffer size for successive requests, so we
can see this pattern in real usage.

tests/test_coinmoves.py::test_generate_coinmoves (2,000,000, sqlite3):
Time (from start to end of l2 node): 227 seconds (was 239)
Worst latency: 62.4 seconds (was 56.9)

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

common: increase jsonrpc_io buffer size temporarily to aggrevate perf issues.

A client can do this by sending a large request, so this allows us to see what
happens if they do that, even though 1MB (2MB buffer) is more than we need.

This drives our performance through the floor: see next patch which gets
us back on track.

tests/test_coinmoves.py::test_generate_coinmoves (2,000,000, sqlite3):
Time (from start to end of l2 node): 271 seconds **WAS 135**
Worst latency: 105 seconds **WAS 12.1**

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

plugins/sql: remove size limit.

Nobody has hit this yet, but we're about to with our tests.

The size of the db is going to be whatever the total size of the tables are; bigger nodes,
bigger db.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

pytest: increase test_generate_coinmoves to 2M entries.

Now we've rid ourselves of the worst offenders, we can make this a real
stress test. We remove plugin io saving and low-level logging, to avoid
benchmarking testing artifacts.

Here are the results:

tests/test_coinmoves.py::test_generate_coinmoves (2,000,000, sqlite3):
Time (from start to end of l2 node): 518 seconds
Worst latency: 353 seconds

tests/test_coinmoves.py::test_generate_coinmoves (2,000,000, Postgres):
Time (from start to end of l2 node): 417 seconds
Worst latency: 96.6 seconds

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

bookkeeper: restore limit on asking for all channelmoves at once.

Now we've found all the issues, the latency spike (4 seconds on my laptop)
for querying 2M elements remains.

Restore the limited sampling which we reverted, but make it 10,000 now.

This doesn't help our worst-case latency, because sql still asks for all 2M entries on
first access. We address that next.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

common: avoid allocations for small numbers of traces.

If we only have 8 or fewer spans at once (as is the normal case), don't
do allocation, which might interfere with tracing.

This doesn't change our test_generate_coinmoves() benchmark.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

pytest: increase test_generate_coinmoves to 5M entries.

This is slow, but will make sure we find out if we add latency spikes in future.

tests/test_coinmoves.py::test_generate_coinmoves (5,000,000, sqlite3):
Time (from start to end of l2 node): 223 seconds
Latency min/median/max: 0.0023 / 0.0033 / 0.113 seconds

tests/test_coinmoves.py::test_generate_coinmoves (5,000,000, Postgres):
Time (from start to end of l2 node): 470 seconds
Worst latency: 0.0024 / 0.0098 / 0.124 seconds

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>
Changelog-Fixed: lightningd: multiple signficant speedups for large nodes, especially preventing "freezes" under exceptionally high load.

common: remove tracing exponential behaviour from large numbers of requests.

If we have USDT compiled in, scanning the array of spans becomes
prohibitive if we have really large numbers of requests. In the
bookkeeper code, when catching up with 1.6M channel events, this
became clear in profiling.

Use a hash table instead.

Before:
tests/test_coinmoves.py::test_generate_coinmoves (100,000, sqlite3):
Time (from start to end of l2 node): 269 seconds (vs 14 with HAVE_USDT=0)
Worst latency: 4.0 seconds

After:
tests/test_coinmoves.py::test_generate_coinmoves (100,000, sqlite3):
Time (from start to end of l2 node): 14 seconds
Worst latency: 4.3 seconds

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

lightningd: don't loop through all commands every time one finishes.

When we have many commands, this is where we spend all our time, and it's
just for an old assertion.

tests/test_coinmoves.py::test_generate_coinmoves (100,000, sqlite3):
Time (from start to end of l2 node): 13 seconds **WAS 34**
Worst latency: 4.0 seconds **WAS 24*

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

lightningd: don't copy hooks array into hook request, simply don't shrink it.

We make a copy, then attach a destructor to the hook in case that plugin exits, so we
can NULL it out in the local copy. When we have 300,000 requests pending, this means
we have 300,000 destructors, which don't scale (it's a single-linked list).

Simply NULL out (rather than shrink) the array in the `plugin_hook`.
Then we can keep using that.

tests/test_coinmoves.py::test_generate_coinmoves (100,000, sqlite3):
Time (from start to end of l2 node): 34 seconds **WAS 85**
Worst latency: 24 seconds **WAS 75**

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

pytest: latency and speed test on large coinmoves.

We start with 100,000 entries. We will scale this to 2M as we fix the
O(N^2) bottlenecks.

I measure the node time after we modify the db, like so:

while guilt push && rm -rf /tmp/ltests* && uv run make -s RUST=0; do RUST=0 VALGRIND=0 TIMEOUT=100 TEST_DEBUG=1 eatmydata uv run pytest -vvv -p no:logging tests/test_coinmoves.py::test_generate_coinmoves > /tmp/`guilt top`-sql 2>&1; done

Then analyzed the results with:
FILE=/tmp/synthetic-data.patch-sql; START=$(grep 'lightningd-2 .* Server started with public key' $FILE | tail -n1 | cut -d\ -f2 | cut -d. -f1); END=$(grep 'lightningd-2 .* JSON-RPC shutdown' $FILE | tail -n1 | cut -d\ -f2 | cut -d. -f1); echo $(( $(date +%s -d $END) - $(date +%s -d $START) )); grep 'E assert' $FILE;

tests/test_coinmoves.py::test_generate_coinmoves (100,000, sqlite3):
Time (from start to end of l2 node): 85 seconds
Worst latency: 75 seconds

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

bookkeeper: no longer read listchannelmoves 1000 entries at a time.

This reverts `bookkeeper: only read listchannelmoves 1000 entries at a time.` commit,
so we can properly fix the scalability in the coming patches.

tests/test_coinmoves.py::test_generate_coinmoves (100,000):
Time (from start to end of l2 node): 207 seconds
Worst latency: 106 seconds

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

plugins/sql: print times taken to do list comand, populate table, and create index.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

bookkeeper: fix printing of bad JSON results.

I noticed this in the logs:

```
listinvoices: description/bolt11/bolt12 not found (

{"jsonrpc":"2)
```

And we make the same formatting mistake in several places.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

pytest: fix changed msg on plugin failure.

bc4bb2b0ef7261a82cb6ff84e635dadf4f283e89 "libplugin: use jsonrpc_io logic for sync requests too."
changed this message, and test was not updated.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>