[mythtv-users] Prebuffering Pause Revisited

[Nicholas Fasano]

Hello everyone,

I just finished setting up my new mythbox (replaced my old mythbox that's been chugging along for over 5 years now) and I now have everything up and running perfectly.  Except for one odd glitch.  It's a prebuffering pause that doesn't seem to be listed on <http://www.mythtv.org/wiki/Troubleshooting:Prebuffering_pause>.  Occasionally, only when tuning LiveTV on an HD channel, I will get repeated prebuffering pauses corresponding to brief skips in audio and video.  Toggling the pause button for an instant completely fixes the problem until a new channel is tuned.  This doesn't happen every time I tune an HD channel, and I haven't been able to figure out what actually causes it.  It only occurs on HD channels from my HDHomerun.  It hasn't happened yet with the HD-PVR, but I just got that up and running over the weekend and haven't used it that much yet. 

Here's my setup:
Foxconn P55MX Motherboard
Intel i5 Quad 2.66 GHz processor
4GB RAM
MSI N220GT-MD512 GeForce GT 220 512MB Video Card

PVR-250 on PCI bus
HDHomerun
Hauppauge HD-PVR

I'm using a clean install of Ubuntu 9.10 with just the standard repositories.  The mythtv version that this pulled in is fixes22594.  I did try upgrading to the weekly Mythbuntu repositories, but that didn't help.  I am using the VDPAU High Quality profile with no VDPAU issues, and I have tried all the different VDPAU profiles and deinterlacers.  My hard drives are not dying. It's not a problem with my system's CPU or graphics card's capabilities.  They can both handle pretty much anything thrown at them.  I can play a full bitrate blu-ray file without a glitch using 2% CPU.  I'm not a developer, but if you ask me the problem is that mythtv is trying to play video too close to "live".  I think I just need to get mythtv to buffer a few more frames so it doesn't get ahead of itself.  I have tried many different settings for the HD Ringbuffer, and that doesn't help.  There's no problem with the video files, as this never happens with recordings, just live
 tv and it always resolves by just briefly pausing the video.  It's not really a major issue, but I have a relatively 'plain vanilla' setup so there's got to be many others who have the same issue but are not taking the time to document and post it.  I have searched the lists and there is one thread on the dev list which sounds similar, but the details are sketchy. I may be suffering from the "Accepted Defect" described here: <http://svn.mythtv.org/trac/ticket/6922>.  With so many users using VDPAU and HD sources, I'm surprised this hasn't attracted much attention.

Here is my frontend log:
2009-12-22 08:13:48.324 TV: Attempting to change from Watching WatchingRecording to None
2009-12-22 08:13:48.333 TV: Changing from Watching WatchingRecording to None
2009-12-22 08:13:48.334 ScreenSaverX11Private: DPMS Reactivated 1
2009-12-22 08:14:08.491 TV: Attempting to change from None to Watching WatchingLiveTV
2009-12-22 08:14:08.492 MythContext: Connecting to backend server: 192.168.0.103:6543 (try 1 of 1)
2009-12-22 08:14:08.493 Using protocol version 50
2009-12-22 08:14:08.580 Spawning LiveTV Recorder -- begin
2009-12-22 08:14:09.062 Spawning LiveTV Recorder -- end
2009-12-22 08:14:09.081 We have a playbackURL(/video/recordings/1078_20091222081408.mpg) & cardtype(MPEG)
2009-12-22 08:14:09.633 We have a RingBuffer
2009-12-22 08:14:09.685 TV: StartPlayer(0, Watching WatchingLiveTV, main) -- begin
2009-12-22 08:14:10.376 AFD: Opened codec 0x97b2ed40, id(MPEG2VIDEO) type(Video)
2009-12-22 08:14:10.376 AFD: codec MP2 has 2 channels
2009-12-22 08:14:10.376 AFD: Opened codec 0x8dfad770, id(MP2) type(Audio)
2009-12-22 08:14:10.432 Opening audio device 'iec958'. ch 2(2) sr 48000
2009-12-22 08:14:10.432 Opening ALSA audio device 'iec958'.
2009-12-22 08:14:10.739 NVP(5): Forcing decode extra audio option on (Video method requires it).
2009-12-22 08:14:10.739 FilterManager: Failed to load filter 'colorspace', no such filter exists
2009-12-22 08:14:10.739 OSD Theme Dimensions W: 640 H: 480
2009-12-22 08:14:10.963 TV: StartPlayer(0, Watching WatchingLiveTV, main) -- end ok
2009-12-22 08:14:10.963 TV: Changing from None to Watching WatchingLiveTV
2009-12-22 08:14:10.963 TV: State is LiveTV & mctx == ctx
2009-12-22 08:14:10.963 The realtime priority setting is not enabled.
2009-12-22 08:14:10.965 TV: UpdateOSDInput done
2009-12-22 08:14:10.965 TV: UpdateLCD done
2009-12-22 08:14:10.966 Video timing method: USleep with busy wait
2009-12-22 08:14:10.966 TV: ITVRestart done
2009-12-22 08:14:11.006 ScreenSaverX11Private: DPMS Deactivated 1
2009-12-22 08:14:18.741 Loading window theme from /usr/share/mythtv/themes/Mythbuntu/schedule-ui.xml
2009-12-22 08:14:24.630 MythContext: Connecting to backend server: 192.168.0.103:6543 (try 1 of 1)
2009-12-22 08:14:24.631 Using protocol version 50
2009-12-22 08:14:24.879 NVP(6): Disabling Audio, params(-1,2,44100)
2009-12-22 08:14:25.062 FilterManager: Failed to load filter 'colorspace', no such filter exists
2009-12-22 08:14:25.064 OSD Theme Dimensions W: 640 H: 480
2009-12-22 08:14:25.310 The realtime priority setting is not enabled.
2009-12-22 08:14:25.313 Video timing method: USleep with busy wait
2009-12-22 08:14:25.315 LiveTVChain(live-nfasano-backend-2009-12-22T08:14:08): SwitchTo() not switching to current
2009-12-22 08:14:26.390 FilterManager: Failed to load filter 'colorspace', no such filter exists
2009-12-22 08:14:27.682 NVP(6): Forcing decode extra audio option on (Video method requires it).
2009-12-22 08:14:27.784 FilterManager: Failed to load filter 'colorspace', no such filter exists
2009-12-22 08:14:27.789 AFD: Opened codec 0x939f130, id(MPEG2VIDEO) type(Video)
2009-12-22 08:14:27.789 AFD: codec AC3 has 6 channels
2009-12-22 08:14:27.789 AFD: Opened codec 0x8f4ce10, id(AC3) type(Audio)
2009-12-22 08:14:27.818 Opening audio device 'iec958'. ch 2(2) sr 48000
2009-12-22 08:14:27.818 Opening ALSA audio device 'iec958'.
2009-12-22 08:14:27.850 NVP(6): Enabling Audio
2009-12-22 08:14:27.853 Opening audio device 'iec958'. ch 2(2) sr 48000
2009-12-22 08:14:27.853 Opening ALSA audio device 'iec958'.
2009-12-22 08:14:28.302 NVP(6): prebuffering pause
2009-12-22 08:14:28.347 NVP(6): prebuffering pause
2009-12-22 08:14:28.425 NVP(6): prebuffering pause
2009-12-22 08:14:28.519 NVP(6): prebuffering pause
2009-12-22 08:14:28.673 NVP(6): prebuffering pause
2009-12-22 08:14:28.757 NVP(6): prebuffering pause
2009-12-22 08:14:28.840 NVP(6): prebuffering pause
2009-12-22 08:14:28.974 NVP(6): prebuffering pause
2009-12-22 08:14:29.108 NVP(6): prebuffering pause
2009-12-22 08:14:29.291 NVP(6): prebuffering pause
2009-12-22 08:14:30.182 NVP(6): prebuffering pause
2009-12-22 08:14:31.163 NVP(6): prebuffering pause
2009-12-22 08:14:31.932 NVP(6): prebuffering pause
2009-12-22 08:14:32.082 NVP(6): prebuffering pause
2009-12-22 08:14:32.868 NVP(6): prebuffering pause
2009-12-22 08:14:33.336 NVP(6): prebuffering pause
2009-12-22 08:14:33.553 NVP(6): prebuffering pause
2009-12-22 08:14:33.804 NVP(6): prebuffering pause
2009-12-22 08:14:35.258 NVP(6): prebuffering pause
2009-12-22 08:14:35.358 NVP(6): prebuffering pause
2009-12-22 08:14:35.626 NVP(6): prebuffering pause
2009-12-22 08:14:36.194 NVP(6): prebuffering pause
2009-12-22 08:14:36.796 NVP(6): prebuffering pause
2009-12-22 08:14:37.802 NVP(6): prebuffering pause
2009-12-22 08:14:38.041 NVP(6): prebuffering pause
2009-12-22 08:14:38.450 NVP(6): prebuffering pause
2009-12-22 08:14:38.684 NVP(6): prebuffering pause
2009-12-22 08:14:39.787 NVP(6): prebuffering pause
2009-12-22 08:14:40.121 NVP(6): prebuffering pause
2009-12-22 08:14:41.291 NVP(6): prebuffering pause
2009-12-22 08:14:41.575 NVP(6): prebuffering pause
2009-12-22 08:14:41.993 NVP(6): prebuffering pause

This is when I hit pause twice and the prebuffering pauses vanish completely.

There's really nothing relevant in the backend log during this time period:
2009-12-22 08:14:10.057 Using runtime prefix = /usr
2009-12-22 08:14:10.092 Using configuration directory = /home/mythtv/.mythtv
2009-12-22 08:14:10.134 Empty LocalHostName.
2009-12-22 08:14:10.167 Using localhost value of nfasano-backend
2009-12-22 08:14:10.216 New DB connection, total: 1
2009-12-22 08:14:10.264 Connected to database 'mythconverg' at host: localhost
2009-12-22 08:14:10.301 Closing DB connection named 'DBManager0'
2009-12-22 08:14:10.364 Connected to database 'mythconverg' at host: localhost
2009-12-22 08:14:10.404 New DB connection, total: 2
2009-12-22 08:14:10.452 Connected to database 'mythconverg' at host: localhost
2009-12-22 08:14:10.498 RecBase(1:/dev/video1): GetKeyframePositions(1,9223372036854775807,#1) out of 2
2009-12-22 08:14:10.528 MythContext: Connecting to backend server: 192.168.0.103:6543 (try 1 of 1)
2009-12-22 08:14:10.586 Using protocol version 50
2009-12-22 08:14:10.627 MainServer::ANN Monitor
2009-12-22 08:14:10.669 adding: nfasano-backend as a client (events: 0)
2009-12-22 08:14:10.711 MainServer::ANN Monitor
2009-12-22 08:14:10.769 adding: nfasano-backend as a client (events: 1)
2009-12-22 08:14:11.023 AFD: Opened codec 0xb0f03c80, id(H264) type(Video)
2009-12-22 08:14:11.069 AFD: codec AAC has 2 channels
2009-12-22 08:14:11.120 AFD: Opened codec 0xb0f04030, id(AAC) type(Audio)
2009-12-22 08:14:11.171 MythContext: Connecting to backend server: 192.168.0.103:6543 (try 1 of 1)
2009-12-22 08:14:11.212 Using protocol version 50
2009-12-22 08:14:11.253 MainServer::ANN Playback
2009-12-22 08:14:11.303 adding: nfasano-backend as a client (events: 0)
2009-12-22 08:14:11.346 RecBase(8:/dev/video0): GetKeyframePositions(2942,9223372036854775807,#0) out of 24
2009-12-22 08:14:24.219 TVRec(1): Changing from Watching WatchingLiveTV to None
2009-12-22 08:14:24.264 Unknown type, recording width was 0
2009-12-22 08:14:24.573 Finished recording NFL Total Access: channel 1078
2009-12-22 08:14:24.631 MainServer::ANN Playback
2009-12-22 08:14:24.680 adding: nfasano-backend as a client (events: 0)
2009-12-22 08:14:24.716 TVRec(2): Changing from None to Watching WatchingLiveTV
2009-12-22 08:14:24.759 TVRec(2): HW Tuner: 2->2
2009-12-22 08:14:24.843 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 8 min
2009-12-22 08:14:26.229 Finished recording Good Morning America: channel 4201
2009-12-22 08:14:26.276 Finished recording Good Morning America: channel 4201
2009-12-22 08:14:26.323 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 8 min
2009-12-22 08:14:27.887 RecBase(2:2): GetKeyframePositions(31,9223372036854775807,#1) out of 3
2009-12-22 08:14:28.001 RecBase(2:2): GetKeyframePositions(31,9223372036854775807,#1) out of 3
2009-12-22 08:16:38.335 Expiring 19 MBytes for 1078 @ Tue Dec 22 08:00:00 2009 => NFL Total Access
2009-12-22 08:16:38.371 Expiring 0 MBytes for 4201 @ Tue Dec 22 07:00:00 2009 => Good Morning America
2009-12-22 08:19:38.421 AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 8 min

$ cat /etc/X11/xorg.conf
# nvidia-settings: X configuration file generated by nvidia-settings
# nvidia-settings:  version 1.0  (buildd at palmer)  Sun Feb  1 20:21:04 UTC 2009

Section "ServerLayout"
   Identifier     "Layout0"
   Screen      0  "Screen0" 0 0
   InputDevice    "Keyboard0" "CoreKeyboard"
   InputDevice    "Mouse0" "CorePointer"
EndSection

Section "Files"
EndSection

Section "Module"
   Load           "dbe"
   Load           "extmod"
   Load           "type1"
   Load           "freetype"
   Load           "glx"
EndSection

Section "ServerFlags"
   Option         "Xinerama" "0"
   Option         "AIGLX" "off"
EndSection

Section "InputDevice"
   # generated from default
   Identifier     "Mouse0"
   Driver         "mouse"
   Option         "Protocol" "auto"
   Option         "Device" "/dev/psaux"
   Option         "Emulate3Buttons" "no"
   Option         "ZAxisMapping" "4 5"
EndSection

Section "InputDevice"
   # generated from default
   Identifier     "Keyboard0"
   Driver         "kbd"
EndSection

Section "Monitor"
   # HorizSync source: edid, VertRefresh source: edid
   Identifier     "Monitor0"
   VendorName     "Unknown"
   ModelName      "PIO PDA-5002"
   HorizSync       24.0 - 65.0
   VertRefresh     55.0 - 61.0
   ModeLine        "Pioneer 503/PDA5002 1280x768" 81.0 1280 1304 1440 1688 768 769 777 802
#    ModeLine       "Pioneer 503/PDA5002 1280x768" 81.000 1280 1304 1440 1688 768 769 777 802 +hsync +vsync
   Option          "DPI" "96 x 96"
   Option         "DPMS"
EndSection

Section "Device"
   Identifier     "Device0"
   Driver         "nvidia"
   VendorName     "NVIDIA Corporation"
   BoardName      "GeForce GT 220"
   Option         "UseEvents"	"True"
   Option         "NoLogo" "true"
EndSection

Section "Screen"
   Identifier     "Screen0"
   Device         "Device0"
   Monitor        "Monitor0"
   DefaultDepth    24
   Option         "TwinView" "0"
   Option         "metamodes" "Pioneer 503/PDA5002 1280x768 +0+0"
   SubSection     "Display"
       Depth       24
   EndSubSection
EndSection

Section "Extensions" 
   Option         "Composite" "Disable"
EndSection 


Thanks for listening,
Nick