Video decoders on FTV3 (AFTN) have huge latency (~2 seconds)

[tmm1]

I have been experiencing issues using MediaCodec directly on the new 3rd generation Fire TV, and have traced it back to an unexpected 2s decoding delay in both the mpeg2 and h264 MediaCodec decoders on that device.

To demonstrate, I wrote the following patch for exoplayer which logs the difference between the input and output timestamps. On most devices, this is under 200ms, but on the FTV3 it is 2000ms.

diff --git a/demos/main/src/main/assets/media.exolist.json b/demos/main/src/main/assets/media.exolist.json
index 7052e7c43..7356d5513 100644
--- a/demos/main/src/main/assets/media.exolist.json
+++ b/demos/main/src/main/assets/media.exolist.json
@@ -1,4 +1,13 @@
 [
+  {
+    "name": "DELAY TEST",
+    "samples": [
+      {
+        "name":"sample",
+        "uri": "http://tmm1.s3.amazonaws.com/720p-h264-60fps.ts"
+      }
+    ]
+  },
   {
     "name": "YouTube DASH",
     "samples": [
diff --git a/library/core/src/main/java/com/google/android/exoplayer2/mediacodec/MediaCodecRenderer.java b/library/core/src/main/java/com/google/android/exoplayer2/mediacodec/MediaCodecRenderer.java
index 1bf1a1e44..4291e5c99 100755
--- a/library/core/src/main/java/com/google/android/exoplayer2/mediacodec/MediaCodecRenderer.java
+++ b/library/core/src/main/java/com/google/android/exoplayer2/mediacodec/MediaCodecRenderer.java
@@ -235,6 +235,9 @@ public abstract class MediaCodecRenderer extends BaseRenderer {
   private boolean codecReceivedBuffers;
   private boolean codecReceivedEos;
 
+  private long inputPts;
+  private long outputPts;
+
   private boolean inputStreamEnded;
   private boolean outputStreamEnded;
   private boolean waitingForKeys;
@@ -809,6 +812,7 @@ public abstract class MediaCodecRenderer extends BaseRenderer {
                                 ", bufferSize = " + buffer.data.limit() +
                                 ", presentationTimeUs = " + presentationTimeUs);
         }
+        this.inputPts = presentationTimeUs;
         codec.queueInputBuffer(inputIndex, 0, buffer.data.limit(), presentationTimeUs, 0);
       }
       resetInputBuffer();
@@ -1084,6 +1088,9 @@ public abstract class MediaCodecRenderer extends BaseRenderer {
             outputBuffer.limit(outputBufferInfo.offset + outputBufferInfo.size);
           }
           shouldSkipOutputBuffer = shouldSkipOutputBuffer(outputBufferInfo.presentationTimeUs);
+          this.outputPts = outputBufferInfo.presentationTimeUs;
+          if (codecInfo.name.contains(".avc") || codecInfo.name.contains(".AVC") || codecInfo.name.contains("mpeg2"))
+            Log.d("DELAY", "dequeueOutputbuffer: idx="+outputIndex+" pts=" + outputBufferInfo.presentationTimeUs + " delay=" + (this.inputPts - this.outputPts) / 1000000.0);
         }
       } else if (outputIndex == MediaCodec.INFO_OUTPUT_FORMAT_CHANGED /* (-2) */) {
         log.i("INFO_OUTPUT_FORMAT_CHANGED");

After applying the above, here is a sample log when playing back 720p-h264-60fps.ts. Notice there are no logs between 16:30:21.592 and 16:30:23.073, a two second gap where no video frames are received:

04-23 16:30:21.378 10857-10891 I/OMX.amlogic.avc.decoder.awesome-MediaCodecVideoRenderer: onOutputFormatChanged: outputFormat:{crop-top=0, crop-right=1279, color-format=17, height=720, color-standard=1, crop-left=0, color-transfer=3, stride=1280, mime=video/raw, slice-height=720, width=1280, color-range=2, crop-bottom=719, hdr-static-info=java.nio.HeapByteBuffer[pos=0 lim=25 cap=25]}, codec:android.media.MediaCodec@3dcff64
    hasCrop = true, currentWidth = 1280, currentHeight = 720, currentPixelWidthHeightRatio = 1.0
04-23 16:30:21.380 10857-10891 D/DELAY: dequeueOutputbuffer: idx=0 pts=61391756 delay=0.150155
04-23 16:30:21.383 10857-10891 D/DELAY: dequeueOutputbuffer: idx=1 pts=61408445 delay=0.133466
04-23 16:30:21.385 10857-10857 D/EventLogger: videoSizeChanged [1280, 720]
04-23 16:30:21.386 10857-10857 D/EventLogger: renderedFirstFrame [Surface(name=null)/@0x64165cd]
04-23 16:30:21.578 10857-10891 I/AudioTrack: calling play
04-23 16:30:21.592 10857-10857 D/EventLogger: state [1.44, true, R]
04-23 16:30:23.073 10857-10891 D/DELAY: dequeueOutputbuffer: idx=2 pts=61425122 delay=1.985323
04-23 16:30:23.097 10857-10891 D/DELAY: dequeueOutputbuffer: idx=3 pts=61441811 delay=1.968634
04-23 16:30:23.102 10857-10891 D/DELAY: dequeueOutputbuffer: idx=4 pts=61458489 delay=1.951956
04-23 16:30:23.125 10857-10891 D/DELAY: dequeueOutputbuffer: idx=5 pts=61475178 delay=1.935267
04-23 16:30:23.137 10857-10891 D/DELAY: dequeueOutputbuffer: idx=6 pts=61491856 delay=1.918589
04-23 16:30:23.158 10857-10891 D/DELAY: dequeueOutputbuffer: idx=7 pts=61508545 delay=1.968633
04-23 16:30:23.178 10857-10891 D/DELAY: dequeueOutputbuffer: idx=8 pts=61525222 delay=2.068734

If I try the same test on FTVStick2 (AFTT), you can see the calculated delay value is much more reasonable (~200ms):

04-23 16:46:58.991 923-1188 I/OMX.MTK.VIDEO.DECODER.AVC-MediaCodecVideoRenderer: hasCrop = true, currentWidth = 1280, currentHeight = 720, currentPixelWidthHeightRatio = 1.0
04-23 16:46:58.991 923-1188 D/DELAY: dequeueOutputbuffer: idx=8 pts=61391756 delay=0.183522
04-23 16:46:58.993 923-923 D/EventLogger: videoSizeChanged [1280, 720]
04-23 16:46:58.995 923-1188 D/DELAY: dequeueOutputbuffer: idx=4 pts=61408445 delay=0.166833
04-23 16:46:59.004 923-923 D/EventLogger: renderedFirstFrame [Surface(name=null)/@0x274299d]
04-23 16:46:59.420 923-1188 I/AudioTrack: calling play
04-23 16:46:59.437 923-923 D/EventLogger: state [2.40, true, R]
04-23 16:47:00.776 923-1188 D/DELAY: dequeueOutputbuffer: idx=5 pts=61425122 delay=0.3003
04-23 16:47:00.787 923-1188 D/DELAY: dequeueOutputbuffer: idx=3 pts=61441811 delay=0.283611
04-23 16:47:00.807 923-1188 D/DELAY: dequeueOutputbuffer: idx=6 pts=61458489 delay=0.216889
04-23 16:47:00.827 923-1188 D/DELAY: dequeueOutputbuffer: idx=9 pts=61475178 delay=0.2002
04-23 16:47:00.847 923-1188 D/DELAY: dequeueOutputbuffer: idx=10 pts=61491856 delay=0.216889

[tmm1]

The MediaCodec documentation states that priority=0 can be used to signal real-time decoding (https://developer.android.com/reference/android/media/MediaFormat.html#KEY_PRIORITY), however on the AFTN device that property appears to be unsupported. Exoplayer already sets that value:

exoplayer-amazon-port/library/core/src/main/java/com/google/android/exoplayer2/mediacodec/MediaCodecRenderer.java

Line 1251 in 3f2fa55

mediaFormat.setInteger(MediaFormat.KEY_PRIORITY, 0 /* realtime priority */);

but it is ignored:

04-23 15:32:24.502 4466-5136 I/ACodec: codec does not support config priority (err -1010)

[peddisri]

acknowledged. investigating

[tmm1]

Thanks @peddisri. Let me know if I can help in any way.

[peddisri]

The decoder has a max buffer that can hold upto 2 seconds of video frames. Hence Exo ends up spending lot of time in queuing up these buffers since the feeding data to input is a tight loop. Thereafter it goes into drainOutputBuffer mode.

After you seeing any issue in the app playback due to this?

[tmm1]

I am playing a live stream from a network tuner device, so the 2s buffer introduces a large delay in playback.

Does setting max-input-size make any difference? I thought exoplayer already calculates and sets it based on the stream:

exoplayer-amazon-port/library/core/src/main/java/com/google/android/exoplayer2/video/MediaCodecVideoRenderer.java

Lines 1096 to 1104 in 3f2fa55

	case MimeTypes.VIDEO_H264:
	if ("BRAVIA 4K 2015".equals(Util.MODEL)) {
	// The Sony BRAVIA 4k TV has input buffers that are too small for the calculated 4k video
	// maximum input size, so use the default value.
	return Format.NO_VALUE;
	}
	// Round up width/height to an integer number of macroblocks.
	maxPixels = Util.ceilDivide(width, 16) * Util.ceilDivide(height, 16) * 16 * 16;
	minCompressionRatio = 2;

exoplayer-amazon-port/library/core/src/main/java/com/google/android/exoplayer2/video/MediaCodecVideoRenderer.java

Lines 1120 to 1121 in 3f2fa55

	// Estimate the maximum input size assuming three channel 4:2:0 subsampled input frames.
	return (maxPixels * 3) / (2 * minCompressionRatio);

[peddisri]

Well, this sets the max size of every frame. I tried to find if there is any API to configure number of input buffers, but Looks like there is none.
I think one hack that you can do in ExoPlayer is to run a counter every time renderer enters into feedInputBuffer API and check how many buffers it is queuing, and break out of that loop if it has reached a limit set by you. Makes sense?

[tmm1]

Well, this sets the max size of every frame. I tried to find if there is any API to configure number of input buffers, but Looks like there is none.

I don't think it's per frame, but total for the decoder. That's why exoplayer uses 3*maxPixels, to allow up to three frames worth of data. Regardless, it seems this option has no effect on AFTN because it buffers 2s even though the option is set to only buffer three frames.

I think one hack that you can do in ExoPlayer is to run a counter every time renderer enters into feedInputBuffer API and check how many buffers it is queuing, and break out of that loop if it has reached a limit set by you. Makes sense?

I tried something like this, but it doesn't work very well. If you don't feed in 2s of data into the decoder, it will stop returning frames.

This seems like a bug in the hardware decoder. I don't see the same behavior on other devices using OMX.amlogic decoder, so perhaps the video driver on the AFTN needs to be updated in the next fireos release.

[peddisri]

don't think it's per frame, but total for the decoder. That's why exoplayer uses 3*maxPixels, to allow up to three frames worth of data.

No, this is per frame. They allocated for max possible input size. Its not 3 frames.

[tmm1]

The comment in the code says:

Estimate the maximum input size assuming three channel 4:2:0 subsampled input frames

which I thought means "estimate input size assuming three [...] input frames" but I guess I misunderstood.

The documentation for MAX_INPUT_SIZE says:

maximum size of a buffer of input data

So you are correct, it is the buffer size for one input frame.

[peddisri]

Can you share the code snippet where you put the hack? I think that should have worked. There is no reason for decoder to wait till 2 sec input buffers are available. of course what would happen is that you get into feedInputBuffer loop, break after say 6 frames, then immediately get into draingOutputBufferLoop. At this time, the decoder may not be ready with buffers immediately. So you get into feedInputBufferloop again, and this time again you feed 6 frames. Then hopefully drainOutputBuffers should have some output buffer. Can you enable verbose logging by doing this in PlayerActivity.java in onCreate and share the logs.

Logger.setLogLevel(Logger.Module.Video, Log.DEBUG);

[peddisri]

Another question is that are you making sure that the first frame is I frame? I'm assuming since its a tuner, maybe you just start feeding the frames from P frame, which again means it is possible that decoder is waiting for the first I frame to start decoding. I'm checking this internally with my codec team and will let you know soon.

[NitroXenon]

@tmm1 @peddisri Any news?

[peddisri]

@tmm1 any update on my last question?

[tmm1]

Sorry for the delay. I was traveling so I did not have access to my FTV3 for testing.

I tried what you suggested, but it has no effect. I added the following patch to limit the input buffers:

diff --git a/library/core/src/main/java/com/google/android/exoplayer2/mediacodec/MediaCodecRenderer.java b/library/core/src/main/java/com/google/android/exoplayer2/mediacodec/MediaCodecRenderer.java
index fb4be054d..b7750b76c 100755
--- a/library/core/src/main/java/com/google/android/exoplayer2/mediacodec/MediaCodecRenderer.java
+++ b/library/core/src/main/java/com/google/android/exoplayer2/mediacodec/MediaCodecRenderer.java
@@ -602,8 +605,9 @@ public abstract class MediaCodecRenderer extends BaseRenderer {
     maybeInitCodec();
     if (codec != null) {
       TraceUtil.beginSection("drainAndFeed");
+      int n = 0;
       while (drainOutputBuffer(positionUs, elapsedRealtimeUs)) {}
-      while (feedInputBuffer()) {}
+      while (feedInputBuffer() && n++ < 6) {}
       TraceUtil.endSection();
     } else {
       decoderCounters.skippedInputBufferCount += skipSource(positionUs);

But when I play any file, the DELAY reported by earlier patch is still ~2s:

D/DELAY: dequeueOutputbuffer: idx=0 pts=9416445 delay=2.018677
D/DELAY: dequeueOutputbuffer: idx=2 pts=9433122 delay=2.002
D/DELAY: dequeueOutputbuffer: idx=3 pts=9449811 delay=1.985311
D/DELAY: dequeueOutputbuffer: idx=4 pts=9466489 delay=1.951956
D/DELAY: dequeueOutputbuffer: idx=5 pts=9483178 delay=1.935267
D/DELAY: dequeueOutputbuffer: idx=6 pts=9499856 delay=1.918589
D/DELAY: dequeueOutputbuffer: idx=7 pts=9516545 delay=1.9019
D/DELAY: dequeueOutputbuffer: idx=8 pts=9533222 delay=1.885223
D/DELAY: dequeueOutputbuffer: idx=9 pts=9549911 delay=1.868534

The decoder refuses to produce any output buffers until 2 seconds of input data has been queued. This delay seems to be hard-coded somewhere in the driver. As I mentioned earlier, I only see this behavior on the FTV3 (and now the new FTV Cube also), but not any other Android TV devices which also use the same AMLogic chipset.

The behavior is the same for all streams. For example if I use the "Apple 16x9 basic stream" test, it shows the same delay:

I/MediaCodecLogger: updatePTSTime [HW.video.avc] First PTS after Flush or reset = 0
                    [ASAP] HW.video.avc Got First Frame Ready 3323362799
D/DELAY: dequeueOutputbuffer: idx=0 pts=0 delay=0.033366
D/DELAY: dequeueOutputbuffer: idx=1 pts=33366 delay=0.4004
D/DELAY: dequeueOutputbuffer: idx=2 pts=66733 delay=2.168833
D/DELAY: dequeueOutputbuffer: idx=3 pts=100100 delay=2.135466
D/DELAY: dequeueOutputbuffer: idx=4 pts=133466 delay=2.1021

I already provided all the details necessary to reproduce this issue, and as I mentioned it happens with any video input. But since you asked, I am also attaching the verbose logs with the Module.Video=DEBUG enabled (also includes my DELAY patch above, using HLS > Apple 16x9 basic stream): https://paste.ubuntu.com/p/88h6zBy6sw/

[peddisri]

Thank you for your response. I'll take a look.

[tmm1]

Were you able to reproduce this issue?

[peddisri]

yes

[peddisri]

I'm afraid, my earlier comment was invalid.My observation of the logs was incorrect. The reason for the delay is not video decoder. I think the Audio Track position does not move, and that's why the video rendering pipeline does not proceed. Need more investigation.