[mythtv-users] mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 102ms for video buffers AAAAAAAAAAAfff

Brian J. Murrell brian at interlinx.bc.ca
Mon Jul 25 11:22:58 UTC 2016 

On Thu, 2016-07-21 at 19:35 -0400, Peter Bennett wrote:
> 
>  
> Generally the VDPAU decoder is faster.

OK.  Good.  As I thought.

> 
>  However it is less forgiving. If
> there is something wrong with the video, Standard will work better.

But this video plays fine with mplayer using VDPAU, so that would rule
out problems with the video wouldn't it?

> 
> With modern
> processors, you don't really need VDPAU decoding, the system
> processor
> is more than up to the task.

This atom used about 2.2 out of 4 cores (i.e. 220% of 400% in top) but
still judders and produces:

Jul 22 10:22:37 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythmainwindow.cpp:2951 (PauseIdleTimer) Suspending idle timer
Jul 22 10:22:37 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:1092 (TV) TV::TV(): Creating TV object
Jul 22 10:22:37 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythmainwindow.cpp:2951 (PauseIdleTimer) Suspending idle timer
Jul 22 10:22:37 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:1314 (Init) TV::Init(): Created TvPlayWindow.
Jul 22 10:22:37 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:2275 (HandleStateChange) TV::HandleStateChange(): Attempting to change from None to WatchingVideo
Jul 22 10:22:38 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext audioplayer.cpp:167 (ReinitAudio) AudioPlayer: Enabling Audio
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext avformatdecoder.cpp:2111 (ScanStreams) AFD: codec AAC has 2 channels
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext avformatdecoder.cpp:2600 (OpenAVCodec) AFD: Opened codec 0x9652a60, id(AAC) type(Audio)
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext avformatdecoder.cpp:2600 (OpenAVCodec) AFD: Opened codec 0xa144400, id(H264) type(Video)
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext audio/audiooutputbase.cpp:809 (Reconfigure) AOBase: Opening audio device 'hdmi:CARD=NVidia,DEV=1' ch 2(2) sr 48000 sf signed 32 bit reenc 0
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: W CoreContext audio/audiooutputalsa.cpp:775 (SetParameters) ALSA: Requested 500000us got 170666 buffer time
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: W CoreContext audio/audiooutputalsa.cpp:243 (IncPreallocBufferSize) ALSA: Try to manually increase audio buffer with: echo 192 | sudo tee /proc/asound/card1/pcm7p/sub0/prealloc
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext mythpainter_ogl.cpp:62 (ClearCache) Clearing OpenGL painter cache.
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext DisplayRes.cpp:162 (SwitchToVideo) Using 1920x1080 24.000 Hz
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext mythrender_vdpau.cpp:1751 (CreatePresentationSurfaces) VDPAU: Created 2 output surfaces.
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext mythrender_vdpau.cpp:429 (Create) VDPAU: Created VDPAU render device 1840x1031
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext osd.cpp:232 (OverrideUIScale) OSD: Base theme size: 1280x720
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext osd.cpp:234 (OverrideUIScale) OSD: Scaling factors: 1.4375x1.43056
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext osd.cpp:232 (OverrideUIScale) OSD: Base theme size: 1280x720
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext osd.cpp:234 (OverrideUIScale) OSD: Scaling factors: 1.4375x1.43056
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext mythplayer.cpp:1793 (InitAVSync) Player(c): Video timing method: USleep with busy wait
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:5855 (StartPlayer) TV::StartPlayer(): Created player.
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:2532 (HandleStateChange) TV::HandleStateChange(): Changing from None to WatchingVideo
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:2632 (HandleStateChange) TV::HandleStateChange(): Main UI disabled.
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:424 (StartTV) TV::StartTV(): Entering main playback loop.
Jul 22 10:22:39 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext screensaver-x11.cpp:149 (DisableDPMS) ScreenSaverX11Private: DPMS Deactivated 1
Jul 22 10:22:40 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext mythrender_vdpau.cpp:615 (CheckOutputSurfaces) VDPAU: Added 2 output surfaces (total 4, max 4)
Jul 22 10:22:46 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 102ms for video buffers AAAA(af)(af)(af)(af)(lf)(af)(lf)ALAAAA           
Jul 22 10:22:46 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 205ms for video buffers AAAA(af)(af)(af)(af)(lf)(af)(lf)ALAAAA           
Jul 22 10:22:54 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 102ms for video buffers A(AL)AAAAA(af)f(af)fLfAALA           
Jul 22 10:22:54 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 204ms for video buffers A(AL)AAAAA(af)f(af)fLfAALA           
Jul 22 10:22:55 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 103ms for video buffers (lf)(AL)(lf)(af)(af)(af)A(af)AAAAAAfAA           
Jul 22 10:23:01 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 102ms for video buffers A(af)AAAA(AL)A(af)AfffLAfL           
Jul 22 10:23:01 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 204ms for video buffers A(af)AAAA(AL)A(af)AfffLAfL           
Jul 22 10:23:02 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 102ms for video buffers (af)(af)f(AL)(lf)(lf)A(af)AAAAAAAAA           
Jul 22 10:23:07 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 102ms for video buffers (AL)(af)A(AL)AA(af)AA(AL)(af)fAfAff           
Jul 22 10:23:08 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 204ms for video buffers (AL)(af)A(AL)AA(af)AA(AL)(af)fAfAff           
Jul 22 10:23:08 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 102ms for video buffers (af)(af)(af)(af)(af)f(AL)(AL)(AL)AAAAAAAA           
Jul 22 10:23:14 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 102ms for video buffers (af)(af)(AL)(af)AA(af)(AL)A(af)AAAfLAf           
Jul 22 10:23:14 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 204ms for video buffers (af)(af)(AL)(af)AA(af)(AL)A(af)AAAfLAf           
Jul 22 10:23:15 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 101ms for video buffers AA(af)(af)(af)(af)(af)(af)(lf)(AL)(AL)AAAAAA           
Jul 22 10:23:21 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 101ms for video buffers (lf)A(af)(af)(AL)(AL)A(af)A(af)AAAffAA           
Jul 22 10:23:21 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 203ms for video buffers (lf)A(af)(af)(AL)(AL)A(af)A(af)AAAffAA           
Jul 22 10:23:21 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 102ms for video buffers AAAAA(af)(af)(af)f(af)(lf)ALAALA           
Jul 22 10:23:28 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 101ms for video buffers (af)(AL)(lf)(AL)(af)(af)A(af)AAAAAAfAA           
Jul 22 10:23:28 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 204ms for video buffers (af)(AL)(lf)(AL)(af)(af)A(af)AAAAAAfAA           
Jul 22 10:23:28 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 102ms for video buffers A(AL)AAAAAAf(af)fLfAAfL           
Jul 22 10:23:34 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 101ms for video buffers (af)(af)(af)(af)(lf)(lf)(AL)(af)AAAAAAAAA           
Jul 22 10:23:34 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 203ms for video buffers (af)(af)(af)(af)(lf)(lf)(AL)(af)AAAAAAAAA           
Jul 22 10:23:35 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 102ms for video buffers A(af)AAAA(AL)A(af)AfffLAfL           
Jul 22 10:23:41 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 101ms for video buffers (af)(af)(af)(af)(af)(af)(af)(AL)(AL)(AL)AAAAAAA           
Jul 22 10:23:41 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 203ms for video buffers (af)(af)(af)(af)(af)(af)(af)(AL)(AL)(AL)AAAAAAA           
Jul 22 10:23:42 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 102ms for video buffers (AL)(af)A(AL)AA(af)AA(af)AfAfLAf           
Jul 22 10:23:48 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 101ms for video buffers AAA(af)(af)(af)(af)(af)(lf)(af)(AL)ALAAAA           
Jul 22 10:23:48 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(c): Waited 203ms for video buffers AAA(af)(af)(af)(af)(af)(lf)(af)(AL)ALAAAA           

Going back to VDPAU decoding, mythfrontend is using less than 20% (of
400%) of CPU.

As further validation of the hardware, O/S and other general
configuration, Kodi also plays this troublesome video just fine.  Less
than 15% of CPU used.

I'm having a hard time seeing how this is not a problem/bug with the
myth FE client at this point.

Cheers,
b.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 473 bytes
Desc: This is a digitally signed message part
URL: <http://lists.mythtv.org/pipermail/mythtv-users/attachments/20160725/b8961a61/attachment.sig>

More information about the mythtv-users mailing list