fix(player): clarify Dolby Vision playback logging

This commit is contained in:
edde746
2026-05-31 06:56:18 +02:00
parent 8413e1e5a7
commit 6438b444bf
7 changed files with 165 additions and 21 deletions
@@ -13,6 +13,32 @@ enum class DvConversionMode { DISABLED, DV81, HEVC_STRIP }
object DoviBridge {
private const val TAG = "DoviBridge"
data class DvAutoDecision(
val mode: DvConversionMode,
val reason: String,
val bridgeReady: Boolean,
val displayDv: Boolean,
val nativeDecoder: Boolean,
val advertisedP7: Boolean,
val advertisedP8: Boolean,
val decoders: String
) {
fun logMessage(): String = "AUTO P7 DV decision: mode=$mode; reason=$reason; bridgeReady=$bridgeReady, " +
"displayDV=$displayDv, nativeDecoder=$nativeDecoder, advertisedP7=$advertisedP7, " +
"advertisedP8=$advertisedP8, decoders=$decoders"
}
data class Dv7FallbackDecision(
val mode: DvConversionMode,
val reason: String,
val bridgeReady: Boolean,
val displayDv: Boolean,
val advertisedP8: Boolean
) {
fun logMessage(): String = "DV7 fallback decision: mode=$mode; reason=$reason; bridgeReady=$bridgeReady, " +
"displayDV=$displayDv, advertisedP8=$advertisedP8"
}
private val DOLBY_VISION_MIME_TYPES = setOf(
"video/dolby-vision",
"video/hevcdv",
@@ -134,7 +160,7 @@ object DoviBridge {
)
}
fun getConversionMode(context: Context): DvConversionMode {
fun getConversionDecision(context: Context): DvAutoDecision {
val bridgeReady = isAvailable()
val displayDv = displaySupportsDolbyVision(context)
val nativeDecoder = hasNativeDolbyVisionDecoder
@@ -154,16 +180,24 @@ object DoviBridge {
!bridgeReady -> "conversion bridge unavailable; stripping DV metadata for HEVC fallback"
else -> "Dolby Vision output path is unavailable; stripping DV metadata for HEVC fallback"
}
Log.i(
TAG,
"AUTO DV decision: mode=$mode; reason=$reason; bridgeReady=$bridgeReady, " +
"displayDV=$displayDv, nativeDecoder=$nativeDecoder, advertisedP7=$advertisedP7, advertisedP8=$advertisedP8"
val decision = DvAutoDecision(
mode = mode,
reason = reason,
bridgeReady = bridgeReady,
displayDv = displayDv,
nativeDecoder = nativeDecoder,
advertisedP7 = advertisedP7,
advertisedP8 = advertisedP8,
decoders = describeDolbyVisionDecoders()
)
return mode
Log.i(TAG, decision.logMessage())
return decision
}
fun getConversionMode(context: Context): DvConversionMode = getConversionDecision(context).mode
/** Get the fallback mode when native DV7 decoding fails. */
fun getDv7FallbackMode(context: Context): DvConversionMode {
fun getDv7FallbackDecision(context: Context): Dv7FallbackDecision {
val bridgeReady = isAvailable()
val displayDv = displaySupportsDolbyVision(context)
val advertisedP8 = deviceSupportsDvProfile8
@@ -173,14 +207,19 @@ object DoviBridge {
!bridgeReady -> "conversion bridge unavailable; stripping DV metadata for HEVC fallback"
else -> "Dolby Vision output or Profile 8 support is unavailable"
}
Log.i(
TAG,
"DV7 fallback decision: mode=$mode; reason=$reason; bridgeReady=$bridgeReady, " +
"displayDV=$displayDv, advertisedP8=$advertisedP8"
val decision = Dv7FallbackDecision(
mode = mode,
reason = reason,
bridgeReady = bridgeReady,
displayDv = displayDv,
advertisedP8 = advertisedP8
)
return mode
Log.i(TAG, decision.logMessage())
return decision
}
fun getDv7FallbackMode(context: Context): DvConversionMode = getDv7FallbackDecision(context).mode
private fun getCurrentDisplay(context: Context): Display? = if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.R) {
context.display
} else {
@@ -100,6 +100,7 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
private const val MAX_AUDIO_RECOVERY_ATTEMPTS = 2
private const val FPS_SAMPLE_COUNT = 8
private const val TS_TIMESTAMP_SEARCH_PACKETS = 1800
private val DV_CODEC_PROFILE_REGEX = Regex("""(?:^|,)\s*dvh[1e]\.(\d{2})""")
// Codec capability caches — codec support doesn't change at runtime
private val hwAudioDecoderCache = HashMap<String, Boolean>()
@@ -236,6 +237,13 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
val score: Int
)
private data class DvPlaybackInfo(
val sourceProfile: Int,
val path: String,
val reason: String,
val decoder: String
)
private fun emitLog(level: String, prefix: String, message: String) {
when (level) {
"error" -> Log.e(TAG, "[$prefix] $message")
@@ -314,12 +322,21 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
private var currentVideoFormat: Format? = null
private var loggedNativeDvSelectionKey: String? = null
private var loggedNativeDvFirstFrame = false
private var loggedDvPlaybackPathKey: String? = null
private var lastDvPlaybackInfo: DvPlaybackInfo? = null
@Volatile private var activeDoviMkvWrapper: DoviExtractorWrapper? = null
@Volatile private var activeDoviMp4Wrapper: DoviExtractorWrapper? = null
private fun getConfiguredDvMode(): DvConversionMode = debugDvModeOverride ?: DoviBridge.getConversionMode(activity)
private fun getConfiguredDvMode(): DvConversionMode {
val override = debugDvModeOverride
if (override != null) return override
val decision = DoviBridge.getConversionDecision(activity)
emitLog("info", "dv-auto", decision.logMessage())
return decision.mode
}
fun initialize(bufferSizeBytes: Int? = null, tunnelingEnabled: Boolean = true): Boolean {
if (isInitialized) {
@@ -909,6 +926,7 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
} ?: ""
emitLog("info", "tracks", "Video: ${vf.codecs} ${vf.width}x${vf.height}$hdr")
logNativeDvSelectionIfNeeded(vf)
logDolbyVisionPlaybackPathIfNeeded()
} else {
currentVideoFormat = null
}
@@ -1075,9 +1093,60 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
return true
}
private fun isDvProfile7Format(format: Format): Boolean {
val codecs = format.codecs?.lowercase() ?: return false
return codecs.startsWith("dvhe.07") || codecs.startsWith("dvh1.07")
private fun activeDoviTrackOutput(): DoviConvertingTrackOutput? = activeDoviMkvWrapper?.doviTrackOutput ?: activeDoviMp4Wrapper?.doviTrackOutput
private fun dolbyVisionProfile(format: Format?): Int? {
val codecs = format?.codecs?.lowercase() ?: return null
return DV_CODEC_PROFILE_REGEX.find(codecs)?.groupValues?.getOrNull(1)?.toIntOrNull()
}
private fun isDvProfile7Format(format: Format): Boolean = dolbyVisionProfile(format) == 7
private fun buildDvPlaybackInfo(format: Format?, decoderName: String?): DvPlaybackInfo? {
val doviTrack = activeDoviTrackOutput()
val conversionActive = doviTrack?.conversionActive == true
val sourceProfile = if (conversionActive) 7 else (dolbyVisionProfile(format) ?: return null)
val decoder = decoderName ?: decoderInitName ?: getVideoDecoderInfo(format) ?: "unknown"
val mimeType = format?.sampleMimeType
val (path, reason) = when {
sourceProfile == 7 && dvMode == DvConversionMode.DV81 ->
"P7 -> P8.1" to "Profile 7 conversion is active; RPU metadata is converted to Profile 8.1"
sourceProfile == 7 && dvMode == DvConversionMode.HEVC_STRIP ->
"P7 -> HEVC" to "Profile 7 HEVC strip is active; DV RPU/EL metadata is removed"
sourceProfile == 7 ->
"Native DV P7" to "Profile 7 conversion is disabled; trying native Dolby Vision decode"
sourceProfile == 8 && mimeType != MimeTypes.VIDEO_DOLBY_VISION ->
"HDR fallback" to "Profile 8 is being decoded through the HEVC/HDR10-compatible path"
sourceProfile == 8 ->
"DV P8 passthrough" to "Profile 8 is being passed through the native Dolby Vision-capable path"
else ->
"Native DV P$sourceProfile" to "Dolby Vision profile $sourceProfile is being sent to the native decoder path"
}
return DvPlaybackInfo(
sourceProfile = sourceProfile,
path = path,
reason = reason,
decoder = decoder
)
}
private fun logDolbyVisionPlaybackPathIfNeeded(decoderName: String? = decoderInitName) {
val format = currentVideoFormat ?: exoPlayer?.videoFormat ?: return
val info = buildDvPlaybackInfo(format, decoderName) ?: return
lastDvPlaybackInfo = info
val key = "${info.sourceProfile}|${format.sampleMimeType}|${format.codecs}|${info.decoder}|${info.path}|$dvMode"
if (loggedDvPlaybackPathKey == key) return
loggedDvPlaybackPathKey = key
emitLog(
"info",
"dv-playback",
"DV source: profile=${info.sourceProfile}, path=${info.path}, reason=${info.reason}, " +
"mime=${format.sampleMimeType}, codecs=${format.codecs}, decoder=${info.decoder}, p7Mode=$dvMode, " +
"displayDV=${DoviBridge.displaySupportsDolbyVision(activity)}, " +
"advertisedP7=${DoviBridge.deviceSupportsDvProfile7}, advertisedP8=${DoviBridge.deviceSupportsDvProfile8}"
)
}
private fun findDv7VideoFormat(): Format? {
@@ -1151,9 +1220,11 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
}
dv7RetryAttempted = true
val newMode = DoviBridge.getDv7FallbackMode(activity)
val fallbackDecision = DoviBridge.getDv7FallbackDecision(activity)
val newMode = fallbackDecision.mode
dvMode = newMode
Log.i(TAG, "Native DV7 playback failed ($reason, ${describeVideoFormat(dv7Format)}), retrying with $newMode")
emitLog("info", "dv-fallback", "${fallbackDecision.logMessage()}; trigger=$reason")
emitLog("info", "dv-fallback", "DV7 native failed ($reason), retrying as $newMode")
return reloadCurrentMediaForDvMode()
@@ -2052,6 +2123,7 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
decoderInitName = decoderName
firstFrameRendered = false
emitLog("debug", "decoder-hang", "Decoder initialized: $decoderName (${initializationDurationMs}ms)")
logDolbyVisionPlaybackPathIfNeeded(decoderName)
startDecoderHangCheck(decoderName)
}
@@ -2156,6 +2228,7 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
cancelDecoderHangCheck()
emitLog("debug", "decoder-hang", "First frame rendered — decoder OK")
logNativeDvFirstFrameIfNeeded()
logDolbyVisionPlaybackPathIfNeeded()
// STATE_READY fires when the player has enough buffered to start, but
// the first frame may not be on screen yet (decoder init + keyframe
// decode). The MPV-parity `playback-restart` event consumers (Dart
@@ -2306,6 +2379,8 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
currentVideoFormat = null
loggedNativeDvSelectionKey = null
loggedNativeDvFirstFrame = false
loggedDvPlaybackPathKey = null
lastDvPlaybackInfo = null
loggedDecodedTrueHdTunnelingGuard = false
updateAudioDecoderPolicy("open")
currentMediaUri = uri
@@ -2422,7 +2497,7 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
activeDoviMkvWrapper = null
activeDoviMp4Wrapper = null
val debugMode = override?.name ?: "AUTO"
emitLog("info", "dv-debug", "Debug DV conversion mode set to $debugMode (active=$dvMode)")
emitLog("info", "dv-debug", "P7 DV conversion mode set to $debugMode (active=$dvMode)")
reloadCurrentMediaForDvMode()
return true
}
@@ -2452,6 +2527,8 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
currentVideoFormat = null
loggedNativeDvSelectionKey = null
loggedNativeDvFirstFrame = false
loggedDvPlaybackPathKey = null
lastDvPlaybackInfo = null
activeDoviMkvWrapper = null
activeDoviMp4Wrapper = null
stopFrameWatchdog()
@@ -2812,6 +2889,8 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
// Get decoder info from the format's codecs field and check if hardware accelerated
val videoDecoderInfo = getVideoDecoderInfo(videoFormat)
val videoDecoderName = decoderInitName ?: videoDecoderInfo
val dvPlaybackInfo = buildDvPlaybackInfo(videoFormat, videoDecoderName) ?: lastDvPlaybackInfo
return mapOf(
// Video metrics
@@ -2821,7 +2900,7 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
"videoHeight" to videoFormat?.height,
"videoFps" to (videoFormat?.frameRate?.takeIf { it > 0 } ?: detectedFrameRate.takeIf { it > 0 }),
"videoBitrate" to videoFormat?.bitrate,
"videoDecoderName" to (decoderInitName ?: videoDecoderInfo),
"videoDecoderName" to videoDecoderName,
"videoDroppedFrames" to player.videoDecoderCounters?.droppedBufferCount,
"videoRenderedFrames" to player.videoDecoderCounters?.renderedOutputBufferCount,
// Color info
@@ -2867,6 +2946,9 @@ class ExoPlayerCore(private val activity: Activity) : Player.Listener {
"dvConversionActive" to (dovi?.conversionActive == true),
"dvConversionMode" to dvMode.name,
"dvConversionDebugMode" to (debugDvModeOverride?.name ?: "AUTO"),
"dvSourceProfile" to dvPlaybackInfo?.sourceProfile,
"dvPlaybackPath" to dvPlaybackInfo?.path,
"dvPlaybackReason" to dvPlaybackInfo?.reason,
"dvStrippedInitNals" to (dovi?.strippedInitNalCount ?: 0L),
"dvStrippedNals" to (dovi?.strippedNalCount ?: 0L),
"dvStrippedRpuNals" to (dovi?.strippedRpuNalCount ?: 0L),
@@ -426,7 +426,6 @@ class PlayerAndroid extends PlayerBase {
@override
Future<void> setLogLevel(String level) async {
if (disposed) return;
await _ensureInitialized();
await invoke('setLogLevel', {'level': level});
}
}
+4
View File
@@ -624,6 +624,10 @@ class VideoPlayerScreenState extends State<VideoPlayerScreen> with WidgetsBindin
final currentPlayer = Player(useExoPlayer: useExoPlayer);
player = currentPlayer;
_playerBackendLabel = currentPlayer.playerType;
if (Platform.isAndroid && useExoPlayer) {
await currentPlayer.setLogLevel(debugLoggingEnabled ? 'v' : 'warn');
if (!mounted || player != currentPlayer) return;
}
// Kick off getPlaybackData() in parallel with the rest of MPV setup.
// The network/DB work has no dependency on the player — it just needs
@@ -58,7 +58,9 @@ class _PlayerPerformanceOverlayState extends State<PlayerPerformanceOverlay> {
if (!isMpv) _metric('Tunneling', _stats.tunneledPlaybackFormatted),
if (_stats.aspectName != null && _stats.aspectName!.isNotEmpty) _metric('Aspect', _stats.aspectName!),
if (_stats.rotate != null && _stats.rotate != 0) _metric('Rotation', _stats.rotateFormatted),
if (_stats.dvConversionActive) _metric('DV', _stats.dvConversionFormatted),
if (_stats.dvSourceProfile != null) _metric('DV Source', _stats.dvSourceProfileFormatted),
if (_stats.dvPlaybackPath != null) _metric('DV Path', _stats.dvPlaybackPathFormatted),
if (_stats.dvConversionActive) _metric('P7 Conv', _stats.dvConversionFormatted),
]),
_buildSection(Symbols.volume_up_rounded, 'Audio', [
if (_stats.audioCodec != null) _metric('Codec', _stats.audioCodec!),
@@ -61,6 +61,9 @@ class PerformanceStats {
final int? dvRpuOutputTooSmall;
final int? dvAvgRpuConversionUs;
final int? dvAvgSampleProcessingUs;
final int? dvSourceProfile;
final String? dvPlaybackPath;
final String? dvPlaybackReason;
// App metrics
final int? appMemoryBytes;
@@ -108,6 +111,9 @@ class PerformanceStats {
this.dvRpuOutputTooSmall,
this.dvAvgRpuConversionUs,
this.dvAvgSampleProcessingUs,
this.dvSourceProfile,
this.dvPlaybackPath,
this.dvPlaybackReason,
this.appMemoryBytes,
this.uiFps,
});
@@ -155,6 +161,9 @@ class PerformanceStats {
dvRpuOutputTooSmall = null,
dvAvgRpuConversionUs = null,
dvAvgSampleProcessingUs = null,
dvSourceProfile = null,
dvPlaybackPath = null,
dvPlaybackReason = null,
appMemoryBytes = null,
uiFps = null;
@@ -273,6 +282,12 @@ class PerformanceStats {
/// Format DV conversion mode for display.
String get dvConversionFormatted => dvConversionMode == 'DV81' ? '7→8.1' : '7→HEVC';
/// Format Dolby Vision source profile.
String get dvSourceProfileFormatted => dvSourceProfile == null ? 'N/A' : 'P$dvSourceProfile';
/// Format Dolby Vision playback path.
String get dvPlaybackPathFormatted => dvPlaybackPath ?? 'N/A';
/// Format DV RPU conversion totals.
String get dvRpuCountFormatted {
final converted = dvConvertedRpus ?? 0;
@@ -213,6 +213,9 @@ class PerformanceStatsService {
dvRpuOutputTooSmall: (statsMap['dvRpuOutputTooSmall'] as num?)?.toInt(),
dvAvgRpuConversionUs: (statsMap['dvAvgRpuConversionUs'] as num?)?.toInt(),
dvAvgSampleProcessingUs: (statsMap['dvAvgSampleProcessingUs'] as num?)?.toInt(),
dvSourceProfile: (statsMap['dvSourceProfile'] as num?)?.toInt(),
dvPlaybackPath: statsMap['dvPlaybackPath'] as String?,
dvPlaybackReason: statsMap['dvPlaybackReason'] as String?,
// App metrics
appMemoryBytes: appMemory,
uiFps: _currentUiFps,