GNOME Bugzilla – Bug 761611
Android (hardware accelerated) playback doesn't recover well if decoding gets too late (pile up of frame drop)
Last modified: 2016-02-07 06:29:08 UTC
OS: Android 6.0.1 Device: Nexus 7 2013 and Nexus 5x Gstreamer version: 1.7.2 (> to commits of https://bugzilla.gnome.org/show_bug.cgi?id=761014) Video test case: http://www.gentil.com/tmp/video.zip Application: Tutorial 5 (cgit.freedesktop.org/~slomo/gst-sdk-tutorials/) Pipeline: playbin (zero copy from hardware acceleration to glimagesink) WORKING: The video provided here (http://www.gentil.com/tmp/video.zip) works perfectly well on Nexus 5x. NOT WORKING: The same video has some trouble on Nexus 5x at mark 31 seconds. For some reasons, the stream gets jerky (perhaps because a frame header is not correct in the video) and the player piles up warnings: 02-05 14:02:53.096: W/GStreamer+amcvideodec(32083): 0:04:19.649383547 0xa050be90 gstamcvideodec.c:1307:gst_amc_video_dec_loop:<amcvideodec-omxqcomvideodecoderavc0> Frame is too late, dropping (deadline -0:00:00.003625245) 02-05 14:02:53.140: W/GStreamer+amcvideodec(32083): 0:04:19.694061280 0xa050be90 gstamcvideodec.c:1307:gst_amc_video_dec_loop:<amcvideodec-omxqcomvideodecoderavc0> Frame is too late, dropping (deadline -0:00:00.013943115) The problem is that there is no kind of recovery. In other words, it seems that if some hardware accelerated frame callbacks are missing, everything goes wrong, worse and worse and worse. Gstreamer doesn't try to "recover" and catch the next hardware decoding callback. It just piles up the drop frames over and over. The same video with the exact same tutorial-5 binaries work fine on a more powerful device such as Nexus 5x. Most likely, the Nexus 5x is powerful enough to go over the glitch at the 31-second mark and there is no callback missing. Remark: You need to play the video on nexus 7 2013 entirely : wait for the 31-second mark to see the problem. Also, if you let the video plays entirely and replays it by pressing the play button (without selecting another video), the stream is completely jerky with a lot of warning messages. But if you reselect the video with the "select a file" button, the video plays well at least for the first 30 seconds. In other words, gstreamer seems to remind of all the drop frames and still doesn't manage to recover even if the video is played from the beginning again.
Same results on git master ?
It's a kind of follow-up of bug #761014 which has been fixed 48 hours ago. I have synced the tree and recompiled clean 24 hours ago...
As usual, a debug log of the failing case with at least *amc*:7 will go a long way to triaging this.
Sure, here is the log: http://www.gentil.com/tmp/log.zip The 30-second mark mentioned in my comment 1 happens at 23:24:27, around line 55064. You can search for the string "Frame is too late, dropping". At line 61174, the video is finished and it's restarted by clicking on the play button. As you can see there are a lot of "frame is too late" while there was none from 0 to 30 seconds during the first playback.
There seem to be a whole bunch of blank lines in the log? Did you cull some of android's logging?
No, I haven't removed anything from the log. It's a pure logcat output on a device shell with: setenv("GST_DEBUG", "*amc*:7", 1); setenv("GST_DEBUG_NO_COLOR", "1", 1);
On line 55064 of the log file, I read: 02-05 23:24:27.160 5948 6056 D GStreamer+amcvideodec: 0:00:49.538421632 0x9fbea8c0 gstamcvideodec.c:1230:gst_amc_video_dec_loop:<amcvidFrame is too late, droppingeodec-omxqcomvideodecoderavc0> dequeueOutputBuffer() returned 10 (0xa) It seems that two lines are concatenate here. I have reproduced the log without doing a real-time logcat and afterwards logcat. http://www.gentil.com/tmp/log2.zip At 12:22:21, I can now read: 02-06 12:22:21.545 11698 11823 V GStreamer+amcvideodec: 0:00:47.738006592 0xa0de55b0 gstamcvideodec.c:111:_gl_sync_result_unref gl_sync result 0xa0338f40 unref 02-06 12:22:21.545 11698 11823 V GStreamer+amcvideodec: 0:00:47.738128662 0xa0de55b0 gstamcvideodec.c:114:_gl_sync_result_unref freeing gl_sync result 0xa0338f40 02-06 12:22:21.551 11698 11812 D GStreamer+amcvideodec: 0:00:47.744018554 0x9fd1d980 gstamcvideodec.c:2216:gst_amc_video_dec_handle_frame:<amcvideodec-omxqcomvideodecoderavc0> Queueing buffer 0: size 146691 time 31540200 flags 0x00000001 02-06 12:22:21.551 11698 11818 D GStreamer+amcvideodec: 0:00:47.744506836 0xa0de50c0 gstamcvideodec.c:1230:gst_amc_video_dec_loop:<amcvideodec-omxqcomvideodecoderavc0> dequeueOutputBuffer() returned 3 (0x3) 02-06 12:22:21.552 11698 11818 D GStreamer+amcvideodec: 0:00:47.744995117 0xa0de50c0 gstamcvideodec.c:1286:gst_amc_video_dec_loop:<amcvideodec-omxqcomvideodecoderavc0> Got output buffer at index 3: offset 0 size 2785280 time 31481800 flags 0x00000001 02-06 12:22:21.552 11698 11818 W GStreamer+amcvideodec: 0:00:47.745361328 0xa0de50c0 gstamcvideodec.c:1307:gst_amc_video_dec_loop:<amcvideodec-omxqcomvideodecoderavc0> Frame is too late, dropping (deadline -0:00:00.007471923) 02-06 12:22:21.553 11698 11818 D GStreamer+amcvideodec: 0:00:47.746643067 0xa0de50c0 gstamcvideodec.c:1498:gst_amc_video_dec_loop:<amcvideodec-omxqcomvideodecoderavc0> Finished frame: ok 02-06 12:22:21.554 11698 11818 D GStreamer+amcvideodec: 0:00:47.746826172 0xa0de50c0 gstamcvideodec.c:1220:gst_amc_video_dec_loop:<amcvideodec-omxqcomvideodecoderavc0> Waiting for available output buffer 02-06 12:22:21.554 11698 11812 D GStreamer+amcvideodec: 0:00:47.747009278 0x9fd1d980 gstamcvideodec.c:2104:gst_amc_video_dec_handle_frame:<amcvideodec-omxqcomvideodecoderavc0> Handling frame 02-06 12:22:21.573 11698 11812 D GStreamer+amcvideodec: 0:00:47.766174318 0x9fd1d980 gstamcvideodec.c:2216:gst_amc_video_dec_handle_frame:<amcvideodec-omxqcomvideodecoderavc0> Queueing buffer 1: size 146355 time 31559600 flags 0x00000001 02-06 12:22:21.573 11698 11818 D GStreamer+amcvideodec: 0:00:47.766693117 0xa0de50c0 gstamcvideodec.c:1230:gst_amc_video_dec_loop:<amcvideodec-omxqcomvideodecoderavc0> dequeueOutputBuffer() returned 4 (0x4) 02-06 12:22:21.574 11698 11818 D GStreamer+amcvideodec: 0:00:47.766998292 0xa0de50c0 gstamcvideodec.c:1286:gst_amc_video_dec_loop:<amcvideodec-omxqcomvideodecoderavc0> Got output buffer at index 4: offset 0 size 2785280 time 31501400 flags 0x00000001 02-06 12:22:21.574 11698 11818 V GStreamer+amcvideodec: 0:00:47.767333986 0xa0de50c0 gstamcvideodec.c:1367:gst_amc_video_dec_loop new gl_sync 0xa02b5a80 result 0x9e77f0e0 02-06 12:22:21.574 11698 11818 V GStreamer+amcvideodec: 0:00:47.767486574 0xa0de50c0 gstamcvideodec.c:139:_gl_sync_ref gl_sync 0xa02b5a80 ref
My understanding of the problem is that if for any reason a hardware framecallback is missed, the gstamcvideodec.c 30ms timer kicks in. But as I have a 50fps file here, it's not fast enough. And it never manages to recover to the framecallback even after a replay (eos -> start again) of the video. I could try to replace the 30ms timer by 15ms but it's not a proper fix.
There are no missed callbacks missing around the time of the stutter. $ cat ~/tmp/log | awk '{$1=$3=$4=$5=$6=$8=$9=""; print $0}' | grep -e unsuccessfully 23:23:54.497 0:00:16.875213622 gl_sync 0xaed566b0 unsuccessfully waited for frame 3 23:23:54.500 0:00:16.878204346 gl_sync 0xaed566e0 unsuccessfully waited for frame 4 23:23:54.503 0:00:16.880859375 gl_sync 0xaed56650 unsuccessfully waited for frame 5 And $ cat ~/tmp/log | awk '{$1=$3=$4=$5=$6=$8=$9=""; print $0}' | grep -e on_frame_available 23:23:54.498 0:00:16.876800536 gl_sync 0xaed566e0 possible 'on_frame_available' listener miss detected, attempting to work around. Jumping forward 0 frames for frame 4 23:23:54.502 0:00:16.880004883 gl_sync 0xaed56650 possible 'on_frame_available' listener miss detected, attempting to work around. Jumping forward 0 frames for frame 5 And $ cat ~/tmp/log | awk '{$1=$3=$4=$5=$6=$8=$9=""; print $0}' | grep -e "frame 3 available" 23:23:54.499 0:00:16.877746582 frame 3 available $ cat ~/tmp/log | awk '{$1=$3=$4=$5=$6=$8=$9=""; print $0}' | grep -e "frame 4 available" 23:23:54.502 0:00:16.880645752 frame 4 available $ cat ~/tmp/log | awk '{$1=$3=$4=$5=$6=$8=$9=""; print $0}' | grep -e "frame 5 available" 23:23:54.504 0:00:16.882720947 frame 5 available So the missed frames do turn up a couple of ms later. Further investigation into the timing of the frames reveals that after the start of the jerkiness, the timings of the input/output of the frames takes a few (3-5) ms longer which I believe puts you over your frame budget of 20ms. As amcvideodec doesn't drop frames before decoding, if decoding suddenly takes 3-5ms longer, we will never be able to catch up. I'm not exactly sure where or why this occurs or who/what's suddenly taking the extra time but there's nothing wrong with the amcvideodec GL frame handling (which involves the listener). The slowdown could be any number of things: 1. Power management downclocking CPU/GPU/decoder 2. A stream change causes a different, more expensive code path to be used "somewhere" 3. Hardware is incapable of keeping up with your stream. (1440×1280×50)÷(1920×1080×30) = 1.481481481 which means you're pushing ~50% more bytes per second through than the more thoroughly tested 1080p@30 video streams. Unfortunately, this all requires careful deduction of all parameters to determine what the problem is which is unavailable without your exact setup.
Thanks for the thorough investigation. Nexus 7 2013 is rated to 1080p@30 so it's indeed pushing the hardware a little bit too far. It's working on Nexus 5x so you can close the bug if you want.