Skip to content

Commit a0146e4

Browse files
tmmampagent
andauthored
fix(zero-swift): send WebSocket frames off the main actor (#107)
* test(zero-swift): report where the URLSession frame order test stalls After 30 s the test records how many frames the server got and what the client's writer logged, so a stall shows whether a client send or the server's receive stopped. Amp-Thread-ID: https://ampcode.com/threads/T-c513a037-a257-45e0-b9a9-15c15edfe859 Co-authored-by: tmm <tmm@tmm.dev> * test(zero-swift): time the frame order test's sends off the main actor The first report showed the frames arriving late, not lost, but the writer's log runs on the main actor and couldn't tell a slow send from a busy main actor. The test now times each send in a wrapping socket, counts the server's frames off the main actor, and measures the main actor's longest wait. Amp-Thread-ID: https://ampcode.com/threads/T-c513a037-a257-45e0-b9a9-15c15edfe859 Co-authored-by: tmm <tmm@tmm.dev> * fix(zero-swift): send WebSocket frames off the main actor The frame order test's report showed each send finishing in at most 7 ms but only 107 of 200 starting in 30 s, with the main actor waiting up to 6.6 s: the writer ran on the main actor and waited for it after every frame. It now runs detached. A new test blocks the main actor for a second after queuing 200 frames; without the fix the server gets none. Amp-Thread-ID: https://ampcode.com/threads/T-c513a037-a257-45e0-b9a9-15c15edfe859 Co-authored-by: tmm <tmm@tmm.dev> --------- Co-authored-by: Amp <amp@ampcode.com>
1 parent b7c61fb commit a0146e4

4 files changed

Lines changed: 147 additions & 12 deletions

File tree

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,5 @@
1+
---
2+
'zero-swift': patch
3+
---
4+
5+
The client's WebSocket frames, such as mutations and query changes, no longer wait for a busy main thread. The writer that sends them one at a time ran on the main actor and went back to it after every frame, so while the app kept the main thread busy each frame waited its turn: on CI, 107 frames took 30 seconds to go out. The writer now runs off the main actor and still sends the frames, and the close after them, in order.

‎swift/Sources/Zero/Client/Scheduler.swift‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -76,7 +76,7 @@ public final class SystemScheduler: Scheduler {
7676
return timer
7777
}
7878

79-
static func milliseconds(_ d: Duration) -> Double {
79+
nonisolated static func milliseconds(_ d: Duration) -> Double {
8080
let (s, attoseconds) = d.components
8181
return Double(s) * 1000 + Double(attoseconds) / 1e15
8282
}

‎swift/Sources/Zero/Client/Socket.swift‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -89,9 +89,11 @@ final class TransportConnection: SocketConnection {
8989
return
9090
}
9191
// One writer keeps the frames in order; each send in a task of its
92-
// own could overtake the one before.
92+
// own could overtake the one before. It runs off the main actor: on
93+
// it, every frame would wait for the main actor to come back from its
94+
// send, so a busy main thread would hold up the frames.
9395
let log = self.log.flatMap { $0.level <= .debug ? $0 : nil }
94-
Task {
96+
Task.detached {
9597
for await frame in frames {
9698
switch frame {
9799
case .text(let text):

‎swift/Tests/AppleTests/URLSessionTransportTests.swift‎

Lines changed: 137 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -66,33 +66,161 @@
6666
}
6767
}
6868

69+
/// When the client's sends ran and finished and the server got the
70+
/// frames, timed off the main actor, which the client's writer runs on.
71+
struct FrameTimes: Sendable {
72+
let start = ContinuousClock.now
73+
var started = 0
74+
var sent = 0
75+
var failures: [String] = []
76+
var lastSent: Duration = .zero
77+
var slowestSend: Duration = .zero
78+
var received = 0
79+
var lastReceived: Duration = .zero
80+
var mainActorWait: Duration = .zero
81+
var mainActorWaitAt: Duration = .zero
82+
83+
var report: String {
84+
func ms(_ d: Duration) -> Int { Int(d / .milliseconds(1)) }
85+
return """
86+
The server got \(received) of 200 frames, the last at \(ms(lastReceived)) ms. \
87+
The client started \(started) sends and finished \(sent), the last at \
88+
\(ms(lastSent)) ms and the slowest in \(ms(slowestSend)) ms; failed: \(failures). \
89+
The main actor's longest wait was \(ms(mainActorWait)) ms, at \(ms(mainActorWaitAt)) ms.
90+
"""
91+
}
92+
}
93+
94+
struct TimedTransport: Transport {
95+
let base: any Transport
96+
let times: Locked<FrameTimes>
97+
98+
func connect(url: String, secProtocol: String?) async throws -> any Socket {
99+
TimedSocket(base: try await base.connect(url: url, secProtocol: secProtocol), times: times)
100+
}
101+
}
102+
103+
final class TimedSocket: Socket {
104+
let base: any Socket
105+
let times: Locked<FrameTimes>
106+
107+
init(base: any Socket, times: Locked<FrameTimes>) {
108+
self.base = base
109+
self.times = times
110+
}
111+
112+
func send(_ message: SocketMessage) async throws {
113+
let began = ContinuousClock.now
114+
times.withLock { $0.started += 1 }
115+
do {
116+
try await base.send(message)
117+
} catch {
118+
times.withLock { $0.failures.append("\(error)") }
119+
throw error
120+
}
121+
let now = ContinuousClock.now
122+
times.withLock { t in
123+
t.sent += 1
124+
t.lastSent = now - t.start
125+
t.slowestSend = max(t.slowestSend, now - began)
126+
}
127+
}
128+
129+
func receive() async throws -> SocketMessage? { try await base.receive() }
130+
131+
func close(code: Int, reason: String) async { await base.close(code: code, reason: reason) }
132+
}
133+
69134
@Test @MainActor func keepsTheOrderOfFramesSentBeforeAndAfterTheOpen() async throws {
70135
let server = try WebSocketServer()
71136
let port = try await server.start()
72137
defer { server.stop() }
73-
var events = server.events.makeAsyncIterator()
74138

139+
let times = Locked(FrameTimes())
75140
let recorder = Recorder()
76-
let factory = TransportSocketFactory(URLSessionTransport())
141+
let factory = TransportSocketFactory(
142+
TimedTransport(base: URLSessionTransport(), times: times))
77143
let connection = factory.open(
78144
url: "ws://127.0.0.1:\(port)/", secProtocol: nil, events: recorder)
79145
for i in 0..<200 { connection.send("\(i)") }
80-
guard case .connected(let peer, _)? = await events.next() else {
146+
147+
// Off the main actor, so that a busy main actor doesn't delay when the
148+
// frames are counted.
149+
let events = server.events
150+
let reading = Task.detached { () -> (peer: WebSocketServer.Peer, texts: [String])? in
151+
var events = events.makeAsyncIterator()
152+
guard case .connected(let peer, _)? = await events.next() else { return nil }
153+
var texts: [String] = []
154+
while texts.count < 200, case .message(_, .text(let text))? = await events.next() {
155+
texts.append(text)
156+
let now = ContinuousClock.now
157+
times.withLock { t in
158+
t.received += 1
159+
t.lastReceived = now - t.start
160+
}
161+
}
162+
return (peer, texts)
163+
}
164+
let probe = Task.detached {
165+
while !Task.isCancelled {
166+
let asked = ContinuousClock.now
167+
await MainActor.run {}
168+
let waited = ContinuousClock.now - asked
169+
times.withLock { t in
170+
if waited > t.mainActorWait {
171+
t.mainActorWait = waited
172+
t.mainActorWaitAt = asked - t.start
173+
}
174+
}
175+
try? await Task.sleep(for: .milliseconds(50))
176+
}
177+
}
178+
let watchdog = Task {
179+
try await Task.sleep(for: .seconds(30))
180+
Issue.record("After 30 s: \(times.withLock { $0.report })")
181+
}
182+
defer {
183+
probe.cancel()
184+
watchdog.cancel()
185+
}
186+
guard let read = await reading.value else {
81187
Issue.record("not connected")
82188
return
83189
}
84-
var texts: [String] = []
85-
while texts.count < 200, case .message(_, .text(let text))? = await events.next() {
86-
texts.append(text)
87-
}
88-
#expect(texts == (0..<200).map(String.init))
190+
#expect(read.texts == (0..<200).map(String.init))
89191
#expect(recorder.opened)
90192

91-
peer.close(code: 4003, reason: "done")
193+
read.peer.close(code: 4003, reason: "done")
92194
while recorder.closed == nil { try await Task.sleep(for: .milliseconds(10)) }
93195
#expect(recorder.closed == SocketClosed(code: 4003, reason: "done", wasClean: true))
94196
}
95197

198+
@Test @MainActor func sendsWhileTheMainActorIsBusy() async throws {
199+
let server = try WebSocketServer()
200+
let port = try await server.start()
201+
defer { server.stop() }
202+
let events = server.events
203+
let received = Locked(0)
204+
let reading = Task.detached {
205+
for await event in events {
206+
guard case .message = event else { continue }
207+
received.withLock { $0 += 1 }
208+
}
209+
}
210+
defer { reading.cancel() }
211+
212+
let recorder = Recorder()
213+
let connection = TransportSocketFactory(URLSessionTransport()).open(
214+
url: "ws://127.0.0.1:\(port)/", secProtocol: nil, events: recorder)
215+
defer { connection.close(code: nil) }
216+
while !recorder.opened { try await Task.sleep(for: .milliseconds(10)) }
217+
218+
for i in 0..<200 { connection.send("\(i)") }
219+
// The main actor stays busy; the frames still go out.
220+
usleep(1_000_000)
221+
#expect(received.withLock { $0 } == 200)
222+
}
223+
96224
@Test @MainActor func connectsAClientThroughTheDefaultFactory() async throws {
97225
let server = try WebSocketServer()
98226
let port = try await server.start()

0 commit comments

Comments
 (0)