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

Wed Jul 20 22:21:26 UTC 2016

On 21 July 2016 5:40:23 AM ACST, "Brian J. Murrell" <brian at interlinx.bc.ca> wrote:
>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.
>
>
>------------------------------------------------------------------------
>
>_______________________________________________
>mythtv-users mailing list
>mythtv-users at mythtv.org
>http://lists.mythtv.org/mailman/listinfo/mythtv-users
>http://wiki.mythtv.org/Mailing_List_etiquette
>MythTV Forums: https://forum.mythtv.org

Couple of suggestions but nothing that particularly stands out. Firstly try running top on BE and FE during playback of problem file in case something stands out. Maybe iotop on BE too. Secondly try making a problem recording available directly to the FE rather than through the BE. I think mounting the recording storage folder on the FE at the same path as it is on the BE is sufficient although I have never tried. Might help narrow it down.

Actually first maybe test the network bandwidth between FE and BE using iperf and see if it is close to the files bitrate.

Are the recordings on local disks to the BE or network mounts? If network mounts maybe the path from NAS-BE-FE is enough to congest network but NAS-FE doesnt?