Opened 14 months ago

Last modified 3 months ago

#13223 assigned Bug Report - General

ffmpeg 3.4 and VDPAU problem with some h264 videos

Reported by: Peter Bennett Owned by: Peter Bennett
Priority: minor Milestone: unknown
Component: MythTV - Video Playback Version: Master Head
Severity: medium Keywords:
Cc: piotr.oniszczuk@… Ticket locked: no

Description (last modified by Peter Bennett)

Certain h264 mkv videos will not play on MythTV with the 3.4.1 ffmpeg version newly incorporated, when using VDPAU decoding. The log displays thousands of errors

2018-02-13 17:41:10.673987 E  AFD: video decode error: Invalid data found when processing input (0)

These videos play correctly with all other setups: Xvideo, OpenGL, Vaapi, OpenMax as well as Standard decoding coupled with VDPAU rendering.

Videos that fail

Attachments (10)

fe.log (57.7 KB) - added by warpme@… 14 months ago.
Log for hanging FE
trace.txt (32.9 KB) - added by warpme@… 14 months ago.
GDB trace for hanging fe
trace2.txt (32.9 KB) - added by warpme@… 14 months ago.
New gdb trace file with all threads
trace3.txt (64.7 KB) - added by warpme@… 14 months ago.
gdb trace with all threads
20180220_ffmpeg_ticket_13223.patch (1.4 KB) - added by Peter Bennett 14 months ago.
Proposed fix for lockout on VC1 video
fe-log2.txt (24.3 KB) - added by warpme@… 14 months ago.
log for FE with patch
trace4.txt (57.1 KB) - added by warpme@… 14 months ago.
trace for FE with patch
20180221_ffmpeg_ticket_13223.patch (1002 bytes) - added by Peter Bennett 14 months ago.
Second attempt patch for freeze when playing
comment7.log (30.1 KB) - added by Peter Bennett 14 months ago.
log from comment 7
comment15.log (17.1 KB) - added by Peter Bennett 14 months ago.
log file from comment 15

Download all attachments as: .zip

Change History (42)

comment:1 Changed 14 months ago by Peter Bennett

Description: modified (diff)

comment:2 Changed 14 months ago by Peter Bennett

Description: modified (diff)

comment:3 Changed 14 months ago by warpme@…

Peter, should I submit this as regression to upstream (ffmpeg bug tracker) or You already done this?

comment:4 Changed 14 months ago by Peter Bennett

I have a fix for MythTV that will revert to software decoding when that error occurs. For best results set the number of CPUs for decoding to 4 on the vdpau playback profile.

I did not submit an upstream bug report to ffmpeg. I searched and did not find a report already there. I do not have an example other than MythTV that shows the problem. They will probably want that.

comment:5 Changed 14 months ago by warpme@…

hmm. but if I can reproduce problem with mythffplay (which is ffplay essentially) - then I think this might be enough for ffmpeg guys. After all ffplay is simple player using ffmpeg libs and SDL2 painter....

comment:6 Changed 14 months ago by Peter Bennett <pbennett@…>

Resolution: fixed
Status: newclosed

In c9857a93f9bcfa2dfad39b0891f7f759a372504f/mythtv:

ffmpeg: Fix handling of stream changes and errors

If a stream cannot be decoded with hardware assist,
then try switching to software decoding.

If a stream cannot be software decoded, display an
error message to the user and stop playback.

Remove stream-change hacks for h264 that are no
longer necessary and are now causing a failure.

Fixes #13211
Fixes #13217
Fixes #13218
Fixes #13223

comment:7 Changed 14 months ago by warpme@…

Peter, FYI With this commit attempt to play sample3 cause my FE to hang with black screen. HW is ION2. FE log attached:

See attached file https://code.mythtv.org/trac/attachment/ticket/13223/comment7.log

Last edited 14 months ago by Peter Bennett (previous) (diff)

comment:8 Changed 14 months ago by Peter Bennett

Resolution: fixed
Status: closednew

Is that where the log ends, i.e. the screen is blank and the last log message is "Clearing OpenGL painter cache." ?

Can you test: Change the playback profile. Set the decoder to "standard" and leave the renderer as VDPAU. See if it will play that way.

If it still does not play that way see if it will play on any other profile, for example Slim.

Let me know the results of the tests.

comment:9 Changed 14 months ago by warpme@…

Peter,

Is that where the log ends, i.e. the screen is blank and the last log message is "Clearing OpenGL painter cache." ?

yes. this is last line. Pls see below another example of output when there was fall-back and fe hangs. It was for profile=standard; decoder=vdpau; renderer=vdpau; painter=OpenGL

