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

LeaseOutput is slow with postgres backend #8809

Closed
yyforyongyu opened this issue Jun 3, 2024 · 1 comment · Fixed by #8961
Closed

LeaseOutput is slow with postgres backend #8809

yyforyongyu opened this issue Jun 3, 2024 · 1 comment · Fixed by #8961
Labels
database Related to the database/storage of LND P1 MUST be fixed or reviewed performance postgres
Milestone
v0.19.0

Comments

@yyforyongyu
Copy link
Member

Issue

SendCoins takes much longer to run with postgres as the db backend, and this itest failure has been shown multiple times,

harness_rpc.go:97: 
        	Error Trace:	/home/runner/work/lnd/lnd/lntest/rpc/harness_rpc.go:97
        	            				/home/runner/work/lnd/lnd/lntest/rpc/lnd.go:374
        	            				/home/runner/work/lnd/lnd/itest/lnd_taproot_test.go:129
        	            				/home/runner/work/lnd/lnd/itest/lnd_taproot_test.go:52
        	            				/home/runner/work/lnd/lnd/lntest/harness.go:385
        	            				/home/runner/work/lnd/lnd/itest/lnd_test.go:139
        	Error:      	Received unexpected error:
        	            	rpc error: code = DeadlineExceeded desc = context deadline exceeded
        	Messages:   	Alice: failed to call SendCoins

Observations

Turns out that when using postgres, leasing outputs take much longer, which is called here when crafting the tx for SendCoins.

  • For kvdb backend, the leasing of 100 utxos takes about 1 second.
  • For postgres backend, the leasing of 100 utxos takes about 40 seconds.

Steps to reproduce

Running with make itest icase=sign_psbt/fund_and_sign_psbt backend=btcd,

2024-06-04 03:37:30.353 [INF] RPCS: [sendcoins] addr=2MzusuQmFdFCBgtns6LjnCnQemeAhRftiku, amt=0 BTC, sat/kw=12500, min_confs=0, send_all=true
2024-06-04 03:37:30.353 [DBG] SWPR: [WithCoinSelectLock] entered the lock
2024-06-04 03:37:30.453 [DBG] SWPR: [WithCoinSelectLock] finished fetching UTXOs
2024-06-04 03:37:30.453 [DBG] SWPR: [WithCoinSelectLock] leasing utxo: 65734f6883a0949f4588589fda166b9339bfb77081cf77dad1ee91b5dc78c000:0
...leasing 98 more...
2024-06-04 03:37:31.616 [DBG] SWPR: [WithCoinSelectLock] leasing utxo: 2fb2947606ac7bf141ae364e8ea8d805344f56a319b679efa4380e6839782bf8:0
2024-06-04 03:37:31.626 [DBG] SWPR: [WithCoinSelectLock] exited the lock
2024-06-04 03:37:31.656 [DBG] SWPR: Creating sweep transaction 6c4bc2d7afeecb395d8bf0654065d7f5acb52b1017e5b4a61442bbd1dd3d7207 for 100 inputs...

Running with make itest icase=sign_psbt/fund_and_sign_psbt backend=bitcoind,

2024-06-04 03:46:54.785 [INF] RPCS: [sendcoins] addr=2MzDETUurmNbcnx2mLWtm4tdeARCFUkdQbU, amt=0 BTC, sat/kw=12500, min_confs=0, send_all=true
2024-06-04 03:46:54.786 [DBG] SWPR: [WithCoinSelectLock] entered the lock
2024-06-04 03:46:54.856 [DBG] SWPR: [WithCoinSelectLock] finished fetching UTXOs
2024-06-04 03:46:54.856 [DBG] SWPR: [WithCoinSelectLock] leasing utxo: f4436cede2c43faa7eb16cc2d4577e0825790f685b146eacfbe2a07a1006df00:0
...leasing 98 more...
2024-06-04 03:46:55.960 [DBG] SWPR: [WithCoinSelectLock] leasing utxo: 8dd273ce89622e59cae55a216a33b65d581a0d9ea95a30d74138140f5a0d15ff:0
2024-06-04 03:46:55.970 [DBG] SWPR: [WithCoinSelectLock] exited the lock
2024-06-04 03:46:55.984 [DBG] SWPR: Creating sweep transaction c383561e0096a6099dfe5c9cd57a42a6f393cb7fd281e137e5d989c518db3627 for 100 inputs...

