diff --git a/Sources/CmuxEventLogWriter.swift b/Sources/CmuxEventLogWriter.swift index fc6aa674c9c0..aae79d557e08 100644 --- a/Sources/CmuxEventLogWriter.swift +++ b/Sources/CmuxEventLogWriter.swift @@ -12,6 +12,7 @@ final class CmuxEventLogWriter: @unchecked Sendable { private let eventLogURL: URL private let maxEventLogBytes: UInt64 private let maxPendingLines: Int + private let writeData: @Sendable (FileHandle, Data) throws -> Void private let lock = NSLock() private var pendingLines: [String] = [] private var flushScheduled = false @@ -20,10 +21,18 @@ final class CmuxEventLogWriter: @unchecked Sendable { private var flushSuspendedForTesting = false #endif - init(eventLogURL: URL, maxEventLogBytes: UInt64, maxPendingLines: Int) { + init( + eventLogURL: URL, + maxEventLogBytes: UInt64, + maxPendingLines: Int, + writeData: @escaping @Sendable (FileHandle, Data) throws -> Void = { handle, data in + try handle.write(contentsOf: data) + } + ) { self.eventLogURL = eventLogURL self.maxEventLogBytes = max(1, maxEventLogBytes) self.maxPendingLines = max(1, maxPendingLines) + self.writeData = writeData } func enqueue(_ line: String) { @@ -140,17 +149,30 @@ final class CmuxEventLogWriter: @unchecked Sendable { defer { try? handle.close() } try handle.seekToEnd() var currentSize = Self.fileSize(at: eventLogURL, fileManager: fileManager) + // One file segment at a time bounds the extra buffer to the rotation limit, + // except for an indivisible oversized record (the existing write-whole policy). + var batchData = Data() + + func writeBatch() throws { + guard !batchData.isEmpty else { return } + try writeData(handle, batchData) + batchData.removeAll(keepingCapacity: true) + } + for line in lines { - let data = Data((line + "\n").utf8) - if currentSize + UInt64(data.count) > maxEventLogBytes { + let lineBytes = UInt64(line.utf8.count) + 1 + if currentSize + lineBytes > maxEventLogBytes { + try writeBatch() try handle.close() try rotate(fileManager: fileManager) handle = try FileHandle(forWritingTo: eventLogURL) currentSize = 0 } - try handle.write(contentsOf: data) - currentSize += UInt64(data.count) + batchData.append(contentsOf: line.utf8) + batchData.append(0x0a) + currentSize += lineBytes } + try writeBatch() } catch { cmuxEventLogLogger.error("Failed to append cmux event log: \(String(describing: error), privacy: .private)") } diff --git a/cmux.xcodeproj/project.pbxproj b/cmux.xcodeproj/project.pbxproj index c5376f05448e..2882b6ca43c9 100644 --- a/cmux.xcodeproj/project.pbxproj +++ b/cmux.xcodeproj/project.pbxproj @@ -1254,6 +1254,8 @@ E7E000000000000000000005 /* CmuxEventBus.swift in Sources */ = {isa = PBXBuildFile; fileRef = E7E000000000000000000006 /* CmuxEventBus.swift */; }; E7E000000000000000000003 /* CmuxEventBusTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = E7E000000000000000000004 /* CmuxEventBusTests.swift */; }; E7E00000000000000000000D /* CmuxEventLogWriter.swift in Sources */ = {isa = PBXBuildFile; fileRef = E7E00000000000000000000E /* CmuxEventLogWriter.swift */; }; + E7E00000000000000000000F /* CmuxEventLogWriterTests.swift in Sources */ = {isa = PBXBuildFile; fileRef = E7E000000000000000000010 /* CmuxEventLogWriterTests.swift */; }; + E7E000000000000000000011 /* CmuxEventLogWriteSpy.swift in Sources */ = {isa = PBXBuildFile; fileRef = E7E000000000000000000012 /* CmuxEventLogWriteSpy.swift */; }; E7E000000000000000000007 /* CmuxEventPublishing.swift in Sources */ = {isa = PBXBuildFile; fileRef = E7E000000000000000000008 /* CmuxEventPublishing.swift */; }; E7E000000000000000000001 /* CmuxEventStream.swift in Sources */ = {isa = PBXBuildFile; fileRef = E7E000000000000000000002 /* CmuxEventStream.swift */; }; C0DE45000000000000000001 /* CmuxExtensionKit in Frameworks */ = {isa = PBXBuildFile; productRef = C0DE45000000000000000002 /* CmuxExtensionKit */; }; @@ -5178,6 +5180,8 @@ E7E000000000000000000006 /* CmuxEventBus.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = CmuxEventBus.swift; sourceTree = ""; }; E7E000000000000000000004 /* CmuxEventBusTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = CmuxEventBusTests.swift; sourceTree = ""; }; E7E00000000000000000000E /* CmuxEventLogWriter.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = CmuxEventLogWriter.swift; sourceTree = ""; }; + E7E000000000000000000010 /* CmuxEventLogWriterTests.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = CmuxEventLogWriterTests.swift; sourceTree = ""; }; + E7E000000000000000000012 /* CmuxEventLogWriteSpy.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = CmuxEventLogWriteSpy.swift; sourceTree = ""; }; E7E000000000000000000008 /* CmuxEventPublishing.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = CmuxEventPublishing.swift; sourceTree = ""; }; E7E000000000000000000002 /* CmuxEventStream.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = CmuxEventStream.swift; sourceTree = ""; }; C57B00050000000000000002 /* CmuxExtensionSidebarSelection+CustomSidebarName.swift */ = {isa = PBXFileReference; lastKnownFileType = sourcecode.swift; path = "CmuxExtensionSidebarSelection+CustomSidebarName.swift"; sourceTree = ""; }; @@ -11467,6 +11471,8 @@ A7984AD10000000000000002 /* SocketConfigurationLifecycleTests.swift */, 9C1BEA3D2E6F49709A71C021 /* TerminalControllerTerminalTextTests.swift */, E7E000000000000000000004 /* CmuxEventBusTests.swift */, + E7E000000000000000000010 /* CmuxEventLogWriterTests.swift */, + E7E000000000000000000012 /* CmuxEventLogWriteSpy.swift */, A10649100000000000000001 /* AutomationRuleTests.swift */, A10649340000000000000001 /* AutomationProcessSessionTests.swift */, 7837E0027837E0027837E002 /* CmuxSocketEventMapperTests.swift */, @@ -15464,6 +15470,8 @@ A5FB1205 /* CmuxConfigWorkspaceActionTests.swift in Sources */, C54860040000000000000001 /* CmuxDurableDeepLinkRestoreTests.swift in Sources */, E7E000000000000000000003 /* CmuxEventBusTests.swift in Sources */, + E7E00000000000000000000F /* CmuxEventLogWriterTests.swift in Sources */, + E7E000000000000000000011 /* CmuxEventLogWriteSpy.swift in Sources */, A11C00040000000000000001 /* CmuxHostedSystemSymbolImageTests.swift in Sources */, D36090010000000000000005 /* CmuxMainWindowConstrainFrameTests.swift in Sources */, D36090020000000000000005 /* CmuxMainWindowFullScreenCapabilityTests.swift in Sources */, diff --git a/cmuxTests/CmuxEventLogWriteSpy.swift b/cmuxTests/CmuxEventLogWriteSpy.swift new file mode 100644 index 000000000000..25cd53fabea9 --- /dev/null +++ b/cmuxTests/CmuxEventLogWriteSpy.swift @@ -0,0 +1,35 @@ +import Foundation + +/// A synchronous FileHandle dependency; the lock protects observations shared with the utility queue. +final class CmuxEventLogWriteSpy: @unchecked Sendable { + private let lock = NSLock() + private var sizes: [Int] = [] + private var onMainThread = false + private let failedCall: Int? + + init(failedCall: Int? = nil) { + self.failedCall = failedCall + } + + var writeSizes: [Int] { + lock.lock() + defer { lock.unlock() } + return sizes + } + + var wroteOnMainThread: Bool { + lock.lock() + defer { lock.unlock() } + return onMainThread + } + + func write(_ handle: FileHandle, data: Data) throws { + lock.lock() + sizes.append(data.count) + onMainThread = onMainThread || Thread.isMainThread + let shouldFail = sizes.count == failedCall + lock.unlock() + if shouldFail { throw CocoaError(.fileWriteUnknown) } + try handle.write(contentsOf: data) + } +} diff --git a/cmuxTests/CmuxEventLogWriterTests.swift b/cmuxTests/CmuxEventLogWriterTests.swift new file mode 100644 index 000000000000..f04934777b36 --- /dev/null +++ b/cmuxTests/CmuxEventLogWriterTests.swift @@ -0,0 +1,231 @@ +import Foundation +import Testing + +#if canImport(cmux_DEV) +@testable import cmux_DEV +#elseif canImport(cmux) +@testable import cmux +#endif + +@Suite("Durable event-log batch writes", .serialized) +struct CmuxEventLogWriterTests { + private let logLimit = 16 * 1024 * 1024 + + @Test(arguments: [0, 1, 32, 256, 1_024]) + func burstUsesOneWriteAndPreservesJSONL(count: Int) throws { + let lines = (0.. 0 { + let stored = try Data(contentsOf: url) + #expect(stored == jsonl(lines)) + try expectJSONRecords(stored, count: count) + } else { + #expect(!FileManager.default.fileExists(atPath: url.path)) + } + #expect(writer.backlogSnapshotForTesting().pending == 0) + #expect(writer.backlogSnapshotForTesting().dropped == 0) + } + + @Test(arguments: [0, 1]) + func batchAtOrBelowSixteenMiBLimitDoesNotRotate(spareBytes: Int) throws { + let lines = (0..<32).map { jsonLine(index: $0) } + let (writer, url, spy) = makeWriter() + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + let seed = try seedLog(url, bytes: logLimit - jsonl(lines).count - spareBytes) + + flush(lines, with: writer) + + #expect(spy.writeSizes == [jsonl(lines).count]) + #expect(try Data(contentsOf: url) == seed + jsonl(lines)) + #expect(!FileManager.default.fileExists(atPath: url.appendingPathExtension("1").path)) + } + + @Test + func batchCrossingSixteenMiBLimitWritesOncePerFile() throws { + let lines = (0..<32).map { jsonLine(index: $0) } + let prefix = jsonl(Array(lines.prefix(13))) + let suffix = jsonl(Array(lines.dropFirst(13))) + let (writer, url, spy) = makeWriter() + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + let seed = try seedLog(url, bytes: logLimit - prefix.count) + + flush(lines, with: writer) + + #expect(spy.writeSizes == [prefix.count, suffix.count]) + #expect(try Data(contentsOf: url.appendingPathExtension("1")) == seed + prefix) + #expect(try Data(contentsOf: url) == suffix) + try expectJSONRecords(suffix, count: 19) + } + + @Test + func maximumPendingBatchBoundsWritesAtSixteenMiB() throws { + // 1,024 maximum-sized producer records plus JSONL delimiters straddle the cap. + let line = "{\"text\":\"" + String(repeating: "x", count: 16_384 - 11) + "\"}" + #expect(line.utf8.count == 16_384) + let lines = Array(repeating: line, count: 1_024) + let (writer, url, spy) = makeWriter() + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + + flush(lines, with: writer) + + #expect(spy.writeSizes == [16_385 * 1_023, 16_385]) + #expect(spy.writeSizes.allSatisfy { $0 <= logLimit }) + #expect(try Data(contentsOf: url.appendingPathExtension("1")) == jsonl(Array(lines.prefix(1_023)))) + #expect(try Data(contentsOf: url) == jsonl([line])) + } + + @Test + func fullExistingLogRotatesBeforeWritingTheBatch() throws { + let (writer, url, spy) = makeWriter() + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + let seed = try seedLog(url, bytes: logLimit) + let lines = (0..<32).map { jsonLine(index: $0) } + + flush(lines, with: writer) + + #expect(spy.writeSizes == [jsonl(lines).count]) + #expect(try Data(contentsOf: url.appendingPathExtension("1")) == seed) + #expect(try Data(contentsOf: url) == jsonl(lines)) + } + + @Test + func multipleRotationsRetainTheSameLastTwoFiles() throws { + let lines = (0..<8).map { "{\"seq\":\($0)}" } + let (writer, url, spy) = makeWriter(maxBytes: 30) + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + + flush(lines, with: writer) + + #expect(spy.writeSizes == [30, 30, 20]) + #expect(try Data(contentsOf: url.appendingPathExtension("1")) == jsonl(Array(lines[3..<6]))) + #expect(try Data(contentsOf: url) == jsonl(Array(lines[6..<8]))) + } + + @Test + func utf8BytesAndNewlinesDetermineTheBoundary() throws { + let lines = [#"{"text":"🌍"}"#, #"{"text":"é"}"#, #"{"seq":2}"#] + let prefix = jsonl(Array(lines.prefix(2))) + let (writer, url, spy) = makeWriter(maxBytes: UInt64(prefix.count)) + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + + flush(lines, with: writer) + + #expect(spy.writeSizes == [prefix.count, jsonl([lines[2]]).count]) + #expect(try Data(contentsOf: url.appendingPathExtension("1")) == prefix) + #expect(try Data(contentsOf: url) == jsonl([lines[2]])) + } + + @Test + func oversizedRecordKeepsExistingWholeRecordAndCleanupPolicy() throws { + let oversized = jsonLine(index: 1) + let seed = #"{"seq":0}"# + let tail = #"{"seq":2}"# + let (writer, url, spy) = makeWriter(maxBytes: 32) + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + + flush([seed, oversized], with: writer) + #expect(try Data(contentsOf: url) == jsonl([oversized])) + #expect(try Data(contentsOf: url.appendingPathExtension("1")) == jsonl([seed])) + + // The pre-existing policy discards an oversized active log on the next rotation. + flush([tail], with: writer) + #expect(spy.writeSizes == [jsonl([seed]).count, jsonl([oversized]).count, jsonl([tail]).count]) + #expect(try Data(contentsOf: url) == jsonl([tail])) + #expect(try Data(contentsOf: url.appendingPathExtension("1")) == jsonl([seed])) + } + + @Test + func suspendedBurstKeepsNewestLinesAndDropAccounting() throws { + let lines = (0..<1_152).map { jsonLine(index: $0) } + let (writer, url, spy) = makeWriter() + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + lines.forEach(writer.enqueue) + + #expect(writer.backlogSnapshotForTesting().pending == 1_024) + #expect(writer.backlogSnapshotForTesting().dropped == 128) + writer.setFlushSuspendedForTesting(false) + writer.flushForTesting() + + #expect(spy.writeSizes.count == 1) + #expect(try Data(contentsOf: url) == jsonl(Array(lines.suffix(1_024)))) + #expect(writer.backlogSnapshotForTesting().pending == 0) + #expect(writer.backlogSnapshotForTesting().dropped == 0) + } + + @Test(arguments: [1, 2]) + func failedWriteStopsTheBatchAndNextFlushRecovers(failedCall: Int) throws { + let lines = (0..<8).map { "{\"seq\":\($0)}" } + let spy = CmuxEventLogWriteSpy(failedCall: failedCall) + let (writer, url, _) = makeWriter(maxBytes: 30, spy: spy) + defer { try? FileManager.default.removeItem(at: url.deletingLastPathComponent()) } + + flush(lines, with: writer) + + #expect(spy.writeSizes.count == failedCall) + #expect(try Data(contentsOf: url).isEmpty) + if failedCall == 2 { + #expect(try Data(contentsOf: url.appendingPathExtension("1")) == jsonl(Array(lines.prefix(3)))) + } else { + #expect(!FileManager.default.fileExists(atPath: url.appendingPathExtension("1").path)) + } + // As before, failed I/O is logged and abandoned, not retried or counted as queue drops. + #expect(writer.backlogSnapshotForTesting().dropped == 0) + flush([#"{"seq":9}"#], with: writer) + #expect(try Data(contentsOf: url) == jsonl([#"{"seq":9}"#])) + } + + private func makeWriter( + maxBytes: UInt64 = 16 * 1024 * 1024, + spy: CmuxEventLogWriteSpy = CmuxEventLogWriteSpy() + ) -> (CmuxEventLogWriter, URL, CmuxEventLogWriteSpy) { + let url = FileManager.default.temporaryDirectory + .appendingPathComponent("cmux-event-log-writer-\(UUID().uuidString)", isDirectory: true) + .appendingPathComponent("events.jsonl") + let writer = CmuxEventLogWriter( + eventLogURL: url, + maxEventLogBytes: maxBytes, + maxPendingLines: 1_024, + writeData: { try spy.write($0, data: $1) } + ) + writer.setFlushSuspendedForTesting(true) + return (writer, url, spy) + } + + private func flush(_ lines: [String], with writer: CmuxEventLogWriter) { + writer.setFlushSuspendedForTesting(true) + lines.forEach(writer.enqueue) + writer.setFlushSuspendedForTesting(false) + writer.flushForTesting() + } + + private func jsonLine(index: Int) -> String { + "{\"seq\":\(index),\"name\":\"agent.hook.PreToolUse\",\"payload\":\"\(String(repeating: "x", count: 900))\"}" + } + + private func jsonl(_ lines: [String]) -> Data { + Data(lines.map { $0 + "\n" }.joined().utf8) + } + + private func seedLog(_ url: URL, bytes: Int) throws -> Data { + try FileManager.default.createDirectory(at: url.deletingLastPathComponent(), withIntermediateDirectories: true) + let data = Data(("{\"seed\":\"" + String(repeating: "x", count: bytes - 12) + "\"}\n").utf8) + #expect(data.count == bytes) + try data.write(to: url) + return data + } + + private func expectJSONRecords(_ data: Data, count: Int) throws { + #expect(data.last == 0x0a) + let records = data.split(separator: 0x0a) + #expect(records.count == count) + for record in records { + #expect(try JSONSerialization.jsonObject(with: Data(record)) is [String: Any]) + } + } +} diff --git a/docs/performance/12984-event-log-batching.md b/docs/performance/12984-event-log-batching.md new file mode 100644 index 000000000000..39ec9a935fa0 --- /dev/null +++ b/docs/performance/12984-event-log-batching.md @@ -0,0 +1,41 @@ +# Event-log batching evidence (#12984) + +The issue reported per-line FileHandle writes during agent/feed bursts. The incident's app-wide CPU/footprint numbers also include other subsystems; this change proves reduced write amplification in `CmuxEventLogWriter`, not resolution of that entire incident. + +## Reproduction and fix + +The red checkpoint `c4881822f28ade0934a512ee154514c9838a2922` adds only constructor injection for the synchronous physical write and the behavior tests, leaving the per-line algorithm intact. Against that checkpoint, 32/256/1024-record batches issue 32/256/1024 calls. The focused Swift Testing run failed with 11 assertions; exact bytes, ordinary rotation layout, and the oversized-record policy were preserved already. + +The fix keeps one `Data` buffer for the current file segment, writing it before rotation and at batch end. UTF-8 plus newline bytes count toward the same limit. The existing utility queue, enqueue scheduling, 1,024-line cap, drop-oldest behavior, drop diagnostic, open/close lifecycle, and error diagnostic remain unchanged. No periodic flush, producer change, or main-actor I/O was introduced. + +## Measured results + +Seven measured samples per workload after one warm-up, optimized Swift 6 build on macOS 26 / Apple Silicon. Every sample uses fresh synthetic files. Each record is about 955 bytes. Timing includes enqueue-to-drain scheduling after a deliberately suspended deterministic batch, directory/file opening, encoding, writing, rotation, and close; fixture generation and verification are outside the timer. It measures kernel-buffered writes, not fsync or physical-media durability. + +| Submitted events | FileHandle write calls before → after | Median flush ms before → after | Dropped events before → after | +| --- | --- | --- | --- | +| 32 | 32 → 1 | 0.441 → 0.410 | 0 → 0 | +| 256 | 256 → 1 | 1.230 → 0.540 | 0 → 0 | +| 1024 | 1024 → 1 | 4.833 → 0.812 | 0 → 0 | +| 1152 | 1024 → 1 | 4.953 → 1.169 | 128 → 128 | +| 256 crossing 16 MiB | 256 → 2 | 2.225 → 0.991 | 0 → 0 | + +The 1,152-event overload keeps the newest 1,024 records and drops 128 before flushing in both versions. No lower drop rate is claimed from this deterministic workload. Every sample checks byte-for-byte contents, complete parseable JSONL, FIFO record IDs, file-size/rotation boundaries, the sum of written bytes, off-main-thread writes, and drained/reset backlog accounting. Raw samples and toolchain details are in [12984-event-log-benchmark.json](12984-event-log-benchmark.json). + +Reproduce from the clone root on an authorized Mac: + +```sh +python3 scripts/benchmark-event-log-writes.py --baseline c4881822f28ade0934a512ee154514c9838a2922 --output /tmp/cmux-12984-benchmark.json +``` + +This compiles only the actual writer, test spy, and benchmark, without building or launching the app. The baseline includes the identical injected write dependency so observations have the same overhead. + +## Behavior coverage and limits + +`CmuxEventLogWriterTests` is wired into the app test target. Ten Swift Testing methods cover empty/single/32/256/1024-record batches, below/exact/across the real 16 MiB boundary, full-existing-log rotation, maximum-sized producer records, multiple rotations, UTF-8/newline byte accounting, oversized records, backpressure, and failures before/after rotation followed by recovery. The standalone focused run passes with warnings as errors. Full app target and hosted verification are tracked in the PR. + +The extra buffer contains at most one log segment for ordinary records (normally at most 16 MiB); it is released after each append call. A single oversized record still writes whole, and the existing next-rotation cleanup discards that oversized active log. This pre-existing exception does not become a truncation or new drop policy. Rotation still retains only the active file and one archive, so multiple rotations retain the same last two segments. + +A failed physical write still stops the append and logs an error without retrying or counting I/O failure as queue overflow. A coalesced call contains more records, so a failure can abandon a larger chunk. Partial-write/disk-full behavior and crash/power-loss durability retain FileHandle's existing limitations; no new fsync guarantee is claimed. No live app/session, UI dogfood, memory-pressure incident, or Intel/macOS 14 run was performed locally. + +Localization audit: production diagnostics are unchanged; no user-facing strings or shortcuts were added. The existing production queue and locks stay at their current ownership boundary; the spy's test-only lock protects synchronous observations from that queue without adding async work to the timed I/O path. diff --git a/docs/performance/12984-event-log-benchmark.json b/docs/performance/12984-event-log-benchmark.json new file mode 100644 index 000000000000..7eb230c99ce5 --- /dev/null +++ b/docs/performance/12984-event-log-benchmark.json @@ -0,0 +1,503 @@ +{ + "baseline": "c4881822f28ade0934a512ee154514c9838a2922", + "head": "1fac7afcd6f26785edb604973332cf4ec8a0ba3a", + "platform": "macOS-26.4.1-arm64-arm-64bit", + "swift": "Apple Swift version 6.3.3 (swiftlang-6.3.3.1.3 clang-2100.1.1.101)\nTarget: arm64-apple-macosx26.0", + "scope": "Warm runtime; fresh synthetic files; kernel-buffered FileHandle writes; no fsync.", + "variants": { + "before": [ + { + "behavior_checks": "passed", + "crossing_16_mib": false, + "samples": [ + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.466917, + "write_calls": 32 + }, + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.426916, + "write_calls": 32 + }, + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.392625, + "write_calls": 32 + }, + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.356667, + "write_calls": 32 + }, + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.5885, + "write_calls": 32 + }, + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.509, + "write_calls": 32 + }, + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.440959, + "write_calls": 32 + } + ], + "submitted_lines": 32 + }, + { + "behavior_checks": "passed", + "crossing_16_mib": false, + "samples": [ + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 0.9715, + "write_calls": 256 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 1.068292, + "write_calls": 256 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 1.128792, + "write_calls": 256 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 1.235208, + "write_calls": 256 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 1.539834, + "write_calls": 256 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 1.342709, + "write_calls": 256 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 1.230041, + "write_calls": 256 + } + ], + "submitted_lines": 256 + }, + { + "behavior_checks": "passed", + "crossing_16_mib": false, + "samples": [ + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 4.83275, + "write_calls": 1024 + }, + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 4.190459, + "write_calls": 1024 + }, + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 6.581666, + "write_calls": 1024 + }, + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 4.000542, + "write_calls": 1024 + }, + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 4.610166, + "write_calls": 1024 + }, + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 5.824416, + "write_calls": 1024 + }, + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 5.291042, + "write_calls": 1024 + } + ], + "submitted_lines": 1024 + }, + { + "behavior_checks": "passed", + "crossing_16_mib": false, + "samples": [ + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 4.565333, + "write_calls": 1024 + }, + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 4.146333, + "write_calls": 1024 + }, + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 4.953458, + "write_calls": 1024 + }, + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 4.30725, + "write_calls": 1024 + }, + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 7.210542, + "write_calls": 1024 + }, + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 5.371625, + "write_calls": 1024 + }, + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 5.10675, + "write_calls": 1024 + } + ], + "submitted_lines": 1152 + }, + { + "behavior_checks": "passed", + "crossing_16_mib": true, + "samples": [ + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 1.621166, + "write_calls": 256 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 1.79875, + "write_calls": 256 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 3.454416, + "write_calls": 256 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 10.434833, + "write_calls": 256 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 1.837791, + "write_calls": 256 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 3.326583, + "write_calls": 256 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 2.224833, + "write_calls": 256 + } + ], + "submitted_lines": 256 + } + ], + "after": [ + { + "behavior_checks": "passed", + "crossing_16_mib": false, + "samples": [ + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.51875, + "write_calls": 1 + }, + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.409958, + "write_calls": 1 + }, + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.369625, + "write_calls": 1 + }, + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.325375, + "write_calls": 1 + }, + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.312166, + "write_calls": 1 + }, + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.654542, + "write_calls": 1 + }, + { + "bytes_written": 30550, + "dropped_lines": 0, + "flush_ms": 0.647792, + "write_calls": 1 + } + ], + "submitted_lines": 32 + }, + { + "behavior_checks": "passed", + "crossing_16_mib": false, + "samples": [ + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 0.671083, + "write_calls": 1 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 0.592625, + "write_calls": 1 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 0.582792, + "write_calls": 1 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 0.46325, + "write_calls": 1 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 0.539583, + "write_calls": 1 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 0.494375, + "write_calls": 1 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 0.495292, + "write_calls": 1 + } + ], + "submitted_lines": 256 + }, + { + "behavior_checks": "passed", + "crossing_16_mib": false, + "samples": [ + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 0.886334, + "write_calls": 1 + }, + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 0.720167, + "write_calls": 1 + }, + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 0.810542, + "write_calls": 1 + }, + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 0.918458, + "write_calls": 1 + }, + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 0.671, + "write_calls": 1 + }, + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 0.854708, + "write_calls": 1 + }, + { + "bytes_written": 978858, + "dropped_lines": 0, + "flush_ms": 0.811709, + "write_calls": 1 + } + ], + "submitted_lines": 1024 + }, + { + "behavior_checks": "passed", + "crossing_16_mib": false, + "samples": [ + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 0.910416, + "write_calls": 1 + }, + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 2.890459, + "write_calls": 1 + }, + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 0.65925, + "write_calls": 1 + }, + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 2.409666, + "write_calls": 1 + }, + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 5.819292, + "write_calls": 1 + }, + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 1.169209, + "write_calls": 1 + }, + { + "bytes_written": 979096, + "dropped_lines": 128, + "flush_ms": 1.064625, + "write_calls": 1 + } + ], + "submitted_lines": 1152 + }, + { + "behavior_checks": "passed", + "crossing_16_mib": true, + "samples": [ + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 0.99075, + "write_calls": 2 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 0.830917, + "write_calls": 2 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 0.804083, + "write_calls": 2 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 0.777375, + "write_calls": 2 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 1.058416, + "write_calls": 2 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 1.01575, + "write_calls": 2 + }, + { + "bytes_written": 244626, + "dropped_lines": 0, + "flush_ms": 1.121167, + "write_calls": 2 + } + ], + "submitted_lines": 256 + } + ] + } +} diff --git a/scripts/benchmark-event-log-writes.py b/scripts/benchmark-event-log-writes.py new file mode 100644 index 000000000000..2b3a2f0f4871 --- /dev/null +++ b/scripts/benchmark-event-log-writes.py @@ -0,0 +1,61 @@ +#!/usr/bin/env python3 +"""Benchmark isolated real event-log writers before/after, including behavior checks. + +The baseline must include the injectable write operation (the red regression +commit). Only the standalone writer/spy/harness are compiled, never the app. +""" +import argparse +import json +import pathlib +import platform +import statistics +import subprocess +import tempfile + + +def main(): + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument('--baseline', required=True) + parser.add_argument('--samples', type=int, default=7) + parser.add_argument('--output', type=pathlib.Path, required=True) + args = parser.parse_args() + if not 1 <= args.samples <= 100: + parser.error('--samples must be between 1 and 100') + root = pathlib.Path(__file__).resolve().parents[1] + baseline = subprocess.check_output(['git', 'rev-parse', '--verify', f'{args.baseline}^{{commit}}'], cwd=root, text=True).strip() + writer = 'Sources/CmuxEventLogWriter.swift' + report = { + 'baseline': baseline, + 'head': subprocess.check_output(['git', 'rev-parse', 'HEAD'], cwd=root, text=True).strip(), + 'platform': platform.platform(), + 'swift': subprocess.check_output(['swiftc', '--version'], text=True).strip(), + 'scope': 'Warm runtime; fresh synthetic files; kernel-buffered FileHandle writes; no fsync.', + 'variants': {}, + } + with tempfile.TemporaryDirectory(prefix='cmux-event-log-benchmark-') as directory: + temp = pathlib.Path(directory) + for variant in ('before', 'after'): + source = temp / f'{variant}.swift' + source.write_bytes(subprocess.check_output(['git', 'show', f'{baseline}:{writer}'], cwd=root) + if variant == 'before' else (root / writer).read_bytes()) + executable = temp / variant + subprocess.run([ + 'swiftc', '-swift-version', '6', '-DDEBUG', '-O', '-warnings-as-errors', str(source), + str(root / 'cmuxTests/CmuxEventLogWriteSpy.swift'), + str(root / 'scripts/benchmarks/EventLogWriteBenchmark.swift'), '-o', str(executable) + ], check=True, cwd=root) + output = subprocess.check_output([str(executable), str(args.samples)], text=True) + rows = [json.loads(line) for line in output.splitlines()] + report['variants'][variant] = rows + for row in rows: + observations = row['samples'] + latency = statistics.median(item['flush_ms'] for item in observations) + print(f"{variant}: lines={row['submitted_lines']} crossing={row['crossing_16_mib']} " + f"writes={observations[0]['write_calls']} median_ms={latency:.3f} " + f"drops={observations[0]['dropped_lines']} behavior={row['behavior_checks']}", flush=True) + args.output.parent.mkdir(parents=True, exist_ok=True) + args.output.write_text(json.dumps(report, indent=2) + '\n') + + +if __name__ == '__main__': + main() diff --git a/scripts/benchmarks/EventLogWriteBenchmark.swift b/scripts/benchmarks/EventLogWriteBenchmark.swift new file mode 100644 index 000000000000..acf38d573cea --- /dev/null +++ b/scripts/benchmarks/EventLogWriteBenchmark.swift @@ -0,0 +1,85 @@ +import Foundation + +/// Measures the real writer, using the same synchronous write spy as the regression suite. +@main +struct EventLogWriteBenchmark { + static func main() throws { + let samples = Int(CommandLine.arguments[1]) ?? 7 + let root = FileManager.default.temporaryDirectory + .appendingPathComponent("cmux-event-log-benchmark-\(UUID().uuidString)") + defer { try? FileManager.default.removeItem(at: root) } + for count in [32, 256, 1_024, 1_152] { + try run(count: count, crossing: false, samples: samples, root: root) + } + try run(count: 256, crossing: true, samples: samples, root: root) + } + + private static func run(count: Int, crossing: Bool, samples: Int, root: URL) throws { + let limit = 16 * 1024 * 1024 + let lines = (0.. 0 { // Warm runtime once; each measured flush still uses a fresh file. + observations.append([ + "write_calls": spy.writeSizes.count, "flush_ms": elapsed, + "dropped_lines": backlog.dropped, "bytes_written": expected.count + ]) + } + } + let result: [String: Any] = [ + "submitted_lines": count, "crossing_16_mib": crossing, + "behavior_checks": "passed", "samples": observations + ] + let encoded = try JSONSerialization.data(withJSONObject: result, options: [.sortedKeys]) + print(String(decoding: encoded, as: UTF8.self)) + } +}