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

Wed Jul 20 20:10:23 UTC 2016

So, after having upgraded both my BE and my FE's to 0.28 and having to
upgrade from Ubuntu to Precise to do that, the FEs that used to work
wonderfully are having problems with some content.  I suspect it has to
do with size/resolution, but I have also noticed that some content at
the same resolution plays fine.  Maybe it's resolution and bit-rate, or
maybe it's something else.

FE hardware is an IOS/Atom so VDPAU is being used.

With the problem content, the frontend logs look like this:

Jul 20 10:28:56 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:1092 (TV) TV::TV(): Creating TV object
Jul 20 10:28:57 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythmainwindow.cpp:2951 (PauseIdleTimer) Suspending idle timer
Jul 20 10:28:57 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:1314 (Init) TV::Init(): Created TvPlayWindow.
Jul 20 10:28:57 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:2275 (HandleStateChange) TV::HandleStateChange(): Attempting to change from None to WatchingVideo
Jul 20 10:28:57 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext audioplayer.cpp:167 (ReinitAudio) AudioPlayer: Enabling Audio
Jul 20 10:28:58 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext avformatdecoder.cpp:2111 (ScanStreams) AFD: codec AAC has 2 channels
Jul 20 10:28:58 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext avformatdecoder.cpp:2600 (OpenAVCodec) AFD: Opened codec 0x989a4a0, id(AAC) type(Audio)
Jul 20 10:28:58 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext avformatdecoder.cpp:2600 (OpenAVCodec) AFD: Opened codec 0xabdea60, id(H264) type(Video)
Jul 20 10:28:58 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 20 10:28:58 pvr-lr mythfrontend.real: mythfrontend[1076]: W CoreContext audio/audiooutputalsa.cpp:775 (SetParameters) ALSA: Requested 500000us got 170666 buffer time
Jul 20 10:28:58 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/s
Jul 20 10:28:58 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext mythpainter_ogl.cpp:62 (ClearCache) Clearing OpenGL painter cache.
Jul 20 10:28:58 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext DisplayRes.cpp:162 (SwitchToVideo) Changing to 1920x1080 24.000 Hz
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext mythrender_vdpau.cpp:1751 (CreatePresentationSurfaces) VDPAU: Created 2 output surfaces.
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext mythrender_vdpau.cpp:429 (Create) VDPAU: Created VDPAU render device 1840x1031
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:520 (CheckExtraAudioDecode) Player(6): Forcing decode extra audio option on (Video method requires it).
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext osd.cpp:232 (OverrideUIScale) OSD: Base theme size: 1280x720
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext osd.cpp:234 (OverrideUIScale) OSD: Scaling factors: 1.4375x1.43056
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext osd.cpp:232 (OverrideUIScale) OSD: Base theme size: 1280x720
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext osd.cpp:234 (OverrideUIScale) OSD: Scaling factors: 1.4375x1.43056
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: E CoreContext mythplayer.cpp:2437 (VideoStart) Player(6): Video sync method can't support double framerate (refresh rate too low for 2x deint)
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext mythplayer.cpp:1793 (InitAVSync) Player(6): Video timing method: USleep with busy wait
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:5855 (StartPlayer) TV::StartPlayer(): Created player.
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:2532 (HandleStateChange) TV::HandleStateChange(): Changing from None to WatchingVideo
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:2632 (HandleStateChange) TV::HandleStateChange(): Main UI disabled.
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext tv_play.cpp:424 (StartTV) TV::StartTV(): Entering main playback loop.
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext screensaver-x11.cpp:149 (DisableDPMS) ScreenSaverX11Private: DPMS Deactivated 1
Jul 20 10:28:59 pvr-lr mythfrontend.real: mythfrontend[1076]: I CoreContext mythrender_vdpau.cpp:615 (CheckOutputSurfaces) VDPAU: Added 2 output surfaces (total 4, max 4)
Jul 20 10:29:06 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 102ms for video buffers AAAAAAAAAAAfff
Jul 20 10:29:06 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 204ms for video buffers AAAAAAAAAAAfff
Jul 20 10:29:13 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 102ms for video buffers fffAAAAAAAAAAA
Jul 20 10:29:14 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 204ms for video buffers fffAAAAAAAAAAA
Jul 20 10:29:14 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 102ms for video buffers AAAfAAAAAAAAAA
Jul 20 10:29:19 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 102ms for video buffers AAAfffAAAAAAAA
Jul 20 10:29:19 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 204ms for video buffers AAAfffAAAAAAAA
Jul 20 10:29:20 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 306ms for video buffers AAAfffAAAAAAAA
Jul 20 10:29:20 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 102ms for video buffers AAAAAAfffAAAAA
Jul 20 10:29:25 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 102ms for video buffers AAAAAAfffAAAAA
Jul 20 10:29:25 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 204ms for video buffers AAAAAAfffAAAAA
Jul 20 10:29:26 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 102ms for video buffers AAAAAAAfffAAAA
Jul 20 10:29:31 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 101ms for video buffers AAAAAAAAAfffAA
Jul 20 10:29:31 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 203ms for video buffers AAAAAAAAAfffAA
Jul 20 10:29:32 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 104ms for video buffers AAAAAAAAAAfffA
Jul 20 10:29:37 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 101ms for video buffers fAAAAAAAAAAAff
Jul 20 10:29:37 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 203ms for video buffers fAAAAAAAAAAAff
Jul 20 10:29:38 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 102ms for video buffers ffAAAAAAAAAAAf
Jul 20 10:29:43 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 102ms for video buffers AfffAAAAAAAAAA
Jul 20 10:29:43 pvr-lr mythfrontend.real: mythfrontend[1076]: N CoreContext mythplayer.cpp:2176 (PrebufferEnoughFrames) Player(6): Waited 204ms for video buffers AfffAAAAAAAAAA

The exact same file played via NFS from the BE plays perfectly fine
with mplayer so I know all of the hardware and interconnects are up to
snuff -- none of which have changed pre/post upgrade, and this content
played just fine with Trusty and 0.27-fixes.

So given that I know the pipeline from the BE to the FE all the way out
to the display are all working fine, as evidenced by mplayer playing
the exact same content, where do I start looking in MythTV for the
bottleneck?

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/20160720/be18f774/attachment.sig>