Running with make itest icase=sign_psbt/fund_and_sign_psbt backend=bitcoind dbbackend=postgres,

2024-06-04 03:41:21.576 [INF] RPCS: [sendcoins] addr=2N6HM91LmDZP63ViD5MPirXxLScp3gmK2zf, amt=0 BTC, sat/kw=12500, min_confs=0, send_all=true
2024-06-04 03:41:21.577 [DBG] SWPR: [WithCoinSelectLock] entered the lock
2024-06-04 03:41:23.324 [DBG] SWPR: [WithCoinSelectLock] finished fetching UTXOs
2024-06-04 03:41:23.324 [DBG] SWPR: [WithCoinSelectLock] leasing utxo: 38fecbec097297b3e4b1e2f535e4d4707efc8d5668424f4c14e29805aa771801:0
...leasing 98 more...
2024-06-04 03:42:02.574 [DBG] SWPR: [WithCoinSelectLock] leasing utxo: ad3297020e2b81993d2093ae239894a47ad3f67b243fc2f79c0f1fdf808384fc:0
2024-06-04 03:42:03.284 [DBG] SWPR: [WithCoinSelectLock] exited the lock
2024-06-04 03:42:03.772 [DBG] SWPR: Creating sweep transaction e50f98c1f40080ee20139d095945149a16d3334080658598bf4a5eef8ec90a7f for 100 inputs...

Running with make itest icase=sign_psbt/fund_and_sign_psbt backend=bitcoind dbbackend=postgres nativesql=true,

2024-06-04 03:53:42.474 [INF] RPCS: [sendcoins] addr=2MuaBevMSc9Gxdi4WGAnuEiRXH2pGAcYNaj, amt=0 BTC, sat/kw=12500, min_confs=0, send_all=true
2024-06-04 03:53:42.475 [DBG] SWPR: [WithCoinSelectLock] entered the lock
2024-06-04 03:53:44.029 [DBG] SWPR: [WithCoinSelectLock] finished fetching UTXOs
2024-06-04 03:53:44.029 [DBG] SWPR: [WithCoinSelectLock] leasing utxo: 1deb82f888c58b2c9e86d0f8773537324a5b1fe2ddd2b3d3a243088cb9990000:0
...leasing 98 more...
2024-06-04 03:54:19.937 [DBG] SWPR: [WithCoinSelectLock] leasing utxo: a4304be189a3075d22f5cabc638af956da871b09ae46ffb48a6dd1c143d084fe:0
2024-06-04 03:54:20.671 [DBG] SWPR: [WithCoinSelectLock] exited the lock
2024-06-04 03:54:21.260 [DBG] SWPR: Creating sweep transaction a6d8019cb0cb3f5bb0603bcfc4676b6eef81f88301933e75bd67673650b4e1c5 for 100 inputs...
@yyforyongyu yyforyongyu added bug Unintended code behaviour needs triage performance postgres and removed bug Unintended code behaviour needs triage labels Jun 3, 2024
@saubyk saubyk added P1 MUST be fixed or reviewed database Related to the database/storage of LND labels Jun 3, 2024
@yyforyongyu yyforyongyu mentioned this issue Jun 3, 2024
Merged
@saubyk saubyk added this to the v0.18.1 milestone Jun 3, 2024
@Roasbeef
Copy link
Member

Roasbeef commented Jun 3, 2024

The implementation here is pretty unglamorous: https://github.com/btcsuite/btcwallet/blob/6fe19a472a627b5f3a6ab2eda9ed7d8809d04f2e/wtxmgr/tx.go#L1184-L1204

Perhaps the culprit is that we'll create 100 distributed transactions for the 100 outpoints, instead of just 1 transaction?

