From 9412ca916c8fb70008866ab0a9134fcdea7be9a7 Mon Sep 17 00:00:00 2001 From: Arkadiusz Fal Date: Sat, 24 Oct 2026 19:36:51 +0200 Subject: [PATCH] Add performance logging and background diagnostics Performance Logging (Developer settings) logs a resource sample every 5s in the foreground and background: CPU by area and thread, wakeups, GPU, memory, disk, activity counters as rates (mpv property updates, player time publishes, renders, saves, network, images, CloudKit events, log entries, main run-loop wakeups), SwiftUI body evaluations of the player views, and app/player/battery context. Each foreground/background transition logs a summary of the period. MetricKit metrics and diagnostics (CPU exceptions, hangs) are logged whenever logging is on. Background diagnostics (iOS) log lifecycle, audio session and power events with an app/player/render snapshot and a heartbeat that detects suspension gaps and main-thread stalls. Logs are persisted per session in Caches/Logs and the previous session is included in exports, so logs survive the app being swiped away. --- Yattee/ContentView.swift | 1 + Yattee/Data/DataManager.swift | 1 + Yattee/Localizable.xcstrings | 11 + .../CloudKit/CloudKitSyncEngine.swift | 22 + .../ImageLoading/ImageLoadingService.swift | 5 + .../Logging/BackgroundDiagnostics.swift | 390 ++++++++++++++++ Yattee/Services/Logging/LogFileStore.swift | 94 ++++ Yattee/Services/Logging/LoggingService.swift | 22 +- .../Logging/PerformanceCounters.swift | 51 +++ .../Services/Logging/PerformanceMonitor.swift | 415 ++++++++++++++++++ Yattee/Services/Logging/ResourceSampler.swift | 260 +++++++++++ Yattee/Services/Networking/HTTPClient.swift | 2 + .../Services/Player/MPV/MPVRenderView.swift | 46 ++ Yattee/Services/Player/MPVBackend.swift | 3 + .../Services/Player/NowPlayingService.swift | 1 + Yattee/Services/Player/PlayerService.swift | 2 + Yattee/Services/Player/PlayerState.swift | 2 + Yattee/Views/Components/MarqueeText.swift | 2 + .../Player/ControlsSectionRenderer.swift | 1 + Yattee/Views/Player/ExpandedPlayerSheet.swift | 1 + Yattee/Views/Player/MiniPlayerView.swift | 1 + Yattee/Views/Player/PlayerControlsView.swift | 2 + .../Views/Player/SegmentedProgressBar.swift | 2 + .../Views/Player/macOS/MacOSControlBar.swift | 1 + .../Player/tvOS/TVPlayerControlsView.swift | 1 + .../Settings/DeveloperSettingsView.swift | 8 + Yattee/Views/Video/VideoInfoView.swift | 1 + Yattee/YatteeApp.swift | 7 + 28 files changed, 1354 insertions(+), 1 deletion(-) create mode 100644 Yattee/Services/Logging/BackgroundDiagnostics.swift create mode 100644 Yattee/Services/Logging/LogFileStore.swift create mode 100644 Yattee/Services/Logging/PerformanceCounters.swift create mode 100644 Yattee/Services/Logging/PerformanceMonitor.swift create mode 100644 Yattee/Services/Logging/ResourceSampler.swift diff --git a/Yattee/ContentView.swift b/Yattee/ContentView.swift index 0bfa8a71..b27cb7cd 100644 --- a/Yattee/ContentView.swift +++ b/Yattee/ContentView.swift @@ -14,6 +14,7 @@ struct ContentView: View { #endif var body: some View { + let _ = PerfCounter.body("ContentView") Group { if let appEnvironment { #if os(iOS) diff --git a/Yattee/Data/DataManager.swift b/Yattee/Data/DataManager.swift index 1d09636d..9fb8e686 100644 --- a/Yattee/Data/DataManager.swift +++ b/Yattee/Data/DataManager.swift @@ -134,6 +134,7 @@ final class DataManager { /// Forces a save of any pending changes. func save() { + PerfCounter.count("data.save") do { try modelContext.save() } catch { diff --git a/Yattee/Localizable.xcstrings b/Yattee/Localizable.xcstrings index cdd602fc..f5562cc4 100644 --- a/Yattee/Localizable.xcstrings +++ b/Yattee/Localizable.xcstrings @@ -11196,6 +11196,17 @@ } } }, + "settings.advanced.debug.performanceLogging" : { + "comment" : "Toggle label for logging CPU, energy and activity every few seconds", + "localizations" : { + "en" : { + "stringUnit" : { + "state" : "translated", + "value" : "Performance Logging" + } + } + } + }, "settings.advanced.debug.playerAreaDebug" : { "comment" : "Toggle label", "localizations" : { diff --git a/Yattee/Services/CloudKit/CloudKitSyncEngine.swift b/Yattee/Services/CloudKit/CloudKitSyncEngine.swift index d514f189..a817c46f 100644 --- a/Yattee/Services/CloudKit/CloudKitSyncEngine.swift +++ b/Yattee/Services/CloudKit/CloudKitSyncEngine.swift @@ -1930,6 +1930,9 @@ final class CloudKitSyncEngine: @unchecked Sendable { extension CloudKitSyncEngine: CKSyncEngineDelegate { nonisolated func handleEvent(_ event: CKSyncEngine.Event, syncEngine: CKSyncEngine) async { + if PerfCounter.enabled { + PerfCounter.count("cloudkit.event." + Self.performanceName(of: event)) + } // Marks the whole callback tree, so anything that re-enters the engine // from inside it says so in a debug build instead of trapping on // someone's device. Inherited by every plain `Task { }` started below @@ -1940,6 +1943,25 @@ extension CloudKitSyncEngine: CKSyncEngineDelegate { } } + /// Event name for performance counters (the event's description includes its payload). + private nonisolated static func performanceName(of event: CKSyncEngine.Event) -> String { + switch event { + case .stateUpdate: "stateUpdate" + case .accountChange: "accountChange" + case .fetchedDatabaseChanges: "fetchedDatabaseChanges" + case .fetchedRecordZoneChanges: "fetchedRecordZoneChanges" + case .sentDatabaseChanges: "sentDatabaseChanges" + case .sentRecordZoneChanges: "sentRecordZoneChanges" + case .willFetchChanges: "willFetchChanges" + case .willFetchRecordZoneChanges: "willFetchRecordZoneChanges" + case .didFetchRecordZoneChanges: "didFetchRecordZoneChanges" + case .didFetchChanges: "didFetchChanges" + case .willSendChanges: "willSendChanges" + case .didSendChanges: "didSendChanges" + @unknown default: "other" + } + } + private nonisolated func handleDelegateEvent(_ event: CKSyncEngine.Event) async { // Events that require async processing must be awaited directly (not in a fire-and-forget Task) // so that CKSyncEngine waits for processing to complete before advancing the sync state token. diff --git a/Yattee/Services/ImageLoading/ImageLoadingService.swift b/Yattee/Services/ImageLoading/ImageLoadingService.swift index 474fbc09..630bf876 100644 --- a/Yattee/Services/ImageLoading/ImageLoadingService.swift +++ b/Yattee/Services/ImageLoading/ImageLoadingService.swift @@ -127,4 +127,9 @@ private final class TokenStrippingPipelineDelegate: ImagePipelineDelegate { guard let url = request.url else { return nil } return ImageLoadingService.cacheKey(for: url) } + + func imageTask(_ task: ImageTask, didCompleteWithResult result: Result, pipeline _: ImagePipeline) { + guard PerfCounter.enabled, case let .success(response) = result else { return } + PerfCounter.count(response.cacheType == nil ? "image.loadFromNetwork" : "image.loadFromCache") + } } diff --git a/Yattee/Services/Logging/BackgroundDiagnostics.swift b/Yattee/Services/Logging/BackgroundDiagnostics.swift new file mode 100644 index 00000000..e141b891 --- /dev/null +++ b/Yattee/Services/Logging/BackgroundDiagnostics.swift @@ -0,0 +1,390 @@ +// +// BackgroundDiagnostics.swift +// Yattee +// +// Heartbeat and event logging to diagnose battery drain and heat while the +// app is in the background. +// + +import Foundation + +/// Render activity counters, reset each time they are read. +final class RenderDiagnosticsCounters: @unchecked Sendable { + struct Counts { + var linkFires = 0 + var renders = 0 + var presents = 0 + var backgroundRenders = 0 + var skippedInBackground = 0 + } + + private let lock = NSLock() + private var counts = Counts() + + func increment(_ key: WritableKeyPath) { + lock.withLock { counts[keyPath: key] += 1 } + } + + func take() -> Counts { + lock.withLock { + defer { counts = Counts() } + return counts + } + } +} + +#if os(iOS) +import AVFoundation +import UIKit + +/// Logs a process/app/player snapshot every 10 seconds while the app is not +/// active (every 30 seconds while active), plus lifecycle, audio and power +/// events, under the Diagnostics category. +/// +/// Only does work while "Enable Logging" is on. Logs are persisted to disk by +/// `LogFileStore`, so they survive the app being swiped away. +/// +/// The heartbeat timer runs on its own queue, independent of the main thread: +/// a "heartbeat gap" means the whole process was suspended, while a heartbeat +/// without its app snapshot means the main thread was blocked. +@MainActor +final class BackgroundDiagnostics { + static let shared = BackgroundDiagnostics() + + private weak var playerService: PlayerService? + private var observers: [NSObjectProtocol] = [] + private var runLoopObserver: CFRunLoopObserver? + private var runLoopWakeups = 0 + private var started = false + private let sampler = ProcessSampler() + + private init() {} + + func start(playerService: PlayerService) { + guard !started else { return } + started = true + self.playerService = playerService + + UIDevice.current.isBatteryMonitoringEnabled = true + sampler.setMainThreadPort(pthread_mach_thread_np(pthread_self())) + installRunLoopObserver() + observeEvents() + sampler.start() + log(.info, "Diagnostics started", details: appSnapshot()) + } + + // MARK: - Snapshot + + /// App, device, player, audio and render state. Must run on the main thread. + func appSnapshot() -> String { + let app = UIApplication.shared + var lines: [String] = [] + + var appLine = "app: state=\(describe(app.applicationState))" + if app.applicationState == .background { + let remaining = app.backgroundTimeRemaining + appLine += " bgTimeRemaining=" + (remaining > 1e6 ? "unlimited" : "\(Int(remaining))s") + } + appLine += " protectedData=\(app.isProtectedDataAvailable ? "available" : "locked")" + appLine += " scenes=[\(app.connectedScenes.map { describe($0.activationState) }.joined(separator: ","))]" + appLine += " idleTimerDisabled=\(app.isIdleTimerDisabled)" + lines.append(appLine) + + let device = UIDevice.current + let battery = device.batteryLevel < 0 ? "?" : "\(Int(device.batteryLevel * 100))%" + lines.append("device: thermal=\(describe(ProcessInfo.processInfo.thermalState)) battery=\(battery)" + + " batteryState=\(describe(device.batteryState)) lowPower=\(ProcessInfo.processInfo.isLowPowerModeEnabled)") + + lines.append("mainRunLoop: wakeups=\(runLoopWakeups) since last sample") + runLoopWakeups = 0 + + if let playerService { + let state = playerService.state + lines.append("player: state=\(describe(state.playbackState)) pip=\(state.pipState)" + + " backend=\(playerService.currentBackendType) video=\(state.currentVideo?.id.videoID ?? "none")" + + " time=\(Int(state.currentTime))/\(Int(state.duration))" + + " publishesTime=\(state.publishesTimeUpdates)") + } + + let session = AVAudioSession.sharedInstance() + let outputs = session.currentRoute.outputs.map { "\($0.portType.rawValue)(\($0.portName))" } + lines.append("audio: category=\(session.category.rawValue) mode=\(session.mode.rawValue)" + + " otherAudioPlaying=\(session.isOtherAudioPlaying)" + + " silenceSecondaryHint=\(session.secondaryAudioShouldBeSilencedHint)" + + " route=[\(outputs.joined(separator: ","))]") + + let renderViews = MPVRenderView.diagnosticsInstances + if renderViews.isEmpty { + lines.append("render: no MPV render views") + } else { + lines.append(contentsOf: renderViews.map { "render: " + $0.diagnosticsSummary() }) + } + + return lines.joined(separator: "\n") + } + + /// Called by the sampler with the process-level part of a heartbeat. + nonisolated fileprivate func deliverHeartbeat(process: String, highCPU: Bool, enqueuedAt: DispatchTime) { + let latencyMs = (DispatchTime.now().uptimeNanoseconds - enqueuedAt.uptimeNanoseconds) / 1_000_000 + MainActor.assumeIsolated { + let state = describe(UIApplication.shared.applicationState) + // Background playback legitimately costs CPU; flag only when nothing is playing. + let isPlaying = playerService?.state.playbackState == .playing + log(highCPU && !isPlaying ? .warning : .info, "Heartbeat [\(state)]", + details: process + "\nmainThread: latency=\(latencyMs)ms\n" + appSnapshot()) + } + } + + // MARK: - Events + + private func installRunLoopObserver() { + let observer = CFRunLoopObserverCreateWithHandler(nil, CFRunLoopActivity.afterWaiting.rawValue, true, 0) { _, _ in + MainActor.assumeIsolated { + BackgroundDiagnostics.shared.runLoopWakeups += 1 + } + } + CFRunLoopAddObserver(CFRunLoopGetMain(), observer, .commonModes) + runLoopObserver = observer + } + + private func observeEvents() { + let center = NotificationCenter.default + + let lifecycle: [(Notification.Name, String)] = [ + (UIApplication.willResignActiveNotification, "App will resign active"), + (UIApplication.didEnterBackgroundNotification, "App did enter background"), + (UIApplication.willEnterForegroundNotification, "App will enter foreground"), + (UIApplication.didBecomeActiveNotification, "App did become active"), + (UIApplication.willTerminateNotification, "App will terminate"), + (UIApplication.didReceiveMemoryWarningNotification, "Memory warning"), + (UIApplication.protectedDataWillBecomeUnavailableNotification, "Device locking (protected data unavailable)"), + (UIApplication.protectedDataDidBecomeAvailableNotification, "Device unlocked (protected data available)"), + (ProcessInfo.thermalStateDidChangeNotification, "Thermal state changed"), + (Notification.Name.NSProcessInfoPowerStateDidChange, "Low Power Mode changed"), + (UIDevice.batteryStateDidChangeNotification, "Battery state changed"), + (UIDevice.batteryLevelDidChangeNotification, "Battery level changed"), + (AVAudioSession.mediaServicesWereResetNotification, "Audio media services were reset"), + (AVAudioSession.mediaServicesWereLostNotification, "Audio media services were lost"), + ] + for (name, message) in lifecycle { + observers.append(center.addObserver(forName: name, object: nil, queue: .main) { _ in + MainActor.assumeIsolated { + BackgroundDiagnostics.shared.logEvent(message) + } + }) + } + + observers.append(center.addObserver(forName: AVAudioSession.interruptionNotification, object: nil, queue: .main) { notification in + let info = notification.userInfo ?? [:] + let type = (info[AVAudioSessionInterruptionTypeKey] as? UInt).flatMap(AVAudioSession.InterruptionType.init) + let reason = (info[AVAudioSessionInterruptionReasonKey] as? UInt).flatMap(AVAudioSession.InterruptionReason.init) + let options = (info[AVAudioSessionInterruptionOptionKey] as? UInt).map(AVAudioSession.InterruptionOptions.init) + let details = "type=\(type == .began ? "began" : type == .ended ? "ended" : "?")" + + " reason=\(reason.map { "\($0.rawValue)" } ?? "none")" + + " shouldResume=\(options?.contains(.shouldResume) ?? false)" + MainActor.assumeIsolated { + BackgroundDiagnostics.shared.logEvent("Audio interruption", extra: details) + } + }) + + observers.append(center.addObserver(forName: AVAudioSession.routeChangeNotification, object: nil, queue: .main) { notification in + let info = notification.userInfo ?? [:] + let reason = (info[AVAudioSessionRouteChangeReasonKey] as? UInt).flatMap(AVAudioSession.RouteChangeReason.init) + let previous = (info[AVAudioSessionRouteChangePreviousRouteKey] as? AVAudioSessionRouteDescription)? + .outputs.map { $0.portType.rawValue }.joined(separator: ",") ?? "?" + let details = "reason=\(reason.map { "\($0.rawValue)" } ?? "?") previousRoute=[\(previous)]" + MainActor.assumeIsolated { + BackgroundDiagnostics.shared.logEvent("Audio route changed", extra: details) + } + }) + + observers.append(center.addObserver(forName: AVAudioSession.silenceSecondaryAudioHintNotification, object: nil, queue: .main) { notification in + let type = (notification.userInfo?[AVAudioSessionSilenceSecondaryAudioHintTypeKey] as? UInt) + .flatMap(AVAudioSession.SilenceSecondaryAudioHintType.init) + let details = "type=\(type == .begin ? "begin" : type == .end ? "end" : "?")" + MainActor.assumeIsolated { + BackgroundDiagnostics.shared.logEvent("Silence secondary audio hint", extra: details) + } + }) + } + + private func logEvent(_ message: String, extra: String? = nil) { + guard LoggingService.shared.isEnabled else { return } + var details = appSnapshot() + if let extra { + details = extra + "\n" + details + } + log(.info, message, details: details) + // A fresh process sample right at the transition, and the cadence follows the new state. + sampler.setAppActive(UIApplication.shared.applicationState == .active) + sampler.sampleSoon() + } + + private func log(_ level: LogLevel, _ message: String, details: String) { + LoggingService.shared.log(level: level, category: .diagnostics, message: message, details: details) + } + + // MARK: - Descriptions + + private func describe(_ state: UIApplication.State) -> String { + switch state { + case .active: "active" + case .inactive: "inactive" + case .background: "background" + @unknown default: "unknown(\(state.rawValue))" + } + } + + private func describe(_ state: UIScene.ActivationState) -> String { + switch state { + case .foregroundActive: "foregroundActive" + case .foregroundInactive: "foregroundInactive" + case .background: "background" + case .unattached: "unattached" + @unknown default: "unknown" + } + } + + private func describe(_ state: ProcessInfo.ThermalState) -> String { + switch state { + case .nominal: "nominal" + case .fair: "fair" + case .serious: "serious" + case .critical: "critical" + @unknown default: "unknown" + } + } + + private func describe(_ state: UIDevice.BatteryState) -> String { + switch state { + case .unknown: "unknown" + case .unplugged: "unplugged" + case .charging: "charging" + case .full: "full" + @unknown default: "unknown" + } + } + + private func describe(_ state: PlaybackState) -> String { + if case .failed = state { return "failed" } + return "\(state)" + } +} + +/// Samples process CPU, per-thread CPU, wakeups, GPU time and memory on its own +/// queue. All mutable state is confined to `queue`. +private final class ProcessSampler: @unchecked Sendable { + private static let interval: TimeInterval = 10 + /// While the app is active, log only every Nth sample. + private static let activeLogEvery = 3 + /// Process CPU above this while not active is logged as a warning. + private static let highCPUPercent = 15.0 + + private let queue = DispatchQueue(label: "stream.yattee.diagnostics", qos: .utility) + private var timer: DispatchSourceTimer? + private var isAppActive = true + private var tick = 0 + + private var lastTick: Date? + private var resourceSampler: ResourceSampler? + private var pendingSoon = false + + func setMainThreadPort(_ port: mach_port_t) { + queue.async { self.resourceSampler = ResourceSampler(mainThreadPort: port) } + } + + func setAppActive(_ active: Bool) { + queue.async { self.isAppActive = active } + } + + func start() { + queue.async { + let timer = DispatchSource.makeTimerSource(queue: self.queue) + timer.schedule(deadline: .now() + Self.interval, repeating: Self.interval, leeway: .seconds(1)) + timer.setEventHandler { self.fire(forced: false) } + timer.resume() + self.timer = timer + _ = self.sample() // baseline + } + } + + /// Take an extra sample shortly after a lifecycle event. + func sampleSoon() { + queue.async { + guard !self.pendingSoon else { return } + self.pendingSoon = true + self.queue.asyncAfter(deadline: .now() + 1) { + self.pendingSoon = false + self.fire(forced: true) + } + } + } + + private func fire(forced: Bool) { + guard UserDefaults.standard.bool(forKey: "loggingEnabled") else { + lastTick = nil + return + } + + let now = Date() + if !forced, let lastTick { + let gap = now.timeIntervalSince(lastTick) + if gap > Self.interval * 2.5 { + LoggingService.shared.log(level: .warning, category: .diagnostics, + message: "Heartbeat gap: \(Int(gap))s since previous heartbeat", + details: "The process was suspended (or not scheduled) during the gap.") + } + } + if !forced { + lastTick = now + tick += 1 + } + + let process = sample() + guard forced || !isAppActive || tick % Self.activeLogEvery == 0 else { return } + + let highCPU = !isAppActive && process.cpuPercent >= Self.highCPUPercent + let enqueuedAt = DispatchTime.now() + let responded = ResponseFlag() + DispatchQueue.main.async { + responded.set() + BackgroundDiagnostics.shared.deliverHeartbeat(process: process.text, highCPU: highCPU, enqueuedAt: enqueuedAt) + } + queue.asyncAfter(deadline: .now() + 3) { + guard !responded.isSet else { return } + LoggingService.shared.log(level: .warning, category: .diagnostics, + message: "Heartbeat: main thread did not respond within 3s", details: process.text) + } + } + + // MARK: - Sampling + + private struct ProcessSample { + let text: String + let cpuPercent: Double + } + + private func sample() -> ProcessSample { + guard let resourceSampler else { return ProcessSample(text: "cpu: unavailable", cpuPercent: 0) } + let sample = resourceSampler.sample() + let footprint = sample.footprintMB.map { "\($0)MB" } ?? "?" + let text = String(format: "cpu: process=%.1f%% over %.0fs", sample.cpuPercent, sample.wall) + + " threads=\(sample.threadCount) footprint=\(footprint)\n" + + "hotThreads: \(sample.hotThreadsText)\n" + + sample.powerText + return ProcessSample(text: text, cpuPercent: sample.cpuPercent) + } +} + +/// Set from the main thread, read on the sampler queue. +private final class ResponseFlag: @unchecked Sendable { + private let lock = NSLock() + private var value = false + + var isSet: Bool { lock.withLock { value } } + + func set() { + lock.withLock { value = true } + } +} +#endif diff --git a/Yattee/Services/Logging/LogFileStore.swift b/Yattee/Services/Logging/LogFileStore.swift new file mode 100644 index 00000000..aa787777 --- /dev/null +++ b/Yattee/Services/Logging/LogFileStore.swift @@ -0,0 +1,94 @@ +// +// LogFileStore.swift +// Yattee +// +// Persists log entries to disk so a session's logs survive the app being +// killed and can be exported on the next launch. +// + +import Foundation + +/// Appends log entries to a per-session file in Caches/Logs. +/// +/// The first use in a process rotates the last session's file to +/// `previous-session.log`, so the export after a relaunch still contains the +/// session that was killed. All file access happens on a private serial queue. +final class LogFileStore: @unchecked Sendable { + static let shared = LogFileStore() + + /// Stop writing a session once it reaches this size. + private static let maxSessionBytes = 25 * 1024 * 1024 + + private let queue = DispatchQueue(label: "stream.yattee.logfile", qos: .utility) + private let currentURL: URL + private let previousURL: URL + private var handle: FileHandle? + private var bytesWritten = 0 + private var reachedLimit = false + + private let formatter: DateFormatter = { + let formatter = DateFormatter() + formatter.locale = Locale(identifier: "en_US_POSIX") + formatter.dateFormat = "yyyy-MM-dd HH:mm:ss.SSS" + return formatter + }() + + private init() { + let directory = FileManager.default.urls(for: .cachesDirectory, in: .userDomainMask)[0] + .appendingPathComponent("Logs", isDirectory: true) + currentURL = directory.appendingPathComponent("current-session.log") + previousURL = directory.appendingPathComponent("previous-session.log") + + queue.async { [self] in + let fileManager = FileManager.default + try? fileManager.createDirectory(at: directory, withIntermediateDirectories: true) + if fileManager.fileExists(atPath: currentURL.path) { + try? fileManager.removeItem(at: previousURL) + try? fileManager.moveItem(at: currentURL, to: previousURL) + } + fileManager.createFile(atPath: currentURL.path, contents: nil) + handle = try? FileHandle(forWritingTo: currentURL) + write("Session started: pid \(ProcessInfo.processInfo.processIdentifier), " + + "\(Bundle.main.infoDictionary?["CFBundleShortVersionString"] as? String ?? "?") " + + "(\(Bundle.main.infoDictionary?["CFBundleVersion"] as? String ?? "?"))\n") + } + } + + func append(_ entry: LogEntry) { + queue.async { [self] in + let details = entry.details.map { "\n Details: \($0)" } ?? "" + write("[\(formatter.string(from: entry.timestamp))] [\(entry.level.rawValue.uppercased())] " + + "[\(entry.category.rawValue)] \(entry.message)\(details)\n") + } + } + + /// The previous session's log, or nil when there is none. + func previousSessionText() -> String? { + queue.sync { + guard let data = try? Data(contentsOf: previousURL) else { return nil } + return String(decoding: data, as: UTF8.self) + } + } + + func clear() { + queue.async { [self] in + try? FileManager.default.removeItem(at: previousURL) + try? handle?.truncate(atOffset: 0) + bytesWritten = 0 + reachedLimit = false + } + } + + /// Must be called on `queue`. + private func write(_ line: String) { + guard let handle, !reachedLimit else { return } + let data = Data(line.utf8) + if bytesWritten + data.count > Self.maxSessionBytes { + reachedLimit = true + try? handle.write(contentsOf: Data("--- log size limit reached, further entries not written ---\n".utf8)) + return + } + try? handle.write(contentsOf: data) + bytesWritten += data.count + } +} diff --git a/Yattee/Services/Logging/LoggingService.swift b/Yattee/Services/Logging/LoggingService.swift index c9c583b1..fcad8ac0 100644 --- a/Yattee/Services/Logging/LoggingService.swift +++ b/Yattee/Services/Logging/LoggingService.swift @@ -39,6 +39,8 @@ enum LogCategory: String, Codable, CaseIterable, Sendable { case imageLoading = "ImageLoading" case mediaSources = "MediaSources" case subscriptions = "Subscriptions" + case diagnostics = "Diagnostics" + case performance = "Performance" case general = "General" var icon: String { @@ -55,6 +57,8 @@ enum LogCategory: String, Codable, CaseIterable, Sendable { case .imageLoading: return "photo" case .mediaSources: return "externaldrive.connected.to.line.below" case .subscriptions: return "person.2" + case .diagnostics: return "stethoscope" + case .performance: return "gauge.with.dots.needle.67percent" case .general: return "doc.text" } } @@ -191,6 +195,7 @@ final class LoggingService: Sendable { /// This method is nonisolated to allow safe logging from any thread. /// OSLog output is synchronous; in-app storage is dispatched to MainActor. nonisolated func log(level: LogLevel, category: LogCategory, message: String, details: String? = nil) { + PerfCounter.count("log.entry") // Log to OSLog in DEBUG builds for Xcode console visibility // OSLog/Logger is thread-safe, so this can be called from any thread. // The master "Enable Logging" toggle gates this too - it takes @@ -214,6 +219,10 @@ final class LoggingService: Sendable { } #endif + // Timestamp at the call site: the MainActor hop below can be late when + // the main thread is busy, which is exactly when timing matters. + let timestamp = Date() + // Dispatch in-app storage to MainActor asynchronously // This ensures thread-safety for the entries array Task { @MainActor [weak self] in @@ -221,6 +230,7 @@ final class LoggingService: Sendable { guard self.isEnabled else { return } let entry = LogEntry( + timestamp: timestamp, level: level, category: category, message: message, @@ -228,6 +238,7 @@ final class LoggingService: Sendable { ) self.entries.insert(entry, at: 0) + LogFileStore.shared.append(entry) // Trim old entries if self.entries.count > self.maxEntries { @@ -241,9 +252,13 @@ final class LoggingService: Sendable { /// Clear all log entries. func clearLogs() { entries.removeAll() + LogFileStore.shared.clear() } /// Export logs as text. + /// + /// Includes the previous app session read back from disk, so logs survive + /// the app being killed (e.g. swiped away while the phone was hot). func exportLogs() -> String { let header = "Yattee Logs - Exported \(Date().formatted())\n" let separator = String(repeating: "=", count: 60) + "\n" @@ -253,7 +268,12 @@ final class LoggingService: Sendable { return "[\(entry.formattedTimestamp)] [\(entry.level.rawValue.uppercased())] [\(entry.category.rawValue)] \(entry.message)\(details)" }.joined(separator: "\n") - return header + separator + logLines + guard let previous = LogFileStore.shared.previousSessionText(), !previous.isEmpty else { + return header + separator + logLines + } + return header + separator + + "PREVIOUS SESSION (read from disk)\n" + separator + previous + "\n" + + separator + "CURRENT SESSION\n" + separator + logLines } /// Reset filters. diff --git a/Yattee/Services/Logging/PerformanceCounters.swift b/Yattee/Services/Logging/PerformanceCounters.swift new file mode 100644 index 00000000..7ac966eb --- /dev/null +++ b/Yattee/Services/Logging/PerformanceCounters.swift @@ -0,0 +1,51 @@ +// +// PerformanceCounters.swift +// Yattee +// +// Activity counters for performance logging. Each counter is reported as a +// rate by PerformanceMonitor, so a log shows what the app was busy doing. +// + +import Foundation +import Synchronization + +/// Named activity counters, safe to bump from any thread. +/// +/// Counting is a no-op unless Performance Logging is on, so call sites can +/// stay in hot paths: +/// +/// PerfCounter.count("mpv.prop.time-pos") +/// +/// In a SwiftUI body, count evaluations with `let _ = PerfCounter.body("Name")`. +enum PerfCounter { + private static let isEnabled = Atomic(false) + + private static let counts = Mutex<[String: Int]>([:]) + + @inline(__always) + static var enabled: Bool { isEnabled.load(ordering: .relaxed) } + + static func setEnabled(_ enabled: Bool) { + isEnabled.store(enabled, ordering: .relaxed) + } + + static func count(_ key: String, by amount: Int = 1) { + guard enabled else { return } + counts.withLock { $0[key, default: 0] += amount } + } + + /// Counts one body evaluation of the named view. + static func body(_ name: StaticString) { + guard enabled else { return } + let key = "view." + name.description + counts.withLock { $0[key, default: 0] += 1 } + } + + /// Returns the counts accumulated since the last call and resets them. + static func take() -> [String: Int] { + counts.withLock { + defer { $0 = [:] } + return $0 + } + } +} diff --git a/Yattee/Services/Logging/PerformanceMonitor.swift b/Yattee/Services/Logging/PerformanceMonitor.swift new file mode 100644 index 00000000..5b9b4bcf --- /dev/null +++ b/Yattee/Services/Logging/PerformanceMonitor.swift @@ -0,0 +1,415 @@ +// +// PerformanceMonitor.swift +// Yattee +// +// Performance Logging: periodic resource usage with attribution, in the +// foreground and the background, under the Performance log category. +// + +import Foundation +#if os(iOS) || os(tvOS) +import UIKit +#elseif os(macOS) +import AppKit +#endif +#if os(iOS) || os(macOS) +import MetricKit +#endif + +/// Logs a resource sample every 5 seconds while Performance Logging is on: +/// CPU split by area and thread, wakeups, GPU, memory, disk, the +/// activity counters (`PerfCounter`) as rates, and app/player context. +/// Each foreground/background transition also logs a summary of the period +/// that just ended. +/// +/// MetricKit reports (daily metrics, CPU exceptions, hangs) are logged +/// whenever logging is enabled, independent of the Performance toggle. +final class PerformanceMonitor: @unchecked Sendable { + static let shared = PerformanceMonitor() + static let enabledKey = "performanceLoggingEnabled" + + private static let interval: TimeInterval = 5 + /// Process CPU above these (percent of one core) logs the sample as a warning. + private static let highCPUForeground = 60.0 + private static let highCPUBackground = 15.0 + + // Confined to `queue`. + private let queue = DispatchQueue(label: "stream.yattee.performance", qos: .utility) + private var sampler: ResourceSampler? + private var timer: DispatchSourceTimer? + private var period: Period? + private var context = "" + private var isBackground = false + + // Main thread only. + @MainActor private weak var appEnvironment: AppEnvironment? + @MainActor private var runLoopObserver: CFRunLoopObserver? + @MainActor private var started = false + @MainActor private var batteryReference: (date: Date, level: Float)? + #if os(iOS) || os(macOS) + @MainActor private var metricSubscriber: MetricSubscriber? + #endif + + private init() {} + + var isEnabled: Bool { + UserDefaults.standard.bool(forKey: Self.enabledKey) + } + + @MainActor + func start(appEnvironment: AppEnvironment) { + guard !started else { return } + started = true + self.appEnvironment = appEnvironment + observeLifecycle() + #if os(iOS) || os(macOS) + let subscriber = MetricSubscriber() + MXMetricManager.shared.add(subscriber) + metricSubscriber = subscriber + #endif + if isEnabled { + activate() + } + } + + @MainActor + func setEnabled(_ enabled: Bool) { + guard enabled != isEnabled else { return } + UserDefaults.standard.set(enabled, forKey: Self.enabledKey) + if enabled { + activate() + } else { + deactivate() + } + } + + // MARK: - Activation + + @MainActor + private func activate() { + PerfCounter.setEnabled(true) + installRunLoopObserver() + #if os(iOS) + UIDevice.current.isBatteryMonitoringEnabled = true + #endif + + let mainThreadPort = pthread_mach_thread_np(pthread_self()) + let background = currentlyInBackground() + let context = makeContext() + queue.async { + self.isBackground = background + self.context = context + let sampler = ResourceSampler(mainThreadPort: mainThreadPort) + sampler.reset() + self.sampler = sampler + _ = PerfCounter.take() + self.period = Period(background: background) + + let timer = DispatchSource.makeTimerSource(queue: self.queue) + timer.schedule(deadline: .now() + Self.interval, repeating: Self.interval, leeway: .milliseconds(500)) + timer.setEventHandler { self.tick() } + timer.resume() + self.timer = timer + + self.log(.info, "Performance logging started", details: "context: " + context) + } + } + + @MainActor + private func deactivate() { + PerfCounter.setEnabled(false) + if let runLoopObserver { + CFRunLoopRemoveObserver(CFRunLoopGetMain(), runLoopObserver, .commonModes) + self.runLoopObserver = nil + } + queue.async { + self.timer?.cancel() + self.timer = nil + self.logPeriodSummary() + self.period = nil + self.sampler = nil + self.log(.info, "Performance logging stopped", details: nil) + } + } + + @MainActor + private func installRunLoopObserver() { + guard runLoopObserver == nil else { return } + let observer = CFRunLoopObserverCreateWithHandler(nil, CFRunLoopActivity.afterWaiting.rawValue, true, 0) { _, _ in + PerfCounter.count("main.runLoopWakeup") + } + CFRunLoopAddObserver(CFRunLoopGetMain(), observer, .commonModes) + runLoopObserver = observer + } + + // MARK: - Lifecycle + + @MainActor + private func observeLifecycle() { + let center = NotificationCenter.default + #if os(iOS) || os(tvOS) + let transitions: [(Notification.Name, Bool)] = [ + (UIApplication.didEnterBackgroundNotification, true), + (UIApplication.willEnterForegroundNotification, false), + ] + #elseif os(macOS) + let transitions: [(Notification.Name, Bool)] = [ + (NSApplication.didResignActiveNotification, true), + (NSApplication.didBecomeActiveNotification, false), + ] + #endif + for (name, background) in transitions { + center.addObserver(forName: name, object: nil, queue: .main) { _ in + MainActor.assumeIsolated { + PerformanceMonitor.shared.stateChanged(background: background) + } + } + } + } + + @MainActor + private func stateChanged(background: Bool) { + guard PerfCounter.enabled else { return } + let context = makeContext() + queue.async { + guard self.sampler != nil, background != self.isBackground else { return } + // Close the period at the transition with a final sample. + self.takeSample() + self.logPeriodSummary() + self.context = context + self.isBackground = background + self.period = Period(background: background) + } + } + + // MARK: - Sampling + + private func tick() { + takeSample() + // Refresh the context for the next sample; the main thread may be + // busy, so the sample itself never waits for it. + DispatchQueue.main.async { + let context = MainActor.assumeIsolated { self.makeContext() } + self.queue.async { self.context = context } + } + } + + /// Must run on `queue`. + private func takeSample() { + guard let sampler else { return } + let sample = sampler.sample() + let counts = PerfCounter.take() + guard sample.wall > 0 else { return } + period?.add(sample, counts: counts) + + // A sample right after the previous one (at a transition) only feeds the period totals. + guard sample.wall >= 1, UserDefaults.standard.bool(forKey: "loggingEnabled") else { return } + + let state = isBackground ? "bg" : "fg" + let threshold = isBackground ? Self.highCPUBackground : Self.highCPUForeground + let footprint = sample.footprintMB.map { "\($0)MB" } ?? "?" + let wakeups = (sample.idleWakeupsPerSecond ?? 0) + (sample.interruptWakeupsPerSecond ?? 0) + let message = String(format: "Perf [%@] cpu %.1f%% | %@ | wakeups %.0f/s | mem %@", + state, sample.cpuPercent, sample.areasText, wakeups, footprint) + + var lines = [ + "threads: \(sample.hotThreadsText)", + sample.powerText, + String(format: "cpu: user %.1f%% system %.1f%% | %d threads | disk ops read %d write %d | window %.1fs", + sample.userPercent, sample.systemPercent, sample.threadCount, + sample.diskReadOps, sample.diskWriteOps, sample.wall), + ] + lines.append(contentsOf: Self.describeCounts(counts, over: sample.wall)) + lines.append("context: \(context)") + + log(sample.cpuPercent >= threshold ? .warning : .info, message, details: lines.joined(separator: "\n")) + } + + /// Must run on `queue`. + private func logPeriodSummary() { + guard let period, period.wall > 0, + UserDefaults.standard.bool(forKey: "loggingEnabled") else { return } + let wall = period.wall + let minutes = Int(wall) / 60 + let seconds = Int(wall) % 60 + let areas = period.areaSeconds.sorted { $0.value > $1.value } + .map { String(format: "%@ %.1f", $0.key, $0.value / wall * 100) } + .joined(separator: " ") + + var lines = [ + String(format: "cpu: avg %.1f%% max %.1f%% | %@", period.cpuSeconds / wall * 100, period.maxCPU, areas.isEmpty ? "idle" : areas), + String(format: "wakeups: avg %.0f/s", period.wakeups / wall), + ] + lines.append(contentsOf: Self.describeCounts(period.counts, over: wall)) + lines.append("context: \(context)") + + log(.info, "Perf summary [\(period.background ? "bg" : "fg")] \(minutes)m \(seconds)s", + details: lines.joined(separator: "\n")) + } + + /// Counters as rates: views in their own line, everything else as "activity". + private static func describeCounts(_ counts: [String: Int], over wall: TimeInterval) -> [String] { + func format(_ entries: [(key: String, value: Int)], stripping prefix: String = "") -> String { + entries.prefix(15).map { entry in + let name = String(entry.key.dropFirst(prefix.count)) + if entry.key.hasSuffix(".bytes") { + return String(format: "%@ %.1fKB/s", name, Double(entry.value) / 1024 / wall) + } + return String(format: "%@ %.1f/s", name, Double(entry.value) / wall) + }.joined(separator: ", ") + } + let sorted = counts.sorted { $0.value > $1.value } + let views = sorted.filter { $0.key.hasPrefix("view.") } + let activity = sorted.filter { !$0.key.hasPrefix("view.") } + return [ + "activity: " + (activity.isEmpty ? "none" : format(activity)), + "views: " + (views.isEmpty ? "none" : format(views, stripping: "view.")), + ] + } + + private func log(_ level: LogLevel, _ message: String, details: String?) { + LoggingService.shared.log(level: level, category: .performance, message: message, details: details) + } + + // MARK: - Context + + @MainActor + private func currentlyInBackground() -> Bool { + #if os(iOS) || os(tvOS) + UIApplication.shared.applicationState == .background + #elseif os(macOS) + !NSApplication.shared.isActive + #endif + } + + @MainActor + private func makeContext() -> String { + var parts: [String] = [] + + #if os(iOS) || os(tvOS) + let appState: String = switch UIApplication.shared.applicationState { + case .active: "active" + case .inactive: "inactive" + case .background: "background" + @unknown default: "unknown" + } + parts.append("app \(appState)") + #elseif os(macOS) + parts.append("app \(NSApplication.shared.isActive ? "active" : "inactive")") + #endif + + if let appEnvironment { + let state = appEnvironment.playerService.state + var player = "player \(state.playbackState)" + if state.currentVideo != nil { + player += state.currentStream?.isAudioOnly == true ? " audio-only" : " video" + player += " pip=\(state.pipState)" + player += " expanded=\(appEnvironment.navigationCoordinator.isPlayerExpanded)" + player += " publishesTime=\(state.publishesTimeUpdates)" + } + parts.append(player) + } + + let thermal: String = switch ProcessInfo.processInfo.thermalState { + case .nominal: "nominal" + case .fair: "fair" + case .serious: "serious" + case .critical: "critical" + @unknown default: "unknown" + } + parts.append("thermal \(thermal)") + if ProcessInfo.processInfo.isLowPowerModeEnabled { + parts.append("low power mode") + } + + #if os(iOS) + parts.append(batteryDescription()) + #endif + + return parts.joined(separator: " | ") + } + + #if os(iOS) + /// Battery level, and the drain rate while unplugged once it is measurable. + @MainActor + private func batteryDescription() -> String { + let device = UIDevice.current + guard device.batteryLevel >= 0 else { return "battery ?" } + let level = device.batteryLevel + var text = "battery \(Int(level * 100))%" + + guard device.batteryState == .unplugged else { + batteryReference = nil + return text + " (\(device.batteryState == .full ? "full" : "charging"))" + } + guard let reference = batteryReference, level <= reference.level else { + batteryReference = (Date(), level) + return text + } + let hours = Date().timeIntervalSince(reference.date) / 3600 + if hours >= 5.0 / 60, reference.level > level { + text += String(format: " (%.0f%%/h over %.0fm)", Double(reference.level - level) * 100 / hours, hours * 60) + } + return text + } + #endif +} + +// MARK: - Period + +/// Totals for one foreground or background period. +private struct Period { + let background: Bool + var wall: TimeInterval = 0 + var cpuSeconds: Double = 0 + var maxCPU: Double = 0 + var areaSeconds: [String: Double] = [:] + var wakeups: Double = 0 + var counts: [String: Int] = [:] + + init(background: Bool) { + self.background = background + } + + mutating func add(_ sample: ResourceSample, counts: [String: Int]) { + wall += sample.wall + cpuSeconds += sample.cpuPercent / 100 * sample.wall + if sample.wall >= 1 { + maxCPU = max(maxCPU, sample.cpuPercent) + } + for area in sample.areas { + areaSeconds[area.area, default: 0] += area.percent / 100 * sample.wall + } + wakeups += ((sample.idleWakeupsPerSecond ?? 0) + (sample.interruptWakeupsPerSecond ?? 0)) * sample.wall + self.counts.merge(counts, uniquingKeysWith: +) + } +} + +// MARK: - MetricKit + +#if os(iOS) || os(macOS) +/// Logs MetricKit payloads. The system delivers them at most daily (metrics) +/// or shortly after the event (diagnostics), usually on a later launch. +private final class MetricSubscriber: NSObject, MXMetricManagerSubscriber { + func didReceive(_ payloads: [MXMetricPayload]) { + for payload in payloads { + LoggingService.shared.log(level: .info, category: .performance, + message: "MetricKit metrics \(payload.timeStampBegin.formatted()) – \(payload.timeStampEnd.formatted())", + details: String(decoding: payload.jsonRepresentation(), as: UTF8.self)) + } + } + + func didReceive(_ payloads: [MXDiagnosticPayload]) { + for payload in payloads { + var kinds: [String] = [] + if let cpu = payload.cpuExceptionDiagnostics, !cpu.isEmpty { kinds.append("\(cpu.count) CPU exception(s)") } + if let hangs = payload.hangDiagnostics, !hangs.isEmpty { kinds.append("\(hangs.count) hang(s)") } + if let disk = payload.diskWriteExceptionDiagnostics, !disk.isEmpty { kinds.append("\(disk.count) disk write exception(s)") } + if let crashes = payload.crashDiagnostics, !crashes.isEmpty { kinds.append("\(crashes.count) crash(es)") } + LoggingService.shared.log(level: kinds.isEmpty ? .info : .warning, category: .performance, + message: "MetricKit diagnostics: \(kinds.isEmpty ? "none" : kinds.joined(separator: ", "))", + details: String(decoding: payload.jsonRepresentation(), as: UTF8.self)) + } + } +} +#endif diff --git a/Yattee/Services/Logging/ResourceSampler.swift b/Yattee/Services/Logging/ResourceSampler.swift new file mode 100644 index 00000000..ff6d79b3 --- /dev/null +++ b/Yattee/Services/Logging/ResourceSampler.swift @@ -0,0 +1,260 @@ +// +// ResourceSampler.swift +// Yattee +// +// Measures the process's CPU, per-thread CPU, wakeups, GPU, memory +// and disk activity between two samples. +// + +import Foundation + +/// One measurement window, from the previous `sample()` call to this one. +struct ResourceSample { + struct Thread { + let name: String + let area: String + let percent: Double + } + + let wall: TimeInterval + /// Percent of one core, all threads. + let cpuPercent: Double + let userPercent: Double + let systemPercent: Double + let threadCount: Int + /// Threads that used CPU in the window, busiest first. + let threads: [Thread] + let idleWakeupsPerSecond: Double? + let interruptWakeupsPerSecond: Double? + let gpuPercent: Double? + let footprintMB: UInt64? + let diskReadOps: Int + let diskWriteOps: Int + + /// CPU percent grouped by area (ui, playback, audio, network, …), busiest first. + /// CPU of threads that exited during the window is reported as "exited". + var areas: [(area: String, percent: Double)] { + var totals: [String: Double] = [:] + for thread in threads { + totals[thread.area, default: 0] += thread.percent + } + let unattributed = cpuPercent - threads.reduce(0) { $0 + $1.percent } + if unattributed >= 0.5 { + totals["exited", default: 0] += unattributed + } + return totals.sorted { $0.value > $1.value }.map { ($0.key, $0.value) } + } + + var hotThreadsText: String { + let hot = threads.filter { $0.percent >= 0.5 }.prefix(8) + guard !hot.isEmpty else { return "none" } + return hot.map { String(format: "%@ %.1f%%", $0.name, $0.percent) }.joined(separator: ", ") + } + + var areasText: String { + let areas = areas.filter { $0.percent >= 0.1 } + guard !areas.isEmpty else { return "idle" } + return areas.map { String(format: "%@ %.1f", $0.area, $0.percent) }.joined(separator: " ") + } + + var powerText: String { + var parts: [String] = [] + if let idle = idleWakeupsPerSecond, let interrupts = interruptWakeupsPerSecond { + parts.append(String(format: "wakeups %.0f/s (idle %.0f, interrupt %.0f)", idle + interrupts, idle, interrupts)) + } + if let gpuPercent { + parts.append(String(format: "gpu %.1f%%", gpuPercent)) + } + return parts.isEmpty ? "power: unavailable" : parts.joined(separator: " | ") + } +} + +/// Keeps the previous sample's counters; not thread-safe, confine each +/// instance to one queue. +final class ResourceSampler { + private var mainThreadPort: mach_port_t = 0 + private var lastSampleTime: DispatchTime? + private var lastUserCPU: Double = 0 + private var lastSystemCPU: Double = 0 + private var lastThreadCPU: [UInt64: UInt64] = [:] + private var lastIdleWakeups: UInt64 = 0 + private var lastInterruptWakeups: UInt64 = 0 + private var lastGPUNanoseconds: UInt64 = 0 + private var lastInBlocks: Int = 0 + private var lastOutBlocks: Int = 0 + + /// Call from the main thread so the main thread can be named in samples. + init(mainThreadPort: mach_port_t) { + self.mainThreadPort = mainThreadPort + } + + /// Resets the baseline without producing a meaningful sample. + func reset() { + _ = sample() + } + + func sample() -> ResourceSample { + let now = DispatchTime.now() + let wall = lastSampleTime.map { Double(now.uptimeNanoseconds - $0.uptimeNanoseconds) / 1e9 } ?? 0 + lastSampleTime = now + + var usage = rusage() + getrusage(RUSAGE_SELF, &usage) + let user = seconds(usage.ru_utime) + let system = seconds(usage.ru_stime) + let userPercent = wall > 0 ? (user - lastUserCPU) / wall * 100 : 0 + let systemPercent = wall > 0 ? (system - lastSystemCPU) / wall * 100 : 0 + lastUserCPU = user + lastSystemCPU = system + let diskReadOps = usage.ru_inblock - lastInBlocks + let diskWriteOps = usage.ru_oublock - lastOutBlocks + lastInBlocks = usage.ru_inblock + lastOutBlocks = usage.ru_oublock + + let (threadCount, threads) = sampleThreads(wall: wall) + + var idleWakeups: Double? + var interruptWakeups: Double? + var gpuPercent: Double? + var power = task_power_info_v2() + var powerCount = mach_msg_type_number_t(MemoryLayout.size / MemoryLayout.size) + let powerResult = withUnsafeMutablePointer(to: &power) { + $0.withMemoryRebound(to: integer_t.self, capacity: Int(powerCount)) { + task_info(mach_task_self_, task_flavor_t(TASK_POWER_INFO_V2), $0, &powerCount) + } + } + if powerResult == KERN_SUCCESS { + let idle = power.cpu_energy.task_platform_idle_wakeups + let interrupts = power.cpu_energy.task_interrupt_wakeups + let gpu = power.gpu_energy.task_gpu_utilisation + if wall > 0 { + idleWakeups = Double(idle &- lastIdleWakeups) / wall + interruptWakeups = Double(interrupts &- lastInterruptWakeups) / wall + gpuPercent = Double(gpu &- lastGPUNanoseconds) / 1e9 / wall * 100 + } + lastIdleWakeups = idle + lastInterruptWakeups = interrupts + lastGPUNanoseconds = gpu + } + + var vmInfo = task_vm_info_data_t() + var vmCount = mach_msg_type_number_t(MemoryLayout.size / MemoryLayout.size) + let vmResult = withUnsafeMutablePointer(to: &vmInfo) { + $0.withMemoryRebound(to: integer_t.self, capacity: Int(vmCount)) { + task_info(mach_task_self_, task_flavor_t(TASK_VM_INFO), $0, &vmCount) + } + } + + return ResourceSample( + wall: wall, + cpuPercent: userPercent + systemPercent, + userPercent: userPercent, + systemPercent: systemPercent, + threadCount: threadCount, + threads: threads, + idleWakeupsPerSecond: idleWakeups, + interruptWakeupsPerSecond: interruptWakeups, + gpuPercent: gpuPercent, + footprintMB: vmResult == KERN_SUCCESS ? vmInfo.phys_footprint / 1_048_576 : nil, + diskReadOps: diskReadOps, + diskWriteOps: diskWriteOps + ) + } + + /// Per-thread CPU since the last sample. + private func sampleThreads(wall: TimeInterval) -> (count: Int, threads: [ResourceSample.Thread]) { + var threadList: thread_act_array_t? + var threadCount: mach_msg_type_number_t = 0 + guard task_threads(mach_task_self_, &threadList, &threadCount) == KERN_SUCCESS, let threadList else { + return (0, []) + } + defer { + for index in 0...stride)) + } + + var current: [UInt64: UInt64] = [:] + var threads: [ResourceSample.Thread] = [] + for index in 0...size / MemoryLayout.size) + let identifierResult = withUnsafeMutablePointer(to: &identifier) { + $0.withMemoryRebound(to: integer_t.self, capacity: Int(identifierCount)) { + thread_info(thread, thread_flavor_t(THREAD_IDENTIFIER_INFO), $0, &identifierCount) + } + } + + var info = thread_extended_info() + var infoCount = mach_msg_type_number_t(MemoryLayout.size / MemoryLayout.size) + let infoResult = withUnsafeMutablePointer(to: &info) { + $0.withMemoryRebound(to: integer_t.self, capacity: Int(infoCount)) { + thread_info(thread, thread_flavor_t(THREAD_EXTENDED_INFO), $0, &infoCount) + } + } + guard identifierResult == KERN_SUCCESS, infoResult == KERN_SUCCESS else { continue } + + let id = identifier.thread_id + let total = info.pth_user_time + info.pth_system_time // nanoseconds + current[id] = total + guard wall > 0 else { continue } + let percent = Double(total &- (lastThreadCPU[id] ?? total)) / 1e9 / wall * 100 + guard percent > 0 else { continue } + + var name = withUnsafeBytes(of: info.pth_name) { raw in + String(decoding: raw.prefix { $0 != 0 }, as: UTF8.self) + } + if thread == mainThreadPort { + name = "main" + } else if name.isEmpty { + name = "unnamed" + } + threads.append(.init(name: name, area: Self.area(forThread: name), percent: percent)) + } + lastThreadCPU = current + + // Merge same-named threads (e.g. several "unnamed" GCD workers). + var merged: [String: ResourceSample.Thread] = [:] + for thread in threads { + let percent = (merged[thread.name]?.percent ?? 0) + thread.percent + merged[thread.name] = .init(name: thread.name, area: thread.area, percent: percent) + } + return (Int(threadCount), merged.values.sorted { $0.percent > $1.percent }) + } + + /// What a thread is doing, from its name. + static func area(forThread name: String) -> String { + let lower = name.lowercased() + if name == "main" { return "ui" } + // mpv names its threads after their role ("core", "demux", "vo", …). + if ["core", "demux", "vo", "ao", "cache", "dec"].contains(lower) + || ["mpv", "stream.yattee.mpv", "lavf", "ffmpeg"].contains(where: lower.hasPrefix) { + return "playback" + } + if lower.contains("auremoteio") || lower.contains("audio") || lower.contains("aqclient") { + return "audio" + } + if lower.contains("nsurlconnection") || lower.contains("com.apple.network") || lower.contains("cfnetwork") { + return "network" + } + if lower.contains("coremedia") || lower.contains("videotoolbox") || lower.contains("vtdecode") { + return "media" + } + if lower.contains("cloudkit") { + return "cloudkit" + } + if lower.hasPrefix("stream.yattee.diagnostics") || lower.hasPrefix("stream.yattee.logfile") + || lower.hasPrefix("stream.yattee.performance") { + return "logging" + } + return "other" + } + + private func seconds(_ time: timeval) -> Double { + Double(time.tv_sec) + Double(time.tv_usec) / 1_000_000 + } +} diff --git a/Yattee/Services/Networking/HTTPClient.swift b/Yattee/Services/Networking/HTTPClient.swift index bda3438e..6da1af6c 100644 --- a/Yattee/Services/Networking/HTTPClient.swift +++ b/Yattee/Services/Networking/HTTPClient.swift @@ -179,6 +179,8 @@ actor HTTPClient { do { (data, response) = try await session.data(for: finalRequest) + PerfCounter.count("net.api.request") + PerfCounter.count("net.api.bytes", by: data.count) } catch let error as URLError { let apiError = mapURLError(error) // Add more context for cancelled requests diff --git a/Yattee/Services/Player/MPV/MPVRenderView.swift b/Yattee/Services/Player/MPV/MPVRenderView.swift index 007bbda4..37a4a63b 100644 --- a/Yattee/Services/Player/MPV/MPVRenderView.swift +++ b/Yattee/Services/Player/MPV/MPVRenderView.swift @@ -239,6 +239,36 @@ final class MPVRenderView: UIView { /// Tracks whether app is in background (to prevent GPU work) private var isInBackground = false + // MARK: - Diagnostics + + /// Live render views, sampled by `BackgroundDiagnostics`. + private static let liveInstances = NSHashTable.weakObjects() + + static var diagnosticsInstances: [MPVRenderView] { + liveInstances.allObjects + } + + /// Render activity since the last diagnostics sample (written from main and the render queue). + private let diagnosticsCounters = RenderDiagnosticsCounters() + + /// One-line render state for the diagnostics heartbeat. Resets the activity counters. + func diagnosticsSummary() -> String { + let counts = diagnosticsCounters.take() + let link: String + if let displayLink { + link = displayLink.isPaused ? "paused" : "running@\(Int(videoFPS))" + } else { + link = "none" + } + return "view=\(String(UInt(bitPattern: ObjectIdentifier(self).hashValue), radix: 16).suffix(6))" + + " window=\(window != nil) superview=\(superview != nil) hidden=\(isHidden) setup=\(isSetup)" + + " displayLink=\(link) inBackground=\(isInBackground) pip=\(isPiPActive)" + + " capturePiP=\(captureFramesForPiP) bgTimer=\(backgroundRenderTimer != nil)" + + " fb=\(renderWidth)x\(renderHeight)" + + " | linkFires=\(counts.linkFires) renders=\(counts.renders) presents=\(counts.presents)" + + " backgroundRenders=\(counts.backgroundRenders) skippedInBackground=\(counts.skippedInBackground)" + } + // MARK: - Video Dimensions for PiP /// Current video width (actual video content, not view size) - set by backend @@ -270,6 +300,7 @@ final class MPVRenderView: UIView { } private func commonInit() { + Self.liveInstances.add(self) backgroundColor = .black contentScaleFactor = traitCollection.displayScale registerForTraitChanges([UITraitDisplayScale.self]) { (self: MPVRenderView, _) in @@ -903,6 +934,9 @@ final class MPVRenderView: UIView { // MARK: - Rendering @objc private func displayLinkFired() { + diagnosticsCounters.increment(\.linkFires) + PerfCounter.count("render.displayLink") + // Skip if not setup, already rendering, or app is in background (GPU work not permitted) guard isSetup, !isRendering, !isInBackground else { return } @@ -934,9 +968,17 @@ final class MPVRenderView: UIView { // but renders queued by appDidBecomeActive/resumeRendering can run // after the app went back to the background. PiP keeps rendering. guard !isInBackground || isPiPActive else { + diagnosticsCounters.increment(\.skippedInBackground) + PerfCounter.count("render.skippedInBackground") MPVLogging.log("performRender: skipped (app in background)") return } + diagnosticsCounters.increment(\.renders) + PerfCounter.count("render.frame") + if isInBackground { + diagnosticsCounters.increment(\.backgroundRenders) + PerfCounter.count("render.frameInBackground") + } let frameStart = Date() let tFrameStart = CACurrentMediaTime() @@ -1012,6 +1054,10 @@ final class MPVRenderView: UIView { } else if !isPiPActive { glBindRenderbuffer(GLenum(GL_RENDERBUFFER), colorRenderbuffer) let presented = eaglContext.presentRenderbuffer(Int(GL_RENDERBUFFER)) + if presented { + diagnosticsCounters.increment(\.presents) + PerfCounter.count("render.present") + } if !presented { MPVLogging.warn("performRender: presentRenderbuffer FAILED", details: "fb:\(framebuffer) rb:\(colorRenderbuffer) layer:\(layer.bounds) superview:\(superview != nil)") diff --git a/Yattee/Services/Player/MPVBackend.swift b/Yattee/Services/Player/MPVBackend.swift index 936e1445..7b047ee5 100644 --- a/Yattee/Services/Player/MPVBackend.swift +++ b/Yattee/Services/Player/MPVBackend.swift @@ -1493,6 +1493,9 @@ final class MPVBackend: PlayerBackend { extension MPVBackend: MPVClientDelegate { nonisolated func mpvClient(_ client: MPVClient, didUpdateProperty property: String, value: Any?) { + if PerfCounter.enabled { + PerfCounter.count("mpv.property." + property) + } Task { @MainActor [weak self] in self?.handlePropertyChange(property: property, value: value) } diff --git a/Yattee/Services/Player/NowPlayingService.swift b/Yattee/Services/Player/NowPlayingService.swift index c6164b82..58580590 100644 --- a/Yattee/Services/Player/NowPlayingService.swift +++ b/Yattee/Services/Player/NowPlayingService.swift @@ -141,6 +141,7 @@ final class NowPlayingService { /// Updates playback time without changing other metadata. func updatePlaybackTime(currentTime: TimeInterval, duration: TimeInterval, isPlaying: Bool) { + PerfCounter.count("nowPlaying.update") guard var info = cachedNowPlayingInfo ?? infoCenter.nowPlayingInfo else { return } info[MPNowPlayingInfoPropertyElapsedPlaybackTime] = currentTime diff --git a/Yattee/Services/Player/PlayerService.swift b/Yattee/Services/Player/PlayerService.swift index e78f375b..441d120c 100644 --- a/Yattee/Services/Player/PlayerService.swift +++ b/Yattee/Services/Player/PlayerService.swift @@ -2798,6 +2798,7 @@ final class PlayerService { } private func saveProgress() { + PerfCounter.count("player.progressSave") guard settingsManager?.incognitoModeEnabled != true, settingsManager?.saveWatchHistory != false else { return } @@ -2884,6 +2885,7 @@ final class PlayerService { } private func checkSponsorBlockSegments(at time: Double) { + PerfCounter.count("player.sponsorBlockCheck") // Read settings - use defaults if settings manager not available let enabled = settingsManager?.sponsorBlockEnabled ?? true let enabledCategories = settingsManager?.sponsorBlockCategories ?? SponsorBlockCategory.defaultEnabled diff --git a/Yattee/Services/Player/PlayerState.swift b/Yattee/Services/Player/PlayerState.swift index df6b8981..04c9bf32 100644 --- a/Yattee/Services/Player/PlayerState.swift +++ b/Yattee/Services/Player/PlayerState.swift @@ -228,8 +228,10 @@ final class PlayerState { } set { if publishesTimeUpdates { + PerfCounter.count("player.time.published") withMutation(keyPath: \.currentTime) { storedCurrentTime = newValue } } else { + PerfCounter.count("player.time.suppressed") storedCurrentTime = newValue } updateActiveChapter() diff --git a/Yattee/Views/Components/MarqueeText.swift b/Yattee/Views/Components/MarqueeText.swift index 9be4e07d..b0db5dab 100644 --- a/Yattee/Views/Components/MarqueeText.swift +++ b/Yattee/Views/Components/MarqueeText.swift @@ -37,6 +37,7 @@ struct MarqueeText: View { // MARK: - Body var body: some View { + let _ = PerfCounter.body("MarqueeText") GeometryReader { geometry in Group { if needsScrolling { @@ -73,6 +74,7 @@ struct MarqueeText: View { // Paused outside the active scene: the timeline otherwise keeps // re-rendering every frame while the app plays in the background. TimelineView(.animation(paused: scenePhase != .active)) { context in + let _ = PerfCounter.body("MarqueeText.frame") HStack(spacing: spacing) { textView textView diff --git a/Yattee/Views/Player/ControlsSectionRenderer.swift b/Yattee/Views/Player/ControlsSectionRenderer.swift index c9569448..18bc53cf 100644 --- a/Yattee/Views/Player/ControlsSectionRenderer.swift +++ b/Yattee/Views/Player/ControlsSectionRenderer.swift @@ -50,6 +50,7 @@ struct ControlsSectionRenderer: View { @State private var isBrightnessExpanded = false var body: some View { + let _ = PerfCounter.body("ControlsSectionRenderer") HStack { ForEach(section.visibleButtons(isWideLayout: actions.isWideScreenLayout)) { config in renderButton(config) diff --git a/Yattee/Views/Player/ExpandedPlayerSheet.swift b/Yattee/Views/Player/ExpandedPlayerSheet.swift index 1cc71dab..639d9dc6 100644 --- a/Yattee/Views/Player/ExpandedPlayerSheet.swift +++ b/Yattee/Views/Player/ExpandedPlayerSheet.swift @@ -183,6 +183,7 @@ struct ExpandedPlayerSheet: View { // MARK: - Body var body: some View { + let _ = PerfCounter.body("ExpandedPlayerSheet") playerContentWithOverlays .applyPlayerSheets( showingQualitySheet: $showingQualitySheet, diff --git a/Yattee/Views/Player/MiniPlayerView.swift b/Yattee/Views/Player/MiniPlayerView.swift index 64a502f8..c9399458 100644 --- a/Yattee/Views/Player/MiniPlayerView.swift +++ b/Yattee/Views/Player/MiniPlayerView.swift @@ -139,6 +139,7 @@ struct MiniPlayerView: View { } var body: some View { + let _ = PerfCounter.body("MiniPlayerView") Group { #if os(macOS) capsuleLayout diff --git a/Yattee/Views/Player/PlayerControlsView.swift b/Yattee/Views/Player/PlayerControlsView.swift index 244c3698..2c3a41f6 100644 --- a/Yattee/Views/Player/PlayerControlsView.swift +++ b/Yattee/Views/Player/PlayerControlsView.swift @@ -198,6 +198,7 @@ struct PlayerControlsView: View { } var body: some View { + let _ = PerfCounter.body("PlayerControlsView") GeometryReader { geometry in ZStack { @@ -1018,6 +1019,7 @@ struct PlayerControlsView: View { private var progressBar: some View { GeometryReader { geometry in + let _ = PerfCounter.body("PlayerControlsView.progressBar") ZStack(alignment: .bottomLeading) { if playerState.isLive { // For live streams, show simple red indicator (no scrubbing) diff --git a/Yattee/Views/Player/SegmentedProgressBar.swift b/Yattee/Views/Player/SegmentedProgressBar.swift index 5d99ec27..08d31a48 100644 --- a/Yattee/Views/Player/SegmentedProgressBar.swift +++ b/Yattee/Views/Player/SegmentedProgressBar.swift @@ -49,6 +49,7 @@ struct SegmentedProgressBar: View { } var body: some View { + let _ = PerfCounter.body("SegmentedProgressBar") GeometryReader { geometry in if chapters.count >= 2 { segmentedBar(geometry: geometry) @@ -217,6 +218,7 @@ private struct ChapterSegmentView: View { } var body: some View { + let _ = PerfCounter.body("ChapterSegmentView") GeometryReader { geometry in ZStack(alignment: .leading) { // Background diff --git a/Yattee/Views/Player/macOS/MacOSControlBar.swift b/Yattee/Views/Player/macOS/MacOSControlBar.swift index e406879c..51686d3d 100644 --- a/Yattee/Views/Player/macOS/MacOSControlBar.swift +++ b/Yattee/Views/Player/macOS/MacOSControlBar.swift @@ -60,6 +60,7 @@ struct MacOSControlBar: View { // MARK: - Body var body: some View { + let _ = PerfCounter.body("MacOSControlBar") VStack(spacing: 8) { // Top row: preset-driven button row MacOSControlsSectionRenderer( diff --git a/Yattee/Views/Player/tvOS/TVPlayerControlsView.swift b/Yattee/Views/Player/tvOS/TVPlayerControlsView.swift index a7ee6dc3..bb6ebe32 100644 --- a/Yattee/Views/Player/tvOS/TVPlayerControlsView.swift +++ b/Yattee/Views/Player/tvOS/TVPlayerControlsView.swift @@ -58,6 +58,7 @@ struct TVPlayerControlsView: View { } var body: some View { + let _ = PerfCounter.body("TVPlayerControlsView") ZStack { // Gradient overlay for readability gradientOverlay diff --git a/Yattee/Views/Settings/DeveloperSettingsView.swift b/Yattee/Views/Settings/DeveloperSettingsView.swift index 8a9dc9f7..fe16de7b 100644 --- a/Yattee/Views/Settings/DeveloperSettingsView.swift +++ b/Yattee/Views/Settings/DeveloperSettingsView.swift @@ -11,6 +11,7 @@ struct DeveloperSettingsView: View { @Environment(\.appEnvironment) private var appEnvironment @Bindable private var loggingService = LoggingService.shared @State private var loggingEnabled = LoggingService.shared.isEnabled + @State private var performanceLoggingEnabled = PerformanceMonitor.shared.isEnabled // Data management state @State private var showingDeduplicateConfirmation = false @@ -137,6 +138,13 @@ struct DeveloperSettingsView: View { )) { Label(String(localized: "settings.advanced.debug.verboseRemote"), systemImage: "antenna.radiowaves.left.and.right") } + + Toggle(isOn: $performanceLoggingEnabled) { + Label(String(localized: "settings.advanced.debug.performanceLogging"), systemImage: "gauge.with.dots.needle.67percent") + } + .onChange(of: performanceLoggingEnabled) { _, newValue in + PerformanceMonitor.shared.setEnabled(newValue) + } } } } diff --git a/Yattee/Views/Video/VideoInfoView.swift b/Yattee/Views/Video/VideoInfoView.swift index 5de4153b..ab70db97 100644 --- a/Yattee/Views/Video/VideoInfoView.swift +++ b/Yattee/Views/Video/VideoInfoView.swift @@ -275,6 +275,7 @@ struct VideoInfoView: View { } var body: some View { + let _ = PerfCounter.body("VideoInfoView") Group { if isLoadingInitialVideo || (displayedVideoIsPlaceholder && isLoadingVideoDetails) { loadingView diff --git a/Yattee/YatteeApp.swift b/Yattee/YatteeApp.swift index 551995af..aabed646 100644 --- a/Yattee/YatteeApp.swift +++ b/Yattee/YatteeApp.swift @@ -58,6 +58,11 @@ struct YatteeApp: App { // Register background tasks early — Apple requires BGTaskScheduler.register() // to be called during the app launch sequence, before the run loop starts. appEnvironment.backgroundRefreshManager.registerBackgroundTasks() + + #if os(iOS) + BackgroundDiagnostics.shared.start(playerService: AppEnvironment.shared.playerService) + #endif + PerformanceMonitor.shared.start(appEnvironment: AppEnvironment.shared) } var body: some Scene { @@ -334,6 +339,7 @@ struct YatteeApp: App { // assertion keeps the app alive until the async flush finishes. var backgroundTask: UIBackgroundTaskIdentifier = .invalid backgroundTask = UIApplication.shared.beginBackgroundTask(withName: "PersistOnBackground") { + LoggingService.shared.warning("Background task PersistOnBackground expired", category: .diagnostics) if backgroundTask != .invalid { UIApplication.shared.endBackgroundTask(backgroundTask) backgroundTask = .invalid @@ -349,6 +355,7 @@ struct YatteeApp: App { // before the assertion is given up. await appEnvironment.watchHistorySync.flushPending() if backgroundTask != .invalid { + LoggingService.shared.info("Background task PersistOnBackground finished", category: .diagnostics) UIApplication.shared.endBackgroundTask(backgroundTask) backgroundTask = .invalid }