10-12 seconds added to trampoline payment for unknown reason

[JssDWt]

I had 2 occurrences of trampoline payments where 10-12 seconds were added in what seems to be a listpeerchannels call. You see between overpay=4050.0000000000005, total_amt=14050 and Starting 1 tasks to wait for channels to be ready there is a 10-12 seconds delay. In between those I only see a listpeerchannels call in the code. No awaiting channels, no communication with the signer necessary.

(Note the times here are recorded on the client side, so they may be distorted)
Node id: 02343160e016c025ba56a364c160761e709d36eb8e25630a86b363ef9a5d86f3cf
Session id: 7256626926981120

Payment 1:

[2024-10-28 12:44:47.193 INFO breez_sdk_core::breez_services:1685] node-logs: DEBUG   plugin-gl-plugin-internal: Await peer connection to 0264a62a4307d701c04a46994ce5f5323b1ca28c80c66b73c631dbcb0990d6e835
[2024-10-28 12:44:47.193 INFO breez_sdk_core::breez_services:1685] node-logs: DEBUG   plugin-gl-plugin-internal: Checking if peer 0264a62a4307d701c04a46994ce5f5323b1ca28c80c66b73c631dbcb0990d6e835 is connected
[2024-10-28 12:44:47.194 INFO breez_sdk_core::breez_services:1685] node-logs: DEBUG   plugin-gl-plugin-internal: Received event Ok(RpcCall(\"/greenlight.Node/TrampolinePay\")) from gl_plugin
[2024-10-28 12:44:47.195 INFO breez_sdk_core::breez_services:1685] node-logs: DEBUG   plugin-gl-plugin-internal: Node mode switched from Proxy => User
[2024-10-28 12:44:47.215 INFO breez_sdk_core::breez_services:1685] node-logs: DEBUG   plugin-gl-plugin-internal: overpay=4050.0000000000005, total_amt=14050
[2024-10-28 12:44:59.504 INFO breez_sdk_core::breez_services:1685] node-logs: INFO    plugin-gl-plugin-internal: Starting 1 tasks to wait for channels to be ready

Payment 2:

[2024-10-28 12:45:48.639 INFO breez_sdk_core::breez_services:1685] node-logs: DEBUG   plugin-gl-plugin-internal: Await peer connection to 0264a62a4307d701c04a46994ce5f5323b1ca28c80c66b73c631dbcb0990d6e835
[2024-10-28 12:45:48.639 INFO breez_sdk_core::breez_services:1685] node-logs: DEBUG   plugin-gl-plugin-internal: Checking if peer 0264a62a4307d701c04a46994ce5f5323b1ca28c80c66b73c631dbcb0990d6e835 is connected
[2024-10-28 12:45:48.639 INFO breez_sdk_core::breez_services:1685] node-logs: DEBUG   plugin-gl-plugin-internal: Received event Ok(RpcCall(\"/greenlight.Node/TrampolinePay\")) from gl_plugin
[2024-10-28 12:45:48.639 INFO breez_sdk_core::breez_services:1685] node-logs: DEBUG   plugin-gl-plugin-internal: Node mode switched from Proxy => User
[2024-10-28 12:45:48.639 INFO breez_sdk_core::breez_services:1685] node-logs: DEBUG   plugin-gl-plugin-internal: overpay=4050.0000000000005, total_amt=14050
[2024-10-28 12:45:59.509 INFO breez_sdk_core::breez_services:1685] node-logs: INFO    plugin-gl-plugin-internal: Starting 1 tasks to wait for channels to be ready

[cdecker]

We are looking into instrumenting the nodes with the tracing support. That should tell us nicely where we're spending time.

[nepet]

@JssDWt do you know how many channels the node has with the trampoline peer?

[JssDWt]

@JssDWt do you know how many channels the node has with the trampoline peer?

The node has 1 channel with the trampoline peer. And 1 channel total.

[cdecker]

We have deployed the opentelemetry tracing, including DB call measurements, so next time we see an instance we can dig deeper 👍

[nepet]

I guess there is nothing more we can do here at the moment. Shall we close this issue and come back to it once there is a new incident we can work on?

[JssDWt]

I guess there is nothing more we can do here at the moment. Shall we close this issue and come back to it once there is a new incident we can work on?

Is there an alert set for slow listpeerchannels calls?

[cdecker]

We are actively monitoring the duration of listpeerchannels calls, and so far we have not found one that exceeds 1s. This is spot-checking, since the context that tempo keeps searchable is only 3 hours, but we should have found one by now.

I plan to instrument the pay plugin further, so we should have a better view pretty soon.