Basically fe hangs with black screen as soon as I select vdpau decoder. Other playback profile settings doesn't matter. Also hang is only when painter is OpenGL. With Qt fall-back works OK.

2018-02-18 17:18:33.679553 I TV::TV(): Creating TV object
2018-02-18 17:18:33.721815 N Suspending idle timer
2018-02-18 17:18:33.722839 I TV::Init(): Created TvPlayWindow.
2018-02-18 17:18:33.797444 I TV::HandleStateChange(): Attempting to change from None to WatchingVideo
2018-02-18 17:18:34.058479 N AudioPlayer: Enabling Audio
2018-02-18 17:18:34.291357 I AFD: codec DTS has 6 channels
2018-02-18 17:18:34.291597 I AFD: Opened codec 0x685bc60, id(DTS) type(Audio)
2018-02-18 17:18:34.292510 I AFD: Opened codec 0x6682160, id(H264) type(Video)
2018-02-18 17:18:34.305615 I AOBase: Opening audio device \'iec958:CARD=Intel,DEV=0\' ch 2(6) sr 48000 sf signed 16 bit reenc 0
2018-02-18 17:18:34.308020 W ALSA: Requested 500000us got 341333 buffer time
2018-02-18 17:18:34.308227 W ALSA: Try to manually increase audio buffer with: echo 128 | sudo tee /proc/asound/card0/pcm1p/sub0/prealloc
2018-02-18 17:18:34.351959 I Clearing OpenGL painter cache.
2018-02-18 17:18:34.582097 I Changing to 1920x1080 23.971 Hz
2018-02-18 17:18:35.129826 I VDPAU: Created 2 output surfaces.
2018-02-18 17:18:35.129866 I VDPAU: Created VDPAU render device 1920x1080
2018-02-18 17:18:35.393102 I Player(1): Video timing method: USleep with busy wait
2018-02-18 17:18:35.394244 I TV::StartPlayer(): Created player.
2018-02-18 17:18:35.394329 I TV::HandleStateChange(): Changing from None to WatchingVideo
2018-02-18 17:18:35.395228 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-18 17:18:35.395558 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-18 17:18:35.395710 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-18 17:18:35.395768 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-18 17:18:35.395917 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-18 17:18:35.397919 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-18 17:18:35.398319 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-18 17:18:35.398737 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-18 17:18:35.398829 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-18 17:18:35.399414 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-18 17:18:35.399499 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-18 17:18:35.399690 W AFD: Warning, audio codec 0x685bc60 id(DTS) type (Audio) already open, leaving it alone.
2018-02-18 17:18:35.399707 I AFD: codec DTS has 6 channels
2018-02-18 17:18:35.399726 I AFD: Opened codec 0x685bc60, id(DTS) type(Audio)
2018-02-18 17:18:35.406919 I TV::HandleStateChange(): Main UI disabled.
2018-02-18 17:18:35.406983 I VDPAU Painter: Clearing VDPAU painter cache.
2018-02-18 17:18:35.407056 I TV::StartTV(): Entering main playback loop.
2018-02-18 17:18:35.506721 I Clearing OpenGL painter cache.

comment:10 Changed 14 months ago by Peter Bennett

I tried this with OpenGL1, OpenGL2 and QT theme painter and I do not see the problem.

Please can you run with -v playback and capture the log.

Is it compiled with patches? maybe they cause a problem in conjuntion with recent changes?

If I cannot find the problem from the log, it will be helpful to get a backtrace, from a version compiled without patches and with debug symbols. I will also need the full version (mythutil --version).

Changed 14 months ago by warpme@…

Attachment: fe.log added

Log for hanging FE

Changed 14 months ago by warpme@…

Attachment: trace.txt added

GDB trace for hanging fe

comment:11 Changed 14 months ago by warpme@…

Peter, Pls find log and trace for hanging FE. Playback was for sample3.mkv. FE is current master without MiniMyth2 patches.

comment:12 Changed 14 months ago by Peter Bennett

There is only 1 thread in your trace. There should be about 133 threads. Can you create it this way in gdb

set logging on
set pagination off
thread apply all bt full

That will create a file gdb.txt in the current directory with the full backtrace of all threads.

Please also tell me the version from running mythutil --version on the same build.

Thanks, and please keep up the testing, it is very helpful to ensure the quality of the next version.

Changed 14 months ago by warpme@…

Attachment: trace2.txt added

New gdb trace file with all threads

comment:13 Changed 14 months ago by warpme@…

argh - sorry. I looks I forgot about gdb commands.

mythutil reports: mythutil version: master [v30-Pre-512-g1278045] www.mythtv.org

