Opened 7 years ago

Closed 5 years ago

Last modified 4 years ago

#13223 closed Bug Report - General (Fixed)

ffmpeg 3.4 and VDPAU problem with some h264 videos

Reported by: Peter Bennett Owned by: Peter Bennett
Priority: minor Milestone: 31.0
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@… 7 years ago.
Log for hanging FE
trace.txt​ (32.9 KB) - added by warpme@… 7 years ago.
GDB trace for hanging fe
trace2.txt​ (32.9 KB) - added by warpme@… 7 years ago.
New gdb trace file with all threads
trace3.txt​ (64.7 KB) - added by warpme@… 7 years ago.
gdb trace with all threads
20180220_ffmpeg_ticket_13223.patch​ (1.4 KB) - added by Peter Bennett 7 years ago.
Proposed fix for lockout on VC1 video
fe-log2.txt​ (24.3 KB) - added by warpme@… 7 years ago.
log for FE with patch
trace4.txt​ (57.1 KB) - added by warpme@… 7 years ago.
trace for FE with patch
20180221_ffmpeg_ticket_13223.patch​ (1002 bytes) - added by Peter Bennett 7 years ago.
Second attempt patch for freeze when playing
comment7.log​ (30.1 KB) - added by Peter Bennett 7 years ago.
log from comment 7
comment15.log​ (17.1 KB) - added by Peter Bennett 7 years ago.
log file from comment 15

Download all attachments as: .zip

Change History (65)

comment:1 Changed 7 years ago by Peter Bennett

Description: modified (diff)

comment:2 Changed 7 years ago by Peter Bennett

Description: modified (diff)

comment:3 Changed 7 years ago by warpme@…

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

comment:4 Changed 7 years 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 7 years 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 7 years ago by Peter Bennett <pbennett@…>

Resolution: → fixed
Status: new → closed

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 7 years 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: 

