From 544ae27ff89aa5878c350eb6c745d8411cade3fd Mon Sep 17 00:00:00 2001 From: SylvainMorel <62572068+SylvainMorel@users.noreply.github.com> Date: Sun, 15 Sep 2024 09:35:07 -0400 Subject: [PATCH] Adds an error log when a potential video codec stall is detected (#26) We have a production issue where we get infinite fast state flips between buffering and playing after a while. So far, investigations have allowed us to understand that the issue seems that video frames do not get out of the codec. So after approximately 3 mins, the playhead gets to the end of the video buffer, so the player switches immediately to buffering. But at the same, the buffer is full (it's not being consumed anymore) so the buffering system flips it back to playing immediately. And that cycle is then repeated. This PR adds a way to detect the codec stall situation, and send an error through the logger. The app will then be able to handle the error properly (potentially by restarting the playback automatically). To do so, we just check if we've been waiting for a decoded buffer for a certain time without getting any. --- .../media3/common/PlaybackException.java | 5 ++++ .../androidx/media3/common/util/Util.java | 3 +- .../mediacodec/MediaCodecRenderer.java | 30 +++++++++++++++++-- .../video/MediaCodecVideoRenderer.java | 5 ++-- 4 files changed, 37 insertions(+), 6 deletions(-) diff --git a/libraries/common/src/main/java/androidx/media3/common/PlaybackException.java b/libraries/common/src/main/java/androidx/media3/common/PlaybackException.java index 04d47fb09e7..696d99dadeb 100644 --- a/libraries/common/src/main/java/androidx/media3/common/PlaybackException.java +++ b/libraries/common/src/main/java/androidx/media3/common/PlaybackException.java @@ -244,6 +244,9 @@ public class PlaybackException extends Exception implements Bundleable { /** MIREGO: Caused by a network error trying to get time from the NTP server */ public static final int ERROR_CODE_NTP = 5905; + /** MIREGO: Caused by the video codec being stalled (issue under investigation) */ + public static final int ERROR_CODE_VIDEO_CODEC_STALLED = 5906; + // DRM errors (6xxx). /** Caused by an unspecified error related to DRM protection. */ @@ -385,6 +388,8 @@ public static String getErrorCodeName(@ErrorCode int errorCode) { return "ERROR_CODE_AUDIO_WAITING_FOR_HEAD_POSITION_RESET"; case ERROR_CODE_NTP: return "ERROR_CODE_NTP"; + case ERROR_CODE_VIDEO_CODEC_STALLED: + return "ERROR_CODE_VIDEO_CODEC_STALLED"; default: if (errorCode >= CUSTOM_ERROR_CODE_BASE) { diff --git a/libraries/common/src/main/java/androidx/media3/common/util/Util.java b/libraries/common/src/main/java/androidx/media3/common/util/Util.java index 4d1bc4875e9..f58611ecd82 100644 --- a/libraries/common/src/main/java/androidx/media3/common/util/Util.java +++ b/libraries/common/src/main/java/androidx/media3/common/util/Util.java @@ -184,13 +184,14 @@ public final class Util { public static boolean useDifferentAudioSessionIdForTunneling = false; // MIREGO ADDED public static int ntpTimeoutMs = 5000; // MIREGO ADDED - // TEMP DEBUG STUFF + // TEMP DEBUG STUFF (to investigate an infinite buffering issue caused by what seems to be a video codec stall) public static int videoLastFeedInputBufferStep = 0; public static int audioLastFeedInputBufferStep = 0; public static int videoLastDrainOutputBufferStep = 0; public static int audioLastDrainOutputBufferStep = 0; public static int currentQueuedInputBuffers = 0; public static int currentProcessedOutputBuffers = 0; + public static long waitingForDecodedVideoBufferTimeMs = 0; /** An empty long array. */ @UnstableApi public static final long[] EMPTY_LONG_ARRAY = new long[0]; diff --git a/libraries/exoplayer/src/main/java/androidx/media3/exoplayer/mediacodec/MediaCodecRenderer.java b/libraries/exoplayer/src/main/java/androidx/media3/exoplayer/mediacodec/MediaCodecRenderer.java index 3f2633ba41c..3b9e840fa9f 100644 --- a/libraries/exoplayer/src/main/java/androidx/media3/exoplayer/mediacodec/MediaCodecRenderer.java +++ b/libraries/exoplayer/src/main/java/androidx/media3/exoplayer/mediacodec/MediaCodecRenderer.java @@ -414,11 +414,13 @@ private static String buildCustomDiagnosticInfo(int errorCode) { private boolean needToNotifyOutputFormatChangeAfterStreamChange; // MIREGO for logging - int dequeuedInputCount = 0; - long lastLogMs = 0; + private int dequeuedInputCount = 0; + private long lastLogMs = 0; - // MIREGO: added the following 2 functions to log and debug a specific issue (rendering pipleine stall) + // MIREGO: added the following field and 2 functions to log and debug a specific issue (rendering pipleine stall) // MIREGO: once the issue is solved, we should get rid of that code + private boolean hasReportedRenderingStall = false; + void saveFeedInputBufferStep(int stepIndex) { if (getTrackType() == TRACK_TYPE_AUDIO) { Util.audioLastFeedInputBufferStep = stepIndex; @@ -790,6 +792,7 @@ protected void onDisabled() { protected void onReset() { // MIREGO Log.v(Log.LOG_LEVEL_VERBOSE2, TAG, "onReset() this: %s", this); + hasReportedRenderingStall = false; try { disableBypass(); @@ -2139,6 +2142,22 @@ private boolean drainOutputBuffer(long positionUs, long elapsedRealtimeUs) } if (outputIndex < 0) { + + // MIREGO video renderer stall detection + if (getTrackType() == TRACK_TYPE_VIDEO) { + + if (Util.currentProcessedOutputBuffers < Util.currentQueuedInputBuffers) { + // waiting for a decoded buffer to be available from the codec + long currentTimeMs = System.currentTimeMillis(); + if (Util.waitingForDecodedVideoBufferTimeMs == 0) { + Util.waitingForDecodedVideoBufferTimeMs = currentTimeMs; // starting to wait for the decoded buffer + } else if (!hasReportedRenderingStall && currentTimeMs > Util.waitingForDecodedVideoBufferTimeMs + 7000) { // been waiting for an arbitrary while, send an error to the app + Log.e(TAG, new PlaybackException("Video codec may be stalled error", new RuntimeException(), PlaybackException.ERROR_CODE_VIDEO_CODEC_STALLED)); + hasReportedRenderingStall = true; + } + } + } + // MIREGO Log.v(Log.LOG_LEVEL_VERBOSE2, TAG, "drainOutputBuffer(type:%d) Failed dequeueOutputBufferIndex res: %d (dequeuedOutputCount: %d)", getTrackType(), outputIndex, dequeuedOutputCount); @@ -2157,6 +2176,11 @@ private boolean drainOutputBuffer(long positionUs, long elapsedRealtimeUs) return false; } + // MIREGO video renderer stall detection + if (getTrackType() == TRACK_TYPE_VIDEO) { + Util.waitingForDecodedVideoBufferTimeMs = 0; // we got a decoded buffer, reset the wait time + } + // MIREGO START dequeuedOutputCount++; Log.v(Log.LOG_LEVEL_VERBOSE3, TAG, "drainOutputBuffer(type:%d) presentationTime: %d dequeuedOutputCount: %d outputIndex: %d", diff --git a/libraries/exoplayer/src/main/java/androidx/media3/exoplayer/video/MediaCodecVideoRenderer.java b/libraries/exoplayer/src/main/java/androidx/media3/exoplayer/video/MediaCodecVideoRenderer.java index b2ea2535e4f..a342daf67e1 100644 --- a/libraries/exoplayer/src/main/java/androidx/media3/exoplayer/video/MediaCodecVideoRenderer.java +++ b/libraries/exoplayer/src/main/java/androidx/media3/exoplayer/video/MediaCodecVideoRenderer.java @@ -734,8 +734,6 @@ protected void onStarted() { hasNotifiedAvDesyncError = false; hasNotifiedAvDesyncSkippedFramesError = false; queuedFrames = 0; - Util.currentQueuedInputBuffers = 0; - Util.currentProcessedOutputBuffers = 0; videoFrameReleaseControl.onStarted(); } @@ -777,6 +775,9 @@ protected void onReset() { if (placeholderSurface != null) { releasePlaceholderSurface(); } + Util.currentQueuedInputBuffers = 0; + Util.currentProcessedOutputBuffers = 0; + Util.waitingForDecodedVideoBufferTimeMs = 0; } }