[mythtv-users] frontends starved to death

Thu Sep 1 00:23:52 UTC 2011

On Wed, Aug 31, 2011 at 1:07 PM, Tom Bongiorno <two.bits.11 at gmail.com>wrote:

> On Tue, Aug 30, 2011 at 9:54 PM, Tom Bongiorno <two.bits.11 at gmail.com>wrote:
>
>> Hello All,
>>
>> I am not sure what is going on with my setup, but I am having problems
>> where my frontends get starved for frames.  This almost always happens when
>> watching live TV, but I do see small recoverable starvations when watching
>> recorded content.  My setup is a fresh install on Mythbuntu 11.04 with Ron
>> Fraziers Ceton patch.  I have a gigabit network with a modern triple core
>> AMD backend and five Atom/ION frontends.  Below is an example output of my
>> logs.  For the record, I have no idea what my kids were watching, "My Wife
>> and Kids "Of Breasts and Basketball"", but channel 2033 is Nickelodeon so
>> keep it clean guys!  ;)
>>
>> -Tom
>>
>>
>> Backend version:
>> --------------------------
>> MythTV Version   : v0.24-243-g9ba3ece
>> MythTV Branch    : fixes/0.24
>> Network Protocol : 63
>> Library API      : 0.24.20101129-1
>> QT Version       : 4.7.2
>> Options compiled in:
>> linux debug using_alsa using_oss using_pulse using_pulseoutput
>> using_backend using_bindings_perl using_bindings_python using_dvb
>> using_firewire using_frontend using_hdhomerun using_ceton using_hdpvr
>> using_iptv using_ivtv using_joystick_menu using_lirc using_mheg
>> using_opengl_video using_opengl_vsync using_qtdbus using_qtwebkit using_v4l2
>> using_x11 using_xrandr using_xv using_bindings_perl using_bindings_python
>> using_mythtranscode using_opengl using_vdpau using_ffmpeg_threads using_live
>> using_mheg
>>
>> Frontend version:
>> --------------------------
>> MythTV Version   : v0.24.1-69-g515171d
>> MythTV Branch    : fixes/0.24
>> Network Protocol : 63
>> Library API      : 0.24.20110505-1
>> QT Version       : 4.7.2
>> Options compiled in:
>> linux debug using_alsa using_oss using_pulse using_pulseoutput
>> using_backend using_bindings_perl using_bindings_python using_dvb
>> using_firewire using_frontend using_hdhomerun using_hdpvr using_iptv
>> using_ivtv using_joystick_menu using_lirc using_mheg using_opengl_video
>> using_opengl_vsync using_qtdbus using_qtwebkit using_v4l using_x11
>> using_xrandr using_xv using_bindings_perl using_bindings_python
>> using_mythtranscode using_opengl using_vdpau using_ffmpeg_threads using_live
>> using_mheg
>>
>>
>> Backend log:
>> --------------------------
>> 2011-08-30 20:31:29.486 TVRec(8): HW Tuner: 8->8
>> 2011-08-30 20:31:29.543 LoadFromScheduler(): Error, called from backend.
>> 2011-08-30 20:31:29.556 AutoExpire: CalcParams(): Max required Free Space:
>> 3.0 GB w/freq: 7 min
>> 2011-08-30 20:31:29.729 Finished recording My Wife and Kids "Of Breasts
>> and Basketball": channel 2033
>> 2011-08-30 20:31:29.931 TVRec(8): RingBufferChanged()
>> 2011-08-30 20:31:29.959 MainServer::ANN Monitor
>> 2011-08-30 20:31:30.055 adding: mythtvbe1 as a client (events: 0)
>> 2011-08-30 20:31:30.063 MainServer::ANN Playback
>> 2011-08-30 20:31:30.098 MainServer::ANN Monitor
>> 2011-08-30 20:31:30.147 adding: mythtvfe4 as a client (events: 0)
>> 2011-08-30 20:31:30.206 adding: mythtvbe1 as a client (events: 1)
>> 2011-08-30 20:31:30.257 MainServer::HandleAnnounce FileTransfer
>>
>> Frontend log:
>> --------------------------
>> 2011-08-30 20:31:31.659 AFD: Resetting byte context eof (livetv 1 was eof
>> 0)
>> 2011-08-30 20:31:31.659 AFD: Resetting byte context eof (livetv 1 was eof
>> 0)
>> 2011-08-30 20:31:31.666 msg: On known multiplex...
>> 2011-08-30 20:31:31.763 Player(0): Waited 100ms for video buffers
>> AAAAAAAAAAAAAAAAA
>> ...
>> 2011-08-30 20:31:32.427 Player(0): Waited 100ms for video buffers
>> AAAAAAAAAAAAAAAAA
>> 2011-08-30 20:31:32.465 VDPAU Painter: Clearing VDPAU painter cache.
>> 2011-08-30 20:31:32.468 Player(0): Timed out waiting for frames, and
>>                        there are not enough free frames. Discarding
>> buffered frames.
>> 2011-08-30 20:31:32.491 MythPainter: 11 images not yet de-allocated.
>> 2011-08-30 20:31:32.574 Clearing OpenGL painter cache.
>> 2011-08-30 20:31:32.632 VDPAU: Created 2 output surfaces.
>> 2011-08-30 20:31:32.633 VDPAU: Created VDPAU render device 1280x720
>> 2011-08-30 20:31:32.752 Player(0): Forcing decode extra audio option on
>> (Video method requires it).
>> 2011-08-30 20:31:32.752 AFD: Opened codec 0x95e4e10, id(MPEG2VIDEO)
>> type(Video)
>> 2011-08-30 20:31:32.752 AFD: codec AC3 has 0 channels
>> 2011-08-30 20:31:32.754 AFD: Opened codec 0x9700560, id(AC3) type(Audio)
>> 2011-08-30 20:31:32.755 [mpegvideo_vdpau @
>> 0x5caeae0]mpeg_decode_postinit() failure
>> 2011-08-30 20:31:32.755 AFD Error: Unknown decoding error
>> 2011-08-30 20:31:32.755 [mpegvideo_vdpau @
>> 0x5caeae0]mpeg_decode_postinit() failure
>> 2011-08-30 20:31:32.755 AFD Error: Unknown decoding error
>> 2011-08-30 20:31:32.756 [mpegvideo_vdpau @
>> 0x5caeae0]mpeg_decode_postinit() failure
>> 2011-08-30 20:31:32.756 AFD Error: Unknown decoding error
>> 2011-08-30 20:31:32.784 Player(0): Waited 100ms for video buffers
>> AAAAAAAAAAAAAAAAA
>> ...
>> 2011-08-30 20:31:32.808 Player(0): Waited 100ms for video buffers
>> AAAAAAAAAAAAAAAAA
>> 2011-08-30 20:31:32.812 VDPAU Painter: Clearing VDPAU painter cache.
>> 2011-08-30 20:31:32.813 Player(0): Timed out waiting for frames, and
>>                        there are not enough free frames. Discarding
>> buffered frames.
>> 2011-08-30 20:31:32.839 Clearing OpenGL painter cache.
>> 2011-08-30 20:31:32.917 VDPAU: Created 2 output surfaces.
>> 2011-08-30 20:31:32.918 VDPAU: Created VDPAU render device 1280x720
>> 2011-08-30 20:31:33.026 Player(0): Forcing decode extra audio option on
>> (Video method requires it).
>> 2011-08-30 20:31:33.040 Player(0): Waited 100ms for video buffers
>> AAAAAAAAAAALAAAAA
>> ...
>> 2011-08-30 20:31:33.058 Player(0): Waited 100ms for video buffers
>> AAAAAAAAAAALAAAAA
>> 2011-08-30 20:31:33.096 VDPAU: Added 2 output surfaces (total 4, max 4)
>> 2011-08-30 20:31:33.300 Player(0): Waited 100ms for video buffers
>> AAAAfAAALAAfAAAAA
>> ...
>> 2011-08-30 20:31:34.125 Player(0): Waited 100ms for video buffers
>> AfAAAAAAfAAALAAAA
>>
>
> I forgot the following line at the end of the backend log:
>
> 2011-08-30 20:31:30.356 adding: mythtvfe4 as a remote file transfer
>
> I am going to do some more testing tonight, but I have a gut feeling it is
> related to the events below.  There may be something bad happening when
> transitioning from one temporary live TV recording buffer to the next.  This
> may explain why I only see it on live TV.
>
> -Tom
>
>
> Backend log:
> --------------------------
> 2011-08-30 20:31:29.486 TVRec(8): HW Tuner: 8->8
> 2011-08-30 20:31:29.556 AutoExpire: CalcParams(): Max required Free Space:
> 3.0 GB w/freq: 7 min
> 2011-08-30 20:31:29.729 Finished recording My Wife and Kids "Of Breasts and
> Basketball": channel 2033
> 2011-08-30 20:31:29.931 TVRec(8): RingBufferChanged()
> 2011-08-30 20:31:30.257 MainServer::HandleAnnounce FileTransfer
>  2011-08-30 20:31:30.356 adding: mythtvfe4 as a remote file transfer
>
>
> Frontend log:
> --------------------------
> 2011-08-30 20:31:31.659 AFD: Resetting byte context eof (livetv 1 was eof
> 0)
> 2011-08-30 20:31:32.468 Player(0): Timed out waiting for frames, and
>                        there are not enough free frames. Discarding
> buffered frames.
>

