[mythtv-users] "Video is x.xxxxx frames behind audio (too slow), dropping frame to catch up"

John Liber johnliber at gmail.com
Sun May 27 01:19:09 UTC 2007 

I'm experiencing the "dropping frame" problem that several people have
reported recently:

http://www.gossamer-threads.com/lists/mythtv/users/270586?search_string=dropping%20frame;#270586
http://www.gossamer-threads.com/lists/mythtv/users/268718?search_string=dropping%20frame;#268718

On the whole, my HD plackback is fantastic, but I occasionally (at random
say 5-10 times per hour) get a quick stutter in the video and audio with the
"dropping frame to catch up" message shown below.  It is quite sporadic
which makes it difficult to reproduce.  It seems to be more prevalent while
viewing 720p content than 1080i content... but it occasionally occurs with
SD playback also.  The problem is just as likely to occur when the system is
playing back a single previously recorded program as when I put a heavy load
on the system (all five tuners recording, one commflag job reading from
disk, and playback of HD content).

   Library API version     : 0.20.20070327-1
   Source code version     : 13416M
   FC6 (2.6.20-1.2948.fc6) and KDE
   nVidia driver 9755

   Intel DG965WH Motherboard
   Core 2 Duo E6420
   2 GB Dual Channel DDR2
   On-board Intel HD Audio (S/PDIF out)
   (2) 500 GB SATA HDDs (no LVM; XFS used for the recordings)
   (2) PVR-350s
   (1) pcHDTV 3000
   (1) HDHR (OTA/ATSC)
   GeForce 6200TC
   DVI to HDMI converter outputting to Hitatchi RPTV (1080i Native
Resolution)


I've tried the following with no improvement:

*** Looked at PCI Interrupt Latency.  My motherboard allows me to adjust the
default latency of the PCI cards.  Experimenting with different values made
no difference.  I am unable to use "setpci" to adjust the latency of the
on-board SATA controller which shows a latency of 0.

*** Switched from RTC timing to OpenGL-VSync.  No difference that I could
perceive between the two.

*** Added 'Option "Composite" "Disable"' to my xorg.conf

*** Added 'Option "UseEvents" "True"' to my xorg.conf

*** Trial and error with the settings in nvidia-settings.  At the moment, I
have "Sync to VBlank" checkboxes and "flipping" enabled.  Honestly, I'm
still not sure what the correct settings should be when using OpenGL-Vsync

*** Extra audio buffering setting in MythTV

*** In MythTV, both GUI and playback output in 1080i for all video
resolutions.  I tried adding an additional 1280x720 at 60 mode and set the 720p
content to use that mode.  The "dropping frames" were still present.

*** Examined CPU utilization at various points.  HD playback requires 20-40%
and I run my commflagging jobs on a separate machine.  There's always plenty
of idle CPU available.