comment:14 Changed 14 months ago by Peter Bennett

This is the same. It looks like you did not attach the gdb.txt file that was created? You can see it has only "Thread 1" listed, no others.

The way to do it is - first remove any prior gdb.txt file, then run

gdb mythfrontend
run

Then when it is hung, press Ctrl-C Then use the commands:

set logging on
set pagination off
thread apply all bt full

Then attach the gdb.txt file to the ticket. It should have many threads listed and about 5000 lines.

Changed 14 months ago by warpme@…

Attachment: trace3.txt added

gdb trace with all threads

comment:15 Changed 14 months ago by warpme@…

Peter, sorry. I had broken gdb. Now should be OK (trace has 45 threads). FE log for trace3.txt is following: FE version is master [v30-Pre-513-g3810d2f]

see attached file https://code.mythtv.org/trac/attachment/ticket/13223/comment15.log

Last edited 14 months ago by Peter Bennett (previous) (diff)

comment:16 Changed 14 months ago by warpme@…

Peter,

FYI I just build latest mplayer (svn38018) together with external provided ffmpeg3.4.2 sources and sample3.mkv plays OK. This tells me that issue with sample3.mkv playback under myth is probably related to way either:

a\ how we are calling ffmpeg vdpau api

b\ integration of ffmpeg3.4 within mythtv

just data point...

comment:17 Changed 14 months ago by Peter Bennett

One interesting fact - VDPAU on my system can play this VC1 video without failing over to software decode, but yours is failing over. Hoevere, even if I force mine to fail over I do not get the lockout.

The backtrace shows that there is a race condition where it is locking the OSD to check for end of recording while the video output is still being initialized.

I have created a patch. I am unable to recreate this error, so I cannot validate the patch. Please test this patch and let me know if it fixes the problem.

Changed 14 months ago by Peter Bennett

Proposed fix for lockout on VC1 video

comment:18 Changed 14 months ago by Peter Bennett

One thing that I am not sure about - your log shows VC1 video which is your Blu Ray Rip - that is sample 4 from ticket 13225 not sample 3 from this ticket. Which is the one that really is giving the problem? If sample 4 VC1 file then this should really be reported on ticket 13225.

Changed 14 months ago by warpme@…

Attachment: fe-log2.txt added

log for FE with patch

Changed 14 months ago by warpme@…

Attachment: trace4.txt added

trace for FE with patch

comment:19 Changed 14 months ago by warpme@…

Peter, Regarding Your comment #17 - sample3.mkv is H264 - not VC1. Probably You are referring to sample4.mkv - which is not for this ticket. Relevant to this ticket samples are only sample2.mkv and sample3.mkv.

Regarding Your comment #18: this is probably a little confusion. trace3 and log in command#15 were gathered for sample3.mkv.

Regarding Your patch: I added it, compile without any MiniMyth2 patches and try to play sample3.mkv.

Unfortunately issue is still the same.

FE log is attached fe-log2.txt.

GDB trace on hanging FE is attached trace4.txt.

Both gathered on v30-Pre-513-g3810d2f with patch applied.

comment:20 Changed 14 months ago by Peter Bennett

Piotr, it looks like maybe you are running without the patch.

If the patch was applied the version would show as v30-Pre-513-g3810d2f-dirty. Your version is showing as v30-Pre-513-g3810d2f in the log, which indicates that it is not patched.

Anyway, this trace is different and indicates that the patch would not work. I will work another way to fix it.

comment:21 Changed 14 months ago by warpme@…

Peter, log2/trace4 was for patched code. It is simply way I'm applying test patches: I do git checkout, patch code, configure, build, create PXE image, test. In this procedure git hash reported by myth is not reflecting patches I'm applying manually after git checkout...

Changed 14 months ago by Peter Bennett

Second attempt patch for freeze when playing

comment:22 Changed 14 months ago by Peter Bennett

Please try this patch instead.

When you test, please use -v playback option to give better information in the log. If you are running with gdb:

gdb mythfrontend
run -v playback

comment:23 Changed 14 months ago by warpme@…

Peter, with 20180221_ffmpeg_ticket_13223.patch it works! (I mean fallback to software decode). Thx for Your hard work.

BTW: I still believe we should have separate ticket for original issue reported in this ticket (I mean sample2/sample3 vdpau playback issue in ffmpeg3.4). After all fallback to software decode is (in case sample2/sample3) workaround - not root cause fix....

comment:24 in reply to:  16 Changed 14 months ago by Peter Bennett

Replying to warpme@…:

Peter,

