Skip to content

Commit

Permalink
Add debug info to help debugging a pipeline stall issue (#23)
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
SylvainMorel authored May 28, 2024
1 parent 1ee3d31 commit ffee4bf
Show file tree
Hide file tree
Showing 3 changed files with 50 additions and 2 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -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];

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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()) {
Expand All @@ -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;
}

Expand Down Expand Up @@ -1422,6 +1444,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException {
resetInputBuffer();
}
codecDrainState = DRAIN_STATE_WAIT_END_OF_STREAM;
saveFeedInputBufferStep(3);
return false;
}

Expand All @@ -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;
}

Expand Down Expand Up @@ -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;
}

Expand All @@ -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) {
Expand All @@ -1481,6 +1507,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException {
codecReconfigurationState = RECONFIGURATION_STATE_WRITE_PENDING;
}
onInputFormatChanged(formatHolder);
saveFeedInputBufferStep(7);
return true;
}

Expand All @@ -1501,6 +1528,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException {
inputStreamEnded = true;
if (!codecReceivedBuffers) {
processEndOfStream();
saveFeedInputBufferStep(8);
return false;
}
try {
Expand All @@ -1520,6 +1548,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException {
throw createRendererException(
e, inputFormat, Util.getErrorCodeForMediaDrmErrorCode(e.getErrorCode()));
}
saveFeedInputBufferStep(9);
return false;
}

Expand All @@ -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;
}

Expand Down Expand Up @@ -1574,6 +1604,7 @@ private boolean feedInputBuffer() throws ExoPlaybackException {
handleInputBufferSupplementalData(buffer);
}

saveFeedInputBufferStep(1000);
onQueueInputBuffer(buffer);
int flags = getCodecBufferFlags(buffer);
try {
Expand Down Expand Up @@ -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 {
Expand All @@ -2114,13 +2145,15 @@ 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.
if (codecNeedsEosPropagation
&& (inputStreamEnded || codecDrainState == DRAIN_STATE_WAIT_END_OF_STREAM)) {
processEndOfStream();
}
saveDrainOutputBufferStep(3);
return false;
}

Expand All @@ -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) {
Expand All @@ -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;
}

Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -734,6 +734,7 @@ protected void onStarted() {
hasNotifiedAvDesyncError = false;
hasNotifiedAvDesyncSkippedFramesError = false;
queuedFrames = 0;
Util.currentAccumulatedVideoQueuedFrames = 0;

videoFrameReleaseControl.onStarted();
}
Expand Down Expand Up @@ -1226,6 +1227,7 @@ protected void onQueueInputBuffer(DecoderInputBuffer buffer) throws ExoPlaybackE

// MIREGO: added
queuedFrames++;
Util.currentAccumulatedVideoQueuedFrames++;
if (queuedFrames >= NOTIFY_QUEUED_FRAMES_THRESHOLD) {
maybeNotifyQueuedFrames();
}
Expand Down

0 comments on commit ffee4bf

Please sign in to comment.