Skip to content

refactor: extract typing diagnostics instrumentation #71

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
teamleaderleo wants to merge 1 commit into from
Closed

refactor: extract typing diagnostics instrumentation #71

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
343 changes: 0 additions & 343 deletions Sources/AppDelegate.swift
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -196,350 +196,7 @@ final class ConfiguredGroupActionAsyncWorkspaceObserver {
}
}

#if DEBUG
enum CmuxTypingTiming {
static let isEnabled: Bool = {
let environment = ProcessInfo.processInfo.environment
if environment["CMUX_TYPING_TIMING_LOGS"] == "1" || environment["CMUX_KEY_LATENCY_PROBE"] == "1" {
return true
}
let defaults = UserDefaults.standard
return defaults.bool(forKey: "cmuxTypingTimingLogs") || defaults.bool(forKey: "cmuxKeyLatencyProbe")
}()
static let isVerboseProbeEnabled: Bool = {
let environment = ProcessInfo.processInfo.environment
if environment["CMUX_KEY_LATENCY_PROBE"] == "1" {
return true
}
return UserDefaults.standard.bool(forKey: "cmuxKeyLatencyProbe")
}()
private static let delayLogThresholdMs: Double = 6.0
private static let durationLogThresholdMs: Double = 1.0

@inline(__always)
static func start() -> TimeInterval? {
guard isEnabled else { return nil }
return ProcessInfo.processInfo.systemUptime
}

@inline(__always)
static func logEventDelay(path: String, event: NSEvent) {
guard isEnabled else { return }
guard event.timestamp > 0 else { return }
let delayMs = max(0, (ProcessInfo.processInfo.systemUptime - event.timestamp) * 1000.0)
guard shouldLog(delayMs: delayMs, elapsedMs: nil) else { return }
cmuxDebugLog("typing.delay probe=\(path) delayMs=\(format(delayMs)) \(eventFields(event))")
}

@inline(__always)
static func logDuration(path: String, startedAt: TimeInterval?, event: NSEvent? = nil, extra: String? = nil) {
CmuxMainThreadTurnProfiler.endMeasure(path, startedAt: startedAt)
guard let startedAt else { return }
let elapsedMs = max(0, (ProcessInfo.processInfo.systemUptime - startedAt) * 1000.0)
let delayMs: Double? = {
guard let event, event.timestamp > 0 else { return nil }
return max(0, (ProcessInfo.processInfo.systemUptime - event.timestamp) * 1000.0)
}()
guard shouldLog(delayMs: delayMs, elapsedMs: elapsedMs) else { return }
var line = "typing.timing probe=\(path) elapsedMs=\(format(elapsedMs))"
if let event {
line += " \(eventFields(event))"
if let delayMs {
line += " delayMs=\(format(delayMs))"
}
}
if let extra, !extra.isEmpty {
line += " \(extra)"
}
cmuxDebugLog(line)
}

@inline(__always)
static func logBreakdown(
path: String,
totalMs: Double,
event: NSEvent? = nil,
thresholdMs: Double = 2.0,
parts: [(String, Double)],
extra: String? = nil
) {
guard isEnabled else { return }
let delayMs: Double? = {
guard let event, event.timestamp > 0 else { return nil }
return max(0, (ProcessInfo.processInfo.systemUptime - event.timestamp) * 1000.0)
}()
let hasSlowPart = parts.contains { $0.1 >= thresholdMs }
guard isVerboseProbeEnabled || totalMs >= thresholdMs || hasSlowPart || (delayMs ?? 0) >= delayLogThresholdMs else {
return
}
var line = "typing.phase probe=\(path) totalMs=\(format(totalMs))"
if let event {
line += " \(eventFields(event))"
}
if let delayMs {
line += " delayMs=\(format(delayMs))"
}
for (name, value) in parts where isVerboseProbeEnabled || value >= 0.05 {
line += " \(name)=\(format(value))"
}
if let extra, !extra.isEmpty {
line += " \(extra)"
}
cmuxDebugLog(line)
}

@inline(__always)
private static func eventFields(_ event: NSEvent) -> String {
"eventType=\(event.type.rawValue) keyCode=\(event.keyCode) mods=\(event.modifierFlags.rawValue) repeat=\(event.isARepeat ? 1 : 0)"
}

@inline(__always)
private static func shouldLog(delayMs: Double?, elapsedMs: Double?) -> Bool {
if isVerboseProbeEnabled {
return true
}
if let delayMs, delayMs >= delayLogThresholdMs {
return true
}
if let elapsedMs, elapsedMs >= durationLogThresholdMs {
return true
}
return false
}

@inline(__always)
private static func format(_ value: Double) -> String {
String(format: "%.2f", value)
}
}

