From ffee4bf6c16e56b4350463587aa3aaca5f8dbf5b Mon Sep 17 00:00:00 2001 From: SylvainMorel <62572068+SylvainMorel@users.noreply.github.com> Date: Tue, 28 May 2024 16:17:41 -0400 Subject: [PATCH] Add debug info to help debugging a pipeline stall issue (#23) We have an issue in production where the player starts to flip between buffering and playing at a very high frequency (dozens of times per seconds). Looking at multiple logs and NR data, I was able to get a partial understanding of what is going on: - The rendering stalls early into the playback (often after 3 queued video frames, possibly always after 3, hard to tell) - The player doesn't know something is stalled - The playhead is moving, but the video frames are not queued - At some point, the video streaming buffer is completely filled up - The playhead gets to the end of the full video buffer - Then the flip begins (after about 3 mins) - The player switches to BUFFERING, since it thinks it needs more data (according to the playhead) - The buffering system switches back to PLAYING, since the buffer is full (it hasn't been consumed at all) This PR has 2 goals: - Giving us a way to detect the pipeline is stalled, by giving visibility to the actual current queued video buffer count - Getting us some data on what is causing the stall, by keeping the steps where the input and output buffer processing is stopped, for both the audio and video renderer. This will then be exposed by the app when the stall is detected. This is intended to be temporary. We should get rid of all that stuff once the issue is resolved, which might require different/additional logs once we have some data from the ones in this PR. --- .../androidx/media3/common/util/Util.java | 8 +++- .../mediacodec/MediaCodecRenderer.java | 42 ++++++++++++++++++- .../video/MediaCodecVideoRenderer.java | 2 + 3 files changed, 50 insertions(+), 2 deletions(-) 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 ca0c2ed63df..7ca58a56324 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 @@ -178,13 +178,19 @@ public final class Util { // MIREGO public static boolean shouldWorkaroundAudioSampleRateDataBug = false; - public static int timeSinceLastVideoRenderToLogErrorMs = 1000; public static int audioVideoDeltaToLogErrorMs = 750; public static boolean shouldIgnoreCodecFpsLimitForResolution = false; // MIREGO ADDED public static boolean doNotIgnorePerformancePointsForResolutionAndFrameRate = false; // MIREGO ADDED public static boolean useDifferentAudioSessionIdForTunneling = false; // MIREGO ADDED public static int ntpTimeoutMs = 5000; // MIREGO ADDED + // TEMP DEBUG STUFF + public static int videoLastFeedInputBufferStep = 0; + public static int audioLastFeedInputBufferStep = 0; + public static int videoLastDrainOutputBufferStep = 0; + public static int audioLastDrainOutputBufferStep = 0; + public static int currentAccumulatedVideoQueuedFrames = 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 7a644a906a3..3f2633ba41c 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 @@ -15,6 +15,8 @@ */ package androidx.media3.exoplayer.mediacodec; +import static androidx.media3.common.C.TRACK_TYPE_AUDIO; +import static androidx.media3.common.C.TRACK_TYPE_VIDEO; import static androidx.media3.common.util.Assertions.checkNotNull; import static androidx.media3.common.util.Assertions.checkState; import static androidx.media3.common.util.Assertions.checkStateNotNull; @@ -415,6 +417,24 @@ private static String buildCustomDiagnosticInfo(int errorCode) { int dequeuedInputCount = 0; long lastLogMs = 0; + // MIREGO: added the following 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 + void saveFeedInputBufferStep(int stepIndex) { + if (getTrackType() == TRACK_TYPE_AUDIO) { + Util.audioLastFeedInputBufferStep = stepIndex; + } else if (getTrackType() == TRACK_TYPE_VIDEO) { + Util.videoLastFeedInputBufferStep = stepIndex; + } + } + + void saveDrainOutputBufferStep(int stepIndex) { + if (getTrackType() == TRACK_TYPE_AUDIO) { + Util.audioLastDrainOutputBufferStep = stepIndex; + } else if (getTrackType() == TRACK_TYPE_VIDEO) { + Util.videoLastDrainOutputBufferStep = stepIndex; + } + } + /** * @param trackType The {@link C.TrackType track type} that the renderer handles. * @param codecAdapterFactory A factory for {@link MediaCodecAdapter} instances. @@ -1380,6 +1400,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException { getTrackType(), codecDrainState, inputStreamEnded); if (codec == null || codecDrainState == DRAIN_STATE_WAIT_END_OF_STREAM || inputStreamEnded) { + saveFeedInputBufferStep(1); return false; } if (codecDrainState == DRAIN_STATE_NONE && shouldReinitCodec()) { @@ -1394,6 +1415,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException { Log.v(Log.LOG_LEVEL_VERBOSE4, TAG, "feedInputBuffer(type:%d) codec.dequeueInputBufferIndex failed", getTrackType()); + saveFeedInputBufferStep(2); return false; } @@ -1422,6 +1444,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException { resetInputBuffer(); } codecDrainState = DRAIN_STATE_WAIT_END_OF_STREAM; + saveFeedInputBufferStep(3); return false; } @@ -1435,6 +1458,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException { codec.queueInputBuffer(inputIndex, 0, ADAPTATION_WORKAROUND_BUFFER.length, 0, 0); resetInputBuffer(); codecReceivedBuffers = true; + saveFeedInputBufferStep(4); return true; } @@ -1463,6 +1487,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException { // that rendering will resume from the next key frame. readSourceOmittingSampleData(/* readFlags= */ 0); flushCodec(); + saveFeedInputBufferStep(5); return true; } @@ -1471,6 +1496,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException { // Notify output queue of the last buffer's timestamp. lastBufferInStreamPresentationTimeUs = largestQueuedPresentationTimeUs; } + saveFeedInputBufferStep(6); return false; } if (result == C.RESULT_FORMAT_READ) { @@ -1481,6 +1507,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException { codecReconfigurationState = RECONFIGURATION_STATE_WRITE_PENDING; } onInputFormatChanged(formatHolder); + saveFeedInputBufferStep(7); return true; } @@ -1501,6 +1528,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException { inputStreamEnded = true; if (!codecReceivedBuffers) { processEndOfStream(); + saveFeedInputBufferStep(8); return false; } try { @@ -1520,6 +1548,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException { throw createRendererException( e, inputFormat, Util.getErrorCodeForMediaDrmErrorCode(e.getErrorCode())); } + saveFeedInputBufferStep(9); return false; } @@ -1536,6 +1565,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException { // into a subsequent buffer (if there is one). codecReconfigurationState = RECONFIGURATION_STATE_WRITE_PENDING; } + saveFeedInputBufferStep(10); return true; } @@ -1574,6 +1604,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException { handleInputBufferSupplementalData(buffer); } + saveFeedInputBufferStep(1000); onQueueInputBuffer(buffer); int flags = getCodecBufferFlags(buffer); try { @@ -2100,7 +2131,7 @@ private boolean drainOutputBuffer(long positionUs, long elapsedRealtimeUs) } // MIREGO Log.v(Log.LOG_LEVEL_VERBOSE1, TAG, "drainOutputBuffer(type:%d) failed to dequeueOutputBufferIndex", getTrackType()); - + saveDrainOutputBufferStep(1); return false; } } else { @@ -2114,6 +2145,7 @@ private boolean drainOutputBuffer(long positionUs, long elapsedRealtimeUs) if (outputIndex == MediaCodec.INFO_OUTPUT_FORMAT_CHANGED /* (-2) */) { processOutputMediaFormatChanged(); + saveDrainOutputBufferStep(2); return true; } // MediaCodec.INFO_TRY_AGAIN_LATER (-1) or unknown negative return value. @@ -2121,6 +2153,7 @@ private boolean drainOutputBuffer(long positionUs, long elapsedRealtimeUs) && (inputStreamEnded || codecDrainState == DRAIN_STATE_WAIT_END_OF_STREAM)) { processEndOfStream(); } + saveDrainOutputBufferStep(3); return false; } @@ -2140,6 +2173,7 @@ private boolean drainOutputBuffer(long positionUs, long elapsedRealtimeUs) shouldSkipAdaptationWorkaroundOutputBuffer = false; codec.releaseOutputBuffer(outputIndex, false); + saveDrainOutputBufferStep(4); return true; } else if (outputBufferInfo.size == 0 && (outputBufferInfo.flags & MediaCodec.BUFFER_FLAG_END_OF_STREAM) != 0) { @@ -2149,6 +2183,7 @@ private boolean drainOutputBuffer(long positionUs, long elapsedRealtimeUs) // MIREGO Log.v(Log.LOG_LEVEL_VERBOSE1, TAG, "drainOutputBuffer(type:%d) processEndOfStream", getTrackType()); + saveDrainOutputBufferStep(5); return false; } @@ -2199,6 +2234,7 @@ private boolean drainOutputBuffer(long positionUs, long elapsedRealtimeUs) // Release the codec, as it's in an error state. releaseCodec(); } + saveDrainOutputBufferStep(6); return false; } } else { @@ -2226,9 +2262,13 @@ private boolean drainOutputBuffer(long positionUs, long elapsedRealtimeUs) boolean isEndOfStream = (outputBufferInfo.flags & MediaCodec.BUFFER_FLAG_END_OF_STREAM) != 0; resetOutputBuffer(); if (!isEndOfStream) { + saveDrainOutputBufferStep(1000); return true; } + saveDrainOutputBufferStep(1001); processEndOfStream(); + } else { + saveDrainOutputBufferStep(7); } return false; 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 bde9b918e33..cebd8a718c0 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,6 +734,7 @@ protected void onStarted() { hasNotifiedAvDesyncError = false; hasNotifiedAvDesyncSkippedFramesError = false; queuedFrames = 0; + Util.currentAccumulatedVideoQueuedFrames = 0; videoFrameReleaseControl.onStarted(); } @@ -1226,6 +1227,7 @@ protected void onQueueInputBuffer(DecoderInputBuffer buffer) throws ExoPlaybackE // MIREGO: added queuedFrames++; + Util.currentAccumulatedVideoQueuedFrames++; if (queuedFrames >= NOTIFY_QUEUED_FRAMES_THRESHOLD) { maybeNotifyQueuedFrames(); }