1542956 - Android decoder fails on 4K video on FireOS

Status: RESOLVED DUPLICATE of bug 1528279

(Core :: Audio/Video: Playback, defect, P2)

Description

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: logcat.txt

I've observed the Android video decoder randomly failing while playing 4K video on FireStick 4K.

STR:

1. Download https://www.youtube.com/watch?v=Jsjtt5dWDYU with youtube-dl, the highest quality 4K 60fps VP9+Opus audio variant.
2. Serve the above on a local WebServer, I'm using IIS. You probably want to configure the webserver to limit its bandwidth to 4MB/s, otherwise you might get stung by bug 1538023.
3. Play video using GeckoViewExample, observe after a while playback hangs.

Alternatively, once bug 1533129 lands, you can just point GVE at the above YouTube URL via:

adb shell am force-stop org.mozilla.geckoview_example && adb shell am start -a android.intent.action.MAIN -c android.intent.category.LAUNCHER -n org.mozilla.geckoview_example/org.mozilla.geckoview_example.GeckoViewActivity -d https://www.youtube.com/tv#/watch/video/control?v=Jsjtt5dWDYU

adb logcat of an example failure is attached.

I've seen this on other 4K videos. It seems to happen more frequently on VP9 video.

Comment 1

[Chris Peterson [:cpeterson]]

Playback stops because decoder is crashing or timing out? cpearce says this is not related to isTypeSupported bug 1533129.

Comment 2

[Nils Ohlmeier [:drno]]

John or Chris can one of you take a look at what is going on here?

Comment 3

[John Lin [:jhlin][:jolin]]