final class CmuxMainRunLoopStallMonitor {
static let shared = CmuxMainRunLoopStallMonitor()

private let thresholdMs: Double = 8.0
private var observer: CFRunLoopObserver?
private var installed = false
private var lastActivity: CFRunLoopActivity?
private var lastTimestamp: TimeInterval?

private init() {}

func installIfNeeded() {
guard CmuxTypingTiming.isEnabled else { return }
guard !installed else { return }

var context = CFRunLoopObserverContext(
version: 0,
info: Unmanaged.passUnretained(self).toOpaque(),
retain: nil,
release: nil,
copyDescription: nil
)

observer = CFRunLoopObserverCreate(
kCFAllocatorDefault,
CFRunLoopActivity.allActivities.rawValue,
true,
CFIndex.max,
{ _, activity, info in
guard let info else { return }
let monitor = Unmanaged<CmuxMainRunLoopStallMonitor>.fromOpaque(info).takeUnretainedValue()
monitor.handle(activity: activity)
},
&context
)

guard let observer else { return }
CFRunLoopAddObserver(CFRunLoopGetMain(), observer, .commonModes)
installed = true
}

private func handle(activity: CFRunLoopActivity) {
let now = ProcessInfo.processInfo.systemUptime
defer {
lastActivity = activity
lastTimestamp = now
}

guard let lastActivity, let lastTimestamp else { return }
let elapsedMs = max(0, (now - lastTimestamp) * 1000.0)
guard elapsedMs >= thresholdMs else { return }
if lastActivity == .beforeWaiting && activity == .afterWaiting {
return
}

let mode = CFRunLoopCopyCurrentMode(CFRunLoopGetMain()).map { String(describing: $0) } ?? "nil"
let firstResponder = NSApp.keyWindow?.firstResponder.map { String(describing: type(of: $0)) } ?? "nil"
let currentEvent = NSApp.currentEvent.map {
"eventType=\($0.type.rawValue) keyCode=\($0.keyCode) mods=\($0.modifierFlags.rawValue)"
} ?? "event=nil"
cmuxDebugLog(
"runloop.stall gapMs=\(String(format: "%.2f", elapsedMs)) prev=\(label(for: lastActivity)) " +
"next=\(label(for: activity)) mode=\(mode) firstResponder=\(firstResponder) \(currentEvent)"
)
}

private func label(for activity: CFRunLoopActivity) -> String {
switch activity {
case .entry:
return "entry"
case .beforeTimers:
return "beforeTimers"
case .beforeSources:
return "beforeSources"
case .beforeWaiting:
return "beforeWaiting"
case .afterWaiting:
return "afterWaiting"
case .exit:
return "exit"
default:
return "unknown(\(activity.rawValue))"
}
}
}

