[bug]: Native SQL migration: Invoice migration slows for many (100k+) rows #10421
Description
Invoice migration slows to ~28 invoices/sec.
LND Version
v0.20.0-beta
LND Configuration
Migrating to native sql using use-native-sql. According to boltbrowser I have Pairs: 727436 in invoice table.
# grep -E 'db|sql|cancel|postg' .lnd/lnd.conf
gc-canceled-invoices-on-startup=true
gc-canceled-invoices-on-the-fly=true
db.bolt.auto-compact=true
[db]
db.backend=postgres
db.use-native-sql=true
[postgres]
db.postgres.dsn=postgresql://lnduser:[email protected]:5432/lnd
db.postgres.timeout=0
Backend Version
Bitcoin core v26
Backend Configuration
n/a
OS/Distribution
Debian 13.2
Bug Details & Steps to Reproduce
- Migrating to native sql
Expected Behavior
Fast migration
Debug Information
LND log:
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.388 [INF] SQLD: Migrating SQL schema to version 5 [70/238]
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.389 [INF] SQLD: Applying migrations from version=4
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.390 [DBG] SQLD: Start buffering 5/u migration_tracker
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.394 [DBG] SQLD: Read and execute 5/u migration_tracker
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.399 [DBG] SQLD: Finished 5/u migration_tracker (read 4.748913ms, ran 4.713093ms)
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.407 [INF] SQLD: Migrating SQL schema to version 6
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.410 [INF] SQLD: Applying migrations from version=5
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.410 [DBG] SQLD: Start buffering 6/u invoice_migration
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.417 [DBG] SQLD: Read and execute 6/u invoice_migration
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.428 [DBG] SQLD: Finished 6/u invoice_migration (read 7.142984ms, ran 10.426966ms)
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.436 [INF] SQLD: Migrating SQL schema to version 6
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.438 [INF] SQLD: Applying migrations from version=6
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.442 [INF] SQLD: Applying custom migration 'kv_invoice_migration' (version 7) to schema version 6
Dec 04 08:58:32 srv70 lnd[53432]: 2025-12-04 08:58:32.442 [INF] INVC: Starting migration of invoices from KV to SQL
Dec 04 09:00:07 srv70 lnd[53432]: 2025-12-04 09:00:07.780 [DBG] INVC: Migrated 1000 invoices (1989.44 invoices/sec)
Dec 04 09:00:39 srv70 lnd[53432]: 2025-12-04 09:00:39.374 [DBG] INVC: Migrated 22000 invoices (664.68 invoices/sec)
Dec 04 09:01:10 srv70 lnd[53432]: 2025-12-04 09:01:10.396 [DBG] INVC: Migrated 32000 invoices (322.36 invoices/sec)
Dec 04 09:01:43 srv70 lnd[53432]: 2025-12-04 09:01:43.299 [DBG] INVC: Migrated 40000 invoices (243.14 invoices/sec)
Dec 04 09:02:13 srv70 lnd[53432]: 2025-12-04 09:02:13.318 [DBG] INVC: Migrated 46000 invoices (199.87 invoices/sec)
Dec 04 09:02:48 srv70 lnd[53432]: 2025-12-04 09:02:48.536 [DBG] INVC: Migrated 52000 invoices (170.37 invoices/sec)
Dec 04 09:03:21 srv70 lnd[53432]: 2025-12-04 09:03:21.271 [DBG] INVC: Migrated 57000 invoices (152.74 invoices/sec)
[..]
Dec 04 09:30:11 srv70 lnd[53432]: 2025-12-04 09:30:11.484 [DBG] INVC: Migrated 165000 invoices (40.59 invoices/sec)
Dec 04 09:30:59 srv70 lnd[53432]: 2025-12-04 09:30:59.661 [DBG] INVC: Migrated 167000 invoices (41.51 invoices/sec)
Dec 04 09:31:47 srv70 lnd[53432]: 2025-12-04 09:31:47.596 [DBG] INVC: Migrated 169000 invoices (41.72 invoices/sec)
[..]
Dec 04 09:56:27 srv70 lnd[53432]: 2025-12-04 09:56:27.568 [DBG] INVC: Migrated 223000 invoices (31.60 invoices/sec)
Dec 04 09:56:58 srv70 lnd[53432]: 2025-12-04 09:56:58.695 [DBG] INVC: Migrated 224000 invoices (32.13 invoices/sec)
Dec 04 09:57:28 srv70 lnd[53432]: 2025-12-04 09:57:28.894 [DBG] INVC: Migrated 225000 invoices (33.11 invoices/sec)
[..]
Dec 04 10:18:43 srv70 lnd[53432]: 2025-12-04 10:18:43.563 [DBG] INVC: Migrated 264000 invoices (28.46 invoices/sec)
Dec 04 10:19:19 srv70 lnd[53432]: 2025-12-04 10:19:19.153 [DBG] INVC: Migrated 265000 invoices (28.10 invoices/sec)
Dec 04 10:19:54 srv70 lnd[53432]: 2025-12-04 10:19:54.025 [DBG] INVC: Migrated 266000 invoices (28.68 invoices/sec)
Postgresql log:
2025-12-04 08:35:50.981 UTC [43041] LOG: checkpoint complete: wrote 127 buffers (0.8%); 0 WAL file(s) added, 0 removed, 29 recycled; write=12.633 s, sync=0.026 s, total=12.938 s; sync files=19, longest=0.012 s, average=0.002 s; distance=475045 kB, estimate=534719 kB; lsn=2/2E013910, redo lsn=2/2E013880
2025-12-04 08:48:54.731 UTC [50961] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:48:54.731 UTC [50961] lnduser@lnd DETAIL: Reason code: Canceled on identification as a pivot, during conflict out checking.
2025-12-04 08:48:54.731 UTC [50961] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:48:54.731 UTC [50961] lnduser@lnd CONTEXT: SQL statement "SELECT 1 FROM ONLY "public"."channeldb_kv" x WHERE "id" OPERATOR(pg_catalog.=) $1 FOR KEY SHARE OF x"
2025-12-04 08:48:54.731 UTC [50961] lnduser@lnd STATEMENT: INSERT INTO channeldb_kv (key, value, parent_id) VALUES($1, $2, $3) ON CONFLICT (key, parent_id) WHERE parent_id IS NOT NULL DO UPDATE SET value=$2 WHERE channeldb_kv.value IS NOT NULL
2025-12-04 08:49:01.474 UTC [50952] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:49:01.474 UTC [50952] lnduser@lnd DETAIL: Reason code: Canceled on identification as a pivot, during write.
2025-12-04 08:49:01.474 UTC [50952] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:49:01.474 UTC [50952] lnduser@lnd STATEMENT: INSERT INTO channeldb_kv (key, value, parent_id) VALUES($1, $2, $3) ON CONFLICT (key, parent_id) WHERE parent_id IS NOT NULL DO UPDATE SET value=$2 WHERE channeldb_kv.value IS NOT NULL
2025-12-04 08:49:10.194 UTC [51048] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:49:10.194 UTC [51048] lnduser@lnd DETAIL: Reason code: Canceled on identification as a pivot, during conflict out checking.
2025-12-04 08:49:10.194 UTC [51048] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:49:10.194 UTC [51048] lnduser@lnd STATEMENT: SELECT id,value FROM channeldb_kv WHERE parent_id=105498 AND key=$1
2025-12-04 08:49:10.893 UTC [51147] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:49:10.893 UTC [51147] lnduser@lnd DETAIL: Reason code: Canceled on identification as a pivot, during conflict in checking.
2025-12-04 08:49:10.893 UTC [51147] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:49:10.893 UTC [51147] lnduser@lnd STATEMENT: INSERT INTO channeldb_kv (key, value, parent_id) VALUES($1, $2, $3) ON CONFLICT (key, parent_id) WHERE parent_id IS NOT NULL DO UPDATE SET value=$2 WHERE channeldb_kv.value IS NOT NULL
2025-12-04 08:49:11.585 UTC [51234] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:49:11.585 UTC [51234] lnduser@lnd DETAIL: Reason code: Canceled on identification as a pivot, during conflict out checking.
2025-12-04 08:49:11.585 UTC [51234] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:49:11.585 UTC [51234] lnduser@lnd STATEMENT: SELECT id,value FROM channeldb_kv WHERE parent_id=105498 AND key=$1
2025-12-04 08:49:12.890 UTC [51355] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:49:12.890 UTC [51355] lnduser@lnd DETAIL: Reason code: Canceled on identification as a pivot, during conflict in checking.
2025-12-04 08:49:12.890 UTC [51355] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:49:12.890 UTC [51355] lnduser@lnd STATEMENT: INSERT INTO channeldb_kv (key, value, parent_id) VALUES($1, $2, $3) ON CONFLICT (key, parent_id) WHERE parent_id IS NOT NULL DO UPDATE SET value=$2 WHERE channeldb_kv.value IS NOT NULL
2025-12-04 08:49:13.571 UTC [51438] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:49:13.571 UTC [51438] lnduser@lnd DETAIL: Reason code: Canceled on identification as a pivot, during conflict out checking.
2025-12-04 08:49:13.571 UTC [51438] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:49:13.571 UTC [51438] lnduser@lnd STATEMENT: SELECT value FROM channeldb_kv WHERE parent_id=105498 AND key=$1
2025-12-04 08:49:14.835 UTC [51590] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:49:14.835 UTC [51590] lnduser@lnd DETAIL: Reason code: Canceled on identification as a pivot, during conflict out checking.
2025-12-04 08:49:14.835 UTC [51590] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:49:14.835 UTC [51590] lnduser@lnd STATEMENT: SELECT id FROM channeldb_kv WHERE parent_id IS NULL AND key=$1 AND value IS NULL
2025-12-04 08:49:16.193 UTC [51719] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:49:16.193 UTC [51719] lnduser@lnd DETAIL: Reason code: Canceled on conflict out to pivot 1857, during read.
2025-12-04 08:49:16.193 UTC [51719] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:49:16.193 UTC [51719] lnduser@lnd STATEMENT: SELECT value FROM channeldb_kv WHERE parent_id=1182060 AND key=$1
2025-12-04 08:49:16.855 UTC [51841] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:49:16.855 UTC [51841] lnduser@lnd DETAIL: Reason code: Canceled on identification as a pivot, during conflict out checking.
2025-12-04 08:49:16.855 UTC [51841] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:49:16.855 UTC [51841] lnduser@lnd STATEMENT: SELECT id FROM channeldb_kv WHERE parent_id IS NULL AND key=$1 AND value IS NULL
2025-12-04 08:50:39.234 UTC [43041] LOG: checkpoint starting: time
2025-12-04 08:53:32.323 UTC [52375] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:53:32.323 UTC [52375] lnduser@lnd DETAIL: Reason code: Canceled on conflict out to pivot 3333, during read.
2025-12-04 08:53:32.323 UTC [52375] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:53:32.323 UTC [52375] lnduser@lnd STATEMENT: SELECT value FROM channeldb_kv WHERE parent_id=1182060 AND key=$1
2025-12-04 08:53:32.956 UTC [52448] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:53:32.956 UTC [52448] lnduser@lnd DETAIL: Reason code: Canceled on identification as a pivot, during conflict out checking.
2025-12-04 08:53:32.956 UTC [52448] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:53:32.956 UTC [52448] lnduser@lnd STATEMENT: SELECT id FROM channeldb_kv WHERE parent_id=105498 AND key=$1 AND value IS NULL
2025-12-04 08:55:09.158 UTC [43041] LOG: checkpoint complete: wrote 796 buffers (4.9%); 0 WAL file(s) added, 1 removed, 1 recycled; write=269.814 s, sync=0.040 s, total=269.925 s; sync files=73, longest=0.007 s, average=0.001 s; distance=33961 kB, estimate=484644 kB; lsn=2/31E20D18, redo lsn=2/3013DF38
2025-12-04 08:55:23.340 UTC [53257] lnduser@lnd ERROR: could not serialize access due to read/write dependencies among transactions
2025-12-04 08:55:23.340 UTC [53257] lnduser@lnd DETAIL: Reason code: Canceled on identification as a pivot, during conflict in checking.
2025-12-04 08:55:23.340 UTC [53257] lnduser@lnd HINT: The transaction might succeed if retried.
2025-12-04 08:55:23.340 UTC [53257] lnduser@lnd STATEMENT: INSERT INTO channeldb_kv (key, value, parent_id) VALUES($1, $2, $3) ON CONFLICT (key, parent_id) WHERE parent_id IS NOT NULL DO UPDATE SET value=$2 WHERE channeldb_kv.value IS NOT NULL
2025-12-04 08:55:39.185 UTC [43041] LOG: checkpoint starting: time
2025-12-04 08:59:59.151 UTC [43041] LOG: checkpoint complete: wrote 2177 buffers (13.3%); 0 WAL file(s) added, 1 removed, 0 recycled; write=259.748 s, sync=0.166 s, total=259.967 s; sync files=156, longest=0.025 s, average=0.002 s; distance=31323 kB, estimate=439311 kB; lsn=2/4FC42F08, redo lsn=2/31FD4DA0
2025-12-04 09:00:04.989 UTC [43041] LOG: checkpoint starting: wal
2025-12-04 09:04:34.636 UTC [43041] LOG: checkpoint complete: wrote 3917 buffers (23.9%); 0 WAL file(s) added, 0 removed, 33 recycled; write=268.995 s, sync=0.164 s, total=269.648 s; sync files=31, longest=0.014 s, average=0.006 s; distance=524604 kB, estimate=524604 kB; lsn=2/61D34028, redo lsn=2/52023DC8
2025-12-04 09:05:04.667 UTC [43041] LOG: checkpoint starting: time
2025-12-04 09:09:34.369 UTC [43041] LOG: checkpoint complete: wrote 6424 buffers (39.2%); 0 WAL file(s) added, 0 removed, 16 recycled; write=269.358 s, sync=0.161 s, total=269.703 s; sync files=25, longest=0.014 s, average=0.007 s; distance=267729 kB, estimate=498916 kB; lsn=2/66DC9580, redo lsn=2/625982C0
2025-12-04 09:10:04.399 UTC [43041] LOG: checkpoint starting: time
2025-12-04 09:14:34.289 UTC [43041] LOG: checkpoint complete: wrote 5126 buffers (31.3%); 0 WAL file(s) added, 2 removed, 3 recycled; write=269.621 s, sync=0.178 s, total=269.891 s; sync files=25, longest=0.013 s, average=0.008 s; distance=79971 kB, estimate=457022 kB; lsn=2/6B103C38, redo lsn=2/673B1218
2025-12-04 09:15:04.319 UTC [43041] LOG: checkpoint starting: time
2025-12-04 09:19:34.232 UTC [43041] LOG: checkpoint complete: wrote 5157 buffers (31.5%); 0 WAL file(s) added, 4 removed, 0 recycled; write=269.650 s, sync=0.176 s, total=269.914 s; sync files=25, longest=0.014 s, average=0.008 s; distance=67461 kB, estimate=418066 kB; lsn=2/6ED13208, redo lsn=2/6B592888
2025-12-04 09:20:04.262 UTC [43041] LOG: checkpoint starting: time
2025-12-04 09:24:34.347 UTC [43041] LOG: checkpoint complete: wrote 4990 buffers (30.5%); 0 WAL file(s) added, 4 removed, 0 recycled; write=269.776 s, sync=0.220 s, total=270.085 s; sync files=25, longest=0.016 s, average=0.009 s; distance=60753 kB, estimate=382334 kB; lsn=2/7283C220, redo lsn=2/6F0E6CC8
2025-12-04 09:25:04.376 UTC [43041] LOG: checkpoint starting: time
2025-12-04 09:29:34.259 UTC [43041] LOG: checkpoint complete: wrote 4993 buffers (30.5%); 0 WAL file(s) added, 3 removed, 0 recycled; write=269.671 s, sync=0.136 s, total=269.883 s; sync files=25, longest=0.013 s, average=0.006 s; distance=60340 kB, estimate=350135 kB; lsn=2/761A1110, redo lsn=2/72BD3DF0
2025-12-04 09:30:04.282 UTC [43041] LOG: checkpoint starting: time
2025-12-04 09:34:34.224 UTC [43041] LOG: checkpoint complete: wrote 3560 buffers (21.7%); 0 WAL file(s) added, 4 removed, 0 recycled; write=269.697 s, sync=0.172 s, total=269.943 s; sync files=26, longest=0.019 s, average=0.007 s; distance=58067 kB, estimate=320928 kB; lsn=2/79A16E18, redo lsn=2/76488DD8
2025-12-04 09:35:04.254 UTC [43041] LOG: checkpoint starting: time
Heavy query seems to be:
usename,
state,
query
FROM pg_stat_activity
ORDER BY state, pid;
pid | usename | state | query
-------+----------+--------+------------------------------------------------------------------------------------
53452 | lnduser | active | -- name: GetInvoiceHTLCCustomRecords :many +
| | | SELECT ihcr.htlc_id, key, value +
| | | FROM invoice_htlcs ih JOIN invoice_htlc_custom_records ihcr ON ih.id=ihcr.htlc_id +
| | | WHERE ih.invoice_id = $1 +
| | |
54944 | postgres | active | SELECT pid, +
| | | usename, +
| | | state, +
| | | query +
| | | FROM pg_stat_activity +
| | | ORDER BY state, pid;
53442 | lnduser | idle | commit
53443 | lnduser | idle | SELECT version, dirty FROM "public"."schema_migrations" LIMIT 1
53444 | lnduser | idle | SELECT pg_advisory_unlock($1)
53445 | lnduser | idle | SELECT pg_advisory_unlock($1)
53446 | lnduser | idle | SELECT pg_advisory_unlock($1)
53448 | lnduser | idle | SELECT pg_advisory_unlock($1)
53449 | lnduser | idle | SELECT pg_advisory_unlock($1)
53450 | lnduser | idle | SELECT pg_advisory_unlock($1)
53451 | lnduser | idle | SELECT pg_advisory_unlock($1)
43041 | | |
43042 | | |
43044 | | |
43045 | | |
43046 | postgres | |
(16 rows)```
### Environment
self-built lnd