[mythtv-users] prebuffering pauses when playing time stretch from playback group

Wed May 30 17:33:31 UTC 2007

There are some shows that I always watch at 1.5 speed.  Works great
with no problems at all expect that I have to go to the menu and
change it each time.  So I finally got around to setting up a playback
group 'Fast' with the 1.5 speed and set a show to use it.  I start
playing and "Fast Settings" comes up... great... but the video has
severe "prebuffering pauses".  If I go back to the menu change the
speed to 1.2 then back to 1.5 all is well.... but this is obviously
worse since I am changing the speed twice instead of once.. :(

Known issue?  I am using 0.20-fixes rev 13460.
If this is fixed in the trunk can someone point me to the change set?
I did some searching but didn't see anything.

Log is below (-v important,general,playback,osd).  You will see
at the end after switching to 1.2 then to 1.5 again things then work
fine.  I tried turning off xvmc but that didn't solve it.  Any ideas?
Or see any other problems to fix in the log?

2007-05-29 21:20:47.631 TV: Attempting to change from None to
WatchingPreRecorded
2007-05-29 21:20:47.670
RingBuf(/video/recordings/1057_20070426170000.mpg):
OpenFile(/video/recordings/1057_20070426170000.mpg, 12)
2007-05-29 21:20:47.751
RingBuf(/video/recordings/1057_20070426170000.mpg):
CalcReadAheadThresh(4000 KB)
			 -> threshhold(146 KB) min read(32 KB) blk size(64 KB)
0: start_time: 0.036 duration: 328.552
1: start_time: 0.026 duration: 328.521
stream: start_time: 0.289 duration: 3650.691 bitrate=3670 kb/s
2007-05-29 21:20:48.174 AFD: Stream #0, has id 0x480 codec id
MPEG2VIDEO, type Video, bitrate 4000000 at 0x0xb117ba0
2007-05-29 21:20:48.193 VideoOutputXv: XvMC version: 1.1
2007-05-29 21:20:48.194 XvMCSurfaceTypes::find(w 720, h 480, chroma 1,
vld 0, idct 1, mpeg2, sub-width 0, sub-height 0, disp, p<= 204, 1730
<=p, port, surfNum)
2007-05-29 21:20:48.194 Trying XvMC port 173
2007-05-29 21:20:48.255 Found a suitable XvMC surface 0
2007-05-29 21:20:48.256 VideoOutputXv: @ j=1 Looking for flag[s]: XvInputMask
2007-05-29 21:20:48.256 VideoOutputXv: Adaptor#0: NV17 Video Texture
has flag[s]: XvInputMask XvImageMask
2007-05-29 21:20:48.256 XvMCSurfaceTypes::find(w 720, h 480, chroma 1,
vld 0, idct 1, mpeg2, sub-width 0, sub-height 0, disp, p<= 204, 1730
<=p, port, surfNum)
2007-05-29 21:20:48.256 Trying XvMC port 173
2007-05-29 21:20:48.256 Found a suitable XvMC surface 0
2007-05-29 21:20:48.257 VideoOutputXv: Grabbed xv port 173
2007-05-29 21:20:48.257 VideoOutputXv: XvMC surface found with IDCT
support on port 173
2007-05-29 21:20:48.277 VideoOutputXv: Closing XVideo port 173
2007-05-29 21:20:48.277 detectInterlace(Detect Scan, Interlaced Scan,
29.97, 480) ->Interlaced Scan
2007-05-29 21:20:48.278 AFD: Looking for decoder for MPEG2VIDEO_XVMC
2007-05-29 21:20:48.278 AFD: Opened codec 0xb1b47a0,
id(MPEG2VIDEO_XVMC) type(Video)
2007-05-29 21:20:48.278 AFD: Stream #1, has id 0x448 codec id MP2,
type Audio, bitrate 384000 at 0x0xb3d4d90
2007-05-29 21:20:48.278 AFD: Looking for decoder for MP2
2007-05-29 21:20:48.278 AFD: Opened codec 0xb3d8b70, id(MP2) type(Audio)
2007-05-29 21:20:48.297
RingBuf(/video/recordings/1057_20070426170000.mpg):
CalcReadAheadThresh(4384 KB)
			 -> threshhold(160 KB) min read(32 KB) blk size(64 KB)
2007-05-29 21:20:48.314 Opening OSS audio device '/dev/dsp'.
2007-05-29 21:20:48.419 Dec: Trying to select track (w/lang)
2007-05-29 21:20:48.420 Dec: Selecting first track
2007-05-29 21:20:48.420 Dec: Selected track #1 in the Unknown language(0)
2007-05-29 21:20:48.420 Resyncing position map. posmapStarted = 0
livetv(0) watchingRec(0)
2007-05-29 21:20:52.338 Position map filled from DB to: 7296
2007-05-29 21:20:52.340 SyncPositionMap prerecorded, from DB: 7296 entries
2007-05-29 21:20:52.341 SyncPositionMap, new totframes: 109440, new
length: 3651, posMap size: 7296
2007-05-29 21:20:52.341 AFD: Position map found
2007-05-29 21:20:52.341 AFD: Successfully opened decoder for file:
"/video/recordings/1057_20070426170000.mpg". novideo(0)
2007-05-29 21:20:52.363 AO: Using time stretch 1.5
2007-05-29 21:20:52.363 VideoOutputXv: ctor
2007-05-29 21:20:52.364 Over/underscan. V: 0, H: 0.05, XOff: 0, YOff: 0
2007-05-29 21:20:52.365 Display Rect  left: 0, top: 0, width: 800,
height: 600, aspect: 1.33333
2007-05-29 21:20:52.365 Video Rect    left: 36, top: 0, width: 648,
height: 480, aspect: 1.33333
2007-05-29 21:20:52.365 VideoOutputXv: Pixel dimensions: Screen
800x600, window 800x600
2007-05-29 21:20:52.365 VideoOutputXv: Estimated display dimensions:
203x152 mm  Aspect: 1.33553
2007-05-29 21:20:52.365 VideoOutputXv: Estimated window dimensions:
203x152 mm  Aspect: 1.33553
2007-05-29 21:20:52.365 VideoOutputXv: XvMC version: 1.1
2007-05-29 21:20:52.370 VideoOutputXv: XvMCTex: Init failed
2007-05-29 21:20:52.370 VideoOutputXv: Number of bits per pixel is 16,
			but we only support ARGB 32 bbp for ChromaKeyOSD.
2007-05-29 21:20:52.371 VideoOutputXv: @ j=1 Looking for flag[s]: XvInputMask
2007-05-29 21:20:52.371 VideoOutputXv: Adaptor#0: NV17 Video Texture
has flag[s]: XvInputMask XvImageMask
2007-05-29 21:20:52.371 XvMCSurfaceTypes::find(w 720, h 480, chroma 1,
vld 0, idct 1, mpeg2, sub-width 0, sub-height 0, disp, p<= 204, 1730
<=p, port, surfNum)
2007-05-29 21:20:52.371 Trying XvMC port 173
2007-05-29 21:20:52.371 Found a suitable XvMC surface 0
2007-05-29 21:20:52.371 VideoOutputXv: Grabbed xv port 173
2007-05-29 21:20:52.372 VideoOutputXv: XvMC surface found with IDCT
support on port 173
2007-05-29 21:20:52.372 VideoOutputXv: XvMC Adaptor Name: 'NV17 Video Texture'
X Error: BadMatch (invalid parameter attributes) 8
  Major opcode:  141
  Minor opcode:  14
  Resource id:  0x194
2007-05-29 21:20:52.423 VideoOutputXv: Chromakeying not possible with
this XVideo port.
2007-05-29 21:20:52.424 Display Rect  left: 0, top: 0, width: 800,
height: 600, aspect: 1.33333
2007-05-29 21:20:52.424 Video Rect    left: 36, top: 0, width: 648,
height: 480, aspect: 1.33333
2007-05-29 21:20:54.289 NVP: ClearAfterSeek(1)
2007-05-29 21:20:54.289 VideoOutputXv: ClearAfterSeek()
2007-05-29 21:20:54.289 VideoOutputXv: DiscardFrames(0)
2007-05-29 21:20:54.290 VideoOutputXv: DiscardFrames() 1: AAAAAAAA
2007-05-29 21:20:54.290 VideoOutputXv: DiscardFrames() 3: AAAAAAAA -- done()
2007-05-29 21:20:54.290 VideoOutputXv: DiscardFrames(1)
2007-05-29 21:20:54.290 VideoOutputXv: DiscardFrames() 1: AAAAAAAA
2007-05-29 21:20:54.290 VideoOutputXv: DiscardFrames() 2: AAAAAAAA
2007-05-29 21:20:54.290 VideoOutputXv: DiscardFrames() 3: AAAAAAAA -- done()
2007-05-29 21:20:54.293 New DB connection, total: 3
2007-05-29 21:20:54.291 TV: StartPlayer(): took 6400 ms to start player.
2007-05-29 21:20:54.318 TV: Changing from None to WatchingPreRecorded
2007-05-29 21:20:54.319 New DB connection, total: 4
2007-05-29 21:20:54.320 NVP: Changing speed to 1.5
2007-05-29 21:20:54.320
RingBuf(/video/recordings/1057_20070426170000.mpg):
CalcReadAheadThresh(6576 KB)
			 -> threshhold(240 KB) min read(32 KB) blk size(128 KB)
2007-05-29 21:20:54.320 NVP: DoPlay: rate: 29.97 speed: 1.5 skip: 1 =>
new interval 22244
2007-05-29 21:20:54.320 NVP: Stretch Factor 1.5, disable passthru
2007-05-29 21:20:54.327 Connected to database 'mythconverg' at host: mythbackend
2007-05-29 21:20:54.328 Connected to database 'mythconverg' at host: mythbackend
2007-05-29 21:20:54.335 Realtime priority would require SUID as root.
XvMC: picture structure FRAME
2007-05-29 21:20:54.422 nVidiaVideoSync: VBlank ioctl did not work,
unimplemented in this driver?
2007-05-29 21:20:54.422 DRMVideoSync: Could not open device
/dev/dri/card0, No such file or directory
2007-05-29 21:20:54.422 RTCVideoSync: Could not set RTC frequency,
Permission denied.
2007-05-29 21:20:54.422 Using audio as timebase
2007-05-29 21:20:54.423 Video timing method: USleep with busy wait
2007-05-29 21:20:54.423 Refresh rate: 16579, frame interval: 22244
2007-05-29 21:20:54.436 VideoOutputXv Error: ProcessFrameXvMC: Failed
to get OSD lock
2007-05-29 21:20:54.604 NVP: Video is 3.14629 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:54.625 NVP: Video is 3.65218 frames behind audio (too
slow), skipping A/V wait.

..snip similar lines, still a problem...

2007-05-29 21:20:56.754 NVP: Video is 4.3391 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:56.770 NVP: Video is 4.18715 frames behind audio (too
slow), skipping A/V wait.
'video_output' mean = '23355.44', std. dev. = '18758.09', fps = '42.82'

...SNIP another section like the previous, real bad section follows...

'video_output' mean = '22662.19', std. dev. = '19628.18', fps = '44.13'
2007-05-29 21:20:59.059 NVP: Video is 4.04158 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:59.072 NVP: Video is 3.8516 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:59.074 NVP: Video is 3.57427 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:59.080 NVP: Video is 3.02909 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:59.215 NVP: Video is 3.05907 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:59.282 NVP: Video is 3.29698 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:59.283 NVP: Video is 3.32687 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:59.284 NVP: Video is 3.0009 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:59.285 NVP: prebuffering pause
2007-05-29 21:20:59.286 NVP: Waiting for prebuffer.. 0 AAADLDdD
2007-05-29 21:20:59.497 NVP: Video is 3.31609 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:59.498 NVP: Video is 3.21759 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:59.567 NVP: Video is 3.25409 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:59.568 NVP: Video is 3.2273 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:20:59.569 NVP: prebuffering pause
2007-05-29 21:20:59.569 NVP: Waiting for prebuffer.. 0 AAADLAdD
2007-05-29 21:20:59.950 NVP: Video is 3.10349 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:00.017 NVP: Video is 3.29383 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:00.018 NVP: Video is 3.27958 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:00.019 NVP: prebuffering pause
2007-05-29 21:21:00.020 NVP: Waiting for prebuffer.. 0 DDDLAALA
2007-05-29 21:21:00.234 NVP: Video is 3.05557 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:00.300 NVP: Video is 3.60969 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:00.301 NVP: Video is 3.75247 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:00.303 NVP: Video is 3.49991 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:00.303 NVP: prebuffering pause
2007-05-29 21:21:00.304 NVP: Waiting for prebuffer.. 0 DDDLAALD
2007-05-29 21:21:00.312 NVP: prebuffering pause
2007-05-29 21:21:00.313 NVP: Waiting for prebuffer.. 0 DDDdALLD
2007-05-29 21:21:00.319 NVP: prebuffering pause
2007-05-29 21:21:00.320 NVP: Waiting for prebuffer.. 0 DDDdLDLA
2007-05-29 21:21:00.328 NVP: prebuffering pause
2007-05-29 21:21:00.329 NVP: Waiting for prebuffer.. 0 DDDddDLA
2007-05-29 21:21:00.338 NVP: prebuffering pause
2007-05-29 21:21:00.339 NVP: Waiting for prebuffer.. 1 ADDddDLA
2007-05-29 21:21:00.346 NVP: prebuffering pause
2007-05-29 21:21:00.347 NVP: Waiting for prebuffer.. 0 ADDDDDdL
2007-05-29 21:21:00.356 NVP: prebuffering pause
2007-05-29 21:21:00.357 NVP: Waiting for prebuffer.. 1 ADADDDdL
2007-05-29 21:21:00.364 NVP: prebuffering pause
2007-05-29 21:21:00.365 NVP: Waiting for prebuffer.. 0 dAADDDdL
2007-05-29 21:21:00.371 NVP: prebuffering pause
2007-05-29 21:21:00.372 NVP: Waiting for prebuffer.. 0 DAdDDDdL
2007-05-29 21:21:00.381 NVP: prebuffering pause
2007-05-29 21:21:00.382 NVP: Waiting for prebuffer.. 1 DAdADDdL
2007-05-29 21:21:00.389 NVP: prebuffering pause
2007-05-29 21:21:00.390 NVP: Waiting for prebuffer.. 0 DLDADDDd
2007-05-29 21:21:00.398 NVP: prebuffering pause
2007-05-29 21:21:00.399 NVP: Waiting for prebuffer.. 1 DLDADADd
2007-05-29 21:21:00.409 NVP: prebuffering pause
2007-05-29 21:21:00.410 NVP: Waiting for prebuffer.. 0 DLDdDADd
2007-05-29 21:21:00.418 NVP: prebuffering pause
2007-05-29 21:21:00.421 NVP: Waiting for prebuffer.. 1 DLDDAuDd
2007-05-29 21:21:00.424 NVP: prebuffering pause
2007-05-29 21:21:00.425 NVP: Waiting for prebuffer.. 0 DLDDAdDd
2007-05-29 21:21:00.434 NVP: prebuffering pause
2007-05-29 21:21:00.435 NVP: Waiting for prebuffer.. 1 DLDDAdAd
2007-05-29 21:21:00.444 NVP: prebuffering pause
2007-05-29 21:21:00.445 NVP: Waiting for prebuffer.. 0 DdDDLDAD
2007-05-29 21:21:00.454 NVP: prebuffering pause
2007-05-29 21:21:00.455 NVP: Waiting for prebuffer.. 1 AdDDLDAD
2007-05-29 21:21:00.462 NVP: prebuffering pause
2007-05-29 21:21:00.462 NVP: Waiting for prebuffer.. 0 AdDDLDdD
2007-05-29 21:21:00.471 NVP: prebuffering pause
2007-05-29 21:21:00.472 NVP: Waiting for prebuffer.. 1 AdADLDdD
2007-05-29 21:21:00.478 NVP: prebuffering pause
2007-05-29 21:21:00.479 NVP: Waiting for prebuffer.. 0 ddADLDDD
2007-05-29 21:21:00.488 NVP: prebuffering pause
2007-05-29 21:21:00.489 NVP: Waiting for prebuffer.. 1 ddADLDDA
2007-05-29 21:21:00.499 NVP: prebuffering pause
2007-05-29 21:21:00.499 NVP: Waiting for prebuffer.. 0 DDLAdDDA
2007-05-29 21:21:00.507 NVP: prebuffering pause
2007-05-29 21:21:00.508 NVP: Waiting for prebuffer.. 0 DDLAdDDd
2007-05-29 21:21:00.517 NVP: prebuffering pause
2007-05-29 21:21:00.518 NVP: Waiting for prebuffer.. 1 DDLAdADd
2007-05-29 21:21:00.525 NVP: prebuffering pause
2007-05-29 21:21:00.526 NVP: Waiting for prebuffer.. 0 DDLddADD
2007-05-29 21:21:00.536 NVP: prebuffering pause
2007-05-29 21:21:00.537 NVP: Waiting for prebuffer.. 1 DALddADD
2007-05-29 21:21:00.544 NVP: prebuffering pause
2007-05-29 21:21:00.545 NVP: Waiting for prebuffer.. 0 DAdDDLDD
2007-05-29 21:21:00.554 NVP: prebuffering pause
2007-05-29 21:21:00.555 NVP: Waiting for prebuffer.. 1 DAdDDLAD
2007-05-29 21:21:00.561 NVP: prebuffering pause
2007-05-29 21:21:00.562 NVP: Waiting for prebuffer.. 0 DddDDLAD
2007-05-29 21:21:00.571 NVP: prebuffering pause
2007-05-29 21:21:00.572 NVP: Waiting for prebuffer.. 1 AddDDLAD
2007-05-29 21:21:00.579 NVP: prebuffering pause
2007-05-29 21:21:00.579 NVP: Waiting for prebuffer.. 0 ADdDDLdD
2007-05-29 21:21:00.588 NVP: prebuffering pause
2007-05-29 21:21:00.589 NVP: Waiting for prebuffer.. 1 ADdDALdD
2007-05-29 21:21:00.596 NVP: prebuffering pause
2007-05-29 21:21:00.597 NVP: Waiting for prebuffer.. 0 LDDDAdDD
2007-05-29 21:21:00.605 NVP: prebuffering pause
2007-05-29 21:21:00.606 NVP: Waiting for prebuffer.. 1 LDDDAdDA
2007-05-29 21:21:00.612 NVP: prebuffering pause
2007-05-29 21:21:00.613 NVP: Waiting for prebuffer.. 0 LDDDddDA
2007-05-29 21:21:00.621 NVP: prebuffering pause
2007-05-29 21:21:00.622 NVP: Waiting for prebuffer.. 1 LDDAddDA
2007-05-29 21:21:00.633 NVP: prebuffering pause
2007-05-29 21:21:00.634 NVP: Waiting for prebuffer.. 0 LDAADdDd
2007-05-29 21:21:00.639 NVP: prebuffering pause
2007-05-29 21:21:00.640 NVP: Waiting for prebuffer.. 0 dDALDDDD
2007-05-29 21:21:00.649 NVP: prebuffering pause
2007-05-29 21:21:00.650 NVP: Waiting for prebuffer.. 1 dAALDDDD
2007-05-29 21:21:00.676 NVP: Video is 4.92268 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:00.677 NVP: prebuffering pause
2007-05-29 21:21:00.677 NVP: Waiting for prebuffer.. 0 dLDLDDAD
2007-05-29 21:21:00.706 NVP: Video is 8.35619 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:00.707 NVP: prebuffering pause
2007-05-29 21:21:00.707 NVP: Waiting for prebuffer.. 0 ddDLAAAD
2007-05-29 21:21:00.744 NVP: Video is 10.8077 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:00.799 NVP: Video is 12.3766 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:00.854 NVP: Video is 13.0025 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:00.910 NVP: Video is 12.9325 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:00.966 NVP: Video is 12.2956 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:01.021 NVP: Video is 11.2447 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:01.077 NVP: Video is 9.90582 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:01.132 NVP: Video is 8.32845 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:01.188 NVP: Video is 6.60596 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:01.243 NVP: Video is 4.74092 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:01.383 NVP: Video is 3.39503 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:01.385 NVP: Video is 3.76007 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:01.386 NVP: Video is 3.68544 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:01.388 NVP: Video is 3.26983 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:01.389 NVP: prebuffering pause
2007-05-29 21:21:01.390 NVP: Waiting for prebuffer.. 0 DLDDADDL
'video_output' mean = '23540.94', std. dev. = '19900.82', fps = '42.48'
2007-05-29 21:21:01.395 NVP: prebuffering pause
2007-05-29 21:21:01.396 NVP: Waiting for prebuffer.. 0 DLDDADDd
2007-05-29 21:21:01.405 NVP: prebuffering pause
2007-05-29 21:21:01.406 NVP: Waiting for prebuffer.. 1 DLDDAADd
2007-05-29 21:21:01.416 NVP: prebuffering pause
2007-05-29 21:21:01.417 NVP: Waiting for prebuffer.. 0 DLDAdADd
2007-05-29 21:21:01.422 NVP: prebuffering pause
2007-05-29 21:21:01.423 NVP: Waiting for prebuffer.. 0 DLDADdDd
2007-05-29 21:21:01.432 NVP: prebuffering pause
2007-05-29 21:21:01.433 NVP: Waiting for prebuffer.. 1 DLDADdAd
2007-05-29 21:21:01.443 NVP: prebuffering pause
2007-05-29 21:21:01.444 NVP: Waiting for prebuffer.. 0 DdDLDDAD
2007-05-29 21:21:01.453 NVP: prebuffering pause
2007-05-29 21:21:01.454 NVP: Waiting for prebuffer.. 1 AdDLDDAD
2007-05-29 21:21:01.458 NVP: prebuffering pause
2007-05-29 21:21:01.459 NVP: Waiting for prebuffer.. 0 AdDLDDdD
2007-05-29 21:21:01.468 NVP: prebuffering pause
2007-05-29 21:21:01.469 NVP: Waiting for prebuffer.. 1 AdALDDdD
2007-05-29 21:21:01.475 NVP: prebuffering pause
2007-05-29 21:21:01.476 NVP: Waiting for prebuffer.. 0 ddALDDDD
2007-05-29 21:21:01.485 NVP: prebuffering pause
2007-05-29 21:21:01.486 NVP: Waiting for prebuffer.. 1 ddALDDDA
2007-05-29 21:21:01.493 NVP: prebuffering pause
2007-05-29 21:21:01.494 NVP: Waiting for prebuffer.. 0 DDLdDDDA
2007-05-29 21:21:01.503 NVP: prebuffering pause
2007-05-29 21:21:01.508 NVP: Waiting for prebuffer.. 1 DDLdADDu
2007-05-29 21:21:01.521 NVP: prebuffering pause
2007-05-29 21:21:01.521 NVP: Waiting for prebuffer.. 0 DDLdLADD
2007-05-29 21:21:01.528 NVP: prebuffering pause
2007-05-29 21:21:01.529 NVP: Waiting for prebuffer.. 0 DDLddADD
2007-05-29 21:21:01.537 NVP: prebuffering pause
2007-05-29 21:21:01.538 NVP: Waiting for prebuffer.. 1 DALddADD
2007-05-29 21:21:01.545 NVP: prebuffering pause
2007-05-29 21:21:01.546 NVP: Waiting for prebuffer.. 0 DAdDDLDD
2007-05-29 21:21:01.555 NVP: prebuffering pause
2007-05-29 21:21:01.555 NVP: Waiting for prebuffer.. 1 DAdDDLAD
2007-05-29 21:21:01.562 NVP: prebuffering pause
2007-05-29 21:21:01.563 NVP: Waiting for prebuffer.. 0 DddDDLAD
2007-05-29 21:21:01.572 NVP: prebuffering pause
2007-05-29 21:21:01.573 NVP: Waiting for prebuffer.. 1 AddDDLAD
2007-05-29 21:21:01.581 NVP: prebuffering pause
2007-05-29 21:21:01.582 NVP: Waiting for prebuffer.. 0 ADdDDLdD
2007-05-29 21:21:01.590 NVP: prebuffering pause
2007-05-29 21:21:01.591 NVP: Waiting for prebuffer.. 1 ADdADLdD
2007-05-29 21:21:01.603 NVP: prebuffering pause
2007-05-29 21:21:01.604 NVP: Waiting for prebuffer.. 0 LDDADdDA
2007-05-29 21:21:01.609 NVP: prebuffering pause
2007-05-29 21:21:01.610 NVP: Waiting for prebuffer.. 0 LDDdDdDA
2007-05-29 21:21:01.619 NVP: prebuffering pause
2007-05-29 21:21:01.619 NVP: Waiting for prebuffer.. 1 LDDdAdDA
2007-05-29 21:21:01.628 NVP: prebuffering pause
2007-05-29 21:21:01.629 NVP: Waiting for prebuffer.. 0 LDDDAdDd
2007-05-29 21:21:01.638 NVP: prebuffering pause
2007-05-29 21:21:01.639 NVP: Waiting for prebuffer.. 1 LDADAdDd
2007-05-29 21:21:01.694 NVP: Video is 4.7063 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:01.749 NVP: Video is 5.93486 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:01.804 NVP: Video is 6.3168 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:01.860 NVP: Video is 6.04131 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:01.915 NVP: Video is 5.28399 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:01.971 NVP: Video is 4.14278 frames ahead of audio,
			doubling video frame interval to slow down.
2007-05-29 21:21:02.145 NVP: Video is 3.17115 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.146 NVP: Video is 3.43481 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.150 NVP: Video is 3.31788 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.151 NVP: prebuffering pause
2007-05-29 21:21:02.151 NVP: Waiting for prebuffer.. 0 DDDALALA
2007-05-29 21:21:02.347 NVP: Video is 3.46862 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.349 NVP: Video is 3.60174 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.350 NVP: Video is 3.34189 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.351 NVP: prebuffering pause
2007-05-29 21:21:02.352 NVP: Waiting for prebuffer.. 0 ALADLDAD
2007-05-29 21:21:02.363 NVP: prebuffering pause
2007-05-29 21:21:02.364 NVP: Waiting for prebuffer.. 0 LdADLDAD
2007-05-29 21:21:02.641 NVP: Video is 3.22433 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.642 NVP: Video is 3.07009 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.714 NVP: Video is 3.05871 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.715 NVP: Video is 3.03578 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.716 NVP: prebuffering pause
2007-05-29 21:21:02.717 NVP: Waiting for prebuffer.. 0 DDLAALDA
2007-05-29 21:21:02.916 NVP: Video is 3.47635 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.917 NVP: Video is 3.58506 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.918 NVP: Video is 3.31815 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:02.919 NVP: prebuffering pause
2007-05-29 21:21:02.919 NVP: Waiting for prebuffer.. 0 AAADDLLD
2007-05-29 21:21:03.243 NVP: Video is 3.05435 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:03.309 NVP: Video is 3.32238 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:03.310 NVP: Video is 3.36841 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:03.312 NVP: Video is 3.03205 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:03.312 NVP: prebuffering pause
2007-05-29 21:21:03.313 NVP: Waiting for prebuffer.. 0 LAALDDDD
2007-05-29 21:21:03.643 NVP: Video is 3.08915 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:03.709 NVP: Video is 3.34481 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:03.710 NVP: 400 interlaced frames seen.
2007-05-29 21:21:03.711 NVP: Video is 3.38523 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:03.713 NVP: Video is 3.05588 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:03.714 NVP: prebuffering pause
2007-05-29 21:21:03.715 NVP: Waiting for prebuffer.. 0 LAADLDDD
'video_output' mean = '23498.76', std. dev. = '18405.87', fps = '42.56'
2007-05-29 21:21:04.029 NVP: Video is 3.06658 frames behind audio (too
slow), skipping A/V wait.

...SNIP a lot more bad stuff, changing to 1.2 then 1.5 here...

2007-05-29 21:21:26.584 NVP: Video is 3.69996 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:26.601 NVP: Video is 4.16858 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:26.618 NVP: Video is 4.43014 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:26.635 NVP: Video is 4.55889 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:26.652 NVP: Play(  1.2, normal 1, unpause audio 1)
2007-05-29 21:21:26.654 NVP: Video is 4.57678 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:26.668 NVP: Changing speed to 1.2
2007-05-29 21:21:26.668
RingBuf(/video/recordings/1057_20070426170000.mpg):
CalcReadAheadThresh(5260 KB)
			 -> threshhold(192 KB) min read(32 KB) blk size(128 KB)
2007-05-29 21:21:26.668 NVP: DoPlay: rate: 29.97 speed: 1.2 skip: 1 =>
new interval 27805
2007-05-29 21:21:26.668 Set video sync frame interval to 27805
2007-05-29 21:21:26.668 NVP: Stretch Factor 1.2, disable passthru
2007-05-29 21:21:26.669 AO: Changing time stretch to 1.2
2007-05-29 21:21:26.671 NVP: Video is 4.51151 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:26.684 NVP: Video is 3.65995 frames behind audio (too
slow), skipping A/V wait.

..snip similar lines, still a problem...

2007-05-29 21:21:27.168 NVP: Video is 3.18461 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:27.187 NVP: Video is 3.01784 frames behind audio (too
slow), skipping A/V wait.
'video_output' mean = '23520.46', std. dev. = '18847.22', fps = '42.52'
2007-05-29 21:21:27.270 NVP: Video is 3.02147 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:27.285 NVP: Video is 3.09329 frames behind audio (too
slow), skipping A/V wait.

..snip similar lines, still a problem...

2007-05-29 21:21:28.070 NVP: Video is 3.0241 frames behind audio (too
slow), skipping A/V wait.
2007-05-29 21:21:28.154 NVP: Video is 3.01273 frames behind audio (too
slow), skipping A/V wait.
'video_output' mean = '27531.53', std. dev. = '8593.25', fps = '36.32'

... change to 1.5, starts working ...

2007-05-29 21:21:32.125 NVP: Play(  1.5, normal 1, unpause audio 1)
2007-05-29 21:21:32.135 NVP: Changing speed to 1.5
2007-05-29 21:21:32.135
RingBuf(/video/recordings/1057_20070426170000.mpg):
CalcReadAheadThresh(6576 KB)
			 -> threshhold(240 KB) min read(32 KB) blk size(128 KB)
2007-05-29 21:21:32.135 NVP: DoPlay: rate: 29.97 speed: 1.5 skip: 1 =>
new interval 22244
2007-05-29 21:21:32.136 Set video sync frame interval to 22244
2007-05-29 21:21:32.136 NVP: Stretch Factor 1.5, disable passthru
2007-05-29 21:21:32.136 AO: Changing time stretch to 1.5
2007-05-29 21:21:32.514 NVP: 1600 interlaced frames seen.
'video_output' mean = '26661.56', std. dev. = '3312.53', fps = '37.51'
'video_output' mean = '22356.59', std. dev. = '4364.14', fps = '44.73'
'video_output' mean = '22078.06', std. dev. = '3328.75', fps = '45.29'
'video_output' mean = '22241.50', std. dev. = '314.65', fps = '44.96'
2007-05-29 21:21:41.410 NVP: 2000 interlaced frames seen.
'video_output' mean = '22242.55', std. dev. = '393.74', fps = '44.96'
'video_output' mean = '22243.48', std. dev. = '435.26', fps = '44.96'
'video_output' mean = '22242.46', std. dev. = '390.21', fps = '44.96'
'video_output' mean = '22246.24', std. dev. = '374.03', fps = '44.95'
2007-05-29 21:21:50.308 NVP: 2400 interlaced frames seen.
'video_output' mean = '22237.36', std. dev. = '432.87', fps = '44.97'
'video_output' mean = '22240.39', std. dev. = '424.00', fps = '44.96'
'video_output' mean = '22249.55', std. dev. = '385.52', fps = '44.94'
'video_output' mean = '22242.38', std. dev. = '398.11', fps = '44.96'
2007-05-29 21:21:58.023 TV: Attempting to change from
WatchingPreRecorded to None
2007-05-29 21:21:58.043 TV: StopStuff() -- begin
2007-05-29 21:21:58.043 TV: StopStuff(): stopping ring buffer[s]
2007-05-29 21:21:58.065 TV: StopStuff(): stopping player[s] (1/2)
2007-05-29 21:21:58.065 TV: StopStuff(): stopping player[s] (2/2)
2007-05-29 21:21:58.077 NVP: Exited decoder loop.
2007-05-29 21:21:58.117 VideoOutputXv: dtor
2007-05-29 21:21:58.117 VideoOutputXv: DiscardFrames(1)
2007-05-29 21:21:58.117 VideoOutputXv: DiscardFrames() 1: DDuuALAA
2007-05-29 21:21:58.117 VideoOutputXv: Frame D is in use by avlib and
so is being held for later discarding.
2007-05-29 21:21:58.117 VideoOutputXv: DiscardFrames() 2: ADddADAA
2007-05-29 21:21:58.117 VideoOutputXv: Frame C is in use by avlib and
so is being held for later discarding.
2007-05-29 21:21:58.118 VideoOutputXv: Frame D is in use by avlib and
so is being held for later discarding.
2007-05-29 21:21:58.118 VideoOutputXv: Frame C is in use by avlib and
so is being held for later discarding.
2007-05-29 21:21:58.118 VideoOutputXv: Frame D is in use by avlib and
so is being held for later discarding.
2007-05-29 21:21:58.118 VideoOutputXv: DiscardFrames() 3: ADddAAAA -- done()
2007-05-29 21:21:58.118 VideoOutputXv: DiscardFrames(1)
2007-05-29 21:21:58.118 VideoOutputXv: DiscardFrames() 1: ADddAAAA
2007-05-29 21:21:58.119 VideoOutputXv: Frame C is in use by avlib and
so is being held for later discarding.
2007-05-29 21:21:58.119 VideoOutputXv: Frame D is in use by avlib and
so is being held for later discarding.
2007-05-29 21:21:58.119 VideoOutputXv: DiscardFrames() 2: ADddAAAA
2007-05-29 21:21:58.119 VideoOutputXv: Frame C is in use by avlib and
so is being held for later discarding.
2007-05-29 21:21:58.119 VideoOutputXv: Frame D is in use by avlib and
so is being held for later discarding.
2007-05-29 21:21:58.119 VideoOutputXv: DiscardFrames() 3: ADddAAAA -- done()
2007-05-29 21:21:58.125 VideoOutputXv: Closing XVideo port 173
2007-05-29 21:21:58.238 TV: StopStuff() -- end
2007-05-29 21:21:58.238 TV: Changing from WatchingPreRecorded to None