[mythtv-users] PVR150 changing channels PrebufferEnoughFrames issue in 0.25

Sat Apr 21 15:14:16 UTC 2012

I switched over from 0.24 to 0.25 and now when switching channels in the PVR150 source, the audio comes through first, then followed by the video about 4-5 seconds later. That's the best case scenario. The worst case is it crashes back to the main menu. 

Is this a configuration issue? I have a HDHomeRun as well and that has no issues switching channels. (although I have another issue where switching from HDHomeRun to the PVR150 will cause it to crash as well). In 0.24 this was not an issue, although there were sometimes when it crashes going into LiveTV. In 0.21 it was rock solid. So 0.25 is the least stable of all so far.

Any ideas? I've been updating nightly from mythupdates and it's still the same since the release.

I've tried various decoding playback options. Curently using Standard/vdpau but I've tried Standard/xv, etc.

Setup:

Mythbuntu 11.04 with 0.25 fixes 20120420

Revision: v0.25-51-g1a671d0

1 x Master Backend server (2 pvr150)
1 x Frontend/Secondary Backend (for hdhomerun)
1 x Frontend only

Mythtv logs:

Apr 21 11:08:23 svr2 mythfrontend[25127]: I CoreContext mythcorecontext.cpp:1178 (CheckProtoVersion) Using protocol version 72
Apr 21 11:08:23 svr2 mythfrontend[25127]: I CoreContext mythcorecontext.cpp:1178 (CheckProtoVersion) Using protocol version 72
Apr 21 11:08:23 svr2 mythfrontend[25127]: N CoreContext avformatdecoder.cpp:752 (SetEof) AFD: Resetting byte context eof (livetv 1 was eof 0)
Apr 21 11:08:23 svr2 mythfrontend[25127]: N CoreContext avformatdecoder.cpp:752 (SetEof) AFD: Resetting byte context eof (livetv 1 was eof 0)
Apr 21 11:08:24 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 102ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:24 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 205ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:24 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 307ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:24 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 409ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:24 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 512ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:24 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 614ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:24 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 716ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:24 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 818ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:25 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 920ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:25 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 1022ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:25 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 1125ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:25 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 1227ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:25 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 1330ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:25 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 1432ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:25 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 1534ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:25 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 1636ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:25 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 1738ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:25 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 1841ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:26 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 1943ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:26 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 2045ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:26 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 2147ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:26 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 2249ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:26 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 2351ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:26 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 2453ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:26 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 2555ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:26 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 2657ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:26 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 2759ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:26 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 2861ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:27 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 2963ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:27 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 3065ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:27 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 3167ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:27 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 3269ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:27 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 3371ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:27 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 3473ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:27 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 3576ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:27 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 3678ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:27 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 3779ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:27 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 3881ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:28 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 3983ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:28 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 4085ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:28 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 4187ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:28 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 4289ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:28 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 4392ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:28 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 4494ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:28 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 4596ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:28 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 4698ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:28 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 4800ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:28 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 4902ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:29 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 5004ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:29 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 5106ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:29 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 5208ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:29 svr2 mythfrontend[25127]: I Decoder ringbuffer.cpp:1091 (WaitForAvail) RingBuf(myth://192.168.1.5:6543/1037_20120421110821.mpg): Waited 0.2 seconds for data #012#011#011#011to become available... 0 < 32768
Apr 21 11:08:29 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 5310ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:29 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 5413ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:29 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 5514ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:29 svr2 mythfrontend[25127]: N CoreContext mythplayer.cpp:2079 (PrebufferEnoughFrames) Player(2): Waited 5617ms for video buffers AAAAAAAAAAAAAAAAAAAAAAAAAALf
Apr 21 11:08:29 svr2 mythfrontend[25127]: W Decoder avformatdecoder.cpp:4343 (GetFrame) AFD: Audio 4546 ms behind video but already 220 video frames queued. AV-Sync might be broken.

Apr 21 11:08:09 svr1 mythbackend[1204]: I ProcessRequest recorderbase.cpp:386 (GetKeyframePositions) RecBase(4:/dev/video1): GetKeyframePositions(16,9223372036854775807,#1) out of 2
Apr 21 11:08:20 svr1 mythbackend[1204]: I TVRecEvent tv_rec.cpp:3456 (TuningCheckForHWChange) TVRec(4): HW Tuner: 4->4
Apr 21 11:08:20 svr1 mythbackend[1204]: E DeviceReadBuffer DeviceReadBuffer.cpp:460 (Poll) DevRdB(/dev/video1): poll error
Apr 21 11:08:20 svr1 mythbackend[1204]: I TVRecEvent v4lchannel.cpp:661 (SetInputAndFormat) V4LChannel(/dev/video1): SetInputAndFormat(4, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
Apr 21 11:08:21 svr1 mythbackend[1204]: I ProcessRequest ringbuffer.cpp:1091 (WaitForAvail) RingBuf(/storage/livetv/1038_20120421110808.mpg): Waited 0.2 seconds for data #012#011#011#011to become available... 127016 < 131072
Apr 21 11:08:21 svr1 mythbackend[1204]: N CoreContext autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
Apr 21 11:08:21 svr1 mythbackend[1204]: N CoreContext autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
Apr 21 11:08:23 svr1 mythbackend[1204]: I ProcessRequest mainserver.cpp:1360 (HandleAnnounce) MainServer::ANN Playback
Apr 21 11:08:23 svr1 mythbackend[1204]: I ProcessRequest mainserver.cpp:1362 (HandleAnnounce) adding: svr2 as a client (events: 0)
Apr 21 11:08:23 svr1 mythbackend[1204]: I ProcessRequest mainserver.cpp:1475 (HandleAnnounce) MainServer::HandleAnnounce FileTransfer
Apr 21 11:08:23 svr1 mythbackend[1204]: I ProcessRequest mainserver.cpp:1477 (HandleAnnounce) adding: svr2 as a remote file transfer
Apr 21 11:08:23 svr1 mythbackend[1204]: I ProcessRequest recorderbase.cpp:386 (GetKeyframePositions) RecBase(4:/dev/video1): GetKeyframePositions(31,9223372036854775807,#1) out of 3