From 63d5e8bbe6ee76fe96460c0f33630d7b8b38cb37 Mon Sep 17 00:00:00 2001 From: Arkadiusz Fal Date: Sat, 31 Oct 2026 16:26:18 +0100 Subject: [PATCH] Log and alert when hardware decoding falls back to software mid-playback With Enable Logging on, MPVBackend watches hwdec-current (property event plus a single-property poll in the stats loop, since mpv does not always emit an event for a silent fallback). When a file that was hardware decoded drops to software, it logs a warning with codec/stream, playback position, scene phase and time since the last change, thermal/low-power state, PiP and the recent mpv log lines, and shows a toast asking to export logs (deferred until the app is active again). The background diagnostics heartbeat now includes the decoder state. --- Yattee/Localizable.xcstrings | 22 ++++ .../Logging/BackgroundDiagnostics.swift | 3 + Yattee/Services/Player/MPV/MPVClient.swift | 15 +++ Yattee/Services/Player/MPVBackend.swift | 103 +++++++++++++++++- Yattee/Services/Player/PlayerBackend.swift | 3 + Yattee/Services/Player/PlayerService.swift | 11 ++ 6 files changed, 154 insertions(+), 3 deletions(-) diff --git a/Yattee/Localizable.xcstrings b/Yattee/Localizable.xcstrings index f5562cc4..f18daa65 100644 --- a/Yattee/Localizable.xcstrings +++ b/Yattee/Localizable.xcstrings @@ -20078,6 +20078,28 @@ } } }, + "toast.player.hwdecFallback.subtitle" : { + "comment" : "Toast subtitle shown (only with Enable Logging on) when hardware video decoding stopped mid-playback", + "localizations" : { + "en" : { + "stringUnit" : { + "state" : "translated", + "value" : "Details were logged — please export logs and report it" + } + } + } + }, + "toast.player.hwdecFallback.title" : { + "comment" : "Toast title shown (only with Enable Logging on) when hardware video decoding stopped mid-playback", + "localizations" : { + "en" : { + "stringUnit" : { + "state" : "translated", + "value" : "Hardware Decoding Stopped" + } + } + } + }, "toast.player.refreshingStream.title" : { "comment" : "Toast title shown when stream URLs are being refreshed due to expiration", "localizations" : { diff --git a/Yattee/Services/Logging/BackgroundDiagnostics.swift b/Yattee/Services/Logging/BackgroundDiagnostics.swift index e141b891..360af60e 100644 --- a/Yattee/Services/Logging/BackgroundDiagnostics.swift +++ b/Yattee/Services/Logging/BackgroundDiagnostics.swift @@ -104,6 +104,9 @@ final class BackgroundDiagnostics { + " backend=\(playerService.currentBackendType) video=\(state.currentVideo?.id.videoID ?? "none")" + " time=\(Int(state.currentTime))/\(Int(state.duration))" + " publishesTime=\(state.publishesTimeUpdates)") + if let mpvBackend = playerService.currentBackend as? MPVBackend { + lines.append("decoder: " + mpvBackend.decoderDiagnosticsSummary) + } } let session = AVAudioSession.sharedInstance() diff --git a/Yattee/Services/Player/MPV/MPVClient.swift b/Yattee/Services/Player/MPV/MPVClient.swift index 0d9c7ccf..4891228e 100644 --- a/Yattee/Services/Player/MPV/MPVClient.swift +++ b/Yattee/Services/Player/MPV/MPVClient.swift @@ -1177,6 +1177,21 @@ final class MPVClient: @unchecked Sendable { } } + /// Get a string property value asynchronously (non-blocking). + func getStringAsync(_ name: String) async -> String? { + await withCheckedContinuation { continuation in + mpvQueue.async { [weak self] in + guard let self, let mpv = self.mpv, !self.isDestroyed, + let cString = mpv_get_property_string(mpv, name) else { + continuation.resume(returning: nil) + return + } + defer { mpv_free(cString) } + continuation.resume(returning: String(cString: cString)) + } + } + } + /// Get MPV version and build information asynchronously (non-blocking). /// Use this from MainActor code instead of getVersionInfo() to avoid blocking the UI. /// - Returns: The version information, or nil if unavailable or MPV is destroyed diff --git a/Yattee/Services/Player/MPVBackend.swift b/Yattee/Services/Player/MPVBackend.swift index 516089a1..f06be504 100644 --- a/Yattee/Services/Player/MPVBackend.swift +++ b/Yattee/Services/Player/MPVBackend.swift @@ -126,6 +126,15 @@ final class MPVBackend: PlayerBackend { private var videoCodec: String = "" private var hwdecCurrent: String = "" private var hwdecInterop: String = "" + // Software-fallback detection (logged + toasted only with "Enable Logging" on). + // mpv falls back to software one-way and does not always emit a property + // event for it, so the stats loop also polls hwdec-current. + private var hwdecTrackingArmed = false + private var hwdecUsedForCurrentFile: String? + private var hwdecFallbackReported = false + private var hwdecFallbackAlertPending = false + private var lastScenePhase: ScenePhase = .active + private var lastScenePhaseChange: Date? #if os(tvOS) private var videoGamma: String = "" #endif @@ -423,7 +432,8 @@ final class MPVBackend: PlayerBackend { LoggingService.shared.debug("MPV: Disabling EDL for live stream (live streams not compatible with EDL)", category: .mpv) } - LoggingService.shared.logMPV("MPV loading stream", details: "\(stream.qualityLabel) - \(stream.format)\n\(stream.url.absoluteString)\nEDL: \(actualUseEDL) (requested: \(useEDL), isLive: \(stream.isLive))\nStream info: videoCodec=\(stream.videoCodec ?? "nil"), audioCodec=\(stream.audioCodec ?? "nil")") + resetHwdecFallbackTracking() + LoggingService.shared.logMPV("MPV loading stream", details:"\(stream.qualityLabel) - \(stream.format)\n\(stream.url.absoluteString)\nEDL: \(actualUseEDL) (requested: \(useEDL), isLive: \(stream.isLive))\nStream info: videoCodec=\(stream.videoCodec ?? "nil"), audioCodec=\(stream.audioCodec ?? "nil")") if let audioStream { LoggingService.shared.logMPV("MPV loading separate audio track", details: "\(audioStream.audioLanguage ?? "default") - \(audioStream.format)\n\(audioStream.url.absoluteString)\nAudio codec: \(audioStream.audioCodec ?? "nil")") } @@ -780,6 +790,7 @@ final class MPVBackend: PlayerBackend { bufferedTime = 0 currentStream = nil loadedStreamHasVideo = false + resetHwdecFallbackTracking() #if os(tvOS) videoGamma = "" clearTVDisplayCriteria() @@ -979,6 +990,15 @@ final class MPVBackend: PlayerBackend { MPVLogging.logAppLifecycle("handleScenePhase(\(phase))", isPiPActive: pipActive, isRendering: nil) + if phase != lastScenePhase { + lastScenePhase = phase + lastScenePhaseChange = Date() + } + if phase == .active, hwdecFallbackAlertPending { + hwdecFallbackAlertPending = false + delegate?.backendDidFallBackToSoftwareDecoding(self) + } + #if os(iOS) if phase == .active { restoreVideoAfterBackground() @@ -1762,6 +1782,7 @@ extension MPVBackend: MPVClientDelegate { case "hwdec-current": if let hwdec = value as? String { hwdecCurrent = hwdec + checkHwdecFallback(hwdec, source: "event") } case "hwdec-interop": @@ -1907,6 +1928,7 @@ extension MPVBackend: MPVClientDelegate { switch event { case MPV_EVENT_FILE_LOADED: LoggingService.shared.debug("MPV: File loaded", category: .mpv) + hwdecTrackingArmed = true startPlaybackStatsLogging() // Log hwdec diagnostics on tvOS (use cached values to avoid sync fetch) #if os(tvOS) @@ -2065,6 +2087,71 @@ extension MPVBackend: MPVClientDelegate { LoggingService.shared.debug("MPV: Buffer stall detection stopped", category: .mpv) } + // MARK: - Hardware Decoding Fallback Detection + + /// Decoder state for diagnostics heartbeats, from cached values (no mpv fetch). + var decoderDiagnosticsSummary: String { + "codec=\(videoCodec.isEmpty ? "none" : videoCodec) hwdec=\(hwdecCurrent.isEmpty ? "none" : hwdecCurrent)" + + " hwUsedThisFile=\(hwdecUsedForCurrentFile ?? "no") fallbackReported=\(hwdecFallbackReported)" + } + + private func resetHwdecFallbackTracking() { + hwdecTrackingArmed = false + hwdecUsedForCurrentFile = nil + hwdecFallbackReported = false + } + + /// Detects mpv dropping from hardware to software decoding mid-file. + /// Armed at FILE_LOADED so stale events from the previous file are ignored; + /// only a file that was seen hardware decoded can report a fallback. + private func checkHwdecFallback(_ hwdec: String, source: String) { + // The poll sees silent fallbacks the property event misses; keep the cache current. + if !hwdec.isEmpty { hwdecCurrent = hwdec } + guard hwdecTrackingArmed, !hwdec.isEmpty else { return } + + guard hwdec == "no" else { + if hwdecFallbackReported { + LoggingService.shared.warning("MPV: Hardware decoding resumed (\(hwdec), via \(source))", category: .mpv) + hwdecFallbackReported = false + } + hwdecUsedForCurrentFile = hwdec + return + } + + guard let previous = hwdecUsedForCurrentFile, !hwdecFallbackReported, + LoggingService.shared.isEnabled else { return } + hwdecFallbackReported = true + + var context = [ + "hwdec: \(previous) -> no (detected via \(source))", + "codec: \(videoCodec.isEmpty ? "unknown" : videoCodec) \(videoWidth)x\(videoHeight)" + + " stream=\(currentStream?.qualityLabel ?? "?") \(currentStream?.format ?? "")", + "playback: time=\(Int(currentTime))/\(Int(duration)) playing=\(isPlaying)", + "scene: \(lastScenePhase)" + + (lastScenePhaseChange.map { String(format: " (changed %.0fs ago)", Date().timeIntervalSince($0)) } ?? " (no change since launch)"), + "thermal: \(ProcessInfo.processInfo.thermalState.rawValue)" + + " lowPower: \(ProcessInfo.processInfo.isLowPowerModeEnabled)", + ] + #if os(iOS) || os(macOS) + context.append("pip: \(isPiPActive)") + #endif + let recentLines = mpvClient?.recentLogLines().map(\.formatted) ?? [] + context.append("recent mpv log (\(recentLines.count) lines):") + context.append(contentsOf: recentLines) + + LoggingService.shared.warning( + "MPV: Hardware decoding fell back to software mid-playback", + category: .mpv, + details: context.joined(separator: "\n") + ) + + if lastScenePhase == .active { + delegate?.backendDidFallBackToSoftwareDecoding(self) + } else { + hwdecFallbackAlertPending = true + } + } + // MARK: - Playback Stats Logging /// Log cache/frame-drop/pacing stats every 10s while a file is loaded, at INFO level @@ -2088,11 +2175,21 @@ extension MPVBackend: MPVClientDelegate { // watchdog below). Elsewhere the batched mpv_get_property // calls contend with the playback core and caused a visible // stutter every 10s on tvOS, so skip the fetch entirely - // unless verbose logging wants the stats line. - guard MPVLogging.verboseEnabled else { continue } + // unless verbose logging wants the stats line. The single + // hwdec-current read is the fallback detector's poll. + guard MPVLogging.verboseEnabled else { + if LoggingService.shared.isEnabled, self.hwdecUsedForCurrentFile != nil, + let hwdec = await client.getStringAsync("hwdec-current") { + self.checkHwdecFallback(hwdec, source: "poll") + } + continue + } #endif let props = await client.getDebugPropertiesAsync() + if let hwdec = props.hwdecCurrent { + self.checkHwdecFallback(hwdec, source: "poll") + } #if os(macOS) // Render watchdog — runs every tick regardless of the verbose diff --git a/Yattee/Services/Player/PlayerBackend.swift b/Yattee/Services/Player/PlayerBackend.swift index ccb653a4..bd1c6b25 100644 --- a/Yattee/Services/Player/PlayerBackend.swift +++ b/Yattee/Services/Player/PlayerBackend.swift @@ -114,6 +114,9 @@ protocol PlayerBackendDelegate: AnyObject { func backend(_ backend: any PlayerBackend, didUpdateTracks tracks: [MPVTrack]) func backendDidBecomeReady(_ backend: any PlayerBackend) func backendDidFinishPlaying(_ backend: any PlayerBackend) + /// Hardware decoding stopped mid-playback for a file that was hardware decoded. + /// Only reported while "Enable Logging" is on, and only once the app is active. + func backendDidFallBackToSoftwareDecoding(_ backend: any PlayerBackend) } // MARK: - Player Backend Protocol diff --git a/Yattee/Services/Player/PlayerService.swift b/Yattee/Services/Player/PlayerService.swift index 566b9c0e..77881ce9 100644 --- a/Yattee/Services/Player/PlayerService.swift +++ b/Yattee/Services/Player/PlayerService.swift @@ -3145,6 +3145,17 @@ extension PlayerService: PlayerBackendDelegate { state.isFirstFrameReady = true } + func backendDidFallBackToSoftwareDecoding(_ backend: any PlayerBackend) { + toastManager?.show( + category: .playerStatus, + title: String(localized: "toast.player.hwdecFallback.title"), + subtitle: String(localized: "toast.player.hwdecFallback.subtitle"), + icon: "cpu", + iconColor: .orange, + autoDismissDelay: 8.0 + ) + } + func backendDidFinishPlaying(_ backend: any PlayerBackend) { // Mark that video ended naturally - prevents play() from saving progress again // when switching to next video (100% is already saved below)