This was referenced Jul 31, 2024
Open
Merged
@saubyk saubyk modified the milestones: v0.18.3, v0.19.0 Aug 6, 2024
yyforyongyu added a commit to yyforyongyu/lnd that referenced this issue Nov 3, 2024
@yyforyongyu
lntest: remove extraTimeout for sql db
1a9ce2a 
Now that lightningnetwork#8809 is fixed, we can remove this extra timeout. We also
increase the `AsyncBenchmarkTimeout` for postgres as it times out a lot.
yyforyongyu added a commit to yyforyongyu/lnd that referenced this issue Nov 4, 2024
@yyforyongyu
lntest: remove extraTimeout for sql db
c3d2488 
Now that lightningnetwork#8809 is fixed, we can remove this extra timeout. We also
increase the `AsyncBenchmarkTimeout` for postgres as it times out a lot.
yyforyongyu added a commit to yyforyongyu/lnd that referenced this issue Nov 5, 2024
@yyforyongyu
lntest: remove extraTimeout for sql db
086afdb 
Now that lightningnetwork#8809 is fixed, we can remove this extra timeout. We also
increase the `AsyncBenchmarkTimeout` for postgres as it times out a lot.
yyforyongyu added a commit to yyforyongyu/lnd that referenced this issue Nov 5, 2024
@yyforyongyu
lntest: remove extraTimeout for sql db
1334e93 
Now that lightningnetwork#8809 is fixed, we can remove this extra timeout. We also
increase the `AsyncBenchmarkTimeout` for postgres as it times out a lot.
yyforyongyu added a commit to yyforyongyu/lnd that referenced this issue Nov 7, 2024
@yyforyongyu
lntest: remove extraTimeout for sql db
2da2acd 
Now that lightningnetwork#8809 is fixed, we can remove this extra timeout. We also
increase the `AsyncBenchmarkTimeout` for postgres as it times out a lot.
yyforyongyu added a commit to yyforyongyu/lnd that referenced this issue Nov 7, 2024
@yyforyongyu
lntest: remove extraTimeout for sql db
acbd232 
Now that lightningnetwork#8809 is fixed, we can remove this extra timeout. We also
increase the `AsyncBenchmarkTimeout` for postgres as it times out a lot.
yyforyongyu added a commit to yyforyongyu/lnd that referenced this issue Nov 7, 2024
@yyforyongyu
lntest: remove extraTimeout for sql db
f1ca7fd 
Now that lightningnetwork#8809 is fixed, we can remove this extra timeout. We also
increase the `AsyncBenchmarkTimeout` for postgres as it times out a lot.
yyforyongyu added a commit to yyforyongyu/lnd that referenced this issue Nov 7, 2024
@yyforyongyu
lntest: remove extraTimeout for sql db
292bd3e 
Now that lightningnetwork#8809 is fixed, we can remove this extra timeout. We also
increase the `AsyncBenchmarkTimeout` for postgres as it times out a lot.
yyforyongyu added a commit to yyforyongyu/lnd that referenced this issue Nov 7, 2024
@yyforyongyu
lntest: remove extraTimeout for sql db
2706429 
Now that lightningnetwork#8809 is fixed, we can remove this extra timeout. We also
increase the `AsyncBenchmarkTimeout` for postgres as it times out a lot.
yyforyongyu added a commit to yyforyongyu/lnd that referenced this issue Nov 8, 2024
@yyforyongyu
lntest: remove extraTimeout for sql db
6c0ec18 
Now that lightningnetwork#8809 is fixed, we can remove this extra timeout. We also
increase the `AsyncBenchmarkTimeout` for postgres as it times out a lot.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
database Related to the database/storage of LND P1 MUST be fixed or reviewed performance postgres
Projects
None yet
Milestone
v0.19.0
Development

Successfully merging a pull request may close this issue.

Improve the performace of LeaseOutput yyforyongyu/lnd
3 participants
@Roasbeef @yyforyongyu @saubyk