Repository navigation
Cold start: single VssStore serves all Cashu + LDK reads synchronously — 19s vs 0.56s local (34x) #90
Description
Activity
Additional evidence that this is per-operation, not just cold start: receive-URI generation shows the same signature. The trusted-tier quote flow (
get_single_use_receive_uri→ cashu mint quote) measured across three configurations, same mint:Configuration get-invoice wall clock local-store wallet (wallet-cli) 103 ms mint server alone (curl, HTTPS) ~700 ms VSS-backed wallet (Android, mobile network, LSP connected) 16,650 ms The ~16s gap is the store layer: the cashu wallet's writes during quote issuance each cost a synchronous VSS round-trip. So batching/caching in the KV path would pay off on the hot request path, not only at boot — and it strengthens the case for fix direction 1 (batch/parallelize) as the first step, since it helps both without touching the rollback-safety semantics that make direction 2 delicate.
Good callout!
We technically already parallelize initial reads in LDK Node for the most part, though we can surely further make some improvements there. I think some parallelization opportunities are also possible the side of Orange SDK.
However, the biggest bottleneck here seems to VSS's usage of
bitreqwhich serializes all these reads again by making all requests through a single, non-pipelined connection, having us eat all these round-trips again. This was briefly mentioned here but I think we never followed up implementing an actual connection pool forbitreq. (cc @TheBlueMatt @tankyleo). Now tracking here: rust-bitcoin/corepc#658However, the biggest bottleneck here seems to VSS's usage of bitreq which serializes all these reads again by making all requests through a single, non-pipelined connection, having us eat all these round-trips again.
I thought we switched Vss-client to use pipelining? That should suffice to cut parallel requests latency down substantially.
I'd really like to see trace-level logging here. 16 seconds is insanely high, even if requests are being sent serially that sounds like something else is going wrong.
Trace-level logs captured (@TheBlueMatt) — Android device, mobile network, staging VSS behind Caddy/HTTPS. We enabled TRACE for
vss_client_ng/bitreq+ rustls DEBUG, millisecond timestamps. Full cold start + one receive-URI generation:The numbers:
- 343 VSS requests in the window (277
GetObjectRequest, 24ListKeyVersions, 42PutObjectRequest) - Perfectly serial: median inter-request gap 896 ms, a steady 9–10 requests per 10s for minutes
- ~Every request opens a fresh connection: 350 rustls client handshakes for 343 requests; 251 of 342 consecutive-request gaps contain a handshake. TLS 1.3 PSK resumption is working ("Resuming session") — but resumption still costs a new TCP connect + 1-RTT handshake per request.
- Cold start on this device:
Initializing orange17:17:12 →Creating LDK node17:19:57 (164 s in the pre-LDK phase alone, ≈ 180 serialized VSS gets) → LDK start 17:20:15. Receive-URI generation on the same run: 14.2 s ≈ 16 serialized round-trips.
So the 16 s isn't "something else" — it's arithmetic: N serialized requests × (TCP connect + TLS resume + HTTP round-trip) on a mobile-RTT path (~0.9 s each). Our earlier 19 s measurement was from a VPS near the VSS host; the phone's RTT amplifies the same per-request cost ~10×. Re: pipelining having been switched on — at our pin (orange-sdk
4e9d230→ vss-client-ng 0.5.0), the handshake-per-request pattern says each request rides a new connection, so whatever pipelining exists isn't engaging on this path.Sample window (repeating pattern, request → fresh connection → ~900 ms → next request):
2026-07-10 17:17:12.983 TRACE [vss_client_ng::client:88] Sending GetObjectRequest 3860541630712530198 for key cZ8kPdoVXlrvfzJQS9pZ 2026-07-10 17:17:13.542 DEBUG [rustls::client::hs:73] No cached session for DnsName("lsp.emergent.money") 2026-07-10 17:17:13.542 DEBUG [rustls::client::hs:132] Not resuming any session 2026-07-10 17:17:13.741 DEBUG [rustls::client::hs:615] Using ciphersuite TLS13_AES_128_GCM_SHA256 2026-07-10 17:17:13.742 DEBUG [rustls::client::hs:472] ALPN protocol is None 2026-07-10 17:17:14.344 TRACE [vss_client_ng::client:174] Sending ListKeyVersionsRequest 4624648138170831944 for key_prefix Some(" 2026-07-10 17:17:14.560 DEBUG [rustls::client::hs:130] Resuming session 2026-07-10 17:17:14.990 DEBUG [rustls::client::hs:615] Using ciphersuite TLS13_AES_128_GCM_SHA256 2026-07-10 17:17:14.991 DEBUG [rustls::client::hs:472] ALPN protocol is None 2026-07-10 17:17:15.611 TRACE [vss_client_ng::client:88] Sending GetObjectRequest 15346573794384891948 for key vQ3MSyu3cTurwbOSE7L 2026-07-10 17:17:15.802 DEBUG [rustls::client::hs:130] Resuming session 2026-07-10 17:17:15.988 DEBUG [rustls::client::hs:615] Using ciphersuite TLS13_AES_128_GCM_SHA256 2026-07-10 17:17:15.989 DEBUG [rustls::client::hs:472] ALPN protocol is None 2026-07-10 17:17:16.403 TRACE [vss_client_ng::client:88] Sending GetObjectRequest 951519899227931550 for key vQ3MSyu3cTurwbOSE7LIKHappy to re-run the same capture against any candidate branch — the setup is scripted now.
- 343 VSS requests in the window (277
New datapoint isolating the per-operation cost from mobile RTT: same-machine A/B (desktop, wired network, ~2 ms RTT to the Caddy-fronted VSS — not a phone), identical binary and config, only
StorageConfigdiffers. Measured the receive/mint saga (mint-quote paid → proofs minted →PaymentReceived), 5,000-sat receive, 39 proofs:Storage Invoice creation Quote paid → PaymentReceivedlocal SQLite ~1 s ~1 s (n=2) VSS 10 s 60 s Step breakdown for the VSS run:
Paidnotification → sagaprepare10 s →execute+6 s →post_mint+3 s →PaymentReceived+41 s. That 41 s tail is entirely after the mint's HTTP response is back — it's the proof/counter/saga-state persistence batch. So even with negligible network RTT, the hot path serializes enough store round-trips to take a minute; the earlier Android numbers (~896 ms/request) are the same arithmetic with mobile RTT multiplied in.One more observation that might sharpen fix direction 2: our production VSS store holds 1,339 keys for a store whose LDK-only baseline (measured before the Cashu tier used VSS) was ~17 keys — i.e., the Cashu
WalletDatabasedominates both key count and write churn. SinceWallet::restore()already re-derives Cashu proofs from the seed on a fresh install, it's worth asking whetherCashuKvDatabaseneeds to live in VSS at all: making the Cashu store local-primary (VSS only for LDK state, which is what actually needs the rollback-safety semantics) would take the entire trusted-tier hot path off the network without touching the delicate channel-state design in direction 2. Happy to test that shape against our staging VSS too.I thought we switched Vss-client to use pipelining? That should suffice to cut parallel requests latency down substantially.
We pipeline reads, but refrained from pipelining writes/removes due to idempotency concerns. While it now looks like the root cause might be the insane number of cashu-related keys, it's likely still very relevant as we require quite a few writes on each event handling and IIRC we also still have interleaving writes when we deserialize channelmanager etc.? So IMO using multiple connections would help a lot here to avoid head of line blocking.
Reacted by Matt CoralloOne more observation that might sharpen fix direction 2: our production VSS store holds 1,339 keys for a store whose LDK-only baseline (measured before the Cashu tier used VSS) was ~17 keys — i.e., the Cashu
WalletDatabasedominates both key count and write churn.Okay, if these 1339 keys are indeed read on startup (sequentially or even in batches) the 15 seconds start making a lot more sense.
- ~Every request opens a fresh connection:
It seems
bitreqcurrently marks the connection as dead if no keep-alive header is set, but HTTP 1.1 doesn't require keep-alive headers, and Caddy might just omit them: rust-bitcoin/corepc#659Can yall confirm if Caddy is returning Connection headers? Might have to just use curl to make an identical connection (or import the server private key into WireGuard, which can use that to decrypt SSL).
Confirmed (@TheBlueMatt): Caddy omits the
Connectionheader entirely on our VSS endpoint. Forced HTTP/1.1 againsthttps://lsp.emergent.money/vss/getObject:< HTTP/1.1 401 Unauthorized < Alt-Svc: h3=":443"; ma=2592000 < Content-Length: 35 < Date: Sat, 11 Jul 2026 17:40:52 GMT < Via: 1.1 Caddy < Vss-Protocol-Version: 0 < Content-Type: application/octet-streamNo
Connection:and noKeep-Alive:— which HTTP/1.1 §9.3 defines as persistent-by-default, but per rust-bitcoin/corepc#659bitreqtreats as connection-dead. That closes the loop on our capture: header omitted → bitreq drops the connection after every request → fresh TCP+TLS per VSS op → ~896 ms × N serialized.(Caddy also negotiates HTTP/2 by default when offered — the
bitreqpath is presumably HTTP/1.1-only, which is fine once keep-alive semantics are honored.)Standing offer stands: when the corepc fix (or a vss-client bump) is in a branch, we'll re-run the same A12 capture for before/after numbers.
One more workload datapoint with a built-in control: a trusted-tier receive's CDK issue saga made 91 VSS requests in 46s (median 634ms apart, serial) — while in the same log window, cdk's mint HTTP calls reused pooled hyper connections and completed in ~200ms each. Same process, two HTTP stacks: hyper-with-pool is fine, bitreq-without-keep-alive crawls. Nicely isolates the fix surface to the vss-client/bitreq path.
Okay but 200ms*91 is still 18 seconds which is insanely high and unacceptable. The requests need to be parallelized on the client side too. @benthecarman is that a CDK issue or something we can do?
This might be more of a cdk issue but we have our own storage impl to work with vss. I'll see if we can parallelize or reduce the number of keys.
cc @thesimplekid might be relevant for you too
@hash-money can you try #93 ? This should fix for cashu hopefully
12 remaining items
Full read/write traces from three independent receives (device-to-device, VSS-backed A12): https://gist.github.com/hash-money/955c29b749c69e0e6c04bda24feae7cb
Headline: a receive is ~30–50 serial VSS round-trips (
ChannelMonitorUpdatepersists areInProgress-gated, strictly one at a time), each ~300–500ms, so ~5–7s total.Important correction to my earlier keep-alive framing: two of the three captures reused connections (0 new
bitreqconnections) and were just as slow — so the per-op cost is the round-trip itself (network + VSS/postgres server), not TCP/TLS handshake. Phone↔AWS RTT is ~50–150ms, so there's ~150–350ms/op of server/round-trip overhead on a warm connection to explain. A local-SQLite A/B (same ldk-node monitor persists) runs each at ~10ms, so the gap is squarely the VSS path. Happy to grab deeper timing (per-request send→response) if useful.Can you include the namespace+key being written/read in each entry? Its hard to tell from just "we wrote something" what's going on. Maybe the LDK log as well with the same timestamps.
Added two files to the gist:
captureC_full_interleaved.log(the complete raw window — LDK + VSS + rustls lines, same timestamps, unfiltered) andcaptureC_keymap.md.On namespace+key: they're in the log, but post-obfuscation —
VssStoreobfuscates client-side (obfuscate(primary_namespace#secondary_namespace)#obfuscate(key), the schema-V1 design, so the server never learns key names), andvss_client_ngtraces the obfuscatedstore_keyit puts in the request. Since the obfuscation is deterministic, I clustered the window's 51 requests (37 Put / 9 Get / 5 List): 11 namespaces, 21 distinct keys. Highest-confidence identifications (details + evidence in the key map):- one namespace with 5 distinct keys, one per
ChannelMonitorUpdateid 1–5, each written 1–2ms after itsPersistence of ChannelMonitorUpdate id Nline — theMonitorUpdatingPersisterper-update deltas; - a separate single key at
Persistence of new ChannelMonitor(the initial full monitor); - the hottest namespace: 4 keys, 20 writes, re-written throughout payment processing (event-queue / tx-metadata / manager class — inference).
If exact identities matter, would you take a small ldk-node change to trace-log the pre-obfuscation namespace+key in
VssStorealongside the request id? That would make future traces self-describing. (Alternatively we can build a de-obfuscation table from our test seed, but the log-side fix helps everyone.)- one namespace with 5 distinct keys, one per
Ugh, the log just says "hottest namespace — re-written throughout payment processing incl. non-channel (cdk) phases → event-queue / tx-metadata / manager class (inference)" but that's just the agent guessing. Can you not patch vss_client to simply print the raw namespace and key in each get/put?
Done — I patched
VssStore(fork of ldk-node at your pinned rev0cea341) rather thanvss_client, since the obfuscation happens inVssStoreandvss_clientnever sees a raw name. Every op now logsVSS-RAW <op> primary#secondary#key -> <obfuscated store_key>, so each line joins 1:1 with the request traces already in the gist (verified 21/21 for the hottest key).Gist updated (same link, now with a readable front page): https://gist.github.com/hash-money/955c29b749c69e0e6c04bda24feae7cb —
00_SUMMARY.mdhas an annotated per-op timeline of one plain 4200-sat receive with raw keys inline; full windows incaptureD_receive_raw_keys.logandcaptureE_coldstart_raw_keys.log(cold start).What the raw names show — no inference this time:
- The "hottest namespace" is
orange_sdk##rebalance_enabled. Its obfuscated store_key is theMmTJGR9…one dominating captures A–C. BothRebalanceTriggermethods begin with an uncachedKVStore::readof this flag (rebalancer.rs:65and:147→store.rs::get_rebalance_enabled), so it is re-fetched over the network on every trigger evaluation — 21 of the 57 round-trips in this one receive window, ~1.4s apart. It is a user-toggle boolean; caching it in memory (invalidated byset_rebalance_enabled) removes ~1/3 of the receive-window VSS traffic for free. (Side note: the same accessorpanic!s on any non-NotFound store error, so each poll is also a crash surface on a flaky link.) - The receive critical path is what you suspected: serial
monitor_updates#<funding_txo>#Ndeltas (ids 6–10 here, strictly one at a time) interleaved with##managerrewrites (9×), one round-trip each. - Cold start is N+1 over history:
cashu_wallet#transactions#<txid>×20 andpayments##<hash>×13, all serial — 126 ops before first paint.
Happy to turn the
rebalance_enabledcaching into a small PR if that shape works for you.- The "hottest namespace" is
- The "hottest namespace" is
orange_sdk##rebalance_enabled. Its obfuscated store_key is theMmTJGR9…one dominating captures A–C. BothRebalanceTriggermethods begin with an uncachedKVStore::readof this flag (rebalancer.rs:65and:147→store.rs::get_rebalance_enabled), so it is re-fetched over the network on every trigger evaluation — 21 of the 57 round-trips in this one receive window, ~1.4s apart. It is a user-toggle boolean; caching it in memory (invalidated byset_rebalance_enabled) removes ~1/3 of the receive-window VSS traffic for free. (Side note: the same accessorpanic!s on any non-NotFound store error, so each poll is also a crash surface on a flaky link.)
Hmm, that seems like it should be immediately addressable. (cc @benthecarman)
- The "hottest namespace" is
Made #103 ! @hash-money lmk how much that improves
When you pull a log with #103, can you ask your agent to provide the full trace-log with the
VssStorepatch so that we get the full trace log with the additional key-level read/write info in the same log output?Also maybe test with #102 at the same time, at least for init.
Measured both. Short version: #103 is a clear win on the receive path — −44% VSS round-trips and −38% latency — and it removes a continuous ~1.5s background poll. It does not move cold start.
All numbers below are fresh captures from today; nothing is reused from the earlier A–E captures.
Build. orange-sdk pinned to
a477046b(head of #103). Against our previous pin841490cthat is exactly 4 commits —Add SECURITY.md, #102, its merge, #103 — so this isolates{#102, #103}and nothing else; the two build branches differ only in thatrev =line. I checked the compiled sources rather than assuming:handle.spawn(Self::init_inner(…))is present for #102, andRebalanceTriggerreadsevent_queue.get_rebalance_enabled()(in-memory cell) rather than the store for #103. ldk-node unchanged at your0cea341with the sameVssStoreraw-key patch, present in both APKs — so every log has the raw keys, thevss_client_ngrequests and the LDK lines in one file on one clock (VSS-RAW joins 1:1 with the requests, 32↔32 and 57↔57).Method. Drift on this device is bigger than the effect — my first single-sample comparison against a five-day-old log looked like a regression and wasn't. So: 3 runs per build, interleaved A/B/A/B/A/B, and then the whole thing repeated as a second independent pass ~2 hours later. 18 captures. Both passes give the same conclusions; pass 2 is quoted here.
Receive — one plain 4200-sat receive, mint → LSP → phone
baseline #103 VSS ops 57 / 60 / 59 (58.7) 32 / 33 / 33 (32.7) rebalance_enabledreads23 / 23 / 24 0 / 0 / 0 pay → PaymentReceived6.92 / 7.99 / 8.22s (7.71s) 4.45 / 4.91 / 5.06s (4.81s) Ranges don't overlap. Pass 1 independently: 55.3 → 31.7 ops (−43%), 7.19 → 5.63s (−22%), also separated. The op saving is entirely the flag — baseline ops minus its own flag reads is 35.3 vs 32.7 for #103, a ~2-op residual.
Where the win comes from. Pairing monitor updates by id and splitting at
PaymentReceived:capture ops flag reads in flight during a monitor update after PaymentReceivedbaseline r1 / r2 / r3 57 / 60 / 59 23 / 23 / 24 1 / 2 / 3 18 / 18 / 18 #103 r1 / r2 / r3 32 / 33 / 33 0 0 0 Only 1–3 of the ~23 reads land inside an open monitor-update window, so the flag was never the main cost on the commitment dance — that's still the serial
monitor_updates#…#Nwrites, one round-trip each.The bigger effect is that the flag is polled continuously at ~1.5s intervals and does not stop. In every baseline run 18 round-trips land after the payment is already received, and the poll was still going when we stopped capturing — last flag read 0.2–0.3s before the end of the window in all three runs, mean interval 1.50–1.60s. I'm deliberately not quoting a "tail duration" since that's bounded by how long I chose to capture rather than by the behaviour. The window-independent statement: the baseline does a VSS round-trip every ~1.5s for as long as the wallet is open; #103 does none. On a phone that's a radio wake-up every 1.5s, and for us it's worth more than the 2.9s of latency.
Cold start — launch to first balance paint
baseline #103 + #102 VSS ops 219 / 215 / 228 (220.7) 142 / 144 / 146 (144.0) rebalance_enabledreads62 / 61 / 63 1 / 1 / 1 init → first balance 17.91 / 20.05 / 21.16s (19.71s) 18.54 / 20.52 / 15.87s (18.31s) −35% round-trips, no measurable latency change — ranges overlap heavily. Pass 1 agrees (−39% ops, 16.75 → 16.46s, overlapping).
The polls weren't gating startup. What gates it is unchanged and is still the original #90 finding — per-item serial reads before first paint:
28 read cashu_wallet#transactions#<txid> 21 read payments##<hash> 13 read orange_sdk#payment_store#<id> 6 read cashu_wallet#mint_quotes#<id> 7 list cashu_wallet#transactions68 per-item reads at ~300–500ms each. Worth noting those grew from 53 in pass 1 purely because the wallet took 6 more receives in between — the cost scales with history, which is the N+1 signature. Until they're batched, or served local-first with async replication, cold start stays ~16–20s here no matter what the flag does.
On #102 specifically — treat us as no evidence either way. We run the Cashu trusted tier, not Spark. In both arms cdk work already began before
Creating LDK node..., so there was no starved initializer to unblock and the difference sits inside noise. #102 wants a Spark-tier reporter; please don't read our null as a negative.Full logs — raw keys + requests + LDK lines interleaved on one clock, preimages redacted: https://gist.github.com/hash-money/955c29b749c69e0e6c04bda24feae7cb
Okay, let's see, for the payment we're running in deferred write mode, so monitor writes are 2x slower. We have
One at2026-08-23 18:37:07.873->2026-08-23 18:37:08.500->2026-08-23 18:37:08.882. We get the response messages out to the LSP at2026-08-23 18:37:08.891, 9ms later.Then we hear back from the LSP at
2026-08-23 18:37:09.116and do a write cycle at2026-08-23 18:37:09.118->2026-08-23 18:37:09.539->2026-08-23 18:37:09.942.We then are ready to claim, but the BP writes the
ChannelManagerbefore processing events. This takes from2026-08-23 18:37:09.946to2026-08-23 18:37:10.547. This RTT is fixed by https://git.rust-bitcoin.org/lightningdevkit/rust-lightning/pulls/4981We then claim, with a write cycle from
2026-08-23 18:37:10.553->2026-08-23 18:37:11.151->2026-08-23 18:37:11.506.We figure out the payment is up and start writing the payment state at
2026-08-23 18:37:11.513.ldk-nodethen writes the payment received event to its store at2026-08-23 18:37:11.920.At this point LDK is continuing to complete the claim, though there's nothing in orange that cares. Still, its a bit delayed initiating the claim but that will also be fixed by https://git.rust-bitcoin.org/lightningdevkit/rust-lightning/pulls/4981.
After ldk-node finishes writing the payment received event, orange writes the payment claimed event at
2026-08-23 18:37:12.320.It appears orange completes handing out the payment sent event and ldk-node and it remove their corresponding events at
2026-08-23 18:37:13.365and2026-08-23 18:37:13.376. However, the list ofcashu_wallet#transactionsat2026-08-23 18:37:13.644might imply orange waited an RTT before it actually handled anything - is it blocking on the payment sent event removal? @benthecarman?There's then a few things in the
cashu_walletnamespace before we get to the 7-8 second mark, so its not entirely clear to me when we got the PaymentReceived event out of orange, but maybe there's some cashu stuff in the way there too? Would be good to update the logs to include the exact time the payment event happened on the client, at least on the next round of testing @hash-money.In
lightningthis means 6 RTTs to VSS + 1 RTT to the LSP after we receive the first message. There's one more RTT to VSS that we can remove with the linked PR. Then we have 2 VSS RTTs in ldk-node writing the payment state then event (@tnull can we cut this down to one at least? If the event is guaranteed to be replayed on restart fromlightningwhy do we need to block waiting on writing the event to VSS before passing it upstream?). We then appear to wait again for an RTT to write the payment event to orange's store (@benthecarman same question as above for ldk-node).This gives a total or 9 RTTs to VSS + 1 RTT to the LSP after PR 4981. We could make this 6 + 1 if we switched off deferred monitor writes, though I don't love that, but hopefully we can improve that with upcoming changes in future
lightningversions.All that said, the biggest issue appear to be that rustls is re-negotiating with VSS every time. That takes those 9 RTTs to VSS and makes them at least 18, or maybe 27. This is obviously the highest leverage fix as it would nearly halve our receive time.
@TheBlueMatt — next round captured, with the client-side event time stamped into the log this time. Same VSS-RAW raw-key harness, baseline fork core (pre-#103), one plain 4200-sat receive (mint → LSP → phone).
All times below are the phone wall clock (UTC). The
ldk-node/orangelines are the on-devicewallet.log; the one[CLIENT-APP]line is our Kotlin event drainer (RealWalletManager) logging the instantWalletEvent::PaymentReceivedcrossed the FFI into the app — it carries its ownInstant.now(), so it joins thewallet.logclock 1:1. Payment hashf800398b…5672d,amount_msat: 4_200_000, preimage redacted.03:37:45.112 Claiming inbound HTLC id 6 (preimage) [lightning::ln::channel] 03:37:45.119 VSS write ##manager (13824 bytes) 03:37:45.804 VSS write monitor_updates#…_0#38 (757 bytes) 03:37:46.358 VSS write payments##<hash> (176 bytes) (ldk-node payment state) 03:37:46.708 VSS write ##events (82 bytes) (ldk-node writes the event to VSS) 03:37:47.219 UpdateHTLCs → LSP: 1 fulfills, 1 commits 03:37:47.222 VSS write ##manager (11587 bytes) 03:37:47.223 orange_sdk::lightning_wallet: "Got ldk-node event PaymentReceived" ← orange has it 03:37:47.224 VSS write ##orange_events (84 bytes) (orange payment-claimed event) 03:37:47.480 commitment_signed from peer, awaiting monitor-update resolution 03:37:47.553 VSS write ##manager (12022 bytes) 03:37:47.750 VSS write ##events (2 bytes) (ldk-node event ack/remove) 03:37:47.758 [CLIENT-APP] RealWalletManager observed PaymentReceived ← the app has it 03:37:47.763 VSS write ##orange_events (2 bytes) (orange event ack/remove)To close the gap you flagged ("not entirely clear when we got the PaymentReceived event out of orange"):
- orange gets the event at
47.223— one##managerwrite after the ldk-node##eventswrite at46.708, i.e. the ~1 VSS RTT (~515 ms here) between ldk-node writing the event and orange picking it up, as you predicted. - the client app doesn't observe it until
47.758— a further ~535 ms. In that gap: the##orange_eventswrite (47.224), a##managerwrite (47.553), and the##events2-byte ack/remove (47.750). The app'swaitNextEventunblocks essentially in lockstep with that##eventsack write, and the##orange_eventsack follows at47.763.
That last stretch looks like exactly the double-block you were raising with @tnull / @benthecarman: on this baseline core the event isn't handed upstream to the app until after the store write cycle around it completes — first on the ldk-node side (
##events), then orange (##orange_events). ~535 ms of the receive is spent between "orange has the event" and "the app can render it," none of it on the wire.For scale, HTLC-land → app-event on this run:
03:37:42.333(firstcommitment_signed) →03:37:47.758= 5.42 s, in line with your baseline pass (6.9–8.2 s; a touch faster here, device/liquidity state).The
[CLIENT-APP]line is a one-liner in our FFI event drainer, kept out ofmain(DO-NOT-MERGE trace build) — I can leave it in for future rounds. Happy to drop the full raw window (VSS keys intact, preimage redacted) in a gist to join against your request log 1:1 if that's useful.- orange gets the event at
@TheBlueMatt — measured corepc#661 on the Lightning receive path you traced, plus a root cause underneath it that turned out to be the bigger story.
Setup. Same A12 / VSS-RAW harness /
[CLIENT-APP]stamp as the 09-09 round, one plain 4200-sat receive per run, mint → LSP → phone, interleaved A/B/A/B/A/B with each arm reinstalled between runs. A = our current core (crates.io bitreq 0.3.4, rustls 0.21 on the VSS path). B = A with[patch.crates-io] bitreq→ corepc#661 headf46ab3a(which also moves that path to rustls 0.23.38, the PR's minimum — disclosed as a confound). Per-op durations come from aVSS-RAW done <op> in <ms>line added to the trace fork.Receive — first
commitment_signedfrom the LSP →PaymentReceivedobserved by the appA (bitreq 0.3.4) B (#661) HTLC → app event 5.51 / 5.19 / 5.03 s (5.24 s) 1.91 / 2.25 / 2.12 s (2.09 s) VSS ops in the window 15 / 16 / 14 13 / 13 / 13 TLS handshakes in the window 13 / 14 / 13 0 / 0 / 0 per-op median (ms) 395 / 477 / 387 (420) 153 / 159 / 150 (154) Ranges don't overlap on any row; pay-request → app event is 7.73 / 7.32 / 7.71 s vs 3.64 / 4.54 / 4.42 s. Every op on A opens a new TLS session (the "Resuming session … PSK" you saw — in the 6 h main-build log before this run: 1,978 requests, 2,185 handshakes). On B the connection persists, so #661 removes the handshake and the cold congestion window from every op: the per-op cost drops ~2.5× and the receive more than halves. Your "would nearly halve" estimate was conservative.
The bigger finding: large VSS writes hang until the timeout — a missing
flush()in bitreqWhile driving the runs, every receive that landed inside a certain 5-minute window after app start took ~2 minutes instead of 5 s. The cause: 60 s after start the BP persists the network graph (
##network_graph, 1,038,424 B on Mutinynet) to VSS, and on the phone that write times out at vss-client's hard 10 s, 13 times in a row, then fails after ldk-node'smax_total_delay(180 s)— 304 s in total — while every queued store write (##manager,monitor_updates) waits behind it. It repeats hourly (NETWORK_PRUNE_TIMER); the main build log shows the same 13-attempt streak at 18:48, 19:28, 20:33, 21:38.It is not bandwidth and not the server:
- phone → LAN host, 1 MB: 0.80 s; a 253 KB
bdk_wallet##local_chainwrite completes in ~850 ms on the same phone; - a standalone client (vss-client-ng 0.6.0 + bitreq 0.3.4, fresh
SigsAuthkey, single attempt) run on the server host straight to vss-server over HTTP: 12/12 OK in 10–20 ms for both 1 MB and 253 KB; - the same binary from a wired desktop through Caddy/TLS: hangs in streaks regardless of size (one run: 6/6 × 253 KB hung), Caddy logging each as
readfrom tcp caddy→vss: unexpected EOF— the client closed at its 10 s timer before the body was complete; ss -tnion the client during a hang:bytes_sent ≈ bytes_acked ≈ 195–203 KB(≈ cwnd × MSS),unacked 0, notsent 0,lastsndclimbing. The kernel had nothing left to send; the application never handed over the last ~50 KB.
The code: bitreq's async request path does
write.write_all(&request.as_bytes()).awaitand goes straight to reading the response, with noflush()(0.3.4connection.rs:487; same on #661 at:517, and the sync path at:793). tokio-rustls'poll_writebuffers the plaintext into the rustls session and only opportunistically pushes ciphertext (while wants_write { write_io → Ready(Ok(0)) | Pending => break }, thenReady(Ok(n))), so whenever the socket is full on the last write the tail of the request stays buffered forever. Small requests never hit it; anything larger than what the socket accepts in one go — a fresh connection's cwnd — hangs.Fix is one line in each path:
let write_res = Self::timeout(request.timeout_at, async { write.write_all(&request.as_bytes()).await?; write.flush().await }).await; // sync path: self.stream.write_all(&request.as_bytes())?; self.stream.flush()?;
Same desktop → Caddy matrix, single attempt each:
stack 253 KB × 12 1 MB × 6 bitreq 0.3.4 6/6, 5/6 and 1/1 hung across three runs 2/8 hung bitreq 0.3.4 + flush 12/12 OK, ~0.53 s 6/6 OK, ~0.8 s #661 f46ab3afirst 4 hung (fresh connections), then 8/8 OK at 0.09 s once warm 6/6 OK at 0.12 s warm #661 + flush 8/8 OK (0.64 s fresh, 0.09 s warm) 4/4 OK, 0.12–0.23 s So #661 masks the bug once a connection is warm (the warm cwnd swallows the whole body) but every fresh connection can still hang — which is exactly what the phone's B arm did: 10 hung graph attempts, then a lucky 11th (121.8 s / 124.7 s in two runs) where A gives up at 304 s. With the flush, the phone-side 1 MB write should be a ~1 s affair. On-device check: a third arm C = #661 + the flush, installed twice — the post-launch 1 MB graph write completed on the first attempt in 1.10 s and 1.22 s (0 retries), where the same write took 304 s to fail on A and ~123 s / 11 attempts on B; its receives were 1.90 / 1.66 s, matching B.
Happy to open the flush as a PR against corepc (on top of #661 or standalone — @tnull, your call), and to put the standalone repro + the
sstraces in the gist. Two smaller observations from the raw keys, for whoever owns them: the graph is persisted to the remote store hourly although it is a rebuildable cache (1 MB up every hour on a phone), andbdk_wallet##local_chain(253 KB) was re-uploaded whole roughly every 30–80 s during the runs.- phone → LAN host, 1 MB: 0.80 s; a 253 KB
The bitreq flush fix is up as a PR against corepc
masteron Forgejo, with unit tests through a buffering writer (both fail without the flush): https://git.rust-bitcoin.org/rust-bitcoin/corepc/pulls/705 — it applies cleanly on top of #661 as well.661 - 1.91 / 2.25 / 2.12 s (2.09 s)
Okay! Now we're getting more reasonable. #107 might cut out another RTT or two and https://git.rust-bitcoin.org/lightningdevkit/rust-lightning/pulls/4981 will cut at least one out, so it'll probably be relatively reliably under 2s. That's not perfect, but seems more tolerable than 6-10s and might be what we have to live with in the short term.
There's long-term reworks of the LDK channel persistence flow that are making progress and will cut out a bit less than half of the RTTs we see here but they're a ways away. At that point we'd be almost bound by LN protocol, basically.
Thanks! I left some review comments, PTAL.
Measurement (signet + Cashu, same config, only storage differs)
OrangeWallet::newStorageConfig::VssTraced with
RUST_LOG=info,cdk=debug,reqwest=debug,hyper=debug,rustls=debug: ~8s in the VSS store build (build_with_sigs_auth) +Cashu::init(the Cashu DB is VSS-backed), then ~10s inldk_nodebuild_with_storereading LDK state — the KV reads appear serial, one network round-trip each. Feerate cache (288ms) and chain sync are minor.fetch_mint_infois a background task and not implicated (earlier misattribution, corrected).OrangeWalletbuilds oneVssStoreand passes it as the singlestoreto bothCashuKvDatabaseandLdkNodeStore(src/lib.rs), so every cold start rebuilds all state over the network.Fix directions (in rough order of ambition)
Happy to test candidate branches against our staging VSS (Caddy-fronted,
https://…/vss) — the 34× gap makes wins easy to verify. Repro recipe and full logs in our downstream issue: emergent-money/graduated-wallet#247.