FYI I just build latest mplayer (svn38018) together with external provided ffmpeg3.4.2 sources and sample3.mkv plays OK.

Can you be sure that mplayer is using vdpau and is not using software decode or failing over to software decode as we are? You can look at top and see the cpu usage to find if it is using software decode. If you compare that to cpu usage of MythTV using vdpau hardware decode (h264 video that plays in MythTV using vdpau without failing over to software), you can verify if mplayer is really using hardware decode.

comment:25 Changed 14 months ago by warpme@…

Eh my dear friend :-) I already verified this.

Here is output from player:

/root $ mplayer-svn -vo vdpau -vc ffh264vdpau /usr/local/share/sample3.mkv
MPlayer SVN-r38018-5.3.0 (C) 2000-2018 MPlayer Team

Playing /usr/local/share/sample3.mkv.
libavformat version 57.83.100 (external)
libavformat file format detected.
[lavf] stream 0: video (h264), -vid 0
[lavf] stream 1: audio (dca), -aid 0, -alang eng
VIDEO:  [H264]  1280x548  0bpp  24.000 fps    0.0 kbps ( 0.0 kbyte/s)
Could not find a UTF-8 locale,
character keys beyond Latin-1 will not be handled.
==========================================================================
Forced video codec: ffh264vdpau
Opening video decoder: [ffmpeg] FFmpeg's libavcodec codec family
libavcodec version 57.107.100 (external)
Selected video codec: [ffh264vdpau] vfm: ffmpeg (FFmpeg H.264 (VDPAU))
==========================================================================
Clip info:
 title: ABBA The Movie (1977)
 encoder: libebml v0.7.7 + libmatroska v0.8.1
 creation_time: 2008-01-17T09:06:58.000000Z
Load subtitles in /usr/local/share/
==========================================================================
Opening audio decoder: [ffmpeg] FFmpeg/libavcodec audio decoders
AUDIO: 48000 Hz, 6 ch, floatle, 1536.0 kbit/16.67% (ratio: 192000->1152000)
Selected audio codec: [ffdca] afm: ffmpeg (FFmpeg DTS)
==========================================================================
AO: [alsa] 48000Hz 2ch floatle (4 bytes per sample)
Starting playback...
Movie-Aspect is 2.34:1 - prescaling to correct movie aspect.
VO: [vdpau] 1280x548 => 1280x548 H.264 VDPAU acceleration
Movie-Aspect is 2.34:1 - prescaling to correct movie aspect.
VO: [vdpau] 1280x548 => 1280x548 H.264 VDPAU acceleration
A:  55.3 V:  55.3 A-V:  0.001 ct: -0.002   0/  0  1%  1%  3.9% 12 0

comment:26 Changed 14 months ago by Peter Bennett <pbennett@…>

In 8c1fe4e7ac0b3c3e7fbd9953f34e06cbb1b7ab4c/mythtv:

ffmpeg: Fix hang when playing certain videos with ION and VDPAU

Fix deadlock when freeing OpenGL resources if video is re-initialized
due to a change from hardware assist to software decode.

Refs #13223

comment:27 Changed 14 months ago by Peter Bennett

Status: newaccepted

I am keeping this ticket open to look into why hardware assist is not working for certain videos.

Changed 14 months ago by Peter Bennett

Attachment: comment7.log added

log from comment 7

Changed 14 months ago by Peter Bennett

Attachment: comment15.log added

log file from comment 15

comment:28 Changed 12 months ago by Peter Bennett

Owner: changed from Peter Bennett to Peter Bennett
Status: acceptedassigned

comment:29 Changed 4 months ago by Peter Bennett

Milestone: 30.0unknown

comment:30 Changed 3 months ago by dagnygren

Any news on this from the ffmpeg side ?

It is still a huge problem here with the Finnish HD TV broadcasts as they keep changing the format now and then in the stream. The fallback to Software decode works, but the ION I am using is not really up to the task and the result is a very choppy playback.

comment:31 Changed 3 months ago by Peter Bennett

For NVidia systems I am working on NVDEC as a replacement for VDPAU, since VDPAU is missing support for many of the latest standards. See #13357

comment:32 Changed 3 months ago by dagnygren

Thanks for that! But will NVDEC work on my ancient ION hardware ?

I am just also confused that the playback will fall back to software when playing back recordings, but will work fluently when watching LiveTV from the same HD channel ?

And if it is the change in format of the stream that makes ffmpeg fail, what prevents us from reopening the ffmpeg VDPAU decoder using the new format when it fails as it seems to be perfectly cabable of doing the decoding if you start at the right point?

If there is anything I can do to help, please let me know.

Note: See TracTickets for help on using tickets.