I have tested my theory multiple times tonight.  It is very repeatable and
always happens on a 30 minute boundary.  The frontend events vary slightly,
but the backend logs always contain the same events.  It is always triggered
by swapping out the temporary recording buffer for live TV.  There is also
that "LoadFromScheduler(): Error, called from backend." that I often see,
but am not sure if it is related to this problem.

Does anyone have any ideas what might cause this type of problem?

-Tom

Backend log:
--------------------------
2011-08-31 19:30:00.189 LoadFromScheduler(): Error, called from backend.
2011-08-31 19:30:00.197 AutoExpire: CalcParams(): Max required Free Space:
3.0 GB w/freq: 14 min
2011-08-31 19:30:00.310 Finished recording SpongeBob SquarePants "Sandy's
Rocket; Squeaky Boots": channel 2033
2011-08-31 19:30:01.350 TVRec(8): RingBufferChanged()
2011-08-31 19:30:01.927 MainServer::HandleAnnounce FileTransfer
2011-08-31 19:30:02.018 adding: mythtvfe4 as a remote file transfer

Frontend log:
--------------------------
2011-08-31 19:30:02.194 AFD: Resetting byte context eof (livetv 1 was eof 0)
2011-08-31 19:30:02.650 RingBuf(myth://
192.168.1.100:6543/2033_20110831193000.mpg): Checking to see if there's a
new livetv program to switch to..
2011-08-31 19:30:02.661 RingBuf(myth://
192.168.1.100:6543/2033_20110831193000.mpg): RingBuffer::Reset() nonzero
readpos.  toAdjust: 1 readpos: 64632 readAdjust: 112558984
2011-08-31 19:30:02.661 AFD: Resetting byte context eof (livetv 1 was eof 1)
2011-08-31 19:30:02.662 [ac3 @ 0x5caeae0]incomplete frame
2011-08-31 19:30:03.943 ALSA, Error: WriteAudio: buffer underrun
2011-08-31 19:30:04.035 Player(1): Waited 100ms for video buffers
AAAAAAfAAAAAAALAA
...
2011-08-31 19:30:23.899 Player(1): Waited 100ms for video buffers
AAAAAAfAAAAAAALAA
2011-08-31 19:30:23.935 Player(1), Error: Waited too long for decoder to
fill video buffers. Exiting..
2011-08-31 19:30:24.052 TV: Attempting to change from WatchingLiveTV to None
2011-08-31 19:30:24.103 VDPAU Painter: Clearing VDPAU painter cache.
2011-08-31 19:30:24.140 MythPainter: 1 images not yet de-allocated.
2011-08-31 19:30:24.462 TV: Changing from WatchingLiveTV to None
2011-08-31 19:30:24.516 TV: Attempting to change from None to WatchingLiveTV
2011-08-31 19:30:24.517 MythCoreContext: Connecting to backend server:
192.168.1.100:6543 (try 1 of 1)
2011-08-31 19:30:24.518 Using protocol version 63
2011-08-31 19:30:24.647 Spawning LiveTV Recorder -- begin
2011-08-31 19:30:24.925 Spawning LiveTV Recorder -- end
2011-08-31 19:30:24.946 We have a playbackURL(myth://
192.168.1.100:6543/2033_20110831193024.mpg) & cardtype(DUMMY)
2011-08-31 19:30:24.948 We have a RingBuffer
2011-08-31 19:30:24.951 TV Error: LiveTV not successfully started
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://www.mythtv.org/pipermail/mythtv-users/attachments/20110831/c4c9bf4d/attachment-0001.html 