You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
{{ message }}
Repository navigation
Contact payment latency on staging with the shared Paykit runtime: pin paykit-rs#171 and re-measure #868
Follow-up from #856. With the shared Paykit runtime on paykit rc59, contact-payment actions are much slower against the staging homeserver than on master. The remaining cost is the per-transaction homeserver lock in the SDK, which pubky/paykit-rs#171 targets. This issue tracks pinning a paykit release that contains #171 and re-measuring.
Measured on staging at #856 head c334a6f (iOS simulator, with an Android emulator as the linked contact):
Done when, on staging, Send Request reaches "Sent" within ~10 s, contact payments off completes within ~30 s, and Request or Pay is offered within one maintenance round (~60 s) of a cold launch.
Journey to reproduce
<journeyname="Contact Payment Latency">
<description>
Measures how long contact-payment actions take against the staging homeserver. Requires two Bitkit instances saved as each other's contacts and linked as identities, with contact payments on, both on the staging homeserver.
</description>
<actions>
<action>Force-quit Bitkit on device A, launch it, and note the launch time</action>
<action>Every 2 minutes, open the contact for device B from Contacts and tap Pay (id "ContactPay"); record the first time the Request or Pay sheet (id "RequestOrPaySheet") appears instead of the amount screen, and verify it is within 60 seconds of launch</action>
<action>Tap Request, enter 1,000 sats, tap Send Request and record the time until "Payment requested" (id "PaymentRequestSent") appears; verify it is within 10 seconds</action>
<action>On device B, idle on Home, record when the Payment Request confirmation screen (id "PaymentRequestConfirm") appears</action>
<action>On device A, open Settings, General, turn off Enable payments with contacts (id "ContactPaymentsToggle") and record the time until the switch is enabled again showing off; verify it is within 30 seconds and no error toast appears</action>
<action>Turn Enable payments with contacts back on and record the time until it settles on</action>
</actions>
</journey>
Retested with published rc60 on iOS 10b85a1 and Android dc73b29d7, using fresh staging identities saved as contacts on both devices.
Warm iOS Contact Pay showed Request or Pay in under a second.
A 1,000-sat request was sent and appeared in Android’s request list. Send Request was still busy after 26.7 seconds and was complete at the next check, 93.3 seconds after tapping. This is a measured interval, not an exact latency, and still misses the 10-second target.
iOS sharing OFF immediately disabled local publication, but remote cleanup exceeded 30 seconds. Both private/public cleanup flags eventually cleared. Android withdrawal also completed with both cleanup flags cleared.
Initial linking still took minutes. This was fresh setup, not the cold-launch journey, and does not validate the 61-contact case.
rc60 includes #169/#170/#171, so the release dependency is removed, but this performance issue is not resolved. The remaining active send/withdrawal paths still perform multiple serialized shared-state transactions. Separating their network time from app-queue and lock waits is the next step; these results do not establish that the homeserver itself is the bottleneck. No payment was broadcast in this run.
Latest staging measurements used the published rc61 binaries with one linked, unfunded iOS/Android pair:
Warm iOS Request or Pay opened in under one second.
A 5,000-sat request sent at approximately 15:23:20 UTC completed between 23.2 and 25.6 seconds after Send.
Android's open request list was still missing it at 4.9 minutes and showed the matching request by 6.4 minutes. This is the observed display interval, not an exact network-delivery timestamp.
Android's private withdrawal phase took about 49 seconds in an earlier rc61 run. That is not the full public/private cleanup duration.
Both PRs now use published rc62. It retains the batching and polling improvements and fixes a separate SDK issue where four concurrent outbound peers could consume each other's leases while waiting on shared storage. It does not explain or establish a fix for the one-peer delay above. No rc62 staging latency result is claimed here.
Keep this open. We need timings for repository/SDK queue waits, outbound work, intake and request-list updates before attributing the remaining delay to Bitkit or the homeserver. Android also queues overlapping refreshes instead of coalescing them as iOS does; its impact in this run is unmeasured. No safety timeout was reduced.
No payment was broadcast in these unfunded-wallet runs. Full payment/unlock, the 61-contact case, cold start and backup-stall QA remain unverified. The separate wallet broadcast dependency is still tracked in iOS #844 and Android #1384.
I profiled one linked, unfunded staging pair using a local build of #171 at 13feb12a. These measurements predate the later registry/endpoint lock reuse and the newest iOS cleanup changes; they are not measurements of the currently published rc62 or the final PR head.
Sending one request took 22.416s:
Dispatch and queue wait: 0.295s.
Identity check: 0.848s.
Link-state read: 0.848s.
Other local/dispatch time: 0.446s.
Save proposal: 4.679s.
Process outbound: 15.300s.
A second request took 21.169s. Both appeared on Android, but Android restarted during the test, so this does not establish warm delivery latency.
Sharing OFF switched the UI immediately, but the last remote cleanup call completed after 84.326s:
Work
Seconds
Dispatch and initial peer lookup
1.038
Batched private withdrawal
21.079
Drain, checks and interleaved poll/backup work
21.408
Private capability registry update
12.748
Queue wait
1.694
Public endpoint cleanup
13.292
Queue wait
2.836
Final registry update
10.233
The drain included an unnecessary 11.296s link check, now skipped when nothing remains queued. Sharing ON also repeated a registry update unnecessarily; that is removed. The channel-availability refresh no longer starts another public publication alongside its explicit publication.
These are wrapper execution times, including SDK checks, not isolated network/CPU timings. Warm Request or Pay opened within one second, but remote actions remain too slow. The newer direct SDK measurements show further improvement, not a completed mobile retest. Keeping this open; no funded payment or content unlock was tested.
Retested with current #171 source, not published rc62: measured breakdown. Request sending took 24.0s; sharing OFF remote work took 63.1s, with both cleanup flags clearing afterward. The main phases are listed there. These still miss the targets, so this remains open. No funded payment or content unlock was tested.
New same-identity staging measurements with the FFI batching fix: request send 21.6s -> 16.6s; full sharing withdrawal 68.2s -> 46.4s. Warm Contact Pay was 10.2s, almost entirely SDK execution in that sample. The local toggle changes immediately; withdrawal numbers include remote cleanup. Detailed queue owners, storage counts and limitations are in pubky/paykit-rs#171 (comment) . These are individual unfunded runs, not final-head acceptance: the latest recovery-marker fix still needs device retesting. Keeping this open.
Matched before/after measurements with the current iOS source and the SDK batching changes: warm Pay 8.5s to 5.0s; send request 18.2s to 14.6s; incoming preparation 20.4s to 20.9s; full sharing withdrawal 44.7s to 40.2s. Both withdrawals finished with cleanup flags clear.
Incoming preparation still spends about 20s inside the SDK, not waiting for the app queue or wallet. Withdrawal spends about 34s in the SDK and 6s waiting for other SDK operations. Those paths still need work, so this issue remains open. One contact, one ordered comparison, unfunded wallets; no full payment claim. The staged-handshake follow-up is not included yet.
I repeated the flows with the existing Send sheet and local builds of the combined SDK stack. The known request details appear immediately and the swipe stays loading until preparation is complete; the sheet then becomes payable in place.
The SDK preparation fell from 16.8s to 7.6s, but the actual incoming-sheet wait was still 17.9s versus 17.3s. The candidate spent 9.4s behind a private-list publication that the same polling round started before presenting the request. I am fixing that scheduling order without interrupting active writes.
Warm Contact Pay was 4.5s, sending a request 19.8s, and complete sharing withdrawal 43.2s. Those are single samples, not averages. No payment was broadcast. Full comparison and limitations. This issue stays open.
Retested the same identity pair with the latest app changes and the unreleased #171 SDK build. Incoming request preparation fell from 18.3s to 5.0s, and the existing Send sheet shows the request details with payment disabled/loading until ready. Send Request took 13.6s; warm Contact Pay took 5.9s; full sharing withdrawal still took 44.8s.
Sender tap to receiver-ready was about 24s, including sending and inbox scheduling. These are single measured runs, not averages or full payment completion. Withdrawal and larger-contact performance remain open. The app PR still uses published rc62.
Contact Pay: iOS amount sheet in 8.6s, repeat 6.2s. Android Send visible 4.5s after handler start.
Send Request: about 15s on both platforms.
Received request: Pay enabled about 3.5-3.7s after preparation/presentation starts. Detection and polling add another 10-21s in these samples.
Sharing OFF: 64.5s iOS and 41.2s Android, including 20.3s and 6.5s of queue wait respectively.
Fresh linking is still slow. Both apps eventually reached Linked, with iOS observed Linked by 117s after Save. The first iOS private Pay attempt failed preparation before a later attempt opened its private endpoint in 2.8s.
Performance remains open. These are individual runs, not matched before/after measurements or downloaded-rc63 binary tests. There was no funded payment in this capture. Large-contact mobile tests and Bitkit plus a running Server still need validation. No five-minute pending-write wait occurred in these completed samples.
Numbers at #856591ac12 with paykit rc63, two simulators on staging, fresh identities:
Action
rc63
rc62
Target
Send Request → "Sent"
≤ 13–17 s
≤ ~30 s, 57–173 s
~10 s
Request reaches the receiver (sheet opens)
17.5–27 s after the Send tap
43–59 s
n/a
Automatic sheet preparing → ready
3.3 s, 15.5 s
57–60 s
3 s
Bell Pay tap → ready
15.6 s
36.7 s
3 s
Swipe → broadcast
~33–36 s
~54 s
n/a
Contact payments off / on
26–46 s / ≤ 20 s
89–113 s / 28–34 s
~30 s
Cold launch → session restored
11–12 s; 61 s once right after a sharing change
19.6–117 s; up to 6 min 13 s
n/a
Cold launch → Request and Pay offered
35 s – 2 min 21 s (bracket)
up to 4 min 53 s
~60 s
First link, fresh pair
≤ 3 min 3 s
~7 min
n/a
Close to target now: Send Request and contact payments off. Still above: Pay → ready when the wallet has to build the transaction (15.6 s), swipe → broadcast, the time until Request is offered after a launch or a new link, and the one 61 s restore with two concurrent_update lines after a sharing change.
Numbers at #856f79cfcb with paykit rc65 (two simulators, staging, identities carried over from rc63): payment and sharing timings are unchanged from rc63 (Send Request ≤ 14 s, sheet ready 3.5 s, swipe → broadcast 34–42 s, sharing off 25–43 s). Paying a contact whose sharing is off now shows the "Unable To Pay Contact" toast in ≤ 4 s.
Open on rc65: a cold launch shortly after a write is slow. A quiet launch restores in ~12 s. A launch 38 s after a payment broadcast took 62.6 s and 69.3 s (Deferred session restoration, 3–4 concurrent_update). A launch 12 s after a sharing toggle settled took 63.4 s on one simulator and 6 min 2 s on the other (SharedStateBusy … pending writes could not be ruled out, then nothing for five minutes). Until the session restores there is no bell, activity rows lose the contact name, and contact deeplinks fail. Full table: #856 (review)
Thanks, the rc65 run confirms the slow relaunch is not Android-only. I recorded the matching Android evidence in synonymdev/bitkit-android#1419. Quiet restoration and restoration after interrupted writes need to stay separate in the measurements. The pending-write wait must remain until we can prove a previous write cannot still finish; these timings do not justify clearing its marker or shortening the safety interval.
Keeping this open. The rc65 atomic contact import fix does not resolve the cold-launch delay or the temporary loss of contact names, bell and deeplink availability during restoration.
Published rc66 check with two fresh staging wallets and regtest funds: both directions completed a 5,000-sat request payment, with receiver credit and independently confirmed chain transactions. App builds were iOS a04232f and Android fd04581d2, before the later link-preparation changes. These are single runs, not a matched before/after benchmark.
For the iOS payer:
Pay on a saved request: preparation preview by 0.92s; private payment opened at 3.745s.
Swipe to private-list consumption: 6.810s.
Local acceptance record to wallet entry: 2.845s, enclosing the combined claim-and-accept call, not an isolated SDK measurement.
Wallet entry to LDK send: 3.096s, including pre-broadcast proof/authorization work.
LDK send to successful broadcast: 0.443s. Total swipe-command to broadcast: 13.208s; Sent observed by 16.722s.
A reverse-direction Send Request showed Sent within 23.81s. Warm Request-or-Pay appeared within 0.46s.
The logs do not split SDK queue wait, homeserver locks, state reads/commits and Noise within those intervals. Initial linking, exact request-delivery timing, cold-start and many-contact performance remain open. This does not resolve the failure/recovery journeys or establish the performance of the newer heads. Transaction: 53f92e55d1eaee0cc3892191026b04e593ed028eeffe42da40c90fd12cba4683, confirmed at regtest height 216148.
@ovitrif Could you attach the redacted app trace around the 47-second resume sample, or capture one bounded repeat with your isolated buyer/seller fixture? Please include the exact error line/call site and timestamps for foreground/auth state, import commit and fresh contact read, preparation enqueue/start, and SDK queue admission/start/completion until the seller's first link call. Record whether the contact snapshot or sign-in generation changed.
@ben-kaufman The earlier trace is gone, so I ran one bounded repeat on e3796d9. sessionNotActive did not reproduce. The delay did, and it was longer. The new seller was imported 20 s after foreground. Its preparation was then dropped at PrivatePaykitService+Contacts.swift:112 and never re-queued, so no link call ran until the next foreground. I brought Bitkit back to the foreground by hand about 5 min after the import, and its first link call came 5 min 19 s after the import. Without that foreground, the wait lasts until some other trigger (foreground, node running, network restored). Auth and sign-in stayed current throughout. The SDK queue never held a preparation call for more than 3.1 s.
No preparation and no ensureLinkWithPeer for about 5 min while the app stayed in front
—
10:49:21.882 → 10:49:32.807
Background, then a second foreground, done by hand to end the wait
AppScene.swift:1233
10:49:33.233
All three keys enqueued; preparation starts
Contacts.swift:114–115, :241–242
10:49:40.187
First ensureLinkWithPeer for S3 (SDK queue wait 0.70 s)
Contacts.swift:694 → PubkyService.swift:957
Why it was dropped.ContactsManager.loadContacts assigns contacts at :396, and that publishes savedContactsChanged. The same call then reaches pruneUnsavedContactState at :407, which calls rememberSavedContacts(replacing: true). That bumps savedContactsRevision (Contacts.swift:1308) between the preparation's read at :109 and its guard at :112, so the import-triggered preparation sees a moved revision and returns. The bump itself was not logged. It follows from the code order and the timestamps: the drop is at 22.283, and Loaded 3 contacts (:411, after the prune) is at 22.284.
The open-app path shows the same drop. S1 and S2 were imported at 10:36:31.7, their preparation was dropped at 10:36:32.001 the same way, and they got no link call for 7.5 min, until the resume above. The drop is a race: the prepare's read and guard run against the prune at ContactsManager.swift:407. It lost on both imports in this run. The earlier e3796d9 open-app sample did get a link call, 72 s after import, so either the race does not lose every time or another trigger fired then. That run has no log to say which.
Your questions.
Sign-in generation: unchanged. isSessionCurrent never returned false; I logged each of its three conditions separately. Auth stayed authenticated the whole run.
Contact snapshot: it changed once, from 2 to 3 keys, at the import. The drop comes from the revision check, not from the snapshot closure.
Obsolete work: none. The old-snapshot run finished at 10:44:11, 10 s before the import, so it never reached the :727 throw. That is the likely reason no sessionNotActive appeared this time.
Lost retry or SDK time: a lost retry. SDK queue waits were at most 3.1 s and each SDK call ran at most 1.9 s.
On the rc75 sample: the import landed 3 s after foreground there, so the old-snapshot run would still have been in flight and could fail at :727. That fits the sessionNotActive we saw, with the new seller's own preparation dropped as here. This run does not prove it. Note also that the 47 s there ran from foreground to link, about 44 s after import, and that run has no log of what started the link.
Setup.
Build: Debug regtest build of e3796d9 against staging. The head has not moved past e3796d9.
Device: iPhone 17 simulator on iOS 26.5, fresh install.
Accounts: a fresh buyer created in Bitkit with contact payments on, and three fresh staging sellers, each publishing a valid shop.json.
Markers: written to the buyer's seller-auto-follow/v1/ folder.
Seller links: the fixture sellers publish no Paykit, so every ensureLinkWithPeer ended in NotFound. The trace times when the link call starts, not a completed link.
Logging: the build adds local log lines only (diff below, not pushed). Line numbers in the table are e3796d9's; the excerpt's are the logging build's.
Recording at 2x: background with Settings in front, the marker written, foreground, then the second background and foreground.
resume.2x.mp4
Log excerpt (UTC, keys shortened)
10:43:26.970 INFO AppScene.swift:1234 Scene phase changed: inactive
10:43:29.832 INFO AppScene.swift:1234 Scene phase changed: background
10:44:00.983 INFO AppScene.swift:1234 Scene phase changed: inactive
10:44:01.415 INFO AppScene.swift:1234 Scene phase changed: active
10:44:01.430 INFO ContactsManager.swift:383 Loading contacts for pubkyjrwya4a...
10:44:01.904 INFO AppScene.swift:1281 foregroundSync done active=true auth=authenticated
10:44:01.904 INFO AppScene.swift:1330 prepareSavedPaykitContacts[6325] snapshot=2 keys=["pubkypcgpncj...", "pubky6rr6dtj..."] expectedIdentity=false
10:44:01.904 INFO PrivatePaykitService+Contacts.swift:115 prepareSavedContacts enqueue keys=["pubkypcgpncj...", "pubky6rr6dtj..."] taskRunning=false active=0
10:44:01.905 INFO PrivatePaykitService+Contacts.swift:243 preparation start keys=["pubky6rr6dtj...", "pubkypcgpncj..."]
10:44:01.923 INFO ContactsManager.swift:411 Loaded 2 contacts
10:44:02.599 INFO PrivatePaykitService+Contacts.swift:670 syncLocalEndpointPublication start reason=contact preparation keys=["pubky6rr6dtj...", "pubkypcgpncj..."]
10:44:04.520 INFO PubkyService.swift:1703 sdkLock admit[AFD3] linkedPeers(priority:) prio=background locked=true waiters=1
10:44:07.607 INFO PubkyService.swift:1705 sdkLock start[AFD3] linkedPeers(priority:) waited=3.08s
10:44:07.971 INFO PubkyService.swift:1707 sdkLock done[AFD3] linkedPeers(priority:) total=3.45s
10:44:07.977 INFO PrivatePaykitService+Contacts.swift:698 link step pubky6rr6dtj... state=nil
10:44:07.977 INFO PubkyService.swift:1703 sdkLock admit[C8FF] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) prio=background locked=true waiters=1
10:44:08.307 INFO PubkyService.swift:1703 sdkLock admit[6A6C] linkedPeers(priority:) prio=background locked=true waiters=1
10:44:08.602 INFO PubkyService.swift:1703 sdkLock admit[440D] linkedPeers(priority:) prio=background locked=true waiters=1
10:44:08.602 INFO PubkyService.swift:1705 sdkLock start[C8FF] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) waited=0.62s
10:44:09.208 INFO PubkyService.swift:1707 sdkLock done[C8FF] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) total=1.23s
10:44:09.209 INFO PubkyService.swift:1705 sdkLock start[6A6C] linkedPeers(priority:) waited=0.90s
10:44:09.212 INFO PrivatePaykitService+Contacts.swift:707 link NotFound pubky6rr6dtj... -> 5 min skip
10:44:09.213 INFO PrivatePaykitService+Contacts.swift:698 link step pubkypcgpncj... state=nil
10:44:09.213 INFO PubkyService.swift:1703 sdkLock admit[0962] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) prio=background locked=true waiters=1
10:44:09.544 INFO PubkyService.swift:1707 sdkLock done[6A6C] linkedPeers(priority:) total=1.24s
10:44:09.545 INFO PubkyService.swift:1705 sdkLock start[440D] linkedPeers(priority:) waited=0.94s
10:44:09.879 INFO PubkyService.swift:1707 sdkLock done[440D] linkedPeers(priority:) total=1.28s
10:44:09.883 INFO PubkyService.swift:1705 sdkLock start[0962] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) waited=0.67s
10:44:10.826 INFO PubkyService.swift:1707 sdkLock done[0962] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) total=1.62s
10:44:10.828 INFO PrivatePaykitService+Contacts.swift:707 link NotFound pubkypcgpncj... -> 5 min skip
10:44:10.830 INFO PrivatePaykitService+Contacts.swift:734 publication lock wait prepared=0 retry=0
10:44:10.830 INFO PrivatePaykitService+Contacts.swift:736 publication lock acquired
10:44:11.170 INFO PrivatePaykitService+Contacts.swift:245 preparation end pending=0
10:44:20.108 INFO ShopContactImporter.swift:61 importer page listed=3
10:44:20.748 INFO ShopContactImporter.swift:89 importer save start sellers=["pubky5n8gn5q..."]
10:44:20.748 INFO PubkyService.swift:1703 sdkLock admit[B8D9] importShopContacts(publicKeys:expectedIdentity:isStillCurrent:) prio=background locked=true waiters=0
10:44:20.895 INFO PubkyService.swift:1705 sdkLock start[B8D9] importShopContacts(publicKeys:expectedIdentity:isStillCurrent:) waited=0.14s
10:44:21.632 INFO PubkyService.swift:1707 sdkLock done[B8D9] importShopContacts(publicKeys:expectedIdentity:isStillCurrent:) total=0.88s
10:44:21.633 INFO ShopContactImporter.swift:91 importer save committed changed=true
10:44:21.633 INFO ContactsManager.swift:383 Loading contacts for pubkyjrwya4a...
10:44:22.277 INFO AppScene.swift:632 savedContactsChanged count=3
10:44:22.282 INFO AppScene.swift:1330 prepareSavedPaykitContacts[CCC5] snapshot=3 keys=["pubky5n8gn5q...", "pubkypcgpncj...", "pubky6rr6dtj..."] expectedIdentity=true
10:44:22.283 INFO PrivatePaykitService+Contacts.swift:112 prepareSavedContacts dropped: revision/generation moved
10:44:22.284 INFO ContactsManager.swift:411 Loaded 3 contacts
10:44:22.284 INFO ShopContactImporter.swift:95 importer contact refresh done
… idle: importer polls every ~11 s and background linkedPeers reads every ~1 min; no preparation, no ensureLinkWithPeer
10:49:21.882 INFO AppScene.swift:1234 Scene phase changed: inactive
10:49:22.716 INFO AppScene.swift:1234 Scene phase changed: background
10:49:32.366 INFO AppScene.swift:1234 Scene phase changed: inactive
10:49:32.807 INFO AppScene.swift:1234 Scene phase changed: active
10:49:32.822 INFO ContactsManager.swift:383 Loading contacts for pubkyjrwya4a...
10:49:33.227 INFO AppScene.swift:1281 foregroundSync done active=true auth=authenticated
10:49:33.228 INFO AppScene.swift:1330 prepareSavedPaykitContacts[9B53] snapshot=3 keys=["pubkypcgpncj...", "pubky6rr6dtj...", "pubky5n8gn5q..."] expectedIdentity=false
10:49:33.233 INFO PrivatePaykitService+Contacts.swift:115 prepareSavedContacts enqueue keys=["pubkypcgpncj...", "pubky6rr6dtj...", "pubky5n8gn5q..."] taskRunning=false active=0
10:49:33.233 INFO PrivatePaykitService+Contacts.swift:243 preparation start keys=["pubky5n8gn5q...", "pubky6rr6dtj...", "pubkypcgpncj..."]
10:49:33.371 INFO ContactsManager.swift:411 Loaded 3 contacts
10:49:33.959 INFO PrivatePaykitService+Contacts.swift:670 syncLocalEndpointPublication start reason=contact preparation keys=["pubky5n8gn5q...", "pubky6rr6dtj...", "pubkypcgpncj..."]
10:49:36.219 INFO PubkyService.swift:1703 sdkLock admit[DE74] linkedPeers(priority:) prio=background locked=true waiters=1
10:49:39.188 INFO PubkyService.swift:1705 sdkLock start[DE74] linkedPeers(priority:) waited=2.97s
10:49:39.475 INFO PubkyService.swift:1707 sdkLock done[DE74] linkedPeers(priority:) total=3.26s
10:49:39.480 INFO PrivatePaykitService+Contacts.swift:698 link step pubky5n8gn5q... state=nil
10:49:39.480 INFO PubkyService.swift:1703 sdkLock admit[0110] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) prio=background locked=true waiters=1
10:49:39.842 INFO PubkyService.swift:1703 sdkLock admit[3206] linkedPeers(priority:) prio=background locked=true waiters=1
10:49:40.187 INFO PubkyService.swift:1705 sdkLock start[0110] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) waited=0.70s
10:49:40.189 INFO PubkyService.swift:1703 sdkLock admit[4562] linkedPeers(priority:) prio=background locked=true waiters=1
10:49:40.908 INFO PubkyService.swift:1707 sdkLock done[0110] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) total=1.43s
10:49:40.911 INFO PrivatePaykitService+Contacts.swift:707 link NotFound pubky5n8gn5q... -> 5 min skip
10:49:40.911 INFO PrivatePaykitService+Contacts.swift:698 link step pubky6rr6dtj... state=nil
10:49:40.912 INFO PubkyService.swift:1703 sdkLock admit[77EE] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) prio=background locked=true waiters=1
10:49:40.912 INFO PubkyService.swift:1705 sdkLock start[3206] linkedPeers(priority:) waited=1.07s
10:49:41.288 INFO PubkyService.swift:1707 sdkLock done[3206] linkedPeers(priority:) total=1.45s
10:49:41.289 INFO PubkyService.swift:1705 sdkLock start[4562] linkedPeers(priority:) waited=1.10s
10:49:41.758 INFO PubkyService.swift:1707 sdkLock done[4562] linkedPeers(priority:) total=1.57s
10:49:41.759 INFO PubkyService.swift:1705 sdkLock start[77EE] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) waited=0.85s
10:49:42.809 INFO PubkyService.swift:1707 sdkLock done[77EE] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) total=1.90s
10:49:42.810 INFO PrivatePaykitService+Contacts.swift:707 link NotFound pubky6rr6dtj... -> 5 min skip
10:49:42.811 INFO PrivatePaykitService+Contacts.swift:698 link step pubkypcgpncj... state=nil
10:49:42.812 INFO PubkyService.swift:1703 sdkLock admit[1D8C] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) prio=background locked=false waiters=0
10:49:42.812 INFO PubkyService.swift:1705 sdkLock start[1D8C] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) waited=0.00s
10:49:43.565 INFO PubkyService.swift:1707 sdkLock done[1D8C] ensureLinkWithPeer(_:maxAdvanceSteps:priority:) total=0.76s
10:49:43.569 INFO PrivatePaykitService+Contacts.swift:707 link NotFound pubkypcgpncj... -> 5 min skip
10:49:43.571 INFO PrivatePaykitService+Contacts.swift:734 publication lock wait prepared=0 retry=0
10:49:43.571 INFO PrivatePaykitService+Contacts.swift:736 publication lock acquired
Thanks, this trace let us reproduce the dropped preparation in a deterministic test. The preparation's session check suspends on MainActor; pruning can advance the service revision while it is suspended, and the original guard then discards the still-current snapshot.
The fix is pushed in #934 at 734e020d30005ab86384048249922d2d9aada3bd. It revalidates that snapshot until the revision is stable, retaining the original preparation generation and still rejecting removed contacts, ended sessions, invalidation and cancellation. No SDK request, polling interval or safety wait was added or changed. The regression fails against the previous source; all five table cases pass with the fix, along with 226 focused tests and 2,572 native unit tests. Current master is integrated and the navigation conflict resolved; diagnostics were compared with clean master with no introduced findings.
@ovitrif Please repeat the bounded already-open and background/resume cases on the updated #934 head, including a newly inserted seller sorting before the scan cursor. After import, leave Bitkit foregrounded without visiting Contacts or triggering another foreground. Record import commit, preparation enqueue/start and first ensureLinkWithPeer admission/start. The new seller's first link call should start automatically. Your storefront-only sellers are sufficient for this scheduling check; successful linking needs a Paykit-capable seller and is a separate assertion. No funding, approval or payment is needed.
Keeping #934 draft until the remaining acceptance checks. This fixes the reproduced lost-preparation race, not every latency report: the earlier 47-second sessionNotActive sample remains unproven, and the reported 5m19s was time until another trigger, not evidence of the uncertain-write safety wait.
Before, on e3796d9: a newly imported seller's preparation was dropped and got no link call until the next trigger: 5 min 19 s after a background import (ended by a manual foreground), and 7.5 min for sellers imported while the app was open.
After, on 734e020: the same race fired on every import and was revalidated. The new seller's first ensureLinkWithPeer started 2.4 s after the import commit with the app open, 8.5 s after background then foreground, 14.5 s on a cold open, 2.9 s on the existing poll with the Send sheet open, and 13.1 s after an interrupted refresh. Bitkit was left alone each time.
sessionNotActive: thrown twice, by an older snapshot's run still in flight, and harmless now: the queued preparation started within 22 ms.
Still open: a completed link and a real Shop request reaching payment review. Both need a Paykit-capable seller.
Thanks, this confirms the reproduced lost-preparation race is fixed in #934 at 734e020. I've recorded the current-head retest in that PR: first link calls now start automatically in the five reported scenarios, without the extra trigger the old build needed.
Keeping #868 open. These are import-commit-to-first-call measurements, not completed-link or Shop-checkout timings. The two obsolete-snapshot errors in this run did not lose the queued work, but they do not prove the cause of the earlier RC75 47-second delay. Completed linking and request-to-review still need the Paykit-capable seller fixture. Repeated unreachable-seller lookups remain a separate, non-blocking optimization candidate.
In 3.0.5: the dropped-preparation race found here is fixed in #934 for 3.0.0; what stays open is explaining the original 47 s sessionNotActive sample, which doesn't block the release.
Activity
ben-kaufman commentedon Oct 3, 2026
Retested with published rc60 on iOS 10b85a1 and Android dc73b29d7, using fresh staging identities saved as contacts on both devices.
rc60 includes #169/#170/#171, so the release dependency is removed, but this performance issue is not resolved. The remaining active send/withdrawal paths still perform multiple serialized shared-state transactions. Separating their network time from app-queue and lock waits is the next step; these results do not establish that the homeserver itself is the bottleneck. No payment was broadcast in this run.
ben-kaufman commentedon Oct 3, 2026
Latest staging measurements used the published rc61 binaries with one linked, unfunded iOS/Android pair:
Both PRs now use published rc62. It retains the batching and polling improvements and fixes a separate SDK issue where four concurrent outbound peers could consume each other's leases while waiting on shared storage. It does not explain or establish a fix for the one-peer delay above. No rc62 staging latency result is claimed here.
Keep this open. We need timings for repository/SDK queue waits, outbound work, intake and request-list updates before attributing the remaining delay to Bitkit or the homeserver. Android also queues overlapping refreshes instead of coalescing them as iOS does; its impact in this run is unmeasured. No safety timeout was reduced.
No payment was broadcast in these unfunded-wallet runs. Full payment/unlock, the 61-contact case, cold start and backup-stall QA remain unverified. The separate wallet broadcast dependency is still tracked in iOS #844 and Android #1384.
jvsena42 commentedon Oct 4, 2026
Re-measured on staging at #856 head 134dce1 (Paykit rc62, which includes paykit-rs#171). Two iOS simulators, fresh identities.
paykit_session loaded from keychain, idlerc62 is faster on most rows, and nothing fails: no lease-expired lines and no crash. Every target is still missed, so this stays open.
Where the time goes now:
concurrent_updateinit failures.ben-kaufman commentedon Oct 5, 2026
I profiled one linked, unfunded staging pair using a local build of #171 at 13feb12a. These measurements predate the later registry/endpoint lock reuse and the newest iOS cleanup changes; they are not measurements of the currently published rc62 or the final PR head.
Sending one request took 22.416s:
A second request took 21.169s. Both appeared on Android, but Android restarted during the test, so this does not establish warm delivery latency.
Sharing OFF switched the UI immediately, but the last remote cleanup call completed after 84.326s:
The drain included an unnecessary 11.296s link check, now skipped when nothing remains queued. Sharing ON also repeated a registry update unnecessarily; that is removed. The channel-availability refresh no longer starts another public publication alongside its explicit publication.
These are wrapper execution times, including SDK checks, not isolated network/CPU timings. Warm Request or Pay opened within one second, but remote actions remain too slow. The newer direct SDK measurements show further improvement, not a completed mobile retest. Keeping this open; no funded payment or content unlock was tested.
ben-kaufman commentedon Oct 5, 2026
Retested with current #171 source, not published rc62: measured breakdown. Request sending took 24.0s; sharing OFF remote work took 63.1s, with both cleanup flags clearing afterward. The main phases are listed there. These still miss the targets, so this remains open. No funded payment or content unlock was tested.
jvsena42 commentedon Oct 5, 2026
Numbers at #856 e2b7326 (rc62), two simulators on staging, linked pair:
shared_state_busy×3)Until the session restores, the bell, contact names in activity, the Contacts screen and
bitkit://contactdeeplinks are all unavailable.ben-kaufman commentedon Oct 5, 2026
New same-identity staging measurements with the FFI batching fix: request send 21.6s -> 16.6s; full sharing withdrawal 68.2s -> 46.4s. Warm Contact Pay was 10.2s, almost entirely SDK execution in that sample. The local toggle changes immediately; withdrawal numbers include remote cleanup. Detailed queue owners, storage counts and limitations are in pubky/paykit-rs#171 (comment) . These are individual unfunded runs, not final-head acceptance: the latest recovery-marker fix still needs device retesting. Keeping this open.
ben-kaufman commentedon Oct 5, 2026
Matched before/after measurements with the current iOS source and the SDK batching changes: warm Pay 8.5s to 5.0s; send request 18.2s to 14.6s; incoming preparation 20.4s to 20.9s; full sharing withdrawal 44.7s to 40.2s. Both withdrawals finished with cleanup flags clear.
Incoming preparation still spends about 20s inside the SDK, not waiting for the app queue or wallet. Withdrawal spends about 34s in the SDK and 6s waiting for other SDK operations. Those paths still need work, so this issue remains open. One contact, one ordered comparison, unfunded wallets; no full payment claim. The staged-handshake follow-up is not included yet.
Combined results and scope: pubky/paykit-rs#171 (comment)
ben-kaufman commentedon Oct 6, 2026
I repeated the flows with the existing Send sheet and local builds of the combined SDK stack. The known request details appear immediately and the swipe stays loading until preparation is complete; the sheet then becomes payable in place.
The SDK preparation fell from 16.8s to 7.6s, but the actual incoming-sheet wait was still 17.9s versus 17.3s. The candidate spent 9.4s behind a private-list publication that the same polling round started before presenting the request. I am fixing that scheduling order without interrupting active writes.
Warm Contact Pay was 4.5s, sending a request 19.8s, and complete sharing withdrawal 43.2s. Those are single samples, not averages. No payment was broadcast. Full comparison and limitations. This issue stays open.
ben-kaufman commentedon Oct 6, 2026
Retested the same identity pair with the latest app changes and the unreleased #171 SDK build. Incoming request preparation fell from 18.3s to 5.0s, and the existing Send sheet shows the request details with payment disabled/loading until ready. Send Request took 13.6s; warm Contact Pay took 5.9s; full sharing withdrawal still took 44.8s.
Sender tap to receiver-ready was about 24s, including sending and inbox scheduling. These are single measured runs, not averages or full payment completion. Withdrawal and larger-contact performance remain open. The app PR still uses published rc62.
Full paired results and timing breakdown.
ben-kaufman commentedon Oct 6, 2026
The latest measured builds use the production SDK source in rc63, with tracing enabled. Full timings and limitations.
Performance remains open. These are individual runs, not matched before/after measurements or downloaded-rc63 binary tests. There was no funded payment in this capture. Large-contact mobile tests and Bitkit plus a running Server still need validation. No five-minute pending-write wait occurred in these completed samples.
jvsena42 commentedon Oct 6, 2026
Numbers at #856 591ac12 with paykit rc63, two simulators on staging, fresh identities:
Close to target now: Send Request and contact payments off. Still above: Pay → ready when the wallet has to build the transaction (15.6 s), swipe → broadcast, the time until Request is offered after a launch or a new link, and the one 61 s restore with two
concurrent_updatelines after a sharing change.jvsena42 commentedon Oct 6, 2026
Numbers at #856 f79cfcb with paykit rc65 (two simulators, staging, identities carried over from rc63): payment and sharing timings are unchanged from rc63 (Send Request ≤ 14 s, sheet ready 3.5 s, swipe → broadcast 34–42 s, sharing off 25–43 s). Paying a contact whose sharing is off now shows the "Unable To Pay Contact" toast in ≤ 4 s.
Open on rc65: a cold launch shortly after a write is slow. A quiet launch restores in ~12 s. A launch 38 s after a payment broadcast took 62.6 s and 69.3 s (
Deferred session restoration, 3–4concurrent_update). A launch 12 s after a sharing toggle settled took 63.4 s on one simulator and 6 min 2 s on the other (SharedStateBusy … pending writes could not be ruled out, then nothing for five minutes). Until the session restores there is no bell, activity rows lose the contact name, and contact deeplinks fail. Full table: #856 (review)ben-kaufman commentedon Oct 6, 2026
Thanks, the rc65 run confirms the slow relaunch is not Android-only. I recorded the matching Android evidence in synonymdev/bitkit-android#1419. Quiet restoration and restoration after interrupted writes need to stay separate in the measurements. The pending-write wait must remain until we can prove a previous write cannot still finish; these timings do not justify clearing its marker or shortening the safety interval.
Keeping this open. The rc65 atomic contact import fix does not resolve the cold-launch delay or the temporary loss of contact names, bell and deeplink availability during restoration.
ben-kaufman commentedon Oct 7, 2026
Published rc66 check with two fresh staging wallets and regtest funds: both directions completed a 5,000-sat request payment, with receiver credit and independently confirmed chain transactions. App builds were iOS a04232f and Android fd04581d2, before the later link-preparation changes. These are single runs, not a matched before/after benchmark.
For the iOS payer:
The logs do not split SDK queue wait, homeserver locks, state reads/commits and Noise within those intervals. Initial linking, exact request-delivery timing, cold-start and many-contact performance remain open. This does not resolve the failure/recovery journeys or establish the performance of the newer heads. Transaction: 53f92e55d1eaee0cc3892191026b04e593ed028eeffe42da40c90fd12cba4683, confirmed at regtest height 216148.
6 remaining items
ovitrif commentedon Oct 15, 2026
@ben-kaufman The earlier trace is gone, so I ran one bounded repeat on e3796d9.
sessionNotActivedid not reproduce. The delay did, and it was longer. The new seller was imported 20 s after foreground. Its preparation was then dropped atPrivatePaykitService+Contacts.swift:112and never re-queued, so no link call ran until the next foreground. I brought Bitkit back to the foreground by hand about 5 min after the import, and its first link call came 5 min 19 s after the import. Without that foreground, the wait lasts until some other trigger (foreground, node running, network restored). Auth and sign-in stayed current throughout. The SDK queue never held a preparation call for more than 3.1 s.AppScene.swift:1233active), same processAppScene.swift:1233authenticated; old snapshot (S1, S2) enqueued, preparation starts at onceAppScene.swift:1279–1283→:1326,Contacts.swift:114–115linkedPeerswaits 3.08 s in the SDK queue; eachensureLinkWithPeerwaits ≤0.7 s and runs ≤1.6 s; publication check passes, no errorContacts.swift:686–727ShopContactImporter.swift:60importShopContactscommits (SDK queue wait 0.14 s) and the fresh contact read startsShopContactImporter.swift:88–91savedContactsChangedwith 3 keys startsprepareSavedPaykitContactsContactsManager.swift:396→AppScene.swift:625–633revision == savedContactsRevisionfails, returns nil, nothing enqueuedContacts.swift:112ContactsManager.swift:411ensureLinkWithPeerfor about 5 min while the app stayed in frontAppScene.swift:1233Contacts.swift:114–115,:241–242ensureLinkWithPeerfor S3 (SDK queue wait 0.70 s)Contacts.swift:694→PubkyService.swift:957Why it was dropped.
ContactsManager.loadContactsassignscontactsat:396, and that publishessavedContactsChanged. The same call then reachespruneUnsavedContactStateat:407, which callsrememberSavedContacts(replacing: true). That bumpssavedContactsRevision(Contacts.swift:1308) between the preparation's read at:109and its guard at:112, so the import-triggered preparation sees a moved revision and returns. The bump itself was not logged. It follows from the code order and the timestamps: the drop is at 22.283, andLoaded 3 contacts(:411, after the prune) is at 22.284.The open-app path shows the same drop. S1 and S2 were imported at 10:36:31.7, their preparation was dropped at 10:36:32.001 the same way, and they got no link call for 7.5 min, until the resume above. The drop is a race: the prepare's read and guard run against the prune at
ContactsManager.swift:407. It lost on both imports in this run. The earlier e3796d9 open-app sample did get a link call, 72 s after import, so either the race does not lose every time or another trigger fired then. That run has no log to say which.Your questions.
isSessionCurrentnever returned false; I logged each of its three conditions separately. Auth stayedauthenticatedthe whole run.:727throw. That is the likely reason nosessionNotActiveappeared this time.On the rc75 sample: the import landed 3 s after foreground there, so the old-snapshot run would still have been in flight and could fail at
:727. That fits thesessionNotActivewe saw, with the new seller's own preparation dropped as here. This run does not prove it. Note also that the 47 s there ran from foreground to link, about 44 s after import, and that run has no log of what started the link.Setup.
shop.json.seller-auto-follow/v1/folder.ensureLinkWithPeerended inNotFound. The trace times when the link call starts, not a completed link.Recording at 2x: background with Settings in front, the marker written, foreground, then the second background and foreground.
resume.2x.mp4
Log excerpt (UTC, keys shortened)
Logging diff applied for this run
ben-kaufman commentedon Oct 15, 2026
Thanks, this trace let us reproduce the dropped preparation in a deterministic test. The preparation's session check suspends on MainActor; pruning can advance the service revision while it is suspended, and the original guard then discards the still-current snapshot.
The fix is pushed in #934 at
734e020d30005ab86384048249922d2d9aada3bd. It revalidates that snapshot until the revision is stable, retaining the original preparation generation and still rejecting removed contacts, ended sessions, invalidation and cancellation. No SDK request, polling interval or safety wait was added or changed. The regression fails against the previous source; all five table cases pass with the fix, along with 226 focused tests and 2,572 native unit tests. Current master is integrated and the navigation conflict resolved; diagnostics were compared with clean master with no introduced findings.@ovitrif Please repeat the bounded already-open and background/resume cases on the updated #934 head, including a newly inserted seller sorting before the scan cursor. After import, leave Bitkit foregrounded without visiting Contacts or triggering another foreground. Record import commit, preparation enqueue/start and first
ensureLinkWithPeeradmission/start. The new seller's first link call should start automatically. Your storefront-only sellers are sufficient for this scheduling check; successful linking needs a Paykit-capable seller and is a separate assertion. No funding, approval or payment is needed.Keeping #934 draft until the remaining acceptance checks. This fixes the reproduced lost-preparation race, not every latency report: the earlier 47-second
sessionNotActivesample remains unproven, and the reported 5m19s was time until another trigger, not evidence of the uncertain-write safety wait.ovitrif commentedon Oct 15, 2026
@ben-kaufman The bounded repeat you asked for ran on #934 at 734e020: results.
ensureLinkWithPeerstarted 2.4 s after the import commit with the app open, 8.5 s after background then foreground, 14.5 s on a cold open, 2.9 s on the existing poll with the Send sheet open, and 13.1 s after an interrupted refresh. Bitkit was left alone each time.sessionNotActive: thrown twice, by an older snapshot's run still in flight, and harmless now: the queued preparation started within 22 ms.ben-kaufman commentedon Oct 15, 2026
Thanks, this confirms the reproduced lost-preparation race is fixed in #934 at
734e020. I've recorded the current-head retest in that PR: first link calls now start automatically in the five reported scenarios, without the extra trigger the old build needed.Keeping #868 open. These are import-commit-to-first-call measurements, not completed-link or Shop-checkout timings. The two obsolete-snapshot errors in this run did not lose the queued work, but they do not prove the cause of the earlier RC75 47-second delay. Completed linking and request-to-review still need the Paykit-capable seller fixture. Repeated unreachable-seller lookups remain a separate, non-blocking optimization candidate.
ovitrif commentedon Oct 15, 2026
In 3.0.5: the dropped-preparation race found here is fixed in #934 for 3.0.0; what stays open is explaining the original 47 s
sessionNotActivesample, which doesn't block the release.