final class CmuxMainThreadTurnProfiler {
static let shared = CmuxMainThreadTurnProfiler()

private struct BucketStats {
var count: Int = 0
var totalMs: Double = 0
var maxMs: Double = 0
}

private let trackedThresholdMs: Double = 3.0
private let countThreshold: Int = 16
private var observer: CFRunLoopObserver?
private var installed = false
private var turnStart: TimeInterval?
private var buckets: [String: BucketStats] = [:]

private init() {}

@inline(__always)
static func endMeasure(_ bucket: String, startedAt: TimeInterval?) {
guard let startedAt, CmuxTypingTiming.isEnabled, Thread.isMainThread else { return }
let elapsedMs = max(0, (ProcessInfo.processInfo.systemUptime - startedAt) * 1000.0)
shared.record(bucket: bucket, elapsedMs: elapsedMs, count: 1)
}

func installIfNeeded() {
guard CmuxTypingTiming.isEnabled else { return }
guard !installed else { return }

var context = CFRunLoopObserverContext(
version: 0,
info: Unmanaged.passUnretained(self).toOpaque(),
retain: nil,
release: nil,
copyDescription: nil
)

observer = CFRunLoopObserverCreate(
kCFAllocatorDefault,
CFRunLoopActivity.allActivities.rawValue,
true,
CFIndex.max,
{ _, activity, info in
guard let info else { return }
let profiler = Unmanaged<CmuxMainThreadTurnProfiler>.fromOpaque(info).takeUnretainedValue()
profiler.handle(activity: activity)
},
&context
)

guard let observer else { return }
CFRunLoopAddObserver(CFRunLoopGetMain(), observer, .commonModes)
installed = true
}

private func handle(activity: CFRunLoopActivity) {
let now = ProcessInfo.processInfo.systemUptime
switch activity {
case .entry, .afterWaiting:
turnStart = now
buckets.removeAll(keepingCapacity: true)
case .beforeWaiting, .exit:
flushTurn(at: now, nextActivity: activity)
default:
break
}
}

private func record(bucket: String, elapsedMs: Double, count: Int) {
if turnStart == nil {
turnStart = ProcessInfo.processInfo.systemUptime
}
var stats = buckets[bucket, default: BucketStats()]
stats.count += count
stats.totalMs += elapsedMs
stats.maxMs = max(stats.maxMs, elapsedMs)
buckets[bucket] = stats
}

private func flushTurn(at now: TimeInterval, nextActivity: CFRunLoopActivity) {
defer {
turnStart = nil
buckets.removeAll(keepingCapacity: true)
}

guard let turnStart else { return }
guard !buckets.isEmpty else { return }

let turnMs = max(0, (now - turnStart) * 1000.0)
let trackedMs = buckets.values.reduce(0) { $0 + $1.totalMs }
let totalCount = buckets.values.reduce(0) { $0 + $1.count }
guard trackedMs >= trackedThresholdMs || totalCount >= countThreshold else { return }

let mode = CFRunLoopCopyCurrentMode(CFRunLoopGetMain()).map { String(describing: $0) } ?? "nil"
let firstResponder = NSApp.keyWindow?.firstResponder.map { String(describing: type(of: $0)) } ?? "nil"
let eventSummary = NSApp.currentEvent.map {
"eventType=\($0.type.rawValue) keyCode=\($0.keyCode) mods=\($0.modifierFlags.rawValue)"
} ?? "event=nil"
let bucketSummary = buckets
.sorted {
if abs($0.value.totalMs - $1.value.totalMs) > 0.01 {
return $0.value.totalMs > $1.value.totalMs
}
return $0.value.count > $1.value.count
}
.prefix(8)
.map { key, value in
if value.totalMs > 0.05 || value.maxMs > 0.05 {
return "\(key)=\(value.count)/\(String(format: "%.2f", value.totalMs))/\(String(format: "%.2f", value.maxMs))"
}
return "\(key)=\(value.count)"
}
.joined(separator: " ")

cmuxDebugLog(
"main.turn.work turnMs=\(String(format: "%.2f", turnMs)) trackedMs=\(String(format: "%.2f", trackedMs)) totalCount=\(totalCount) " +
"next=\(label(for: nextActivity)) mode=\(mode) firstResponder=\(firstResponder) \(eventSummary) " +
"\(bucketSummary)"
)
}

private func label(for activity: CFRunLoopActivity) -> String {
switch activity {
case .entry:
return "entry"
case .beforeTimers:
return "beforeTimers"
case .beforeSources:
return "beforeSources"
case .beforeWaiting:
return "beforeWaiting"
case .afterWaiting:
return "afterWaiting"
case .exit:
return "exit"
default:
return "unknown(\(activity.rawValue))"
}
}
}
#endif

@MainActor
final class AppDelegate: NSObject, NSApplicationDelegate, UNUserNotificationCenterDelegate, NSMenuItemValidation, NSMenuDelegate, CmuxConfigStoreReloadEnvironment {
Expand Down
Loading