[mythtv-users] "Wandering" audio/video sync... What the heck is going on here? (Long Post)
William Munson
william_munson at bellsouth.net
Tue May 22 03:03:08 UTC 2007
I am troubleshooting a video glitching problem and think I may have
finally gotten to the heart of the matter. Unfortunately I have no clue
what is actually going on with it. I played a HD program with a number
of glitches using -v playback and found a number of things interesting
in the log. The log is quite large at 600K for a 10 minute chunk of
playback. Here are some excerpts from the log. I can provide the
complete log for anyone who is interested.
Things start out somewhat normally. Here is the first part of the log.
-----------------------------------
2007-05-21 22:02:55.316 Using runtime prefix = /usr
2007-05-21 22:02:55.320 DPMS is disabled.
2007-05-21 22:02:55.625 New DB connection, total: 1
2007-05-21 22:02:55.713 Connected to database 'mythconverg' at host:
localhost
2007-05-21 22:02:55.817 Total desktop dim: 1640x920, with 1 screen[s].
2007-05-21 22:02:55.947 Using screen 0, 1640x920 at 0,0
2007-05-21 22:02:56.062 user: 109 effective user: 109 before privileged
thread
2007-05-21 22:02:56.062 user: 109 effective user: 109 after privileged
thread
2007-05-21 22:02:56.063 user: 109 effective user: 109 run_priv_thread
2007-05-21 22:02:56.225 Current Schema Version: 1189
2007-05-21 22:02:56.226 mythfrontend version: 0.20.20070327-1 www.mythtv.org
2007-05-21 22:02:56.226 Enabled verbose msgs: important general playback
2007-05-21 22:02:56.978 max_width: 1640 max_height: 920
2007-05-21 22:02:57.107 Total desktop dim: 1640x920, with 1 screen[s].
2007-05-21 22:02:57.108 Using screen 0, 1640x920 at 0,0
2007-05-21 22:02:57.108 Switching to square mode (Titivillus)
2007-05-21 22:02:57.191 Using the Qt painter
2007-05-21 22:02:57.221 Joystick disabled.
2007-05-21 22:02:57.249 lirc init success using configuration file:
/home/mythtv/.mythtv/lircrc
2007-05-21 22:02:57.792 Loading from:
/usr/share/mythtv/themes/default/base.xml
2007-05-21 22:02:58.377 Registering Internal as a media playback plugin.
2007-05-21 22:02:58.852 MythMusic adding CD-Writer: 0,0,0 -- MAXTOR
STM332062
2007-05-21 22:02:58.872 MythMusic adding CD-Writer: ATA:1,0,0 -- IDE1008
2007-05-21 22:03:00.386 Failed to run 'cdrecord --scanbus -dev=ATAPI'
2007-05-21 22:03:25.707 XMLParse::LoadTheme using
/usr/share/mythtv/themes/Titivillus/ui.xml
2007-05-21 22:03:25.871 Unable to find image file:
/usr/share/mythtv/themes/Titivillus/playback_box/solid-pbb_back.png
2007-05-21 22:03:25.881 UIImageType::LoadImage() - Cannot find image:
playback_box/solid-pbb_back.png
2007-05-21 22:03:26.331 Connecting to backend server: 192.168.1.10:6543
(try 1 of 5)
2007-05-21 22:03:26.458 Using protocol version 34
2007-05-21 22:03:36.129 New DB connection, total: 2
2007-05-21 22:03:36.289 Connected to database 'mythconverg' at host:
localhost
2007-05-21 22:03:36.548 TV: Attempting to change from None to
WatchingPreRecorded
2007-05-21 22:03:36.585 RingBuf(/tv/2251_20070521200000.mpg):
OpenFile(/tv/2251_20070521200000.mpg, 12)
2007-05-21 22:03:36.597 RingBuf(/tv/2251_20070521200000.mpg):
CalcReadAheadThresh(3086225832 KB)
-> threshhold(64 KB) min read(0 KB) blk size(32 KB)
2007-05-21 22:03:37.187 Avg read interval was 198 msec. 64K block size
2007-05-21 22:03:37.193 Avg read interval was 196 msec. 96K block size
2007-05-21 22:03:37.220 Avg read interval was 197 msec. 128K block size
2007-05-21 22:03:37.247 Avg read interval was 198 msec. 160K block size
2007-05-21 22:03:37.383 Avg read interval was 184 msec. 192K block size
2007-05-21 22:03:37.441 Avg read interval was 180 msec. 64K block size
2007-05-21 22:03:38.042 Avg read interval was 193 msec. 96K block size
2007-05-21 22:03:38.046 Avg read interval was 196 msec. 128K block size
2007-05-21 22:03:38.050 Avg read interval was 196 msec. 160K block size
2007-05-21 22:03:38.055 Avg read interval was 196 msec. 192K block size
2007-05-21 22:03:38.061 Avg read interval was 196 msec. 224K block size
2007-05-21 22:03:38.154 Avg read interval was 183 msec. 64K block size
2007-05-21 22:03:38.158 Avg read interval was 196 msec. 96K block size
2007-05-21 22:03:38.162 Avg read interval was 196 msec. 128K block size
2007-05-21 22:03:38.168 Avg read interval was 196 msec. 160K block size
2007-05-21 22:03:38.173 Avg read interval was 196 msec. 192K block size
2007-05-21 22:03:38.178 Avg read interval was 196 msec. 224K block size
2007-05-21 22:03:38.284 Avg read interval was 184 msec. 64K block size
2007-05-21 22:03:38.305 Avg read interval was 197 msec. 64K block size
0: start_time: 3072.923 duration: 328.973
1: start_time: 3072.890 duration: 328.965
stream: start_time: 34143.217 duration: 3655.625 bitrate=15937 kb/s
2007-05-21 22:03:38.311 Avg read interval was 196 msec. 64K block size
2007-05-21 22:03:38.310 AFD: Stream #0, has id 0x101 codec id
MPEG2VIDEO, type Video, bitrate 16500000 at 0x0x8430430
2007-05-21 22:03:38.359 Avg read interval was 198 msec. 96K block size
2007-05-21 22:03:38.363 Avg read interval was 196 msec. 128K block size
2007-05-21 22:03:38.368 Avg read interval was 196 msec. 160K block size
2007-05-21 22:03:38.372 Avg read interval was 196 msec. 192K block size
2007-05-21 22:03:38.377 Avg read interval was 196 msec. 224K block size
2007-05-21 22:03:38.531 AFD: Using libmpeg2 for video decoding
2007-05-21 22:03:38.532 detectInterlace(Detect Scan, Interlaced Scan,
59.9401, 720) ->Progressive Scan
2007-05-21 22:03:38.547 AFD: Looking for decoder for MPEG2VIDEO
2007-05-21 22:03:38.547 AFD: Opened codec 0x84fda90, id(MPEG2VIDEO)
type(Video)
2007-05-21 22:03:38.547 AFD: Stream #1, has id 0x102 codec id AC3, type
Audio, bitrate 384000 at 0x0x842ce80
2007-05-21 22:03:38.547 AFD: Looking for decoder for AC3
2007-05-21 22:03:38.548 AFD: Opened codec 0x8633080, id(AC3) type(Audio)
2007-05-21 22:03:38.557 RingBuf(/tv/2251_20070521200000.mpg):
CalcReadAheadThresh(3063248296 KB)
-> threshhold(64 KB) min read(0 KB) blk size(32 KB)
2007-05-21 22:03:38.588 Opening ALSA audio device 'iec958:{ AES0 0x02 }'.
2007-05-21 22:03:38.801 Dec: Trying to select track (w/lang)
2007-05-21 22:03:38.801 Dec: Selecting first track
2007-05-21 22:03:38.801 Dec: Selected track #1 in the Unknown language(0)
2007-05-21 22:03:38.802 Resyncing position map. posmapStarted = 0
livetv(0) watchingRec(0)
2007-05-21 22:03:39.535 Position map filled from DB to: 218519
2007-05-21 22:03:39.536 SyncPositionMap prerecorded, from DB: 7297 entries
2007-05-21 22:03:39.536 SyncPositionMap, new totframes: 218519, new
length: 3645, posMap size: 7297
2007-05-21 22:03:39.537 AFD: Position map found
2007-05-21 22:03:39.537 AFD: Successfully opened decoder for file:
"/tv/2251_20070521200000.mpg". novideo(0)
2007-05-21 22:03:39.638 VideoOutputXv: ctor
2007-05-21 22:03:39.639 Over/underscan. V: 0.02, H: 0.02, XOff: 0, YOff: 0
2007-05-21 22:03:39.640 Display Rect left: 0, top: 115, width: 1640,
height: 690, aspect: 1.33333
2007-05-21 22:03:39.640 Video Rect left: 26, top: 14, width: 1229,
height: 691, aspect: 1.77778
2007-05-21 22:03:39.640 VideoOutputXv: Pixel dimensions: Screen
1640x920, window 1640x920
2007-05-21 22:03:39.653 VideoOutputXv: Estimated display dimensions:
555x312 mm Aspect: 1.77885
2007-05-21 22:03:39.653 VideoOutputXv: Estimated window dimensions:
555x312 mm Aspect: 1.77885
2007-05-21 22:03:39.664 VideoOutputXv: XvMCTex: Init failed
2007-05-21 22:03:39.673 VideoOutputXv: @ j=3 Looking for flag[s]:
XvInputMask XvImageMask
2007-05-21 22:03:39.673 VideoOutputXv: Adaptor#0: NV17 Video Texture has
flag[s]: XvInputMask XvImageMask
2007-05-21 22:03:39.674 VideoOutputXv: Grabbed xv port 245
2007-05-21 22:03:39.674 VideoOutputXv: XVideo surface found on port 245
2007-05-21 22:03:39.674 VideoOutputXv: XVideo Adaptor Name: 'NV17 Video
Texture'
2007-05-21 22:03:39.680 VideoOutputXv: XVideo Format #0 is 'YUY2'
2007-05-21 22:03:39.680 VideoOutputXv: XVideo Format #1 is 'YV12'
2007-05-21 22:03:39.680 VideoOutputXv: XVideo Format #2 is 'UYVY'
2007-05-21 22:03:39.680 VideoOutputXv: XVideo Format #3 is 'I420'
2007-05-21 22:03:39.680 VideoOutputXv: Using XVideo Format 'I420'
2007-05-21 22:03:39.680 VideoOutputXv: CreateShmImages(32): video_dim:
1280x720
2007-05-21 22:03:39.851 VideoOutputXv: Chromakeying not possible with
this XVideo port.
2007-05-21 22:03:39.852 Display Rect left: 0, top: 0, width: 1640,
height: 920, aspect: 1.77778
2007-05-21 22:03:39.852 Video Rect left: 26, top: 14, width: 1229,
height: 691, aspect: 1.77778
2007-05-21 22:03:41.528 NVP: ClearAfterSeek(1)
2007-05-21 22:03:41.530 VideoOutputXv: ClearAfterSeek()
2007-05-21 22:03:41.540 VideoOutputXv: DiscardFrames(0)
2007-05-21 22:03:41.540 VideoBuffers::DiscardFrames(0):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2007-05-21 22:03:41.540 VideoBuffers::DiscardFrames(0):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2007-05-21 22:03:41.540 VideoOutputXv: DiscardFrames() 3:
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-05-21 22:03:41.571 TV: StartPlayer(): took 4403 ms to start player.
2007-05-21 22:03:41.580 TV: Changing from None to WatchingPreRecorded
2007-05-21 22:03:41.614 Using realtime priority.
2007-05-21 22:03:41.622 Avg read interval was 186 msec. 64K block size
2007-05-21 22:03:41.680 Avg read interval was 180 msec. 96K block size
2007-05-21 22:03:41.709 Using deinterlace method linearblend
2007-05-21 22:03:41.828 nVidiaVideoSync: VBlank ioctl did not work,
unimplemented in this driver?
2007-05-21 22:03:41.828 DRMVideoSync: Could not open device
/dev/dri/card0, No such file or directory
2007-05-21 22:03:41.828 RTCVideoSync: Could not set RTC frequency,
Permission denied.
2007-05-21 22:03:41.831 Using audio as timebase
2007-05-21 22:03:41.832 Video timing method: USleep with busy wait
2007-05-21 22:03:41.832 Refresh rate: 33362, frame interval: 16683
2007-05-21 22:03:41.832 NVP: Waiting for prebuffer.. 0
ALLULAAAAAAAAAAAAAAAAAAAAAAAAAA
2007-05-21 22:03:41.879 AFD: DoFastForward(217197 (1), do discard frames)
2007-05-21 22:03:41.879 Dec: DoFastForward(217197 (1), do discard frames)
2007-05-21 22:03:41.880 AFD: SeekReset(217199, 0, do flush, do discard)
2007-05-21 22:03:41.880 AFD: SeekReset() flushing
2007-05-21 22:03:41.881 VideoOutputXv: DiscardFrames(1)
2007-05-21 22:03:41.881 VideoBuffers::DiscardFrames(1):
ALLULAAAAAAAAAAAAAAAAAAAAAAAAAA
2007-05-21 22:03:41.881 VideoBuffers::DiscardFrames():
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-05-21 22:03:41.881 VideoBuffers::DiscardFrames(1):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2007-05-21 22:03:41.881 VideoOutputXv: DiscardFrames() 3:
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-05-21 22:03:41.882 NVP: ClearAfterSeek(0)
2007-05-21 22:03:41.900 NVP: Waiting for prebuffer.. 1
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2007-05-21 22:03:41.920 Avg read interval was 192 msec. 64K block size
2007-05-21 22:03:41.927 Avg read interval was 196 msec. 96K block size
2007-05-21 22:03:41.937 Avg read interval was 196 msec. 128K block size
2007-05-21 22:03:41.946 Avg read interval was 197 msec. 160K block size
2007-05-21 22:03:41.959 Avg read interval was 196 msec. 192K block size
2007-05-21 22:03:41.968 NVP: Waiting for prebuffer.. 2
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2007-05-21 22:03:41.979 Avg read interval was 198 msec. 224K block size
2007-05-21 22:03:42.036 NVP: Waiting for prebuffer.. 3
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2007-05-21 22:03:42.104 NVP: Waiting for prebuffer.. 4
AAAAALLAAAAAAAAAAAAAAAAAAAAAAAA
2007-05-21 22:03:42.154 Avg read interval was 189 msec. 256K block size
2007-05-21 22:03:42.172 NVP: Waiting for prebuffer.. 5
AAAAAUUULUULLAAAAAAAAAAAAAAAAAA
2007-05-21 22:03:42.228 NVP: progressive frame seen after 2 interlaced
frames
2007-05-21 22:03:42.267 Disabled deinterlacing
2007-05-21 22:03:42.569 Avg read interval was 193 msec. 288K block size
2007-05-21 22:03:43.546 Avg read interval was 197 msec. 320K block size
'video_output' mean = '16783.36', std. dev. = '2148.50', fps = '59.58'
2007-05-21 22:03:44.829 Avg read interval was 199 msec. 352K block size
'video_output' mean = '16679.44', std. dev. = '670.60', fps = '59.95'
'video_output' mean = '16693.21', std. dev. = '680.00', fps = '59.90'
2007-05-21 22:03:47.470 Avg read interval was 196 msec. 384K block size
2007-05-21 22:03:47.698 NVP: Video is 3.84691 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:03:47.699 NVP: Video is 5.07301 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:03:47.701 NVP: Video is 5.76779 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:03:47.702 NVP: Video is 6.04915 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:03:47.703 NVP: Video is 6.03537 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:03:47.704 NVP: Video is 5.78529 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:03:47.706 NVP: Video is 5.37295 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:03:47.707 NVP: Video is 4.82389 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:03:47.708 NVP: Video is 4.18732 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:03:47.709 NVP: Video is 3.4851 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:03:47.799 Marking recording as watched using offset 8 minutes
2007-05-21 22:03:47.812 TV: Attempting to change from
WatchingPreRecorded to None
2007-05-21 22:03:47.812 TV: StopStuff() -- begin
2007-05-21 22:03:47.828 TV: StopStuff(): stopping ring buffer[s]
2007-05-21 22:03:47.834 TV: StopStuff(): stopping player[s] (1/2)
2007-05-21 22:03:47.835 TV: StopStuff(): stopping player[s] (2/2)
2007-05-21 22:03:47.843 NVP: Exited decoder loop.
2007-05-21 22:03:47.875 VideoOutputXv: dtor
2007-05-21 22:03:47.875 VideoOutputXv: DiscardFrames(1)
2007-05-21 22:03:47.875 VideoBuffers::DiscardFrames(1):
UAALAAAAUAAUUUUUUUUUUUUUUUuUULU
2007-05-21 22:03:47.875 VideoBuffers::DiscardFrames():
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-05-21 22:03:47.875 VideoBuffers::DiscardFrames(1):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2007-05-21 22:03:47.875 VideoOutputXv: DiscardFrames() 3:
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-05-21 22:03:47.875 VideoOutputXv: DiscardFrames(1)
2007-05-21 22:03:47.875 VideoBuffers::DiscardFrames(1):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2007-05-21 22:03:47.876 VideoBuffers::DiscardFrames():
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-05-21 22:03:47.876 VideoBuffers::DiscardFrames(1):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2007-05-21 22:03:47.876 VideoOutputXv: DiscardFrames() 3:
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-05-21 22:03:47.894 VideoOutputXv: Closing XVideo port 245
2007-05-21 22:03:48.000 TV: StopStuff() -- end
2007-05-21 22:03:48.001 TV: Changing from WatchingPreRecorded to None
2007-05-21 22:03:53.121 TV: Attempting to change from None to
WatchingPreRecorded
2007-05-21 22:03:53.152 RingBuf(/tv/2251_20070521200000.mpg):
OpenFile(/tv/2251_20070521200000.mpg, 12)
2007-05-21 22:03:53.152 RingBuf(/tv/2251_20070521200000.mpg):
CalcReadAheadThresh(138743400 KB)
-> threshhold(64 KB) min read(0 KB) blk size(32 KB)
2007-05-21 22:03:53.205 Avg read interval was 196 msec. 64K block size
2007-05-21 22:03:53.206 Avg read interval was 196 msec. 64K block size
2007-05-21 22:03:53.218 Avg read interval was 197 msec. 64K block size
2007-05-21 22:03:53.329 Avg read interval was 183 msec. 64K block size
2007-05-21 22:03:53.352 Avg read interval was 198 msec. 64K block size
0: start_time: 3072.923 duration: 328.973
1: start_time: 3072.890 duration: 328.965
stream: start_time: 34143.217 duration: 3655.625 bitrate=15937 kb/s
2007-05-21 22:03:53.356 AFD: Stream #0, has id 0x101 codec id
MPEG2VIDEO, type Video, bitrate 16500000 at 0x0x8a313c0
2007-05-21 22:03:53.357 AFD: Using libmpeg2 for video decoding
2007-05-21 22:03:53.358 detectInterlace(Detect Scan, Interlaced Scan,
59.9401, 720) ->Progressive Scan
2007-05-21 22:03:53.358 AFD: Looking for decoder for MPEG2VIDEO
2007-05-21 22:03:53.358 AFD: Opened codec 0x8515c20, id(MPEG2VIDEO)
type(Video)
2007-05-21 22:03:53.358 AFD: Stream #1, has id 0x102 codec id AC3, type
Audio, bitrate 384000 at 0x0x84a8f40
2007-05-21 22:03:53.358 AFD: Looking for decoder for AC3
2007-05-21 22:03:53.359 AFD: Opened codec 0x84b8a30, id(AC3) type(Audio)
2007-05-21 22:03:53.359 RingBuf(/tv/2251_20070521200000.mpg):
CalcReadAheadThresh(3063248296 KB)
-> threshhold(64 KB) min read(0 KB) blk size(32 KB)
2007-05-21 22:03:53.361 Opening ALSA audio device 'iec958:{ AES0 0x02 }'.
2007-05-21 22:03:53.362 Dec: Trying to select track (w/lang)
2007-05-21 22:03:53.362 Dec: Selecting first track
2007-05-21 22:03:53.362 Dec: Selected track #1 in the Unknown language(0)
2007-05-21 22:03:53.363 Resyncing position map. posmapStarted = 0
livetv(0) watchingRec(0)
2007-05-21 22:03:53.365 Avg read interval was 197 msec. 64K block size
2007-05-21 22:03:53.368 Avg read interval was 196 msec. 96K block size
2007-05-21 22:03:53.373 Avg read interval was 196 msec. 128K block size
2007-05-21 22:03:53.379 Avg read interval was 196 msec. 160K block size
2007-05-21 22:03:53.387 Avg read interval was 196 msec. 192K block size
2007-05-21 22:03:53.407 Avg read interval was 197 msec. 224K block size
2007-05-21 22:03:53.636 Position map filled from DB to: 218519
2007-05-21 22:03:53.637 SyncPositionMap prerecorded, from DB: 7297 entries
2007-05-21 22:03:53.638 SyncPositionMap, new totframes: 218519, new
length: 3645, posMap size: 7297
2007-05-21 22:03:53.638 AFD: Position map found
2007-05-21 22:03:53.638 AFD: Successfully opened decoder for file:
"/tv/2251_20070521200000.mpg". novideo(0)
2007-05-21 22:03:53.640 VideoOutputXv: ctor
2007-05-21 22:03:53.641 Over/underscan. V: 0.02, H: 0.02, XOff: 0, YOff: 0
2007-05-21 22:03:53.641 Display Rect left: 0, top: 115, width: 1640,
height: 690, aspect: 1.33333
2007-05-21 22:03:53.641 Video Rect left: 26, top: 14, width: 1229,
height: 691, aspect: 1.77778
2007-05-21 22:03:53.641 VideoOutputXv: Pixel dimensions: Screen
1640x920, window 1640x920
2007-05-21 22:03:53.642 VideoOutputXv: Estimated display dimensions:
555x312 mm Aspect: 1.77885
2007-05-21 22:03:53.642 VideoOutputXv: Estimated window dimensions:
555x312 mm Aspect: 1.77885
2007-05-21 22:03:53.643 VideoOutputXv: XvMCTex: Init failed
2007-05-21 22:03:53.643 VideoOutputXv: @ j=3 Looking for flag[s]:
XvInputMask XvImageMask
2007-05-21 22:03:53.643 VideoOutputXv: Adaptor#0: NV17 Video Texture has
flag[s]: XvInputMask XvImageMask
2007-05-21 22:03:53.643 VideoOutputXv: Grabbed xv port 245
2007-05-21 22:03:53.643 VideoOutputXv: XVideo surface found on port 245
2007-05-21 22:03:53.643 VideoOutputXv: XVideo Adaptor Name: 'NV17 Video
Texture'
2007-05-21 22:03:53.643 VideoOutputXv: XVideo Format #0 is 'YUY2'
2007-05-21 22:03:53.643 VideoOutputXv: XVideo Format #1 is 'YV12'
2007-05-21 22:03:53.644 VideoOutputXv: XVideo Format #2 is 'UYVY'
2007-05-21 22:03:53.644 VideoOutputXv: XVideo Format #3 is 'I420'
2007-05-21 22:03:53.644 VideoOutputXv: Using XVideo Format 'I420'
2007-05-21 22:03:53.644 VideoOutputXv: CreateShmImages(32): video_dim:
1280x720
2007-05-21 22:03:54.053 VideoOutputXv: Chromakeying not possible with
this XVideo port.
2007-05-21 22:03:54.053 Display Rect left: 0, top: 0, width: 1640,
height: 920, aspect: 1.77778
2007-05-21 22:03:54.053 Video Rect left: 26, top: 14, width: 1229,
height: 691, aspect: 1.77778
2007-05-21 22:03:55.487 NVP: ClearAfterSeek(1)
2007-05-21 22:03:55.488 TV: StartPlayer(): took 2286 ms to start player.
2007-05-21 22:03:55.489 TV: Changing from None to WatchingPreRecorded
2007-05-21 22:03:55.488 VideoOutputXv: ClearAfterSeek()
2007-05-21 22:03:55.490 VideoOutputXv: DiscardFrames(0)
2007-05-21 22:03:55.490 VideoBuffers::DiscardFrames(0):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2007-05-21 22:03:55.490 VideoBuffers::DiscardFrames(0):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2007-05-21 22:03:55.490 VideoOutputXv: DiscardFrames() 3:
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2007-05-21 22:03:55.492 Using deinterlace method linearblend
2007-05-21 22:03:55.492 Using realtime priority.
2007-05-21 22:03:55.533 Avg read interval was 430 msec. 192K block size
2007-05-21 22:03:55.553 Avg read interval was 197 msec. 224K block size
2007-05-21 22:03:55.592 nVidiaVideoSync: VBlank ioctl did not work,
unimplemented in this driver?
2007-05-21 22:03:55.592 DRMVideoSync: Could not open device
/dev/dri/card0, No such file or directory
2007-05-21 22:03:55.592 RTCVideoSync: Could not set RTC frequency,
Permission denied.
2007-05-21 22:03:55.592 Using audio as timebase
2007-05-21 22:03:55.592 Video timing method: USleep with busy wait
2007-05-21 22:03:55.592 Refresh rate: 33362, frame interval: 16683
2007-05-21 22:03:55.593 NVP: Waiting for prebuffer.. 0
AAUUUuUULULLAAAAAAAAAAAAAAAAAAA
2007-05-21 22:03:55.627 NVP: progressive frame seen after 2 interlaced
frames
2007-05-21 22:03:55.653 Disabled deinterlacing
2007-05-21 22:03:55.991 Avg read interval was 193 msec. 256K block size
2007-05-21 22:03:56.487 Avg read interval was 194 msec. 288K block size
'video_output' mean = '16900.53', std. dev. = '1993.40', fps = '59.17'
2007-05-21 22:03:57.937 Avg read interval was 195 msec. 320K block size
'video_output' mean = '16677.07', std. dev. = '338.69', fps = '59.96'
2007-05-21 22:03:59.674 Avg read interval was 197 msec. 352K block size
2007-05-21 22:03:59.717 Resyncing position map. posmapStarted = 1
livetv(0) watchingRec(0)
'video_output' mean = '17017.48', std. dev. = '3551.69', fps = '58.76'
2007-05-21 22:04:02.329 NVP: 400 progressive frames seen.
'video_output' mean = '16677.92', std. dev. = '625.38', fps = '59.96'
2007-05-21 22:04:02.962 Avg read interval was 195 msec. 384K block size
'video_output' mean = '16687.67', std. dev. = '735.72', fps = '59.92'
'video_output' mean = '16693.92', std. dev. = '591.09', fps = '59.90'
2007-05-21 22:04:06.878 Avg read interval was 197 msec. 416K block size
'video_output' mean = '16680.18', std. dev. = '561.72', fps = '59.95'
2007-05-21 22:04:09.005 NVP: 800 progressive frames seen.
'video_output' mean = '16689.61', std. dev. = '699.39', fps = '59.92'
'video_output' mean = '16687.62', std. dev. = '654.01', fps = '59.92'
2007-05-21 22:04:10.800 Avg read interval was 195 msec. 448K block size
'video_output' mean = '16689.14', std. dev. = '740.22', fps = '59.92'
'video_output' mean = '16688.34', std. dev. = '712.54', fps = '59.92'
2007-05-21 22:04:15.681 NVP: 1200 progressive frames seen.
'video_output' mean = '16705.57', std. dev. = '700.36', fps = '59.86'
'video_output' mean = '16675.31', std. dev. = '621.63', fps = '59.97'
'video_output' mean = '16688.22', std. dev. = '667.06', fps = '59.92'
'video_output' mean = '16687.51', std. dev. = '655.24', fps = '59.93'
2007-05-21 22:04:22.358 NVP: 1600 progressive frames seen.
'video_output' mean = '16680.36', std. dev. = '725.20', fps = '59.95'
'video_output' mean = '16690.73', std. dev. = '630.63', fps = '59.91'
'video_output' mean = '16690.43', std. dev. = '669.49', fps = '59.91'
'video_output' mean = '16697.39', std. dev. = '679.79', fps = '59.89'
2007-05-21 22:04:29.034 NVP: 2000 progressive frames seen.
'video_output' mean = '16680.28', std. dev. = '537.98', fps = '59.95'
'video_output' mean = '16686.17', std. dev. = '444.65', fps = '59.93'
'video_output' mean = '16685.10', std. dev. = '682.63', fps = '59.93'
'video_output' mean = '16686.94', std. dev. = '529.84', fps = '59.93'
2007-05-21 22:04:35.710 NVP: 2400 progressive frames seen.
'video_output' mean = '16689.22', std. dev. = '393.24', fps = '59.92'
'video_output' mean = '16694.08', std. dev. = '537.01', fps = '59.90'
'video_output' mean = '16683.90', std. dev. = '557.07', fps = '59.94'
'video_output' mean = '16689.91', std. dev. = '496.61', fps = '59.92'
2007-05-21 22:04:41.235 NVP: Video is 3.01163 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:04:42.370 NVP: 2800 progressive frames seen.
'video_output' mean = '16526.57', std. dev. = '1892.08', fps = '60.51'
'video_output' mean = '16685.10', std. dev. = '515.01', fps = '59.93'
'video_output' mean = '16689.97', std. dev. = '481.06', fps = '59.92'
'video_output' mean = '16688.15', std. dev. = '554.49', fps = '59.92'
2007-05-21 22:04:49.046 NVP: 3200 progressive frames seen.
'video_output' mean = '16687.42', std. dev. = '620.17', fps = '59.93'
'video_output' mean = '16685.27', std. dev. = '657.16', fps = '59.93'
'video_output' mean = '16710.60', std. dev. = '557.35', fps = '59.84'
'video_output' mean = '16661.15', std. dev. = '682.53', fps = '60.02'
2007-05-21 22:04:55.723 NVP: 3600 progressive frames seen.
'video_output' mean = '16696.23', std. dev. = '466.99', fps = '59.89'
'video_output' mean = '16685.20', std. dev. = '434.54', fps = '59.93'
'video_output' mean = '16681.42', std. dev. = '644.73', fps = '59.95'
2007-05-21 22:05:00.113 NVP: Video is 3.02631 frames behind audio (too
slow), dropping frame to catch up.
'video_output' mean = '16691.59', std. dev. = '2163.77', fps = '59.91'
2007-05-21 22:05:02.399 NVP: 4000 progressive frames seen.
'video_output' mean = '16692.76', std. dev. = '597.75', fps = '59.91'
'video_output' mean = '16688.84', std. dev. = '550.34', fps = '59.92'
'video_output' mean = '16682.65', std. dev. = '581.44', fps = '59.94'
'video_output' mean = '16692.67', std. dev. = '793.16', fps = '59.91'
2007-05-21 22:05:09.075 NVP: 4400 progressive frames seen.
'video_output' mean = '16682.96', std. dev. = '592.17', fps = '59.94'
2007-05-21 22:05:09.893 NVP: Video is 3.00504 frames behind audio (too
slow), dropping frame to catch up.
'video_output' mean = '16522.18', std. dev. = '1815.69', fps = '60.52'
'video_output' mean = '16691.79', std. dev. = '717.70', fps = '59.91'
'video_output' mean = '16681.70', std. dev. = '456.13', fps = '59.95'
2007-05-21 22:05:14.750 NVP: Video is 6.47881 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.750 NVP: Video is 9.47456 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.750 NVP: Video is 11.4816 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.750 NVP: Video is 12.7322 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.750 NVP: Video is 13.4153 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.750 NVP: Video is 13.6879 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.750 NVP: Video is 13.6377 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.750 NVP: Video is 13.3451 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.750 NVP: Video is 12.886 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.750 NVP: Video is 12.2869 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.750 NVP: Video is 11.5828 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.751 NVP: Video is 10.815 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.751 NVP: Video is 9.98442 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.751 NVP: Video is 9.1067 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.751 NVP: Video is 8.20866 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.751 NVP: Video is 7.29533 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.751 NVP: Video is 6.35563 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.751 NVP: Video is 5.39609 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.751 NVP: Video is 4.43667 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.751 NVP: Video is 3.46233 frames behind audio (too
slow), dropping frame to catch up.
2007-05-21 22:05:14.992 Avg read interval was 198 msec. 480K block size
2007-05-21 22:05:15.216 NVP: Video is 4.28442 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.234 NVP: Video is 7.10945 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.250 NVP: Video is 9.21327 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.267 NVP: Video is 10.7911 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.283 NVP: Video is 11.9745 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.300 NVP: Video is 12.8771 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.317 NVP: Video is 13.554 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.334 NVP: Video is 14.0466 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.350 NVP: Video is 14.4162 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.367 NVP: Video is 14.6933 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.383 NVP: Video is 14.9012 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.401 NVP: Video is 15.0571 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.401 NVP: 4800 progressive frames seen.
2007-05-21 22:05:15.417 NVP: Video is 15.1739 frames ahead of audio,
doubling video frame interval to slow down.
'video_output' mean = '13352.45', std. dev. = '6686.59', fps = '74.89'
2007-05-21 22:05:15.433 NVP: Video is 15.2616 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.450 NVP: Video is 15.3424 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.467 NVP: Video is 15.4029 frames ahead of audio,
doubling video frame interval to slow down.
2007-05-21 22:05:15.484 NVP: Video is 15.4484 frames ahead of audio,
doubling video frame interval to slow down.
--------------------------------------
As you can see from the last part of the log, first it thinks its
playing too slowly, then its too fast. This pattern repeats with many
hundred entries like the above.
I am running the on-board audio out the SPDIF optic port on the
motherboard. ALSA thinks this is a Intel 810 audio chip. I sorta
remember that this might be a problem but before running out and
plopping down money for a new sound card I wanted to pass this to the
list for thoughts and suggestions for more diagnostics.
PS - CPU usage runs about 45-50% during playback so it should not be a
processor issue.
Thoughts or suggestions??
TIA,
Bill
More information about the mythtv-users
mailing list