2018-02-16 10:26:02.891117 I Setup Interrupt handler
2018-02-16 10:26:02.891277 I Setup Terminated handler
2018-02-16 10:26:02.891303 I Setup Segmentation fault handler
2018-02-16 10:26:02.891327 I Setup Aborted handler
2018-02-16 10:26:02.891351 I Setup Bus error handler
2018-02-16 10:26:02.891376 I Setup Floating point exception handler
2018-02-16 10:26:02.891400 I Setup Illegal instruction handler
2018-02-16 10:26:02.891429 I Setup Real-time signal 0 handler
2018-02-16 10:26:02.891462 I Setup User defined signal 1 handler
2018-02-16 10:26:02.891486 I Setup User defined signal 2 handler
2018-02-16 10:26:02.891509 I Setup Hangup handler
2018-02-16 10:26:02.891903 C mythfrontend version: master [v30-Pre-509-gc9857a9] www.mythtv.org
2018-02-16 10:26:02.891938 C Qt version: compile: 5.4.1, runtime: 5.4.1
2018-02-16 10:26:02.891985 N Enabled verbose msgs: general
2018-02-16 10:26:02.892054 N Setting Log Level to LOG_INFO
2018-02-16 10:26:02.903706 I Added logging to the console
2018-02-16 10:26:02.903832 N Using runtime prefix = /usr
2018-02-16 10:26:02.903852 N Using configuration directory = /home/minimyth/.mythtv
2018-02-16 10:26:02.904088 I Assumed character encoding: en_US.UTF-8
2018-02-16 10:26:02.910082 N Empty LocalHostName.
2018-02-16 10:26:02.910119 I Using localhost value of FE-Sleepingroom
2018-02-16 10:26:02.910329 I Start up testing connections. DB 192.168.1.254, BE , attempt 0, status dbAwake
2018-02-16 10:26:05.014598 N Setting QT default locale to pl_US
2018-02-16 10:26:05.014657 I Current locale pl_US
2018-02-16 10:26:05.014856 E No locale defaults file for pl_US, skipping
2018-02-16 10:26:05.015684 I Starting process manager
2018-02-16 10:26:05.015820 I Starting process signal handler
2018-02-16 10:26:05.018548 I Starting IO manager (read)
2018-02-16 10:26:05.018548 I Starting IO manager (write)
2018-02-16 10:26:05.066433 I ScreenSaverX11Private: XScreenSaver support enabled
2018-02-16 10:26:05.067630 I ScreenSaverX11Private: DPMS is disabled.
2018-02-16 10:26:05.119632 N Desktop video mode: 1920x1080 60.000 Hz
2018-02-16 10:26:05.467831 I Listening on TCP 0.0.0.0:6547
2018-02-16 10:26:05.474340 I Listening on TCP [::]:6547
2018-02-16 10:26:05.605178 I Loading pl translation for module mythfrontend
2018-02-16 10:26:05.612740 N Desktop video mode: 1920x1080 60.000 Hz
2018-02-16 10:26:05.675294 I Using 1920x1080 60.000 Hz
2018-02-16 10:26:05.675321 I SwitchToGUI: Switched to 1920x1080 60.000 Hz
2018-02-16 10:26:05.706896 I LIRC: Successfully initialized \'/dev/lircd\' using \'/home/minimyth/.mythtv/lircrc\' config
2018-02-16 10:26:05.707019 I UDPListener: Enabling
2018-02-16 10:26:05.710635 I Binding to UDP 0.0.0.0:6948
2018-02-16 10:26:05.710779 I Binding to UDP [::]:6948
2018-02-16 10:26:05.733520 I Using Frameless Window
2018-02-16 10:26:05.733531 I Using Full Screen Window
2018-02-16 10:26:05.771713 I UI Screen Resolution: 1920 x 1080
2018-02-16 10:26:05.787825 I OpenGL: Sync to VBlank is enabled (good!)
2018-02-16 10:26:05.863103 I Trying the OpenGL 2.0 render
2018-02-16 10:26:05.875579 I OpenGL painter using existing OpenGL context.
2018-02-16 10:26:05.919950 I OpenGL2: GLSL supported
2018-02-16 10:26:05.920099 I OpenGL: OpenGL vendor : NVIDIA Corporation
2018-02-16 10:26:05.920112 I OpenGL: OpenGL renderer: ION/PCIe/SSE2
2018-02-16 10:26:05.920123 I OpenGL: OpenGL version : 3.3.0 NVIDIA 340.106
2018-02-16 10:26:05.920140 I OpenGL: Max texture size: 8192 x 8192
2018-02-16 10:26:05.920151 I OpenGL: Max texture units: 4
2018-02-16 10:26:05.920162 I OpenGL: Direct rendering: Yes
2018-02-16 10:26:05.920198 I OpenGL: Extensions Supported: 1e3b
2018-02-16 10:26:05.920208 I OpenGL: PixelBufferObject support available
2018-02-16 10:26:05.924947 I OpenGL: Initialised MythRenderOpenGL
2018-02-16 10:26:05.934727 I MythUIHelper: Pruning cache directory: /home/minimyth/.mythtv/cache/remotecache is disabled
2018-02-16 10:26:05.934755 I MythUIHelper: Pruning cache directory: /home/minimyth/.mythtv/cache/thumbnails is disabled
2018-02-16 10:26:12.257324 I MythCoreContext::ConnectCommandSocket(): Connecting to backend server: 192.168.1.254:6543 (try 1 of 1)
2018-02-16 10:26:12.261344 I MythCoreContext::CheckProtoVersion(): Using protocol version 91 BuzzOff
2018-02-16 10:26:12.638234 W MythCookieJar::load() failed to open file for reading: /home/minimyth/.mythtv/MythBrowser/cookiejar.txt
2018-02-16 10:26:12.645985 I MythUIWebBrowser: Loading css from - file:///usr/share/mythtv/themes/default/htmls/mythbrowser.css
2018-02-16 10:26:12.653577 I MythUIWebBrowser: enabling plugins
2018-02-16 10:26:12.785983 I RAOP Device: Created RAOP device objects.
2018-02-16 10:26:12.786467 I Listening on TCP 0.0.0.0:5000
2018-02-16 10:26:12.786607 I Listening on TCP [::]:5000
2018-02-16 10:26:12.786676 I RAOP Device: Listening for connections on port 5000
2018-02-16 10:26:12.789569 I AirPlay: Created airplay objects.
2018-02-16 10:26:12.789949 I Listening on TCP 0.0.0.0:5100
2018-02-16 10:26:12.790092 I Listening on TCP [::]:5100
2018-02-16 10:26:12.797603 I Registering service 345e4e554c65@MythTV on FE-Sleepingroom._raop._tcp port 5000 TXT tp=UDPsm=falsesv=falseek=1et=0,1cn=0,1ch=2ss=16sr=44100pw=falsevn=3	txtvers=1md=0,1,2vs=115.2da=true am=MythTV,1
2018-02-16 10:26:12.807346 I Current MythTV Schema Version (DBSchemaVer): 1348
2018-02-16 10:26:13.615206 I Bonjour: Service registration complete: name \'MythTV on FE-Sleepingroom\' type \'_airplay._tcp.\' domain: \'local.\'
2018-02-16 10:26:13.652228 I Bonjour: Service registration complete: name \'345e4e554c65@MythTV on FE-Sleepingroom\' type \'_raop._tcp.\' domain: \'local.\'
2018-02-16 10:26:13.729667 W Key Alt+V is already bound to a jump point.
2018-02-16 10:26:13.735545 N Registering Internal as a media playback plugin.
2018-02-16 10:26:13.766973 N Registering WebBrowser as a media playback plugin.
2018-02-16 10:26:13.767216 I Loading pl translation for module mythbrowser
2018-02-16 10:26:13.782223 I Loading pl translation for module mythgame
2018-02-16 10:26:13.821386 I Current MythMusic Schema Version (MusicDBSchemaVer): 1024
2018-02-16 10:26:13.851707 I Loading pl translation for module mythmusic
2018-02-16 10:26:13.857096 I Loading pl translation for module mythnetvision
2018-02-16 10:26:13.867861 I Loading pl translation for module mythnews
2018-02-16 10:26:13.882729 I Loading pl translation for module mythweather
2018-02-16 10:26:13.896400 I Connecting to zm server: 192.168.1.254:6548 (try 1 of 2)
2018-02-16 10:26:14.900855 I Using protocol version 11
2018-02-16 10:26:14.950080 N Monitor: Salon (5) is using 3 bytes per pixel
2018-02-16 10:26:14.950587 I Loading pl translation for module mythzoneminder
2018-02-16 10:26:14.964111 I Listening on TCP 0.0.0.0:6546
2018-02-16 10:26:14.970509 I Listening on TCP [::]:6546
2018-02-16 10:26:15.164965 N Found mainmenu.xml for theme \'Default\'
2018-02-16 10:26:15.174142 I Registering HouseKeeperTask \'HardwareProfiler\'.
2018-02-16 10:26:15.185132 I Starting HouseKeeper.
2018-02-16 10:26:15.634528 I Bonjour: Service registration complete: name \'Mythfrontend on FE-Sleepingroom\' type \'_mythfrontend._tcp.\' domain: \'local.\'
2018-02-16 10:26:18.823586 I NetworkControl: New connection established.
2018-02-16 10:26:18.825622 N Verbose mask changed, new level is: general playback audio
2018-02-16 10:26:18.839983 I NetworkControl: Client Socket disconnected
2018-02-16 10:26:23.383218 I NetworkControl: New connection established.
2018-02-16 10:26:23.384784 N Verbose loglevel changed, new loglevel is: debug
2018-02-16 10:26:23.386138 I NetworkControl: Client Socket disconnected
2018-02-16 10:26:35.827342 D Using Folder mode
2018-02-16 10:26:44.278429 N Suspending idle timer
2018-02-16 10:26:44.278995 D MythCoreContext::SendReceiveStringList(): SendReceiveStringList(QUERY_FILE_EXISTS,Muzyczne/HD/ABBA - The Movie.mkv/VIDEO_TS...) called from UI thread
2018-02-16 10:26:44.280713 D MythCoreContext::SendReceiveStringList(): SendReceiveStringList(QUERY_FILE_EXISTS,Muzyczne/HD/ABBA - The Movie.mkv/BDMV...) called from UI thread
2018-02-16 10:26:44.302961 N Resuming idle timer
2018-02-16 10:26:46.596459 I TV::TV(): Creating TV object
2018-02-16 10:26:46.650849 I TV::TV(): Finished creating TV object
2018-02-16 10:26:46.650918 D TV::StartTV(): -- begin
2018-02-16 10:26:46.651013 N Suspending idle timer
2018-02-16 10:26:46.651042 D TV::Init(): -- begin
2018-02-16 10:26:46.655364 I TV::Init(): Created TvPlayWindow.
2018-02-16 10:26:46.656305 D TV::DrawUnusedRects(): -- begin
2018-02-16 10:26:46.656381 D TV::DrawUnusedRects(): -- end
2018-02-16 10:26:46.704245 D TV::Init(): -- end
2018-02-16 10:26:46.704324 D TV::StartTV(): tv->Playback() -- begin
2018-02-16 10:26:46.724030 D TV::HandleStateChange(): (0) -- begin
2018-02-16 10:26:46.724084 I TV::HandleStateChange(): Attempting to change from None to WatchingVideo
2018-02-16 10:26:46.727565 D MythCoreContext::SendReceiveStringList(): SendReceiveStringList(QUERY_FILE_EXISTS,Muzyczne/HD/ABBA - The Movie.mkv...) called from UI thread
2018-02-16 10:26:46.729227 I FileRingBuf(myth://Videos@mythtv/Muzyczne/HD/ABBA - The Movie.mkv): OpenFile(myth://Videos@mythtv/Muzyczne/HD/ABBA - The Movie.mkv, 2000 ms)
2018-02-16 10:26:46.730127 D PortChecker::checkPort(): host 192.168.1.254 port 6543 timeLimit 30000 linkLocalOnly 1
2018-02-16 10:26:46.734679 D PortChecker::checkPort(): host 192.168.1.254 port 6543 timeLimit 30000 linkLocalOnly 1
2018-02-16 10:26:46.744495 D TV::StartPlayer(): (0, WatchingVideo, main) -- begin
2018-02-16 10:26:46.744606 I TV::StartPlayer(): Elapsed time since TV constructor was called: 148 ms
2018-02-16 10:26:46.751088 D FilterManager: filters[adjust] = 0x3043bf0
2018-02-16 10:26:46.752299 D FilterManager: filters[bobdeint] = 0x5f84e80
2018-02-16 10:26:46.753842 D FilterManager: filters[crop] = 0x7c7d1f0
2018-02-16 10:26:46.755370 D FilterManager: filters[denoise3d] = 0x3050f10
2018-02-16 10:26:46.756575 D FilterManager: filters[fieldorderdoubleprocessdeint] = 0x3051080
2018-02-16 10:26:46.757638 D FilterManager: filters[forceyv12] = 0x304e750
2018-02-16 10:26:46.757672 D FilterManager: filters[forceyuv422p] = 0x63974e0
2018-02-16 10:26:46.757697 D FilterManager: filters[forcergb24] = 0x6397610
2018-02-16 10:26:46.757723 D FilterManager: filters[forceargb32] = 0x6397ff0
2018-02-16 10:26:46.759468 D FilterManager: filters[greedyhdeint] = 0x639a3c0
2018-02-16 10:26:46.759500 D FilterManager: filters[greedyhdoubleprocessdeint] = 0x639a590
2018-02-16 10:26:46.760706 D FilterManager: filters[invert] = 0x6399370
2018-02-16 10:26:46.761763 D FilterManager: filters[ivtc] = 0x639c040
2018-02-16 10:26:46.764197 D FilterManager: filters[kerneldeint] = 0x639bf10
2018-02-16 10:26:46.764236 D FilterManager: filters[kerneldoubleprocessdeint] = 0x639e2d0
2018-02-16 10:26:46.766047 D FilterManager: filters[linearblend] = 0x639eef0
2018-02-16 10:26:46.767220 D FilterManager: filters[onefield] = 0x639ff00
2018-02-16 10:26:46.768918 D FilterManager: filters[postprocess] = 0x63a3dd0
2018-02-16 10:26:46.770481 D FilterManager: filters[quickdnr] = 0x63a50d0
2018-02-16 10:26:46.771648 D FilterManager: filters[vflip] = 0x63a5340
2018-02-16 10:26:46.773693 D FilterManager: filters[yadifdeint] = 0x63a7160
2018-02-16 10:26:46.773732 D FilterManager: filters[yadifdoubleprocessdeint] = 0x63a7330
2018-02-16 10:26:46.843232 D PortChecker::checkPort(): host 192.168.1.254 port 6543 timeLimit 30000 linkLocalOnly 1
2018-02-16 10:26:46.848151 D PortChecker::checkPort(): host 192.168.1.254 port 6543 timeLimit 30000 linkLocalOnly 1
2018-02-16 10:26:47.009076 I ALSA: OpenDevice hdmi:CARD=NVidia,DEV=1
2018-02-16 10:26:47.019519 I AOS: Sample rate 32000 is supported
2018-02-16 10:26:47.019584 I AOS: Sample rate 44100 is supported
2018-02-16 10:26:47.019608 I AOS: Sample rate 48000 is supported
2018-02-16 10:26:47.019682 I AOS: Format signed 16 bit is supported
2018-02-16 10:26:47.019705 I AOS: Format signed 24 bit MSB is supported
2018-02-16 10:26:47.019721 I AOS: Format signed 32 bit is supported
2018-02-16 10:26:47.019775 I AOS: 2 channel(s) are supported
2018-02-16 10:26:47.020814 I ALSA: Successfully retrieved ELD data
2018-02-16 10:26:47.020947 I ELDUTILS: Detected monitor SAMSUNG at connection type HDMI
2018-02-16 10:26:47.020980 I ELDUTILS: available speakers: FL/FR
2018-02-16 10:26:47.021002 I ELDUTILS: max LPCM channels = 2
2018-02-16 10:26:47.021026 I ELDUTILS: max channels = 2
2018-02-16 10:26:47.021045 I ELDUTILS: supported codecs = LPCM
2018-02-16 10:26:47.021124 I ELDUTILS: supports coding type LPCM: channels = 2, rates = 32000 44100 48000, bits = 16 20 24
2018-02-16 10:26:47.084328 I AOS: may be AC3 or DTS capable
2018-02-16 10:26:47.084361 I AOS: 6 channel(s) are supported
2018-02-16 10:26:47.094711 N AudioPlayer: Enabling Audio
2018-02-16 10:26:47.140870 I AFD: PlayerFlags: 0xc0, AudioReadAhead: 100 msec
2018-02-16 10:26:47.140987 I Player(0): Stretch Factor 1, allow passthru 
2018-02-16 10:26:47.141029 D AFD: OpenFile -- begin
2018-02-16 10:26:47.142139 I AFD: Buffer size: 32768 streamed 0 seekable 1
2018-02-16 10:26:47.373365 I AFD: Stream #0, has id 0x0 codec id H264, type Video, bitrate 0 at 0x620be00
2018-02-16 10:26:47.373397 I AFD: Stream #1, has id 0x0 codec id DTS, type Audio, bitrate 1536000 at 0x61b99e0
2018-02-16 10:26:47.373419 I AFD: codec DTS has 6 channels
2018-02-16 10:26:47.373430 I AFD: Looking for decoder for DTS
2018-02-16 10:26:47.373788 I AFD: Opened codec 0x626cde0, id(DTS) type(Audio)
2018-02-16 10:26:47.373938 I AFD: Audio Track #1, of type (Normalny) is A/V stream #1 (id=0x0) and has 6 channels in the English language(6647399).
2018-02-16 10:26:47.373951 I AFD: Trying to select best video track
2018-02-16 10:26:47.374079 I AFD: Selected track #0 (id 0x0 codec id H264, type Video, bitrate 500000 at 0x620be00)
2018-02-16 10:26:47.381375 I VDP: Accepting: cmp() w(>=0) h(>=720) framerate() codecs() dec(vdpau) cpus(4) skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(enabled) deint(vdpaubasicdoublerate,vdpaubasic) filt(vdpaucolorspace=auto,vdpausharpen=1.0)
2018-02-16 10:26:47.381456 I VDP: Accepting: cmp() w() h() framerate() codecs() dec(vdpau) cpus(4) skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(enabled) deint(vdpauadvanceddoublerate,vdpauadvanced) filt(vdpaucolorspace=auto)
2018-02-16 10:26:47.381495 I VDP: LoadBestPreferences(1280x548, 0.000, h264)
2018-02-16 10:26:47.381615 I VDP: LoadBestPreferences Result prio:2, w:, h:, fps:, codecs:, decoder:vdpau, renderer:vdpau, deint:vdpauadvanceddoublerate
2018-02-16 10:26:47.381746 I VDPAU: Checking VDPAU support.
2018-02-16 10:26:47.898113 I VDPAU: Version 1
2018-02-16 10:26:47.898140 I VDPAU: Information NVIDIA VDPAU Driver Shared Library 340.106 Tue Jan 9 14:26:01 PST 2018
2018-02-16 10:26:47.898167 I VDPAU: HQ scaling level 1 of 9 available.
2018-02-16 10:26:47.898182 I VDPAU: MPEG4 hardware acceleration supported.
2018-02-16 10:26:47.898193 I VDPAU: HEVC hardware acceleration not supported.
2018-02-16 10:26:47.909878 I AFD: Using 1 CPUs for decoding
2018-02-16 10:26:47.909908 I AFD: InitVideoCodec() 0x8d39500 id(H264) type (Video).
2018-02-16 10:26:47.909956 I AFD: Selected FPS is 24 (avg 24 codec 0 container 1000 estimated 24)
2018-02-16 10:26:47.910013 I Player(0): SetFrameInterval ps:1 scan:3
2018-02-16 10:26:47.910053 I Player(0): detectInterlace(Detect Scan, Interlaced Scan, 24, 548) ->Interlaced Scan
2018-02-16 10:26:47.910081 D AFD: ScanATSCCaptionStreams() called with no PMT
2018-02-16 10:26:47.910097 I AFD: Using vdpau for video decoding
2018-02-16 10:26:47.910562 I AFD: Opened codec 0x8d39500, id(H264) type(Video)
2018-02-16 10:26:47.923937 I AFD: Selected track 1: English DCA 5.1ch (A/V Stream #1)
2018-02-16 10:26:47.924060 I AFD: Audio data is planar
2018-02-16 10:26:47.924151 I AFD: Initializing audio parms from audio track #1
2018-02-16 10:26:47.924211 I AFD: Audio format changed 
from id(NONE) -1Hz -1/-1ch -1bps (profile 0) to id( DTS) 48000Hz 6/6ch 32bps (profile 20)
2018-02-16 10:26:47.924256 I AOBase: Needs downmix from 6 -> 2 channels
2018-02-16 10:26:47.924277 I AOBase: Killing AudioOutputDSP
2018-02-16 10:26:47.924328 I AOBase: Original codec was DTS, 32 bit floating point, 48 kHz, 6 channels
2018-02-16 10:26:47.924372 I AOBase: enc(0), passthru(0), features () configured_channels(2), 2 channels supported(1) max_channels(2)
2018-02-16 10:26:47.924394 I AOBase: Audio processing enabled
2018-02-16 10:26:47.924424 I AOBase: Opening audio device \'hdmi:CARD=NVidia,DEV=1\' ch 2(6) sr 48000 sf signed 32 bit reenc 0
2018-02-16 10:26:47.924440 I ALSA: OpenDevice hdmi:CARD=NVidia,DEV=1
2018-02-16 10:26:47.931756 I ALSA: SetParameters(format=10, channels=2, rate=48000, buffer_time=500000, period_time=4)
2018-02-16 10:26:47.932150 I ALSA: Buffer size range from 32 to 65536
2018-02-16 10:26:47.932167 I ALSA: Period size range from 16 to 32768
2018-02-16 10:26:47.932247 I ALSA: Buffer time = 500000 us
2018-02-16 10:26:47.932305 I ALSA: Period time = 4 periods
2018-02-16 10:26:48.069342 I ALSA: Buffer size = 24000 | Period size = 6000
2018-02-16 10:26:48.219226 I AOBase: Audio fragment size: 24000
2018-02-16 10:26:48.219313 I AOBase: Audio Stretch Factor: 1
2018-02-16 10:26:48.219401 I AOBase: Ending Reconfigure()
2018-02-16 10:26:48.219451 I Dec: Selected track #1 (type 2) in the Unknown language(0)
2018-02-16 10:26:48.219478 I Dec: Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(0)
2018-02-16 10:26:48.219851 I AOBase: kickoffOutputAudioLoop: pid = 31119
2018-02-16 10:26:48.219922 I AOBase: OutputAudioLoop: Play Event
2018-02-16 10:26:48.230026 I Dec: SyncPositionMap prerecorded, from DB: 0 entries
2018-02-16 10:26:48.233841 I AFD: Recording has no position -- using libavformat seeking.
2018-02-16 10:26:48.234722 I AFD: Successfully opened decoder for file: "myth://Videos@mythtv/Muzyczne/HD/ABBA - The Movie.mkv". novideo(0)
2018-02-16 10:26:48.236978 I Using file start
2018-02-16 10:26:48.239728 I VideoOutput: Allowed renderers: vdpau
2018-02-16 10:26:48.239763 I VideoOutput: Allowed renderers (filt: vdpau): vdpau
2018-02-16 10:26:48.239995 I VDP: Accepting: cmp() w(>=0) h(>=720) framerate() codecs() dec(vdpau) cpus(4) skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(enabled) deint(vdpaubasicdoublerate,vdpaubasic) filt(vdpaucolorspace=auto,vdpausharpen=1.0)
2018-02-16 10:26:48.240074 I VDP: Accepting: cmp() w() h() framerate() codecs() dec(vdpau) cpus(4) skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(enabled) deint(vdpauadvanceddoublerate,vdpauadvanced) filt(vdpaucolorspace=auto)
2018-02-16 10:26:48.240108 I VDP: LoadBestPreferences(1280x548, 24.000, h264)
2018-02-16 10:26:48.240214 I VDP: LoadBestPreferences Result prio:2, w:, h:, fps:, codecs:, decoder:vdpau, renderer:vdpau, deint:vdpauadvanceddoublerate
2018-02-16 10:26:48.240239 I VideoOutput: Preferred renderer: vdpau
2018-02-16 10:26:48.240250 I VideoOutput: Trying video renderer: \'vdpau\'
2018-02-16 10:26:48.282919 D TV::DrawUnusedRects(): -- begin
2018-02-16 10:26:48.282952 D TV::DrawUnusedRects(): -- end
2018-02-16 10:26:48.301086 D ColourSpace: Brightness: -0.0400 Contrast: 1.0000 Saturation: 1.0000 Hue: 0.0000 StudioLevels: 0
2018-02-16 10:26:48.301142 D ColourSpace: 1.1644 0.0000 1.5972 -0.9213
2018-02-16 10:26:48.301187 D ColourSpace: 1.1644 -0.3916 -0.8128 0.4849
2018-02-16 10:26:48.301226 D ColourSpace: 1.1644 2.0184 0.0000 -1.1328
2018-02-16 10:26:48.301276 D ColourSpace: Brightness: -0.0400 Contrast: 1.1000 Saturation: 1.0000 Hue: 0.0000 StudioLevels: 0
2018-02-16 10:26:48.301319 D ColourSpace: 1.2808 0.0000 1.7569 -1.0088
2018-02-16 10:26:48.301363 D ColourSpace: 1.2808 -0.4308 -0.8941 0.5381
2018-02-16 10:26:48.301398 D ColourSpace: 1.2808 2.2202 0.0000 -1.2414
2018-02-16 10:26:48.301453 D ColourSpace: Brightness: -0.0400 Contrast: 1.1000 Saturation: 0.9000 Hue: 0.0000 StudioLevels: 0
2018-02-16 10:26:48.301497 D ColourSpace: 1.2808 0.0000 1.5812 -0.9206
2018-02-16 10:26:48.301540 D ColourSpace: 1.2808 -0.3877 -0.8047 0.4716
2018-02-16 10:26:48.301577 D ColourSpace: 1.2808 1.9982 0.0000 -1.1300
2018-02-16 10:26:48.301629 D ColourSpace: Brightness: -0.0400 Contrast: 1.1000 Saturation: 0.9000 Hue: 0.0000 StudioLevels: 0
2018-02-16 10:26:48.301671 D ColourSpace: 1.2808 0.0000 1.5812 -0.9206
2018-02-16 10:26:48.301714 D ColourSpace: 1.2808 -0.3877 -0.8047 0.4716
2018-02-16 10:26:48.301748 D ColourSpace: 1.2808 1.9982 0.0000 -1.1300
2018-02-16 10:26:48.301801 D ColourSpace: Brightness: -0.0400 Contrast: 1.1000 Saturation: 0.9000 Hue: 0.0000 StudioLevels: 1
2018-02-16 10:26:48.301843 D ColourSpace: 1.1000 0.0000 1.3890 -0.7372
2018-02-16 10:26:48.301883 D ColourSpace: 1.1000 -0.3406 -0.7069 0.4858
2018-02-16 10:26:48.301921 D ColourSpace: 1.1000 1.7553 0.0000 -0.9211
2018-02-16 10:26:48.321628 I VideoOutWindow::SetPIPState. pip_state: 0]
2018-02-16 10:26:48.321664 I Clearing OpenGL painter cache.
2018-02-16 10:26:48.533647 I Display Rect left: 0, top: 232, width: 1920, height: 616, aspect: 1.33333
2018-02-16 10:26:48.533681 I Video Rect left: 0, top: 0, width: 1280, height: 548, aspect: 2.33577
2018-02-16 10:26:48.533714 I VDP: LoadBestPreferences(1280x560, 24.000, h264)
2018-02-16 10:26:48.533866 I VDP: LoadBestPreferences Result prio:2, w:, h:, fps:, codecs:, decoder:vdpau, renderer:vdpau, deint:vdpauadvanceddoublerate
2018-02-16 10:26:48.533903 I Display Rect left: 0, top: 232, width: 1920, height: 616, aspect: 1.33333
2018-02-16 10:26:48.533928 I Video Rect left: 0, top: 0, width: 1280, height: 548, aspect: 2.33577
2018-02-16 10:26:48.533952 I VDP: SetVideoRenderer(vdpau)
2018-02-16 10:26:48.533968 I VDP: SetVideoRender(vdpau) == GetVideoRenderer()
2018-02-16 10:26:48.617356 I Trying to match best refresh rate 24.000Hz
2018-02-16 10:26:48.617400 I Changing to 1920x1080 23.971 Hz
2018-02-16 10:26:48.666310 I Dynamic TwinView rate found, set 23.9709Hz as XRandR 55
2018-02-16 10:26:48.981512 I SwitchToVideo: Video size 1280 x 548: 
Switched to displaying resolution 1920 x 1080, 650mm x 366mm
2018-02-16 10:26:48.981581 I Display Rect left: 0, top: 129, width: 1920, height: 822, aspect: 1.77778
2018-02-16 10:26:48.981625 I Video Rect left: 0, top: 0, width: 1280, height: 548, aspect: 2.33577
2018-02-16 10:26:48.981660 I VideoOutput: Pixel dimensions: Screen 1920x1080, window 1920x1080
2018-02-16 10:26:48.981699 I VideoOutput: Actual display dimensions: 650x366 mm Aspect: 1.77596
2018-02-16 10:26:48.981737 I VideoOutput: Estimated window dimensions: 650x366 mm Aspect: 1.77596
2018-02-16 10:26:49.131165 I VDPAU: Created 2 output surfaces.
2018-02-16 10:26:49.131322 I VDPAU: Set colorkey to 0x20202
2018-02-16 10:26:49.131352 I VDPAU: Created VDPAU render device 1920x1080
2018-02-16 10:26:49.144797 I VidOutVDPAU: Created VDPAU osd (1920x1080)
2018-02-16 10:26:49.284384 I ColourSpace: PictureAttributes: Brightness, Contrast, Colour, Hue, Studio Levels, 
2018-02-16 10:26:49.284408 I VidOutVDPAU: Using ITU BT.709 colorspace
2018-02-16 10:26:49.284462 D ColourSpace: Brightness: -0.0400 Contrast: 1.1000 Saturation: 0.9000 Hue: 0.0000 StudioLevels: 1
2018-02-16 10:26:49.284494 D ColourSpace: 1.1000 0.0000 1.5544 -0.8202
2018-02-16 10:26:49.284522 D ColourSpace: 1.1000 -0.1851 -0.4617 0.2847
2018-02-16 10:26:49.284548 D ColourSpace: 1.1000 1.8370 0.0000 -0.9621
2018-02-16 10:26:49.284605 I Display Rect left: 0, top: 129, width: 1920, height: 822, aspect: 1.77778
2018-02-16 10:26:49.284631 I Video Rect left: 0, top: 0, width: 1280, height: 548, aspect: 2.33577
2018-02-16 10:26:49.284646 I VidOutVDPAU: Created VDPAU context (GPU decode)
2018-02-16 10:26:49.291109 I Over/underscan. V: 0, H: 0
2018-02-16 10:26:49.291148 I Display Rect left: 0, top: 129, width: 1920, height: 822, aspect: 1.77778
2018-02-16 10:26:49.291175 I Video Rect left: 0, top: 0, width: 1280, height: 548, aspect: 2.33577
2018-02-16 10:26:49.291217 D Player(0): InitFilters() vo \'vdpaucolorspace=auto\' prog \'\' over \'\'
2018-02-16 10:26:49.291275 I FilterManager: GetFilterInfo(convert) returning: 0x0
2018-02-16 10:26:49.291312 I Player(0): LoadFilters(\'vdpaucolorspace=auto\'..) -> 0x0
2018-02-16 10:26:49.298313 I Player(0): Decoder thread starting.
2018-02-16 10:26:49.324531 I OSD: Loaded window osd_message
2018-02-16 10:26:49.339873 I OSD: Loaded window osd_input
2018-02-16 10:26:49.414433 I OSD: Loaded window program_info
2018-02-16 10:26:49.435686 I OSD: Loaded window browse_info
2018-02-16 10:26:49.465673 I OSD: Loaded window osd_status
2018-02-16 10:26:49.546056 I OSD: Loaded window osd_program_editor
2018-02-16 10:26:49.593452 I OSD: Loaded window osd_debug
2018-02-16 10:26:49.593510 I OSD: Loaded OSD: size 1920x1080 offset 0+0
2018-02-16 10:26:49.593847 I OSD: Created window aa_OSD_SUBTITLES
2018-02-16 10:26:49.597368 I EnableCaptions(32) msg: Napisy tekstowe WłÄ
cz
2018-02-16 10:26:49.597446 I Player(0): ClearAfterSeek(0)
2018-02-16 10:26:49.599762 I VDP: GetFilteredDeint() : vdpau -> \'vdpauadvanceddoublerate\'
2018-02-16 10:26:49.601493 I AOBase: OutputAudioLoop: Play Event
2018-02-16 10:26:49.602089 I VidOutVDPAU: Enabled deinterlacing.
2018-02-16 10:26:49.602289 E VSYNC: DRMVideoSync: VBlank ioctl did not work, unimplemented in this driver?
2018-02-16 10:26:49.602470 E VSYNC: RTCVideoSync: Could not open /dev/rtc: 
eno: No such file or directory (2)
2018-02-16 10:26:49.602576 E Player(0): Video sync method can\'t support double framerate (refresh rate too low for 2x deint)
2018-02-16 10:26:49.604639 I VDP: GetFilteredDeint(vdpauadvanced) : vdpau -> \'vdpauadvanced\'
2018-02-16 10:26:49.606501 I VidOutVDPAU: Enabled deinterlacing.
2018-02-16 10:26:49.614207 I Player(0): Video timing method: USleep with busy wait
2018-02-16 10:26:49.614244 I Player(0): Display Refresh Rate: 23.971 Video Frame Rate: 24.000
2018-02-16 10:26:49.614267 I Player(0): SetFrameInterval ps:1 scan:1
2018-02-16 10:26:49.614670 I playCtx: StartPlaying(): took 0 ms to start player.
2018-02-16 10:26:49.614711 I TV::StartPlayer(): Created player.
2018-02-16 10:26:49.614757 D TV::StartPlayer(): (0, WatchingVideo, main) -- end ok
2018-02-16 10:26:49.614793 I TV::HandleStateChange(): Changing from None to WatchingVideo
2018-02-16 10:26:49.615675 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-16 10:26:49.616050 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-16 10:26:49.616147 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-16 10:26:49.616195 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-16 10:26:49.616299 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-16 10:26:49.617135 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-16 10:26:49.617335 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-16 10:26:49.617441 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-16 10:26:49.617519 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-16 10:26:49.618846 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-16 10:26:49.618936 E AFD: video decode error: Invalid data found when processing input (0)
2018-02-16 10:26:49.618959 I AFD: SeekReset(0, 0, do flush, do discard)
2018-02-16 10:26:49.619055 I AFD: SeekReset() flushing
2018-02-16 10:26:49.619285 I VidOutVDPAU: DiscardFrames(1)
2018-02-16 10:26:49.619379 I VideoBuffers::DiscardFrames(1): AAAAAAAAAAAAAA
2018-02-16 10:26:49.619413 I VideoBuffers::DiscardFrames(1): AAAAAAAAAAAAAA -- done
2018-02-16 10:26:49.619440 I VidOutVDPAU: DiscardFrames() 3: AAAAAAAAAAAAAA -- done()
2018-02-16 10:26:49.619512 I AFD: Stream #0, has id 0x0 codec id H264, type Video, bitrate 0 at 0x620be00
2018-02-16 10:26:49.619539 I AFD: Stream #1, has id 0x0 codec id DTS, type Audio, bitrate 1536000 at 0x61b99e0
2018-02-16 10:26:49.619569 W AFD: Warning, audio codec 0x626cde0 id(DTS) type (Audio) already open, leaving it alone.
2018-02-16 10:26:49.619584 I AFD: codec DTS has 6 channels
2018-02-16 10:26:49.619603 I AFD: Looking for decoder for DTS
2018-02-16 10:26:49.619622 I AFD: Opened codec 0x626cde0, id(DTS) type(Audio)
2018-02-16 10:26:49.619691 I AFD: Audio Track #1, of type (Normalny) is A/V stream #1 (id=0x0) and has 6 channels in the English language(6647399).
2018-02-16 10:26:49.619711 I AFD: Trying to select best video track
2018-02-16 10:26:49.620012 I AFD: Selected track #0 (id 0x0 codec id H264, type Video, bitrate 500000 at 0x620be00)
2018-02-16 10:26:49.620347 I VDP: Accepting: cmp() w(>=0) h(>=720) framerate() codecs() dec(vdpau) cpus(4) skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(enabled) deint(vdpaubasicdoublerate,vdpaubasic) filt(vdpaucolorspace=auto,vdpausharpen=1.0)
2018-02-16 10:26:49.620495 I VDP: Accepting: cmp() w() h() framerate() codecs() dec(vdpau) cpus(4) skiploop(enabled) rend(vdpau) osd(vdpau) osdfade(enabled) deint(vdpauadvanceddoublerate,vdpauadvanced) filt(vdpaucolorspace=auto)
2018-02-16 10:26:49.620585 I VDP: LoadBestPreferences(1280x548, 0.000, h264)
2018-02-16 10:26:49.620712 I VDP: LoadBestPreferences Result prio:2, w:, h:, fps:, codecs:, decoder:vdpau, renderer:vdpau, deint:vdpauadvanceddoublerate
2018-02-16 10:26:49.620739 W AFD: Unsupported Video Profile, forcing software decode
2018-02-16 10:26:49.620770 I AFD: Using 4 CPUs for decoding
2018-02-16 10:26:49.620789 I AFD: InitVideoCodec() 0x7f11340b7ce0 id(H264) type (Video).
2018-02-16 10:26:49.620831 I Player(0): SetFrameInterval ps:1 scan:3
2018-02-16 10:26:49.620868 I VidOutVDPAU: InputChanged(1280,548,2.33577) \'H.264 VDPAU\'->\'H.264\'
2018-02-16 10:26:49.621989 I VidOutVDPAU: DiscardFrames(1)
2018-02-16 10:26:49.622050 I VideoBuffers::DiscardFrames(1): AAAAAAAAAAAAAA
2018-02-16 10:26:49.622096 I VideoBuffers::DiscardFrames(1): AAAAAAAAAAAAAA -- done
2018-02-16 10:26:49.622134 I VidOutVDPAU: DiscardFrames() 3: AAAAAAAAAAAAAA -- done()
2018-02-16 10:26:49.625091 D TV::DrawUnusedRects(): -- begin
2018-02-16 10:26:49.625131 D TV::DrawUnusedRects(): -- end
2018-02-16 10:26:49.625247 I TV::HandleStateChange(): Main UI disabled.
2018-02-16 10:26:49.625278 D TV::HandleStateChange(): (0) -- end
2018-02-16 10:26:49.626143 D TV::StartTV(): tv->Playback() -- end
2018-02-16 10:26:49.626318 I TV::StartTV(): Entering main playback loop.
2018-02-16 10:26:49.659578 W MythPainter: 40 images not yet de-allocated.
2018-02-16 10:26:49.659629 I VDPAU Painter: Clearing VDPAU painter cache.
2018-02-16 10:26:49.704568 D ScreenSaverX11Private: ResetTimer -- begin
2018-02-16 10:26:49.704600 D ScreenSaverX11Private: StopTimer
2018-02-16 10:26:49.708678 D ScreenSaverX11Private: StartTimer
2018-02-16 10:26:49.708750 D ScreenSaverX11Private: ResetTimer -- end
2018-02-16 10:26:49.729089 I Clearing OpenGL painter cache.

Version 0, edited 7 years ago by warpme@… (next)

comment:8 Changed 7 years ago by Peter Bennett

Resolution: fixed
Status: closed → new

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 7 years 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 7 years 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 7 years ago by warpme@…

Attachment: fe.log​ added

Log for hanging FE

Changed 7 years ago by warpme@…

Attachment: trace.txt​ added

GDB trace for hanging fe

comment:11 Changed 7 years 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 7 years 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 7 years ago by warpme@…

Attachment: trace2.txt​ added

New gdb trace file with all threads

comment:13 Changed 7 years 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 7 years 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 7 years ago by warpme@…

Attachment: trace3.txt​ added

gdb trace with all threads

comment:15 Changed 7 years 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 7 years ago by Peter Bennett (previous) (diff)

comment:16 Changed 7 years 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 7 years 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 7 years ago by Peter Bennett

Attachment: 20180220_ffmpeg_ticket_13223.patch​ added

Proposed fix for lockout on VC1 video

comment:18 Changed 7 years 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 7 years ago by warpme@…

Attachment: fe-log2.txt​ added

log for FE with patch

Changed 7 years ago by warpme@…

Attachment: trace4.txt​ added

trace for FE with patch

comment:19 Changed 7 years 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 7 years 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 7 years 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 7 years ago by Peter Bennett

Attachment: 20180221_ffmpeg_ticket_13223.patch​ added

Second attempt patch for freeze when playing

comment:22 Changed 7 years 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 7 years 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 7 years 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 7 years 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 7 years 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 7 years ago by Peter Bennett

Status: new → accepted

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

Changed 7 years ago by Peter Bennett

Attachment: comment7.log​ added

log from comment 7

Changed 7 years ago by Peter Bennett

Attachment: comment15.log​ added

log file from comment 15

comment:28 Changed 7 years ago by Peter Bennett

Owner: changed from Peter Bennett to Peter Bennett
Status: accepted → assigned

comment:29 Changed 6 years ago by Peter Bennett

Milestone: 30.0 → unknown

comment:30 Changed 6 years 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 6 years 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 6 years 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.

comment:33 Changed 6 years ago by tlathm

I'm curious as to the status of this one as well. Since upgrading to 30.0 I've run into a number of h264 videos that decode with no problem using xine but which need to revert to software in mythtv, which never happened to me in 29.1. A small example I was able to find is sample 7 under "3 Codecs, Framerates and Subtitles" here:

​https://kodi.wiki/view/Samples

That is:

​https://drive.google.com/file/d/0BwxFVkl63-lEbVptTVZ2NENURHM/view?usp=sharing

I'm aware of the issues with h265 etc, but was there a significant regression in h264 vdpau decoding support between 29.1 and 30.0? It sort of seems that way to me.

From what I'm seeing NVDEC may not even be supported on my GT 430 card. Thanks in advance.

comment:34 Changed 6 years ago by tlathm

Something else I should clarify: When I have these issues it always appears to be from errors regarding avcodec_send_packet, for example:

2019-05-17 10:37:09.222935 E [14504/28060] Decoder avformatdecoder.cpp:3785 (ProcessVideoPacket?) - AFD: video avcodec_send_packet error: Invalid data found when processing input (-1094995529) gotpicture:0

comment:35 Changed 6 years ago by tlathm

Here's a much better example. Again, in xine (Gentoo media-libs/xine-lib-1.2.9-r2 and media-video/ffmpeg-3.4.5) this uses vdpau just fine, but in mythtv falls back to software from those avcodec_send_packet errors:

​http://jell.yfish.us/media/jellyfish-60-mbps-hd-h264.mkv

Also note that just as a test, I had recompiled mythtv with SEQ_PKT_ERR_MAX increased from 10 to 500 and this still occurs, which tells me it's clearly failing every time.

comment:36 Changed 6 years ago by tlathm

I just realized something potentially important that I neglected to mention: In my case this is on a 32 bit x86 frontend. I suppose it's possible that could be a factor.

comment:37 Changed 6 years ago by Peter Bennett

I just tested this with MythTV version v30.0-51-ga32ec4bdea1. I do not see any issues with VDPAU Slim, using adapter card "NVIDIA Corporation GP108 [GeForce GT 1030]". Below are the results of "playback data" while playing these videos.

FPS_test_1080p50_L4.2.mkv 

1920x1080@50.00fps
H.264 vdpau
CPUs from 1% to 10%

jellyfish-60-mbps-hd-h264.mkv 

1020x1080@29.97fps
H.264 vdpau
CPUs from 0% to 6%

Send packet data errors you are seeing indicate that the decoder (in this case vdpau) thinks the data is invalid. I don't know why that would be the case.

comment:38 Changed 6 years ago by tlathm

Thanks for testing that. Wow...that's frustrating. Now I'm wondering if this isn't a 32 bit x86 specific issue.

comment:39 Changed 6 years ago by tlathm

I figured I'd at least summarize what I have, and have not figured out about these failures for future reference.

So far I haven't been able to correlate any specific similarities in the h264 videos that have this issue vs the ones that don't...for example the reported encoder, bit rates etc. I also have no idea why I'm experiencing this and you've not been able to reproduce it. I'm still waiting to see if others can reproduce the issue. Again, I'm on a 32 bit x86 system.

The specific decode errors causing this are as follows when I enable the playback and libav logging: 

2019-05-19 14:02:44.177296 E [1497/1564] Decoder avformatdecoder.cpp:350 (myth_av_log) - [h264 @ 0xb7396c80] Failed setup for format vdpau: hwaccel in itialisation returned error.
2019-05-19 14:02:44.177320 E [1497/1564] Decoder avformatdecoder.cpp:350 (myth_av_log) - [h264 @ 0xb7396c80] decode_slice_header error
2019-05-19 14:02:44.177335 E [1497/1564] Decoder avformatdecoder.cpp:350 (myth_av_log) - [h264 @ 0xb7396c80] no frame!
2019-05-19 14:02:44.177363 E [1497/1564] Decoder avformatdecoder.cpp:3785 (ProcessVideoPacket) - AFD: video avcodec_send_packet error: Invalid data found when processing input (-1094995529) gotpicture:0

The -1094995529 is an AVERROR_INVALIDDATA error.

The most perplexing part of this is the fact that the underlying vdpau as well as the nVidia card obviously can decode these, as they decode perfectly with vdpau using xine. The primary difference appears to be the fact that xine-libs still uses the old avcodec_decode_video2 call as did MythTV 29.1, and not the new separate calls (including the avcodec_send_packet that fails in this case). I strongly suspect I'd have no problems with these using 29.1 but I'd have to downgrade to be sure.

Thanks for the help with this!

comment:40 Changed 6 years ago by Peter Bennett

There is a newer version of ffmpeg in master version. If you feel inclined you could test it with master. Note that current master frontend will work with v30 backend. This is not guaranteed to be always the case.

comment:41 Changed 6 years ago by tlathm

Thanks! I'm not sure if I can do that too readily with my current setup, but I might. Another interesting thing to note that I just tested today: The problem videos can be decoded with vdpau using the command line ffmpeg (in my case media-video/ffmpeg-3.4.5) without issues...using for example: 

ffmpeg -hwaccel vdpau -i <filename> -f rawvideo -y /dev/null

Thanks again.

comment:42 Changed 6 years ago by tlathm

A few more additions to this: What especially struck me about the ffmpeg test above is the fact that the ffmpeg utility is in fact using the same avcodec_send_packet function that's failing for me in MythTV 30.0 for these videos. That test was with the ffmpeg-3.4.5 that's installed on my frontend.

That gave me the idea to try a few other tests. I downloaded the ffmpeg source for both version 4.0.2 (as is used in MythTV 30.0) as well as the newest stable 4.1.3 version. In both I did a configure and "make examples" in order to test the hw_decode.c under docs/examples...for example: 

hw_decode vdpau jellyfish-55-mbps-hd-h264.mkv out

That worked in both of those versions, and is also using avcodec_send_packet. Very odd. That would seem to rule out quite a bit. It seems as though there has to be something different about the raw data getting sent to that function in MythTV, though I can't imagine what.

Also note that I've now actually reverted to MythTV 29.1 and can confirm that all the problem videos play fine using vdpau decoding. At this point I'm just hoping that someone else will be able to duplicate this. If it happens to somehow be a 32-bit issue of some sort the odds might not be great.

comment:43 Changed 6 years ago by tlathm

Another user on the mailing list confirmed that he was able to reproduce this fallback to software decoding, and this was also on 32bit. Specifically it was on two ASRock ION 330HT systems running 18.04 Ubuntu 32bit and 16.04 Ubuntu 32bit respectively.

comment:44 Changed 5 years ago by dagnygren

Well. I don't know if it is the same problem, but I am running a 64-bit Zotac ION setup and also having trouble with some (a lot) x264 recordings. These played perfectly with hardware support using the Mythtv that used the old ffmpeg... I haven't tried your recordings though. Reverting to a working Mythtv seems to be undoable due to changes in the database :-(

PS! Had a look at the database scheme change between 1348 (for 0,29) and the current 1350 and noticed that there is very little change. One for HDHOMERUN device format (doesn't concern me) and then a deletion of a setting for AltClearSavedPosition? which I also could live without I think. Anyone having experience of just patching the database version down to 1348 to re-enable the working 0.29 frontend?

Last edited 5 years ago by dagnygren (previous) (diff)

comment:45 Changed 5 years ago by Peter Bennett

dagnygren - I don't know if this is the same problem, you have not described what you see. Please continue this conversation in the mailing list or forums, as this ticket is not the place to discuss database schema changes.

comment:46 Changed 5 years ago by Peter Bennett

Resolution: → Fixed
Status: assigned → closed

Closing this as it seems to be something particular to 32 bit systems, and I do not see any solution for that.

comment:47 Changed 5 years ago by dagnygren

Well. I started the whole report through warpme... By using his minimyth2 and reporting the problem.... Which can bee seen from my earlier comments.

And it is NOT a 32-bit only problem.

It is a bug in the upgraded ffmpeg library that will feed broken data to VDPAU. Seems to be triggered by on the fly format change in the stream.

And the bug is still there. Your workaround is fine on the systems with a CPU to support software decoding, but not on a low-performance ION, which will stutter and eventually crash. The real bug in ffmpeg is still there.

Last edited 5 years ago by dagnygren (previous) (diff)

comment:48 Changed 5 years ago by tlathm

dagnygren: Sorry I hadn't looked at this ticket recently. If you want to post to the mythtv users mailing list I can help with reverting that database schema. I did so in order to revert to 29.1...don't want to clutter this ticket.

It's interesting that you're having issues on 64 bit. If there's any chance you could try any of the tests I did above, it's possible you may find what I did. In my case it doesn't appear to be caused by the newer version of ffmpeg, but rather something about the MythTV change that replaced the old ffmpeg calls to avcodec_decode_video2 with the two calls including avcodec_send_packet. In my case, much newer versions of ffmpeg that I compiled ARE able to decode the problem videos using their hw_decode as a test, which also uses those newer calls.

comment:49 Changed 5 years ago by Mark Kendall

FYI - these files appear to play without issue on latest master following the render branch merge.

comment:50 Changed 5 years ago by tlathm

Thanks for the reply Mark...just noticed this today. However note that apparently nobody's been able to reproduce this issues on 64 bit systems. So unless someone tests this on 32 bit x86 I'm not sure it would tell us much. It would be great if that were the case. I've been staying on 29.1 for now but I'd hate to do that indefinitely. Thanks again!

comment:51 in reply to:  50 ; Changed 5 years ago by Mark Kendall

Replying to tlathm:

Thanks for the reply Mark...just noticed this today. However note that apparently nobody's been able to reproduce this issues on 64 bit systems. So unless someone tests this on 32 bit x86 I'm not sure it would tell us much. It would be great if that were the case. I've been staying on 29.1 for now but I'd hate to do that indefinitely. Thanks again!

Ah - missed the 32bit reference. I can't test on a 32bit system.

As discussed with warpme on irc, versions up to and including v30 used the old, deprecated VDPAU/FFmpeg API (some code was copied over from the previous FFmpeg versions to keep VDPAU decoding going).

V31/master now use the 'official' VDAPU FFmpeg API - and most of the decoding and rendering code is very different.

I can't do anything with this until someone actually does some testing on a problematic system (I think warpme has that in hand). That said - any fixes that may be required will not be backported.

comment:52 Changed 5 years ago by Stuart Auchterlonie

Milestone: unknown → 31.0

comment:53 Changed 5 years ago by warpme

Mark, I received 2 samples which are demonstrating problem on system with nvidia 340.108 and current master. Here are links:

​http://warped.inet2.org/sample_1080_slow_film.mkv

​http://warped.inet2.org/sample_1080_slow_fastdecode.mkv

may You pls try on Your nvidia 340 testbed?

comment:54 in reply to:  51 ; Changed 5 years ago by tlathm

Replying to mark-kendall:

Replying to tlathm: Ah - missed the 32bit reference. I can't test on a 32bit system.

As discussed with warpme on irc, versions up to and including v30 used the old, deprecated VDPAU/FFmpeg API (some code was copied over from the previous FFmpeg versions to keep VDPAU decoding going).

V31/master now use the 'official' VDAPU FFmpeg API - and most of the decoding and rendering code is very different.

I can't do anything with this until someone actually does some testing on a problematic system (I think warpme has that in hand). That said - any fixes that may be required will not be backported.

Maybe you could clarify something about the above changes: Version 30 did in fact include changes that replaced the old avcodec_decode_video2 with the two calls including avcodec_send_packet. I thought that the former (avcodec_decode_video2) in fact was the old deprecated API you're saying was in v30(?). Are the above changes in V31/master something else over and above that? Thanks!

comment:55 in reply to:  54 Changed 4 years ago by Mark Kendall

Replying to tlathm:

Replying to mark-kendall:

Maybe you could clarify something about the above changes: Version 30 did in fact include changes that replaced the old avcodec_decode_video2 with the two calls including avcodec_send_packet. I thought that the former (avcodec_decode_video2) in fact was the old deprecated API you're saying was in v30(?). Are the above changes in V31/master something else over and above that? Thanks!

The avcodec_decode_video2 change is not the API change I was referring to.

Previously FFmpeg's hardware acceleration was based around the use of AVCodecContext->hwaccel_context

This was replaced some time ago with the use of either AVCodecContext->hw_device_ctx or AVCodecContext->hw_frames_ctx.

The newer API is much more extensive and requires very different handling.

Note: See TracTickets for help on using tickets.