*** Examined relative disk access speed at various points (I used hdparm,
but I'm not sure how valid it is with SATA.  The problem occurs under normal
conditions (judging by the activity as well as looking at direct disk read
perf counters).

*** Disabled the on-board sound card in favor of a different soundcard with
optical output (using a different ALSA module).  This made no difference.

*** One peculiar thing of note... nvidia-settings shows the GPU at
1920x540 at 60 Hz, but the KDE GUI shows 1920x540 at 50 Hz.  Further, after I
added the 1280x720 mode, the KDE offered a choice betweeen 51 or 53 Hz.  I'm
not sure what to make of that, but I saw some postings that said to only
worry about what the nvidia utility said the resolution was.


Any ideas which aspect is the most likely culprit?  I've run out of things
to try, and I'm hoping for suggestions on how to even troubleshoot this from
here.  I'd prefer to stay away from XvMC on this machine if possible.
However, I'm willing to take this any direction which will iron out this
issue.

Thanks very much for any help!

-John Liber


XORG.CONF (relevant portions)
Section "Monitor"
    Identifier     "HDTV"
    ModelName      "51F710"
    HorizSync       15.0 - 46.0
    VertRefresh     59.0 - 61.0
    DisplaySize    160 90
    ModeLine       "Custom1080i" 74.2 1920 2008 2052 2200 540 542 547 562
EndSection
Section "Device"
 Identifier  "6200"
 Driver      "nvidia"
 Option      "NoLogo" "True"
    Option         "ExactModeTimingsDVI" "True"
    Option          "UseEvents" "True"
    #Option         "UseEDID" "False"
    Option         "ModeValidation" "NoVertRefreshCheck, NoHorizSyncCheck,
NoXServerModes, NoVesaModes, NoPredefinedModes"
EndSection
Section "Screen"
 Identifier "Screen0"
 Device     "6200"
 Monitor    "HDTV"
 DefaultDepth     24
 SubSection "Display"
  Viewport   0 0
  Depth     24
  Modes    "Custom1080i" "1280x720_60"
 EndSubSection
EndSection
Section "Extensions"
Option "Composite" "Disable"
EndSection




2007-05-25 14:41:59.613 TV: Attempting to change from None to
WatchingRecording
2007-05-25 14:41:59.667 RingBuf(/recordings/1121_20070525140000.mpg):
OpenFile(/recordings/1121_20070525140000.mpg, 12)
2007-05-25 14:41: 59.680 RingBuf(/recordings/1121_20070525140000.mpg):
CalcReadAheadThresh(161506544 KB)
    -> threshhold(64 KB) min read(0 KB) blk size(32 KB)
2007-05-25 14:41:59.681 Using protocol version 34
2007-05-25 14:41: 59.761 Avg read interval was 196 msec. 64K block size
2007-05-25 14:41:59.777 Avg read interval was 197 msec. 64K block size
2007-05-25 14:41:59.779 Avg read interval was 196 msec. 64K block size
0: start_time: 5486.513 duration: 226.383
1: start_time: 5486.476 duration: 226.382
stream: start_time: 60960.849 duration: 2515.766 bitrate=12831 kb/s
2007-05-25 14:41:59.779 AFD: Stream #0, has id 0x49 codec id MPEG2VIDEO,
type Video, bitrate 18900000 at 0x0x9ab0cd0
2007-05-25 14:41:59.784 Avg read interval was 196 msec. 64K block size
2007-05-25 14:41:59.792 Avg read interval was 196 msec. 96K block size
2007-05-25 14:41:59.824 Avg read interval was 198 msec. 128K block size
2007-05-25 14:41:59.836 detectInterlace(Detect Scan, Interlaced Scan,
59.9401, 720) ->Progressive Scan
2007-05-25 14:41:59.836 AFD: Looking for decoder for MPEG2VIDEO
2007-05-25 14:41:59.836 AFD: Opened codec 0xa663b10, id(MPEG2VIDEO)
type(Video)
2007-05-25 14:41:59.837 AFD: Stream #1, has id 0x52 codec id AC3, type
Audio, bitrate 384000 at 0x0x9a07070
2007-05-25 14:41:59.837 AFD: Looking for decoder for AC3
2007-05-25 14:41:59.837 AFD: Opened codec 0xa664060, id(AC3) type(Audio)
2007-05-25 14:41:59.847 RingBuf(/recordings/1121_20070525140000.mpg):
CalcReadAheadThresh(61062378 KB)
    -> threshhold(64 KB) min read(0 KB) blk size(32 KB)
2007-05-25 14:41:59.849 Opening ALSA audio device 'default'.
2007-05-25 14:41:59.878 Dec: Trying to select track (w/lang)
2007-05-25 14:41:59.878 Dec: Selecting first track
2007-05-25 14:41:59.878 Dec: Selected track #1 in the Unknown language(0)
2007-05-25 14:41:59.878 Resyncing position map. posmapStarted = 0 livetv(0)
watchingRec(1)
2007-05-25 14:41:59.883 Avg read interval was 180 msec. 64K block size
2007-05-25 14:42:00.015 Avg read interval was 187 msec. 96K block size
2007-05-25 14:42: 00.041 Avg read interval was 197 msec. 128K block size
2007-05-25 14:42:00.173 Avg read interval was 187 msec. 160K block size
2007-05-25 14:42:00.235 Avg read interval was 180 msec. 192K block size
2007-05-25 14:42: 00.438 Position map filled from DB to: 150150
2007-05-25 14:42:00.438 SyncPositionMap watchingrecording, from DB: 5006
entries
2007-05-25 14:42:00.439 Filling position map from 150151 to 150827
2007-05-25 14:42:00.440 Position map filled from Encoder to: 150810
2007-05-25 14:42:00.440 SyncPositionMap watchingrecording total: 5028
entries
2007-05-25 14:42:00.440 SyncPositionMap, new totframes: 150810, new length:
2516, posMap size: 5028
2007-05-25 14:42:00.440 AFD: Partial position map found
2007-05-25 14:42:00.440 AFD: Successfully opened decoder for file:
"/recordings/1121_20070525140000.mpg". novideo(0)
2007-05-25 14:42:00.441 VideoOutputXv: ctor
2007-05-25 14:42:00.441 Over/underscan. V: 0, H: 0, XOff: 0, YOff: 0
2007-05-25 14:42:00.441 Display Rect  left: 0, top: 67, width: 1920, height:
405, aspect: 1.33333
2007-05-25 14:42:00.441 Video Rect    left: 0, top: 0, width: 1280, height:
720, aspect: 1.77778
2007-05-25 14:42:00.450 VideoOutputXv: Pixel dimensions: Screen 1920x540,
window 1920x540
2007-05-25 14:42:00.450 VideoOutputXv: Estimated display dimensions: 160x90
mm  Aspect: 1.77778
2007-05-25 14:42:00.450 VideoOutputXv: Estimated window dimensions: 160x90
mm  Aspect: 1.77778
2007-05-25 14:42:00.451 VideoOutputXv: XvMCTex: Init failed
2007-05-25 14:42:00.451 VideoOutputXv: @ j=3 Looking for flag[s]:
XvInputMask XvImageMask
2007-05-25 14:42:00.451 VideoOutputXv: Adaptor#0: NV17 Video Texture has
flag[s]: XvInputMask XvImageMask
2007-05-25 14:42:00.451 VideoOutputXv: Grabbed xv port 275
2007-05-25 14:42:00.451 VideoOutputXv: XVideo surface found on port 275
2007-05-25 14:42:00.451 VideoOutputXv: XVideo Adaptor Name: 'NV17 Video
Texture'
2007-05-25 14:42:00.451 VideoOutputXv: XVideo Format #0 is 'YUY2'
2007-05-25 14:42:00.451 VideoOutputXv: XVideo Format #1 is 'YV12'
2007-05-25 14:42:00.452 VideoOutputXv: XVideo Format #2 is 'UYVY'
2007-05-25 14:42:00.452 VideoOutputXv: XVideo Format #3 is 'I420'
2007-05-25 14:42:00.452 VideoOutputXv: Using XVideo Format 'I420'
2007-05-25 14:42:00.452 VideoOutputXv: CreateShmImages(32): video_dim:
1280x720
2007-05-25 14:42:00.503 VideoOutputXv: Chromakeying not possible with this
XVideo port.
2007-05-25 14:42:00.503 Display Rect  left: 0, top: 0, width: 1920, height:
540, aspect: 1.77778
2007-05-25 14:42:00.503 Video Rect    left: 0, top: 0, width: 1280, height:
720, aspect: 1.77778
2007-05-25 14:42:01.467 NVP: ClearAfterSeek(1)
2007-05-25 14:42:01.467 VideoOutputXv: ClearAfterSeek()
2007-05-25 14:42: 01.467 VideoOutputXv: DiscardFrames(0)
2007-05-25 14:42:01.467 VideoBuffers::DiscardFrames(0):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2007-05-25 14:42:01.467 VideoBuffers::DiscardFrames(0):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2007-05-25 14:42:01.467 VideoOutputXv: DiscardFrames() 3:
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-05-25 14:42:01.467 The realtime priority setting is not enabled.
2007-05-25 14:42:01.467 TV: StartPlayer(): took 1710 ms to start player.
2007-05-25 14:42:01.468 TV: Changing from None to WatchingRecording
2007-05-25 14:42:01.470 Using deinterlace method kerneldeint
2007-05-25 14:42:01.570 nVidiaVideoSync: VBlank ioctl did not work,
unimplemented in this driver?
2007-05-25 14:42:01.571 DRMVideoSync: Could not open device /dev/dri/card0,
No such file or directory
2007-05-25 14:42:01.572 OpenGLVideoSync: GLX extensions: GLX_EXT_visual_info
GLX_EXT_visual_rating GLX_SGIX_fbconfig GLX_SGIX_pbuffer GLX_SGI_video_sync
GLX_SGI_swap_control GLX_EXT_texture_from_pixmap GLX_ARB_multisample
GLX_NV_float_buffer GLX_ARB_fbconfig_float GLX_ARB_get_proc_address
2007-05-25 14:42:01.572 OpenGLVideoSync: x,y -> 960, 270
2007-05-25 14:42:01.585 Using OpenGLVideoSync
2007-05-25 14:42:01.593 Using audio as timebase
2007-05-25 14:42:01.593 Video timing method: SGI OpenGL
2007-05-25 14:42:01.593 Refresh rate: 16663, frame interval: 16683
2007-05-25 14:42:01.610 NVP: progressive frame seen after 2 interlaced
frames
2007-05-25 14:42:01.648 Disabled deinterlacing
2007-05-25 14:42: 02.032 Avg read interval was 189 msec. 224K block size
2007-05-25 14:42:02.313 Dec: Selected track #1 in the Unknown language(0)
2007-05-25 14:42:02.641 Avg read interval was 183 msec. 256K block size
'video_output' mean = ' 16648.30', std. dev. = '178.49', fps = '60.07'
2007-05-25 14:42:03.501 Resyncing position map. posmapStarted = 1 livetv(0)
watchingRec(1)
2007-05-25 14:42:03.502 Filling position map from 150811 to 151011
2007-05-25 14:42:03.502 Position map filled from Encoder to: 150990
2007-05-25 14:42:03.502 SyncPositionMap watchingrecording total: 5034
entries
2007-05-25 14:42:03.502 SyncPositionMap, new totframes: 150990, new length:
2519, posMap size: 5034
2007-05-25 14:42:04.039 Avg read interval was 197 msec. 288K block size
'video_output' mean = '16786.39', std. dev. = '1363.87', fps = '59.57'
2007-05-25 14:42:06.497 Avg read interval was 199 msec. 320K block size
'video_output' mean = '16682.80', std. dev. = '354.00', fps = '59.94'
2007-05-25 14:42:08.275 NVP: 400 progressive frames seen.
'video_output' mean = '16650.32', std. dev. = ' 148.32', fps = '60.06'
'video_output' mean = '16649.28', std. dev. = '111.32', fps = '60.06'
'video_output' mean = '16648.83', std. dev. = '151.16', fps = ' 60.06'
'video_output' mean = '16816.98', std. dev. = '1407.63', fps = '59.46'

<SNIP>

2007-05-25 14:57:43.152 NVP: 51600 progressive frames seen.
'video_output' mean = '16816.31', std. dev. = '1400.28', fps = '59.47'
'video_output' mean = '16648.79', std. dev. = ' 205.55', fps = '60.06'
'video_output' mean = '16652.11', std. dev. = '163.56', fps = '60.05'
'video_output' mean = '16648.26', std. dev. = '155.60', fps = ' 60.07'
2007-05-25 14:57:49.813 NVP: 52000 progressive frames seen.
'video_output' mean = '16651.36', std. dev. = '150.86', fps = '60.06'
'video_output' mean = '16816.23 ', std. dev. = '1401.95', fps = '59.47'
'video_output' mean = '16653.38', std. dev. = '191.54', fps = '60.05'
'video_output' mean = '16647.75', std. dev. = ' 151.73', fps = '60.07'
2007-05-25 14:57:55.924 NVP: Video is 3.22388 frames behind audio (too
slow), dropping frame to catch up.
2007-05-25 14:57:55.924 NVP: Video is 3.69166 frames behind audio (too
slow), dropping frame to catch up.
2007-05-25 14:57:55.924 NVP: Video is 3.78775 frames behind audio (too
slow), dropping frame to catch up.
2007-05-25 14:57:55.924 NVP: Video is 3.62003 frames behind audio (too
slow), dropping frame to catch up.
2007-05-25 14:57:55.924 NVP: Video is 3.23947 frames behind audio (too
slow), dropping frame to catch up.
2007-05-25 14:57:56.523 NVP: 52400 progressive frames seen.
'video_output' mean = '16983.43', std. dev. = ' 13306.39', fps = '58.88'
'video_output' mean = '16651.65', std. dev. = '140.66', fps = '60.05'
'video_output' mean = '16649.55', std. dev. = '251.85', fps = ' 60.06'
'video_output' mean = '16651.96', std. dev. = '208.49', fps = '60.05'
2007-05-25 14:58:03.184 NVP: 52800 progressive frames seen.
'video_output' mean = '16649.61 ', std. dev. = '317.74', fps = '60.06'
'video_output' mean = '16649.55', std. dev. = '263.46', fps = '60.06'
'video_output' mean = '16650.39', std. dev. = ' 175.93', fps = '60.06'
'video_output' mean = '16656.35', std. dev. = '220.06', fps = '60.04'
2007-05-25 14:58:09.845 NVP: 53200 progressive frames seen.
'video_output' mean = ' 16646.57', std. dev. = '154.08', fps = '60.07'
'video_output' mean = '16651.28', std. dev. = '183.81', fps = '60.06'
'video_output' mean = '16648.13', std. dev. = ' 152.34', fps = '60.07'
'video_output' mean = '16653.27', std. dev. = '125.38', fps = '60.05'
2007-05-25 14:58:16.505 NVP: 53600 progressive frames seen.
'video_output' mean = ' 16648.21', std. dev. = '141.44', fps = '60.07'
'video_output' mean = '16817.87', std. dev. = '1401.07', fps = '59.46'
'video_output' mean = '16648.51', std. dev. = ' 147.95', fps = '60.07'
'video_output' mean = '16652.30', std. dev. = '143.73', fps = '60.05
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mythtv.org/pipermail/mythtv-users/attachments/20070526/201511e9/attachment.htm

More information about the mythtv-users mailing list