From 4ea6229be6d91bdb1bafb4565dbb66766b4f7e16 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Tue, 4 Nov 2025 10:52:06 +1030 Subject: [PATCH 1/2] bookkeeper: don't flood logs if we have many channelmoves all at once. Since we're synchronous, these only reach lightningd after we're done: in the case of 1.6M channelmoves, that can give it major heartburn. In practice, this reduces the first bkpr command on a fresh upgrade from 349 to 235 seconds (but this was before other improvements we did this release). Signed-off-by: Rusty Russell Changelog-Changed: Plugins: `bookkeeper` reduced logging for large imports to increase speed. --- plugins/bkpr/bookkeeper.c | 26 ++++++++++++++++++-------- 1 file changed, 18 insertions(+), 8 deletions(-) diff --git a/plugins/bkpr/bookkeeper.c b/plugins/bkpr/bookkeeper.c index e5e2e82f8e87..bba69efbafee 100644 --- a/plugins/bkpr/bookkeeper.c +++ b/plugins/bkpr/bookkeeper.c @@ -87,7 +87,8 @@ static void parse_and_log_channel_move(struct command *cmd, const char *buf, const jsmntok_t *channelmove, - struct refresh_info *rinfo); + struct refresh_info *rinfo, + bool log); static struct command_result *datastore_done(struct command *cmd, const char *method, @@ -120,8 +121,15 @@ static struct command_result *listchannelmoves_done(struct command *cmd, be64 be_index; moves = json_get_member(buf, result, "channelmoves"); + if (moves->size > 2) { + plugin_log(cmd->plugin, LOG_DBG, + "%u channelmoves, only logging first and last", + moves->size); + } + json_for_each_arr(i, t, moves) - parse_and_log_channel_move(cmd, buf, t, rinfo); + parse_and_log_channel_move(cmd, buf, t, rinfo, + i == 0 || i == moves->size - 1); be_index = cpu_to_be64(bkpr->channelmoves_index); jsonrpc_set_datastore_binary(cmd, "bookkeeper/channelmoves_index", @@ -1277,7 +1285,8 @@ static void parse_and_log_channel_move(struct command *cmd, const char *buf, const jsmntok_t *channelmove, - struct refresh_info *rinfo) + struct refresh_info *rinfo, + bool log) { struct channel_event *e = tal(cmd, struct channel_event); struct account *acct; @@ -1324,11 +1333,12 @@ parse_and_log_channel_move(struct command *cmd, err = tal_free(err); } - plugin_log(cmd->plugin, LOG_DBG, "coin_move 2 (%s) %s -%s %s %"PRIu64, - e->tag, - fmt_amount_msat(tmpctx, e->credit), - fmt_amount_msat(tmpctx, e->debit), - CHANNEL_MOVE, e->timestamp); + if (log) + plugin_log(cmd->plugin, LOG_DBG, "coin_move 2 (%s) %s -%s %s %"PRIu64, + e->tag, + fmt_amount_msat(tmpctx, e->credit), + fmt_amount_msat(tmpctx, e->debit), + CHANNEL_MOVE, e->timestamp); /* Go find the account for this event */ acct = find_account(bkpr, acct_name); From ab3866a3763018fd8ca21c9d3be328080416872e Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Tue, 4 Nov 2025 10:52:15 +1030 Subject: [PATCH 2/2] sql: only create sql indices after initial load of data. This makes a big difference for large tables. Consider 1.6M channelmoves, which took 82 seconds to populate, now takes 17 seconds: Before: plugin-sql: Time to call listchannelmoves: 10.380341485 seconds plugin-sql: Time to refresh channelmoves: 82.311287310 seconds After: plugin-sql: Time to call listchannelmoves: 9.962815480 seconds plugin-sql: Time to refresh channelmoves: 15.711549299 seconds plugin-sql: Time to refresh + create indices for channelmoves: 17.100151235 seconds tests/test_coinmoves.py::test_generate_coinmoves (50,000): Time (from start to end of l2 node): 27 seconds Worst latency: 16.0 seconds Changelog-Changed: Plugins: `sql` initial load for tables is much faster (e.g 82 to 17 seconds for very large channelmoves table). Signed-off-by: Rusty Russell --- plugins/sql.c | 50 ++++++++++++++++++++++++++++++-------------------- 1 file changed, 30 insertions(+), 20 deletions(-) diff --git a/plugins/sql.c b/plugins/sql.c index ca622c08f72b..be7df11dfe76 100644 --- a/plugins/sql.c +++ b/plugins/sql.c @@ -119,6 +119,8 @@ struct table_desc { bool is_subobject; /* Do we use created_index as primary key? Otherwise we create rowid. */ bool has_created_index; + /* Have we created our sql indexes yet? */ + bool indices_created; /* function to refresh it. */ struct command_result *(*refresh)(struct command *cmd, const struct table_desc *td, @@ -487,6 +489,28 @@ static struct command_result *refresh_complete(struct command *cmd, return command_finished(cmd, ret); } +static void init_indices(struct plugin *plugin, const struct table_desc *td) +{ + for (size_t i = 0; i < ARRAY_SIZE(indices); i++) { + char *errmsg, *cmd; + int err; + + if (!streq(indices[i].tablename, td->name)) + continue; + + cmd = tal_fmt(tmpctx, "CREATE INDEX %s_%zu_idx ON %s (%s", + indices[i].tablename, i, + indices[i].tablename, + indices[i].fields[0]); + if (indices[i].fields[1]) + tal_append_fmt(&cmd, ", %s", indices[i].fields[1]); + tal_append_fmt(&cmd, ");"); + err = sqlite3_exec(db, cmd, NULL, NULL, &errmsg); + if (err != SQLITE_OK) + plugin_err(plugin, "Failed '%s': %s", cmd, errmsg); + } +} + /* Recursion */ static struct command_result *refresh_tables(struct command *cmd, struct db_query *dbq); @@ -502,6 +526,11 @@ static struct command_result *one_refresh_done(struct command *cmd, assert(td->refreshing); td->refreshing = false; + if (!td->indices_created) { + init_indices(cmd->plugin, td); + td->indices_created = 1; + } + /* Transfer refresh waiters onto local list */ list_head_init(&waiters); list_append_list(&waiters, &td->refresh_waiters); @@ -1524,6 +1553,7 @@ static struct table_desc *new_table_desc(const tal_t *ctx, td->last_created_index = 0; td->has_created_index = false; td->refreshing = false; + td->indices_created = false; list_head_init(&td->refresh_waiters); /* Only top-levels have refresh functions */ @@ -1704,25 +1734,6 @@ static void init_tablemap(struct plugin *plugin) } } -static void init_indices(struct plugin *plugin) -{ - for (size_t i = 0; i < ARRAY_SIZE(indices); i++) { - char *errmsg, *cmd; - int err; - - cmd = tal_fmt(tmpctx, "CREATE INDEX %s_%zu_idx ON %s (%s", - indices[i].tablename, i, - indices[i].tablename, - indices[i].fields[0]); - if (indices[i].fields[1]) - tal_append_fmt(&cmd, ", %s", indices[i].fields[1]); - tal_append_fmt(&cmd, ");"); - err = sqlite3_exec(db, cmd, NULL, NULL, &errmsg); - if (err != SQLITE_OK) - plugin_err(plugin, "Failed '%s': %s", cmd, errmsg); - } -} - static void memleak_mark_tablemap(struct plugin *p, struct htable *memtable) { memleak_ptr(memtable, dbfilename); @@ -1735,7 +1746,6 @@ static const char *init(struct command *init_cmd, struct plugin *plugin = init_cmd->plugin; db = sqlite_setup(plugin); init_tablemap(plugin); - init_indices(plugin); plugin_set_memleak_handler(plugin, memleak_mark_tablemap); return NULL;