mirror of
https://github.com/yattee/yattee.git
synced 2026-10-30 16:37:17 +00:00
9412ca916c
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.
391 lines
16 KiB
Swift
391 lines
16 KiB
Swift
//
|
|
// 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<Counts, Int>) {
|
|
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
|