On Wed, Aug 31, 2011 at 1:07 PM, Tom Bongiorno <span dir="ltr"><<a href="mailto:two.bits.11@gmail.com">two.bits.11@gmail.com</a>></span> wrote:<br><div class="gmail_quote"><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex;">
<div><div></div><div class="h5"><div class="gmail_quote">On Tue, Aug 30, 2011 at 9:54 PM, Tom Bongiorno <span dir="ltr"><<a href="mailto:two.bits.11@gmail.com" target="_blank">two.bits.11@gmail.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Hello All,<br><br>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! ;)<div>
<br></div><div>-Tom<br><div><br><br>Backend version:<div>--------------------------<br>MythTV Version : v0.24-243-g9ba3ece<br>MythTV Branch : fixes/0.24<br>Network Protocol : 63<br>Library API : 0.24.20101129-1<br>
QT Version : 4.7.2<br>Options compiled in:<br> 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<br>
<br>Frontend version:<br>--------------------------</div><div>MythTV Version : v0.24.1-69-g515171d<br>MythTV Branch : fixes/0.24<br>Network Protocol : 63<br>Library API : 0.24.20110505-1<br>QT Version : 4.7.2<br>
Options compiled in:<br> 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<br>
<br><br>Backend log:<br>--------------------------</div><div>2011-08-30 20:31:29.486 TVRec(8): HW Tuner: 8->8<br>2011-08-30 20:31:29.543 LoadFromScheduler(): Error, called from backend.<br>2011-08-30 20:31:29.556 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 7 min<br>
2011-08-30 20:31:29.729 Finished recording My Wife and Kids "Of Breasts and Basketball": channel 2033<br>2011-08-30 20:31:29.931 TVRec(8): RingBufferChanged()<br>2011-08-30 20:31:29.959 MainServer::ANN Monitor<br>
2011-08-30 20:31:30.055 adding: mythtvbe1 as a client (events: 0)<br>2011-08-30 20:31:30.063 MainServer::ANN Playback<br>2011-08-30 20:31:30.098 MainServer::ANN Monitor<br>2011-08-30 20:31:30.147 adding: mythtvfe4 as a client (events: 0)<br>
2011-08-30 20:31:30.206 adding: mythtvbe1 as a client (events: 1)<br>2011-08-30 20:31:30.257 MainServer::HandleAnnounce FileTransfer<br><br>Frontend log:<br>--------------------------</div><div>2011-08-30 20:31:31.659 AFD: Resetting byte context eof (livetv 1 was eof 0)<br>
2011-08-30 20:31:31.659 AFD: Resetting byte context eof (livetv 1 was eof 0)<br>2011-08-30 20:31:31.666 msg: On known multiplex...<br>2011-08-30 20:31:31.763 Player(0): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA<br>
...<br>2011-08-30 20:31:32.427 Player(0): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA<br>2011-08-30 20:31:32.465 VDPAU Painter: Clearing VDPAU painter cache.<br>2011-08-30 20:31:32.468 Player(0): Timed out waiting for frames, and<br>
there are not enough free frames. Discarding buffered frames.<br>2011-08-30 20:31:32.491 MythPainter: 11 images not yet de-allocated.<br>2011-08-30 20:31:32.574 Clearing OpenGL painter cache.<br>2011-08-30 20:31:32.632 VDPAU: Created 2 output surfaces.<br>
2011-08-30 20:31:32.633 VDPAU: Created VDPAU render device 1280x720<br>2011-08-30 20:31:32.752 Player(0): Forcing decode extra audio option on (Video method requires it).<br>2011-08-30 20:31:32.752 AFD: Opened codec 0x95e4e10, id(MPEG2VIDEO) type(Video)<br>
2011-08-30 20:31:32.752 AFD: codec AC3 has 0 channels<br>2011-08-30 20:31:32.754 AFD: Opened codec 0x9700560, id(AC3) type(Audio)<br>2011-08-30 20:31:32.755 [mpegvideo_vdpau @ 0x5caeae0]mpeg_decode_postinit() failure<br>
2011-08-30 20:31:32.755 AFD Error: Unknown decoding error<br>
2011-08-30 20:31:32.755 [mpegvideo_vdpau @ 0x5caeae0]mpeg_decode_postinit() failure<br>2011-08-30 20:31:32.755 AFD Error: Unknown decoding error<br>2011-08-30 20:31:32.756 [mpegvideo_vdpau @ 0x5caeae0]mpeg_decode_postinit() failure<br>
2011-08-30 20:31:32.756 AFD Error: Unknown decoding error<br>2011-08-30 20:31:32.784 Player(0): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA<br>...<br>2011-08-30 20:31:32.808 Player(0): Waited 100ms for video buffers AAAAAAAAAAAAAAAAA<br>
2011-08-30 20:31:32.812 VDPAU Painter: Clearing VDPAU painter cache.<br>2011-08-30 20:31:32.813 Player(0): Timed out waiting for frames, and<br> there are not enough free frames. Discarding buffered frames.<br>
2011-08-30 20:31:32.839 Clearing OpenGL painter cache.<br>2011-08-30 20:31:32.917 VDPAU: Created 2 output surfaces.<br>2011-08-30 20:31:32.918 VDPAU: Created VDPAU render device 1280x720<br>2011-08-30 20:31:33.026 Player(0): Forcing decode extra audio option on (Video method requires it).<br>
2011-08-30 20:31:33.040 Player(0): Waited 100ms for video buffers AAAAAAAAAAALAAAAA<br>...<br>2011-08-30 20:31:33.058 Player(0): Waited 100ms for video buffers AAAAAAAAAAALAAAAA<br>2011-08-30 20:31:33.096 VDPAU: Added 2 output surfaces (total 4, max 4)<br>
2011-08-30 20:31:33.300 Player(0): Waited 100ms for video buffers AAAAfAAALAAfAAAAA<br>...<br>2011-08-30 20:31:34.125 Player(0): Waited 100ms for video buffers AfAAAAAAfAAALAAAA</div></div></div>
</blockquote></div><br></div></div>I forgot the following line at the end of the backend log:<br><br>2011-08-30 20:31:30.356 adding: mythtvfe4 as a remote file transfer<br><br>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.<br>
<br>-Tom<div class="im"><br><br>Backend log:<br>--------------------------<br>2011-08-30 20:31:29.486 TVRec(8): HW Tuner: 8->8<br></div><div class="im">2011-08-30 20:31:29.556 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 7 min<br>
2011-08-30 20:31:29.729 Finished recording My Wife and Kids "Of Breasts and Basketball": channel 2033<br>2011-08-30 20:31:29.931 TVRec(8): RingBufferChanged()<br></div><div class="im">2011-08-30 20:31:30.257 MainServer::HandleAnnounce FileTransfer<br>
</div>
2011-08-30 20:31:30.356 adding: mythtvfe4 as a remote file transfer<div class="im"><br><br>Frontend log:<br>--------------------------<br>2011-08-30 20:31:31.659 AFD: Resetting byte context eof (livetv 1 was eof 0)<br></div>
<div><div></div><div class="h5">2011-08-30 20:31:32.468 Player(0): Timed out waiting for frames, and<br>
there are not enough free frames. Discarding buffered frames.<br>
</div></div></blockquote></div><div><br></div><div>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.</div>
<div><br></div><div>Does anyone have any ideas what might cause this type of problem?</div><div><br></div><div>-Tom</div><div><br></div>Backend log:<div>--------------------------<br><div><div>2011-08-31 19:30:00.189 LoadFromScheduler(): Error, called from backend.</div>
<div>2011-08-31 19:30:00.197 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min</div><div>2011-08-31 19:30:00.310 Finished recording SpongeBob SquarePants "Sandy's Rocket; Squeaky Boots": channel 2033</div>
<div>2011-08-31 19:30:01.350 TVRec(8): RingBufferChanged()</div><div>2011-08-31 19:30:01.927 MainServer::HandleAnnounce FileTransfer</div><div>2011-08-31 19:30:02.018 adding: mythtvfe4 as a remote file transfer</div></div>
<div><br></div><div><br></div><div>Frontend log:</div><div>--------------------------</div><div><div>2011-08-31 19:30:02.194 AFD: Resetting byte context eof (livetv 1 was eof 0)</div><div>2011-08-31 19:30:02.650 RingBuf(myth://<a href="http://192.168.1.100:6543/2033_20110831193000.mpg">192.168.1.100:6543/2033_20110831193000.mpg</a>): Checking to see if there's a new livetv program to switch to..</div>
<div>2011-08-31 19:30:02.661 RingBuf(myth://<a href="http://192.168.1.100:6543/2033_20110831193000.mpg">192.168.1.100:6543/2033_20110831193000.mpg</a>): RingBuffer::Reset() nonzero readpos. toAdjust: 1 readpos: 64632 readAdjust: 112558984</div>
<div>2011-08-31 19:30:02.661 AFD: Resetting byte context eof (livetv 1 was eof 1)</div><div>2011-08-31 19:30:02.662 [ac3 @ 0x5caeae0]incomplete frame</div><div>2011-08-31 19:30:03.943 ALSA, Error: WriteAudio: buffer underrun</div>
<div>2011-08-31 19:30:04.035 Player(1): Waited 100ms for video buffers AAAAAAfAAAAAAALAA</div></div><div>...</div><div><div>2011-08-31 19:30:23.899 Player(1): Waited 100ms for video buffers AAAAAAfAAAAAAALAA</div><div>2011-08-31 19:30:23.935 Player(1), Error: Waited too long for decoder to fill video buffers. Exiting..</div>
<div>2011-08-31 19:30:24.052 TV: Attempting to change from WatchingLiveTV to None</div><div>2011-08-31 19:30:24.103 VDPAU Painter: Clearing VDPAU painter cache.</div><div>2011-08-31 19:30:24.140 MythPainter: 1 images not yet de-allocated.</div>
<div>2011-08-31 19:30:24.462 TV: Changing from WatchingLiveTV to None</div><div>2011-08-31 19:30:24.516 TV: Attempting to change from None to WatchingLiveTV</div><div>2011-08-31 19:30:24.517 MythCoreContext: Connecting to backend server: <a href="http://192.168.1.100:6543">192.168.1.100:6543</a> (try 1 of 1)</div>
<div>2011-08-31 19:30:24.518 Using protocol version 63</div><div>2011-08-31 19:30:24.647 Spawning LiveTV Recorder -- begin</div><div>2011-08-31 19:30:24.925 Spawning LiveTV Recorder -- end</div><div>2011-08-31 19:30:24.946 We have a playbackURL(myth://<a href="http://192.168.1.100:6543/2033_20110831193024.mpg">192.168.1.100:6543/2033_20110831193024.mpg</a>) & cardtype(DUMMY)</div>
<div>2011-08-31 19:30:24.948 We have a RingBuffer</div><div>2011-08-31 19:30:24.951 TV Error: LiveTV not successfully started</div></div><div><br></div></div>