(In reply to Nils Ohlmeier [:drno] from comment #2)

John or Chris can one of you take a look at what is going on here?

I'm on it.

Comment 4

[John Lin [:jhlin][:jolin]]

I reproduced this bug and found that although the playback hanged, the decoder did not fail as we thought. The "error" message

04-05 13:33:03.067   273  9264 E MtkOmxVdecEx: ## [ERROR] MtkOmxVdecDecodeThread() line: 1393 WAIT timeout...

is, in fact, just an indication that the video decoder hasn't received input for a while.

The playback hanged because the reader is waiting for data:

04-15 14:48:18.264  9748 10213 I Gecko   : [Child 9748: Unnamed thread 0x852c6a00]: V/MediaFormatReader MediaFormatReader[0x8a574000] ::HandleDemuxedSamples: Input:184935000 (dts:184935000 kf:0)
04-15 14:48:18.271  9748 10046 I Gecko   : [Child 9748: Unnamed thread 0x8c955600]: D/MediaFormatReader MediaFormatReader[0x8a574000] ::OnDemuxFailed: Failed to demux video, failure:NS_ERROR_DOM_MEDIA_WAITING_FOR_DATA
04-15 14:48:18.271  9748 10046 I Gecko   : [Child 9748: Unnamed thread 0x8c955600]: V/MediaFormatReader MediaFormatReader[0x8a574000] ::Update: Still waiting for data or key. data(1)/key(0)

but there was none arrived.

From the log, the lastest buffered range ends at position of the demuxer failure:

04-15 14:48:05.377  9748  9767 I Gecko   : [Child 9748: Main Thread]: D/MediaSource MediaSourceDecoder[0x8c9e5580] ::GetBuffered: ranges=[(153.920000, 184.952000)]

When this happened, the 'Stats for nerds` overlay showed Buffer Health to be ~12s, which IIUC means there is still some much data buffered ahead from JS's POV. Chris, can you think of any reason why MediaSource didn't receive the data?

BTW, during my test, I found that if I don't start the playback immediately and wait for ~1m before hitting the space key, the video often plays through.

Comment 5

[Chris Pearce [:cpearce (Not reading bugmail)]]

(In reply to John Lin [:jhlin][:jolin] from comment #4)

I reproduced this bug and found that although the playback hanged, the decoder did not fail as we thought. The "error" message

04-05 13:33:03.067   273  9264 E MtkOmxVdecEx: ## [ERROR] MtkOmxVdecDecodeThread() line: 1393 WAIT timeout...

is, in fact, just an indication that the video decoder hasn't received input for a while.

The playback hanged because the reader is waiting for data:

04-15 14:48:18.264  9748 10213 I Gecko   : [Child 9748: Unnamed thread 0x852c6a00]: V/MediaFormatReader MediaFormatReader[0x8a574000] ::HandleDemuxedSamples: Input:184935000 (dts:184935000 kf:0)
04-15 14:48:18.271  9748 10046 I Gecko   : [Child 9748: Unnamed thread 0x8c955600]: D/MediaFormatReader MediaFormatReader[0x8a574000] ::OnDemuxFailed: Failed to demux video, failure:NS_ERROR_DOM_MEDIA_WAITING_FOR_DATA
04-15 14:48:18.271  9748 10046 I Gecko   : [Child 9748: Unnamed thread 0x8c955600]: V/MediaFormatReader MediaFormatReader[0x8a574000] ::Update: Still waiting for data or key. data(1)/key(0)

but there was none arrived.

From the log, the lastest buffered range ends at position of the demuxer failure:

04-15 14:48:05.377  9748  9767 I Gecko   : [Child 9748: Main Thread]: D/MediaSource MediaSourceDecoder[0x8c9e5580] ::GetBuffered: ranges=[(153.920000, 184.952000)]

I note the timestamps for the decoder timeout happens 1h15m before the decoder waiting for data log. Are they from different instances of the same class of playback failure, or are there two different problems here?

When this happened, the 'Stats for nerds` overlay showed Buffer Health to be ~12s, which IIUC means there is still some much data buffered ahead from JS's POV. Chris, can you think of any reason why MediaSource didn't receive the data?

One reason could be that the player is appending video based on DTS rather than PTS... So maybe the current playback position isn't in the buffered ranges? I'd have thought we'd have picked that up on YouTube by now though, as that logic should all be platform independent.

BTW, during my test, I found that if I don't start the playback immediately and wait for ~1m before hitting the space key, the video often plays through.

FirefoxTV+GV blocks autoplay (unintentionally see https://github.com/mozilla-mobile/firefox-tv/issues/2040 and https://github.com/mozilla-mobile/firefox-tv/issues/1901 ), which may be what you're seeing here.

Comment 6

[John Lin [:jhlin][:jolin]]

(In reply to Chris Pearce [:cpearce (GMT+13)] from comment #5)

I note the timestamps for the decoder timeout happens 1h15m before the decoder waiting for data log. Are they from different instances of the same class of playback failure, or are there two different problems here?

Yes, that was captured in another playback session. The message is shown when we don't feed inputs in a timely matter.

I haven't been able to reproduce this problem with my local GVE build since I pulled the latest central code yesterday. So I started to test with more builds of GVTV that uses different versions of GV nightly. So far, it can be reproduced with GV-68.0.68.0.20190416095014 but not with GV-68.0.20190417093858 and later.

Comment 7

[Chris Pearce [:cpearce (Not reading bugmail)]]

I also can't repro this any longer with a local build of GVE.

Comment 8

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: Logcat of failure

Here's another log of the failure, happening pretty soon after startup, with MOZ_LOGs.

It looks like something causes us to drain the decoder, and then we end up pushing 71 frames into the decoder without it producing any output.

Comment 9

[John Lin [:jhlin][:jolin]]

(In reply to Chris Pearce [:cpearce (GMT+13)] from comment #8)

Created attachment 9059996 [details]
Logcat of failure

Here's another log of the failure, happening pretty soon after startup, with MOZ_LOGs.

It looks like something causes us to drain the decoder, and then we end up pushing 71 frames into the decoder without it producing any output.

I still haven't been able to reproduce it with locally built m-c GVE, but your log shows the same "waiting for data situation": 04-18 16:54:13.784 12945 13196 I Gecko : [Child 12945: Unnamed thread 0x7a1f5080]: D/MediaFormatReader MediaFormatReader[0x7a16d800] ::OnDemuxFailed: Failed to demux video, failure:NS_ERROR_DOM_MEDIA_WAITING_FOR_DATA
And it probably caused the draining [1]: 04-18 16:54:13.784 12945 13196 I Gecko : [Child 12945: Unnamed thread 0x7a1f5080]: D/MediaFormatReader MediaFormatReader[0x7a16d800] ::DrainDecoder: Requesting Video decoder to drain

After that, it looks like the reader tried to resume from the last sample it processed: 04-18 16:54:13.855 12945 13180 I Gecko : [Child 12945: Unnamed thread 0x7a1bb680]: D/MediaFormatReader MediaFormatReader[0x7a16d800] ::Update: Seeking to last sample time: 8259000 by starting from the previous key frame: 04-18 16:54:13.861 12945 13179 I Gecko : [Child 12945: Unnamed thread 0x7a1bb480]: V/MediaFormatReader MediaFormatReader[0x7a16d800] ::HandleDemuxedSamples: Input:5339000 (dts:5339000 kf:1)
and setting the seek threshold to the last sample time:04-18 16:54:13.860 12945 13192 I Gecko : [Child 12945: Unnamed thread 0x7a1bb980]: D/MediaFormatReader MediaFormatReader[0x7a16d800] ::SetVideoDecodeThreshold: Set seek threshold to 8259000, which made the decoder release instead of report the 71 outputs it produced.

Once reaching the threshold, it failed to demux more sample, and started to wait for data again:

04-18 16:54:14.512 12945 13192 I Gecko   : [Child 12945: Unnamed thread 0x7a1bb980]: V/MediaFormatReader MediaFormatReader[0x7a16d800] ::HandleDemuxedSamples: Input:8259000 (dts:8259000 kf:0)
04-18 16:54:14.516 12945 13196 I Gecko   : [Child 12945: Unnamed thread 0x7a1f5080]: D/MediaFormatReader MediaFormatReader[0x7a16d800] ::OnDemuxFailed: Failed to demux video, failure:NS_ERROR_DOM_MEDIA_WAITING_FOR_DATA

[1] https://searchfox.org/mozilla-central/source/dom/media/MediaFormatReader.cpp#1420

Comment 10

[Chris Pearce [:cpearce (Not reading bugmail)]]

I ran a bisection, and determined that this was fixed 7 days ago by Bug 1528279.