[mythtv] [Fwd: Re: r9061 still fails at program boundary]

Tue Feb 21 11:01:11 UTC 2006

Rats - too big. Try again....

> On Monday 20 February 2006 16:54, Robin Gilks wrote:
>> Just upgraded to SVN r9061 before breakfast today to check out the fixes
>> that Isaac checked in last night. Still broken for me:-(
>>
>> I've not had a chance to dump a detailed log yet (work calls!) but here
>> is
>> the standard (non-verbose) frontend log from starting LiveTV a couple of
>> minutes before a program change. Note that it normally seems to take 3
>> goes at finding the file...
>
> Reproduce it with >= r9065, and don't bother sending an email unless it's
> with
> -v playback on the frontend.
>
>

Now at r9065, log from mythfrontend -v playback. The full bzip2 log can be
found at http://gilks.ath.cx/~g8ecj/mythfrontend.log.bz2. Here is a small
extract.

[******************* marker **************]
2006-02-21 20:29:37.410 TV: Attempting to change from None to WatchingLiveTV
2006-02-21 20:29:37.420 Using protocol version 27
2006-02-21 20:29:38.811 LiveTVChain(live-media-2006-02-21T20:29:37):
ReloadAll(): Added new recording
2006-02-21 20:29:38.857 RingBuf(/mnt/store//2013_20060221202938.mpg):
OpenFile(/mnt/store//2013_20060221202938.mpg, 12)
2006-02-21 20:29:38.929 RingBuf(/mnt/store//2013_20060221202938.mpg):
Invalid file (fd 16) when opening '/mnt/store//2013_20060221202938.mpg'.
12 retries remaining.
2006-02-21 20:29:39.431 RingBuf(/mnt/store//2013_20060221202938.mpg):
Invalid file (fd 16) when opening '/mnt/store//2013_20060221202938.mpg'.
11 retries remaining.
2006-02-21 20:29:39.934 RingBuf(/mnt/store//2013_20060221202938.mpg):
Invalid file (fd 16) when opening '/mnt/store//2013_20060221202938.mpg'.
10 retries remaining.
2006-02-21 20:29:40.448 TV: StartRecorder(): took 10 ms to start recorder.
2006-02-21 20:29:40.575 reads allowed (128001 -1)
2006-02-21 20:29:40.586 reads allowed (128001 -1)
[mpeg @ 0xb7670360]Parser not found for Codec Id: 94210 !
2006-02-21 20:29:41.484 reads allowed (128001 -1)
2006-02-21 20:29:41.488 reads allowed (128001 -1)
2006-02-21 20:29:42.065 reads allowed (128001 -1)
2006-02-21 20:29:42.705 reads allowed (128001 -1)
2006-02-21 20:29:42.708 reads allowed (128001 -1)
0: start_time: 0.036 duration: 0.176
1: start_time: 774.761 duration: 0.187
2: start_time: 0.025 duration: 0.143
stream: start_time: 0.276 duration: 8610.261 bitrate=1 kb/s
2006-02-21 20:29:42.709 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO,
type Video at 0x0x828f600
2006-02-21 20:29:42.711 reads allowed (128001 -1)
2006-02-21 20:29:42.722 VideoOutputXv: XvMC version: 1.1
2006-02-21 20:29:42.724 XvMCSurfaceTypes::find(w 320, h 576, chroma 1, vld
1, idct 0, mpeg2, sub-width 0, sub-height 0, disp, p<= 68, 680 <=p, port,
surfNum)
2006-02-21 20:29:42.725 Trying XvMC port 68
2006-02-21 20:29:42.785 Found a suitable XvMC surface 0
2006-02-21 20:29:42.785 VideoOutputXv: @ j=0 Looking for flag[s]: XvInputMask
2006-02-21 20:29:42.785 VideoOutputXv: Adaptor: 0 has flag[s]: XvInputMask
XvImageMask
2006-02-21 20:29:42.785 XvMCSurfaceTypes::find(w 320, h 576, chroma 1, vld
1, idct 0, mpeg2, sub-width 0, sub-height 0, disp, p<= 68, 680 <=p, port,
surfNum)
2006-02-21 20:29:42.786 Trying XvMC port 68
2006-02-21 20:29:42.786 Found a suitable XvMC surface 0
2006-02-21 20:29:42.786 VideoOutputXv: Grabbed xv port 68
2006-02-21 20:29:42.787 VideoOutputXv: XvMC surface found with VLD support
on port 68
2006-02-21 20:29:42.791 VideoOutputXv: Closing XVideo port 68
2006-02-21 20:29:42.792 detectInterlace(Detect Scan, Detect Scan, 25, 576)
->Interlaced Scan
2006-02-21 20:29:42.792 Interlaced: Interlaced Scan  video_height: 576
fps: 25
2006-02-21 20:29:42.792 AFD: Looking for decoder for MPEG2VIDEO_XVMC_VLD
2006-02-21 20:29:42.792 AFD: Opened codec 0x82eff80,
id(MPEG2VIDEO_XVMC_VLD) type(Video)
2006-02-21 20:29:42.793 AFD: Stream #1, has id 0x105 codec id MPEG2VBI,
type Data at 0x0x82f0ab0
2006-02-21 20:29:42.803 AFD: data codec (Data)
2006-02-21 20:29:42.803 AFD: Stream #2, has id 0x448 codec id MP2, type
Audio at 0x0x8270520
2006-02-21 20:29:42.804 AFD: Looking for decoder for MP2
2006-02-21 20:29:42.922 AFD: Opened codec 0x82eccd0, id(MP2) type(Audio)
2006-02-21 20:29:43.159 RingBuf(/mnt/store//2013_20060221202938.mpg):
CalcReadAheadThresh(4456 KB)
			 -> threshhold(163 KB) min read(32 KB) blk size(128 KB)
2006-02-21 20:29:43.161 Opening audio device 'default'.
2006-02-21 20:29:43.164 reads allowed (1341317 32768)
2006-02-21 20:29:43.320 Resyncing position map. posmapStarted = 0
livetv(1) watchingRec(0)
2006-02-21 20:29:43.324 Position map filled from DB to: 6
2006-02-21 20:29:43.324 SyncPositionMap watchingrecording, from DB: 6 entries
2006-02-21 20:29:43.329 Filling position map from 7 to 6
2006-02-21 20:29:43.335 Position map filled from Encoder to: 6
2006-02-21 20:29:43.336 SyncPositionMap watchingrecording total: 6 entries
2006-02-21 20:29:43.336 SyncPositionMap, new totframes: 72, new length: 2,
posMap size: 6
2006-02-21 20:29:43.336 AFD: Partial position map found
2006-02-21 20:29:43.336 AFD: Successfully opened decoder for file:
"/mnt/store//2013_20060221202938.mpg". novideo(0)
2006-02-21 20:29:43.354 VideoOutputXv: ctor
2006-02-21 20:29:43.370 Over/underscan. V: 0, H: 0, XOff: 0, YOff: 0
2006-02-21 20:29:43.380 Snapping height to avoid scaling: disphoff 576,
dispyoff: 0
2006-02-21 20:29:43.382 Image size. dispxoff 0, dispyoff: 0, dispwoff:
720, disphoff: 576, dispaspect: 1.33333
2006-02-21 20:29:43.383 Image size. imgx 0, imgy: 0, imgw: 320, imgh: 576,
aspect: 1.33333
2006-02-21 20:29:43.383 VideoOutputXv: Pixel dimensions: Screen 720x576,
window 720x576
2006-02-21 20:29:43.383 VideoOutputXv: Estimated display dimensions:
244x195 mm Aspect: 1.25128
2006-02-21 20:29:43.384 VideoOutputXv: Estimated window dimensions:
244x195 mm Aspect: 1.25128
2006-02-21 20:29:43.386 VideoOutputXv: @ j=0 Looking for flag[s]: XvInputMask
2006-02-21 20:29:43.386 VideoOutputXv: Adaptor: 0 has flag[s]: XvInputMask
XvImageMask
2006-02-21 20:29:43.386 XvMCSurfaceTypes::find(w 320, h 576, chroma 1, vld
1, idct 0, mpeg2, sub-width 0, sub-height 0, disp, p<= 68, 680 <=p, port,
surfNum)
2006-02-21 20:29:43.386 Trying XvMC port 68
2006-02-21 20:29:43.388 Found a suitable XvMC surface 0
2006-02-21 20:29:43.388 VideoOutputXv: Grabbed xv port 68
2006-02-21 20:29:43.388 VideoOutputXv: XvMC surface found with VLD support
on port 68
2006-02-21 20:29:43.398 Snapping height to avoid scaling: disphoff 576,
dispyoff: 0
2006-02-21 20:29:43.398 Image size. dispxoff 0, dispyoff: 0, dispwoff:
720, disphoff: 576, dispaspect: 1.25128
2006-02-21 20:29:43.399 Image size. imgx 0, imgy: 0, imgw: 320, imgh: 576,
aspect: 1.33333
2006-02-21 20:29:44.342 NVP: ClearAfterSeek()
2006-02-21 20:29:44.342 VideoOutputXv: ClearAfterSeek()
2006-02-21 20:29:44.343 VideoOutputXv: DiscardFrames() 1: AAAAAAAAAAAAAAAA
2006-02-21 20:29:44.343 VideoOutputXv: DiscardFrames() 2: AAAAAAAAAAAAAAAA
2006-02-21 20:29:44.343 VideoOutputXv: DiscardFrames() 3: AAAAAAAAAAAAAAAA
2006-02-21 20:29:44.343 VideoOutputXv: DiscardFrames() 4: AAAAAAAAAAAAAAAA
-- done()
2006-02-21 20:29:44.344 TV: StartPlayer(): took 3775 ms to start player.
2006-02-21 20:29:44.344 TV: Changing from None to WatchingLiveTV
2006-02-21 20:29:44.344 VideoOutputXv: DiscardFrames() 1: AAAAAAAAAAAAAAAA
2006-02-21 20:29:44.345 VideoOutputXv: DiscardFrames() 2: AAAAAAAAAAAAAAAA
2006-02-21 20:29:44.346 VideoOutputXv: DiscardFrames() 3: AAAAAAAAAAAAAAAA
2006-02-21 20:29:44.347 VideoOutputXv: DiscardFrames() 4: AAAAAAAAAAAAAAAA
-- done()
2006-02-21 20:29:44.355 Realtime priority would require SUID as root.
2006-02-21 20:29:44.408 nVidiaVideoSync: Could not open device
/dev/nvidia0, No such file or directory
2006-02-21 20:29:44.432 reads allowed (131073 32768)
2006-02-21 20:29:44.457 Using audio as timebase
2006-02-21 20:29:44.457 Video timing method: DRM
2006-02-21 20:29:44.458 Refresh rate: 20000, frame interval: 40000
2006-02-21 20:29:44.459 reads allowed (131073 32768)
2006-02-21 20:29:44.527 AFD: HandleGopStart: gopset not set, syncing
positionMap
2006-02-21 20:29:44.527 Resyncing position map. posmapStarted = 0
livetv(1) watchingRec(1)
2006-02-21 20:29:44.529 Position map filled from DB to: 6
2006-02-21 20:29:44.530 SyncPositionMap watchingrecording, from DB: 6 entries
2006-02-21 20:29:44.540 Filling position map from 7 to 9
2006-02-21 20:29:44.546 Position map filled from Encoder to: 9
2006-02-21 20:29:44.547 SyncPositionMap watchingrecording total: 9 entries
2006-02-21 20:29:44.547 SyncPositionMap, new totframes: 108, new length:
4, posMap size: 9
2006-02-21 20:29:44.547 AFD: HandleGopStart: Initial key frame distance: 12.
2006-02-21 20:29:45.141 reads allowed (131073 32768)
2006-02-21 20:29:47.376 reads allowed (131073 32768)
2006-02-21 20:29:47.389 reads allowed (131073 32768)
'video_output' mean = '40358.16', std. dev. = '4372.94', fps = '24.78'
2006-02-21 20:29:48.687 reads allowed (131073 32768)
2006-02-21 20:29:48.744 AFD: positionMap[ 9 ] == 2012402.
2006-02-21 20:29:49.179 reads allowed (131073 32768)
2006-02-21 20:29:49.235 AFD: positionMap[ 10 ] == 2230018.
2006-02-21 20:29:49.704 AFD: positionMap[ 11 ] == 2461970.
2006-02-21 20:29:50.184 AFD: positionMap[ 12 ] == 2677538.
2006-02-21 20:29:50.664 AFD: positionMap[ 13 ] == 2895198.
2006-02-21 20:29:51.144 AFD: positionMap[ 14 ] == 3041134.
2006-02-21 20:29:51.624 AFD: positionMap[ 15 ] == 3254654.
2006-02-21 20:29:52.221 reads allowed (131073 32768)
2006-02-21 20:29:52.228 AFD: positionMap[ 16 ] == 3492750.
2006-02-21 20:29:52.380 reads allowed (131073 32768)
'video_output' mean = '40003.62', std. dev. = '6837.62', fps = '25.00'
2006-02-21 20:29:52.584 AFD: positionMap[ 17 ] == 3794334.
2006-02-21 20:29:53.064 AFD: positionMap[ 18 ] == 4024238.
2006-02-21 20:29:53.210 reads allowed (131073 32768)
2006-02-21 20:29:53.544 AFD: positionMap[ 19 ] == 4200894.
2006-02-21 20:29:54.024 AFD: positionMap[ 20 ] == 4299726.
2006-02-21 20:29:54.334 reads allowed (131073 32768)
2006-02-21 20:29:54.504 AFD: positionMap[ 21 ] == 4423134.
2006-02-21 20:29:54.576 reads allowed (131073 32768)
2006-02-21 20:29:54.984 AFD: positionMap[ 22 ] == 4575214.
2006-02-21 20:29:55.464 AFD: positionMap[ 23 ] == 4747774.
2006-02-21 20:29:55.944 AFD: positionMap[ 24 ] == 4926478.
2006-02-21 20:29:56.424 AFD: positionMap[ 25 ] == 5111326.
'video_output' mean = '39994.66', std. dev. = '1889.97', fps = '25.00'
2006-02-21 20:29:56.554 reads allowed (131073 32768)
2006-02-21 20:29:56.904 AFD: positionMap[ 26 ] == 5306414.
2006-02-21 20:29:56.992 reads allowed (131073 32768)
2006-02-21 20:29:57.384 AFD: positionMap[ 27 ] == 5509694.
2006-02-21 20:29:57.478 reads allowed (131073 32768)
2006-02-21 20:29:57.864 AFD: positionMap[ 28 ] == 5704782.
2006-02-21 20:29:57.922 reads allowed (131073 32768)
2006-02-21 20:29:58.018 reads allowed (131073 32768)
2006-02-21 20:29:58.243 reads allowed (131073 32768)
2006-02-21 20:29:58.344 AFD: positionMap[ 29 ] == 5893726.
2006-02-21 20:29:58.824 AFD: positionMap[ 30 ] == 6041710.
2006-02-21 20:29:59.177 reads allowed (131073 32768)
2006-02-21 20:29:59.196 reads allowed (131073 32768)
2006-02-21 20:29:59.304 AFD: positionMap[ 31 ] == 6287998.
2006-02-21 20:29:59.567 reads allowed (131073 32768)
2006-02-21 20:29:59.784 AFD: positionMap[ 32 ] == 6505614.
2006-02-21 20:29:59.977 reads allowed (131073 32768)
2006-02-21 20:29:59.983 reads allowed (131073 32768)
2006-02-21 20:30:00.219 reads allowed (131073 32768)
2006-02-21 20:30:00.264 AFD: positionMap[ 33 ] == 6710942.
'video_output' mean = '39989.06', std. dev. = '2025.96', fps = '25.01'
2006-02-21 20:30:00.745 AFD: positionMap[ 34 ] == 6930606.
2006-02-21 20:30:00.830 LiveTVChain(live-media-2006-02-21T20:29:37):
ReloadAll(): Added new recording
2006-02-21 20:30:00.831 Resyncing position map. posmapStarted = 0
livetv(1) watchingRec(0)
2006-02-21 20:30:00.835 Position map filled from DB to: 44
2006-02-21 20:30:00.835 SyncPositionMap watchingrecording, from DB: 44
entries
2006-02-21 20:30:00.835 SyncPositionMap watchingrecording no entries from
encoder, try DB
2006-02-21 20:30:00.839 Position map filled from DB to: 44
2006-02-21 20:30:00.839 SyncPositionMap watchingrecording total: 44 entries
2006-02-21 20:30:00.839 SyncPositionMap, new totframes: 528, new length:
21, posMap size: 44
2006-02-21 20:30:01.539 LiveTVChain(live-media-2006-02-21T20:29:37):
SwitchTo(1)
2006-02-21 20:30:01.539 LiveTVChain(live-media-2006-02-21T20:29:37):
Entry at 1: '2013_20060221203000'
2006-02-21 20:30:01.567 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1116KB) vfl(12) frh(50) ne:0
2006-02-21 20:30:01.579 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1116KB) vfl(12) frh(50) ne:0
2006-02-21 20:30:01.609 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1116KB) vfl(12) frh(50) ne:0
2006-02-21 20:30:01.623 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1084KB) vfl(13) frh(48) ne:0
2006-02-21 20:30:01.635 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1084KB) vfl(12) frh(48) ne:0
2006-02-21 20:30:01.646 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1084KB) vfl(12) frh(48) ne:0
2006-02-21 20:30:01.657 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1084KB) vfl(12) frh(48) ne:0
2006-02-21 20:30:01.671 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1051KB) vfl(12) frh(47) ne:0
2006-02-21 20:30:01.682 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1051KB) vfl(12) frh(47) ne:0
2006-02-21 20:30:01.696 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1051KB) vfl(12) frh(47) ne:0
2006-02-21 20:30:01.759 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1051KB) vfl(11) frh(47) ne:0
2006-02-21 20:30:01.766 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1018KB) vfl(12) frh(45) ne:0
2006-02-21 20:30:01.777 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1018KB) vfl(12) frh(45) ne:0
2006-02-21 20:30:01.791 NVP: IsReallyNearEnd() br(557KB) fps(24)
sz(1018KB) vfl(12) frh(45) ne:0
2006-02-21 20:30:01.797 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(985KB)
vfl(13) frh(44) ne:0
2006-02-21 20:30:01.808 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(985KB)
vfl(13) frh(44) ne:0
[******************* marker **************]
[snipped out a chunk...]
[******************* marker **************]
2006-02-21 20:30:02.801 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(592KB)
vfl(13) frh(26) ne:0
2006-02-21 20:30:02.815 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(592KB)
vfl(13) frh(26) ne:0
2006-02-21 20:30:02.826 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(592KB)
vfl(12) frh(26) ne:0
2006-02-21 20:30:02.837 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(592KB)
vfl(12) frh(26) ne:0
2006-02-21 20:30:02.848 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(592KB)
vfl(12) frh(26) ne:0
2006-02-21 20:30:02.859 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(592KB)
vfl(12) frh(26) ne:0
2006-02-21 20:30:02.871 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(592KB)
vfl(12) frh(26) ne:0
2006-02-21 20:30:02.882 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(592KB)
vfl(12) frh(26) ne:0
2006-02-21 20:30:02.897 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(592KB)
vfl(12) frh(26) ne:0
2006-02-21 20:30:02.912 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(592KB)
vfl(12) frh(26) ne:0
2006-02-21 20:30:02.918 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(559KB)
vfl(13) frh(25) ne:0
2006-02-21 20:30:02.929 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(559KB)
vfl(13) frh(25) ne:0
2006-02-21 20:30:02.940 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(559KB)
vfl(13) frh(25) ne:0
2006-02-21 20:30:02.951 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(559KB)
vfl(12) frh(25) ne:0
2006-02-21 20:30:02.962 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(559KB)
vfl(12) frh(25) ne:0
2006-02-21 20:30:02.974 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(559KB)
vfl(12) frh(25) ne:0
2006-02-21 20:30:02.990 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(559KB)
vfl(12) frh(25) ne:0
2006-02-21 20:30:03.001 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(559KB)
vfl(12) frh(25) ne:0
2006-02-21 20:30:03.015 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(559KB)
vfl(12) frh(25) ne:0
2006-02-21 20:30:03.032 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(527KB)
vfl(12) frh(23) ne:0
2006-02-21 20:30:03.039 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(527KB)
vfl(13) frh(23) ne:0
2006-02-21 20:30:03.050 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(527KB)
vfl(13) frh(23) ne:0
2006-02-21 20:30:03.061 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(527KB)
vfl(13) frh(23) ne:0
2006-02-21 20:30:03.072 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(527KB)
vfl(12) frh(23) ne:0
2006-02-21 20:30:03.083 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(527KB)
vfl(12) frh(23) ne:0
2006-02-21 20:30:03.094 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(527KB)
vfl(12) frh(23) ne:0
2006-02-21 20:30:03.109 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(527KB)
vfl(12) frh(23) ne:0
2006-02-21 20:30:03.120 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(527KB)
vfl(12) frh(23) ne:0
2006-02-21 20:30:03.131 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(527KB)
vfl(12) frh(23) ne:0
2006-02-21 20:30:03.153 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(494KB)
vfl(12) frh(22) ne:0
2006-02-21 20:30:03.168 reads allowed (131073 32768)
2006-02-21 20:30:03.175 NVP: IsReallyNearEnd() br(557KB) fps(24) sz(98KB)
vfl(13) frh(4) ne:1
2006-02-21 20:30:03.176 SwitchToProgram(void)
2006-02-21 20:30:03.257 RingBuf(/mnt/store//2013_20060221202938.mpg):
OpenFile(myth://192.168.1.33:6543/2013_20060221203000.mpg, 10)
'video_output' mean = '39994.43', std. dev. = '3724.94', fps = '25.00'
2006-02-21 20:30:04.830 buffering (1 32768 0)
2006-02-21 20:30:04.944 NVP: prebuffering pause
2006-02-21 20:30:04.944 NVP: Waiting for prebuffer.. 0 AAALAAAAAAAAAAdA
2006-02-21 20:30:05.123 NVP: Waiting for prebuffer.. 1 AAALAAAAAAAAAAdA
2006-02-21 20:30:05.145 buffering (1 32768 0)
2006-02-21 20:30:05.303 NVP: Waiting for prebuffer.. 2 AAALAAAAAAAAAAdA
2006-02-21 20:30:05.460 buffering (1 32768 0)
2006-02-21 20:30:05.483 NVP: Waiting for prebuffer.. 3 AAALAAAAAAAAAAdA
2006-02-21 20:30:05.519 RingBuf(/mnt/store//2013_20060221203000.mpg):
Taking too long to be allowed to read..
2006-02-21 20:30:05.663 NVP: Waiting for prebuffer.. 4 AAALAAAAAAAAAAdA
2006-02-21 20:30:05.770 buffering (1 32768 0)
2006-02-21 20:30:05.843 NVP: Waiting for prebuffer.. 5 AAALAAAAAAAAAAdA
2006-02-21 20:30:06.024 NVP: Waiting for prebuffer.. 6 AAALAAAAAAAAAAdA
2006-02-21 20:30:06.080 buffering (1 32768 0)
2006-02-21 20:30:06.203 NVP: Waiting for prebuffer.. 7 AAALAAAAAAAAAAdA
2006-02-21 20:30:06.383 NVP: Waiting for prebuffer.. 8 AAALAAAAAAAAAAdA
2006-02-21 20:30:06.416 buffering (1 32768 0)
2006-02-21 20:30:06.521 RingBuf(/mnt/store//2013_20060221203000.mpg):
Taking too long to be allowed to read..
2006-02-21 20:30:06.563 NVP: Waiting for prebuffer.. 9 AAALAAAAAAAAAAdA
2006-02-21 20:30:06.725 NVP: Prebuffer wait timed out 10 times.
2006-02-21 20:30:06.726 buffering (1 32768 0)
2006-02-21 20:30:06.743 NVP: Waiting for prebuffer.. 0 AAALAAAAAAAAAAdA
2006-02-21 20:30:06.923 NVP: Waiting for prebuffer.. 1 AAALAAAAAAAAAAdA
2006-02-21 20:30:07.040 buffering (1 32768 0)
2006-02-21 20:30:07.103 NVP: Waiting for prebuffer.. 2 AAALAAAAAAAAAAdA
2006-02-21 20:30:07.283 NVP: Waiting for prebuffer.. 3 AAALAAAAAAAAAAdA
2006-02-21 20:30:07.355 buffering (1 32768 0)
2006-02-21 20:30:07.463 NVP: Waiting for prebuffer.. 4 AAALAAAAAAAAAAdA
2006-02-21 20:30:07.523 RingBuf(/mnt/store//2013_20060221203000.mpg):
Taking too long to be allowed to read..
2006-02-21 20:30:07.523 restarting readhead thread..
2006-02-21 20:30:07.643 NVP: Waiting for prebuffer.. 5 AAALAAAAAAAAAAdA
2006-02-21 20:30:07.679 buffering (1 32768 0)
2006-02-21 20:30:07.823 NVP: Waiting for prebuffer.. 6 AAALAAAAAAAAAAdA
2006-02-21 20:30:07.990 buffering (1 32768 0)
2006-02-21 20:30:08.003 NVP: Waiting for prebuffer.. 7 AAALAAAAAAAAAAdA
2006-02-21 20:30:08.183 NVP: Waiting for prebuffer.. 8 AAALAAAAAAAAAAdA
2006-02-21 20:30:08.303 buffering (1 32768 0)
2006-02-21 20:30:08.363 NVP: Waiting for prebuffer.. 9 AAALAAAAAAAAAAdA
2006-02-21 20:30:08.525 NVP: Prebuffer wait timed out 10 times.
2006-02-21 20:30:08.543 NVP: Waiting for prebuffer.. 0 AAALAAAAAAAAAAdA
2006-02-21 20:30:08.637 buffering (1 32768 0)
2006-02-21 20:30:08.684 RingBuf(/mnt/store//2013_20060221203000.mpg):
Taking too long to be allowed to read..
2006-02-21 20:30:08.723 NVP: Waiting for prebuffer.. 1 AAALAAAAAAAAAAdA
2006-02-21 20:30:08.903 NVP: Waiting for prebuffer.. 2 AAALAAAAAAAAAAdA
2006-02-21 20:30:08.957 buffering (1 32768 0)
2006-02-21 20:30:09.083 NVP: Waiting for prebuffer.. 3 AAALAAAAAAAAAAdA
2006-02-21 20:30:09.263 NVP: Waiting for prebuffer.. 4 AAALAAAAAAAAAAdA
2006-02-21 20:30:09.267 buffering (1 32768 0)
2006-02-21 20:30:09.443 NVP: Waiting for prebuffer.. 5 AAALAAAAAAAAAAdA
2006-02-21 20:30:09.578 buffering (1 32768 0)
2006-02-21 20:30:09.624 NVP: Waiting for prebuffer.. 6 AAALAAAAAAAAAAdA
2006-02-21 20:30:09.685 RingBuf(/mnt/store//2013_20060221203000.mpg):
Taking too long to be allowed to read..
2006-02-21 20:30:09.686 restarting readhead thread..
2006-02-21 20:30:09.803 NVP: Waiting for prebuffer.. 7 AAALAAAAAAAAAAdA
2006-02-21 20:30:09.888 buffering (1 32768 0)
2006-02-21 20:30:09.983 NVP: Waiting for prebuffer.. 8 AAALAAAAAAAAAAdA
2006-02-21 20:30:10.163 NVP: Waiting for prebuffer.. 9 AAALAAAAAAAAAAdA
2006-02-21 20:30:10.201 buffering (1 32768 0)
2006-02-21 20:30:10.325 NVP: Prebuffer wait timed out 10 times.
2006-02-21 20:30:10.343 NVP: Waiting for prebuffer.. 0 AAALAAAAAAAAAAdA
2006-02-21 20:30:10.511 buffering (1 32768 0)
2006-02-21 20:30:10.523 NVP: Waiting for prebuffer.. 1 AAALAAAAAAAAAAdA
2006-02-21 20:30:10.703 NVP: Waiting for prebuffer.. 2 AAALAAAAAAAAAAdA
2006-02-21 20:30:10.831 buffering (1 32768 0)
2006-02-21 20:30:10.883 NVP: Waiting for prebuffer.. 3 AAALAAAAAAAAAAdA
2006-02-21 20:30:10.896 RingBuf(/mnt/store//2013_20060221203000.mpg):
Taking too long to be allowed to read..
2006-02-21 20:30:11.063 NVP: Waiting for prebuffer.. 4 AAALAAAAAAAAAAdA
2006-02-21 20:30:11.143 buffering (1 32768 0)
2006-02-21 20:30:11.243 NVP: Waiting for prebuffer.. 5 AAALAAAAAAAAAAdA
2006-02-21 20:30:11.423 NVP: Waiting for prebuffer.. 6 AAALAAAAAAAAAAdA
2006-02-21 20:30:11.455 buffering (1 32768 0)
2006-02-21 20:30:11.603 NVP: Waiting for prebuffer.. 7 AAALAAAAAAAAAAdA
2006-02-21 20:30:11.764 buffering (1 32768 0)
2006-02-21 20:30:11.783 NVP: Waiting for prebuffer.. 8 AAALAAAAAAAAAAdA
2006-02-21 20:30:11.898 RingBuf(/mnt/store//2013_20060221203000.mpg):
Taking too long to be allowed to read..
2006-02-21 20:30:11.899 restarting readhead thread..
2006-02-21 20:30:11.963 NVP: Waiting for prebuffer.. 9 AAALAAAAAAAAAAdA
2006-02-21 20:30:12.077 buffering (1 32768 0)
2006-02-21 20:30:12.125 NVP: Prebuffer wait timed out 10 times.
2006-02-21 20:30:12.143 NVP: Waiting for prebuffer.. 0 AAALAAAAAAAAAAdA
2006-02-21 20:30:12.323 NVP: Waiting for prebuffer.. 1 AAALAAAAAAAAAAdA
2006-02-21 20:30:12.388 buffering (1 32768 0)
2006-02-21 20:30:12.503 NVP: Waiting for prebuffer.. 2 AAALAAAAAAAAAAdA
2006-02-21 20:30:12.683 NVP: Waiting for prebuffer.. 3 AAALAAAAAAAAAAdA
2006-02-21 20:30:12.698 buffering (1 32768 0)
2006-02-21 20:30:12.863 NVP: Waiting for prebuffer.. 4 AAALAAAAAAAAAAdA
2006-02-21 20:30:13.018 buffering (1 32768 0)
2006-02-21 20:30:13.043 NVP: Waiting for prebuffer.. 5 AAALAAAAAAAAAAdA
2006-02-21 20:30:13.082 RingBuf(/mnt/store//2013_20060221203000.mpg):
Taking too long to be allowed to read..
2006-02-21 20:30:13.223 NVP: Waiting for prebuffer.. 6 AAALAAAAAAAAAAdA
2006-02-21 20:30:13.329 buffering (1 32768 0)
2006-02-21 20:30:13.403 NVP: Waiting for prebuffer.. 7 AAALAAAAAAAAAAdA
2006-02-21 20:30:13.583 NVP: Waiting for prebuffer.. 8 AAALAAAAAAAAAAdA
2006-02-21 20:30:13.641 buffering (1 32768 0)
2006-02-21 20:30:13.763 NVP: Waiting for prebuffer.. 9 AAALAAAAAAAAAAdA
2006-02-21 20:30:13.925 NVP: Prebuffer wait timed out 10 times.
2006-02-21 20:30:13.943 NVP: Waiting for prebuffer.. 0 AAALAAAAAAAAAAdA
2006-02-21 20:30:13.951 buffering (1 32768 0)
2006-02-21 20:30:14.084 RingBuf(/mnt/store//2013_20060221203000.mpg):
Taking too long to be allowed to read..
2006-02-21 20:30:14.084 restarting readhead thread..
2006-02-21 20:30:14.123 NVP: Waiting for prebuffer.. 1 AAALAAAAAAAAAAdA
2006-02-21 20:30:14.264 buffering (1 32768 0)
2006-02-21 20:30:14.303 NVP: Waiting for prebuffer.. 2 AAALAAAAAAAAAAdA
2006-02-21 20:30:14.483 NVP: Waiting for prebuffer.. 3 AAALAAAAAAAAAAdA
2006-02-21 20:30:14.575 buffering (1 32768 0)
2006-02-21 20:30:14.663 NVP: Waiting for prebuffer.. 4 AAALAAAAAAAAAAdA
2006-02-21 20:30:14.843 NVP: Waiting for prebuffer.. 5 AAALAAAAAAAAAAdA
2006-02-21 20:30:14.885 buffering (1 32768 0)
2006-02-21 20:30:15.023 NVP: Waiting for prebuffer.. 6 AAALAAAAAAAAAAdA
2006-02-21 20:30:15.197 buffering (1 32768 0)
2006-02-21 20:30:15.203 NVP: Waiting for prebuffer.. 7 AAALAAAAAAAAAAdA
2006-02-21 20:30:15.267 RingBuf(/mnt/store//2013_20060221203000.mpg):
Taking too long to be allowed to read..
2006-02-21 20:30:15.383 NVP: Waiting for prebuffer.. 8 AAALAAAAAAAAAAdA
2006-02-21 20:30:15.508 buffering (1 32768 0)
2006-02-21 20:30:15.563 NVP: Waiting for prebuffer.. 9 AAALAAAAAAAAAAdA
2006-02-21 20:30:15.725 NVP: Prebuffer wait timed out 10 times.
2006-02-21 20:30:15.743 NVP: Waiting for prebuffer.. 0 AAALAAAAAAAAAAdA
2006-02-21 20:30:15.818 buffering (1 32768 0)
2006-02-21 20:30:15.923 NVP: Waiting for prebuffer.. 1 AAALAAAAAAAAAAdA
2006-02-21 20:30:16.103 NVP: Waiting for prebuffer.. 2 AAALAAAAAAAAAAdA
2006-02-21 20:30:16.130 buffering (1 32768 0)
2006-02-21 20:30:16.269 RingBuf(/mnt/store//2013_20060221203000.mpg):
Taking too long to be allowed to read..
2006-02-21 20:30:16.269 restarting readhead thread..
2006-02-21 20:30:16.283 NVP: Waiting for prebuffer.. 3 AAALAAAAAAAAAAdA
2006-02-21 20:30:16.447 buffering (1 32768 0)
2006-02-21 20:30:16.449 RingBuf(/mnt/store//2013_20060221203000.mpg)
Error: Took more than 10 seconds to be allowed to read, aborting.
2006-02-21 20:30:16.449 Ignoring livetv eof in decoder loop
2006-02-21 20:30:16.463 NVP: Waiting for prebuffer.. 4 AAALAAAAAAAAAAdA
2006-02-21 20:30:16.504 Ignoring livetv eof in decoder loop
2006-02-21 20:30:16.509 buffering (1 32768 0)
2006-02-21 20:30:16.510 buffering (1 32768 0)
2006-02-21 20:30:16.510 buffering (1 32768 0)
[******************* marker **************]

[snip many many repeats of the previous line could do with a syslog filter
here!!]

[sometimes, something different ]
[******************* marker **************]
2006-02-21 20:31:33.839 buffering (1 32768 0)
2006-02-21 20:31:33.839 buffering (1 32768 0)
2006-02-21 20:31:33.839 buffering (1 32768 0)
2006-02-21 20:31:33.840 buffering (1 32768 0)
2006-02-21 20:31:33.840 Ignoring livetv eof in decoder loop
2006-02-21 20:31:33.840 buffering (1 32768 0)
2006-02-21 20:31:33.840 buffering (1 32768 0)
2006-02-21 20:31:33.840 buffering (1 32768 0)
2006-02-21 20:31:33.840 buffering (1 32768 0)
2006-02-21 20:31:33.841 buffering (1 32768 0)
2006-02-21 20:31:33.841 buffering (1 32768 0)
2006-02-21 20:31:33.841 NVP: Waiting for prebuffer.. 5 AAAAAAAdAAAdAAAL
2006-02-21 20:31:33.842 buffering (1 32768 0)
2006-02-21 20:31:33.842 buffering (1 32768 0)
2006-02-21 20:31:33.842 buffering (1 32768 0)
2006-02-21 20:31:33.842 buffering (1 32768 0)
2006-02-21 20:31:33.842 buffering (1 32768 0)
2006-02-21 20:31:33.842 buffering (1 32768 0)
2006-02-21 20:31:33.843 buffering (1 32768 0)
[******************* marker **************]

[eventually gave up and pressed ESC to exit LiveTV]

[******************* marker **************]
2006-02-21 20:31:56.242 buffering (1 32768 0)
2006-02-21 20:31:56.242 buffering (1 32768 0)
2006-02-21 20:31:56.242 buffering (1 32768 0)
2006-02-21 20:31:56.242 buffering (1 32768 0)
2006-02-21 20:31:56.242 TV: Attempting to change from WatchingLiveTV to None
2006-02-21 20:31:56.243 TV: StopStuff() -- begin
2006-02-21 20:31:56.243 TV: StopStuff(): stopping ring buffer[s]
2006-02-21 20:31:56.242 buffering (1 32768 0)
2006-02-21 20:31:56.243 TV: StopStuff(): stopping player[s] (1/2)
2006-02-21 20:31:56.243 TV: StopStuff(): stopping recorder[s]
2006-02-21 20:31:56.290 NVP: Exited decoder loop.
2006-02-21 20:31:56.400 VideoOutputXv: dtor
2006-02-21 20:31:56.401 VideoOutputXv: DiscardFrames() 1: AAAAAAAdAAAdAAAL
2006-02-21 20:31:56.401 VideoOutputXv: DiscardFrames() 2: AAAAAAAdAAAdAAAL
2006-02-21 20:31:56.401 VideoOutputXv: DiscardFrames() 3: AAAAAAAdAAAdAAAL
2006-02-21 20:31:56.401 VideoOutputXv: DiscardFrames() 4: AAAAAAAdAAAdAAAA
-- done()
2006-02-21 20:31:56.402 VideoOutputXv: DiscardFrames() 1: AAAAAAAdAAAdAAAA
2006-02-21 20:31:56.402 VideoOutputXv: DiscardFrames() 2: AAAAAAAaAAAdAAAA
2006-02-21 20:31:56.402 VideoOutputXv: DiscardFrames() 3: AAAAAAAaAAAdAAAA
2006-02-21 20:31:56.402 VideoOutputXv: DiscardFrames() 4: AAAAAAAaAAAdAAAA
-- done()
2006-02-21 20:31:56.406 VideoOutputXv: Closing XVideo port 68
2006-02-21 20:31:56.449 TV: StopStuff(): stopping player[s] (2/2)
2006-02-21 20:31:56.504 TV: StopStuff() -- end
2006-02-21 20:31:56.504 TV: Changing from WatchingLiveTV to None
2006-02-21 20:31:58.635 TV: Attempting to change from None to WatchingLiveTV
2006-02-21 20:31:58.643 Using protocol version 27
2006-02-21 20:31:59.868 LiveTVChain(live-media-2006-02-21T20:31:58):
ReloadAll(): Added new recording
2006-02-21 20:31:59.912 RingBuf(/mnt/store//2013_20060221203159.mpg):
OpenFile(/mnt/store//2013_20060221203159.mpg, 12)
2006-02-21 20:31:59.985 RingBuf(/mnt/store//2013_20060221203159.mpg):
Invalid file (fd 16) when opening '/mnt/store//2013_20060221203159.mpg'.
12 retries remaining.
2006-02-21 20:32:00.487 RingBuf(/mnt/store//2013_20060221203159.mpg):
Invalid file (fd 16) when opening '/mnt/store//2013_20060221203159.mpg'.
11 retries remaining.
2006-02-21 20:32:00.990 RingBuf(/mnt/store//2013_20060221203159.mpg):
Invalid file (fd 16) when opening '/mnt/store//2013_20060221203159.mpg'.
10 retries remaining.
2006-02-21 20:32:01.505 TV: StartRecorder(): took 11 ms to start recorder.
2006-02-21 20:32:01.904 reads allowed (121273 -1)
2006-02-21 20:32:01.979 reads allowed (128001 -1)
[mpeg @ 0xb7670360]Parser not found for Codec Id: 94210 !
2006-02-21 20:32:02.886 reads allowed (39001 -1)
2006-02-21 20:32:03.407 reads allowed (8281 -1)
2006-02-21 20:32:03.920 reads allowed (128001 -1)
2006-02-21 20:32:03.923 reads allowed (128001 -1)
0: start_time: 0.036 duration: 0.166
1: start_time: 787.448 duration: 0.184
2: start_time: 0.025 duration: 0.136
stream: start_time: 0.276 duration: 8751.181 bitrate=0 kb/s
2006-02-21 20:32:03.924 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO,
type Video at 0x0x829c7a0
2006-02-21 20:32:03.926 reads allowed (128001 -1)
2006-02-21 20:32:03.930 VideoOutputXv: XvMC version: 1.1
2006-02-21 20:32:03.930 XvMCSurfaceTypes::find(w 320, h 576, chroma 1, vld
1, idct 0, mpeg2, sub-width 0, sub-height 0, disp, p<= 68, 680 <=p, port,
surfNum)
2006-02-21 20:32:03.931 Trying XvMC port 68
2006-02-21 20:32:03.935 Found a suitable XvMC surface 0
2006-02-21 20:32:03.936 VideoOutputXv: @ j=0 Looking for flag[s]: XvInputMask
2006-02-21 20:32:03.937 VideoOutputXv: Adaptor: 0 has flag[s]: XvInputMask
XvImageMask
2006-02-21 20:32:03.937 XvMCSurfaceTypes::find(w 320, h 576, chroma 1, vld
1, idct 0, mpeg2, sub-width 0, sub-height 0, disp, p<= 68, 680 <=p, port,
surfNum)
2006-02-21 20:32:03.937 Trying XvMC port 68
2006-02-21 20:32:03.937 Found a suitable XvMC surface 0
2006-02-21 20:32:03.938 VideoOutputXv: Grabbed xv port 68
2006-02-21 20:32:03.939 VideoOutputXv: XvMC surface found with VLD support
on port 68
2006-02-21 20:32:03.946 VideoOutputXv: Closing XVideo port 68
2006-02-21 20:32:03.948 detectInterlace(Detect Scan, Detect Scan, 25, 576)
->Interlaced Scan
2006-02-21 20:32:03.948 Interlaced: Interlaced Scan  video_height: 576
fps: 25
2006-02-21 20:32:03.949 AFD: Looking for decoder for MPEG2VIDEO_XVMC_VLD
2006-02-21 20:32:03.949 AFD: Opened codec 0x829b090,
id(MPEG2VIDEO_XVMC_VLD) type(Video)
2006-02-21 20:32:03.949 AFD: Stream #1, has id 0x105 codec id MPEG2VBI,
type Data at 0x0x828e030
2006-02-21 20:32:03.949 AFD: data codec (Data)
2006-02-21 20:32:03.949 AFD: Stream #2, has id 0x448 codec id MP2, type
Audio at 0x0x84b1070
2006-02-21 20:32:03.949 AFD: Looking for decoder for MP2
2006-02-21 20:32:03.950 AFD: Opened codec 0x828f8a0, id(MP2) type(Audio)
2006-02-21 20:32:03.950 RingBuf(/mnt/store//2013_20060221203159.mpg):
CalcReadAheadThresh(4456 KB)
			 -> threshhold(163 KB) min read(32 KB) blk size(128 KB)
2006-02-21 20:32:03.950 Opening audio device 'default'.
2006-02-21 20:32:03.952 reads allowed (899073 32768)
2006-02-21 20:32:03.962 Resyncing position map. posmapStarted = 0
livetv(1) watchingRec(0)
2006-02-21 20:32:03.967 Position map filled from DB to: 6
2006-02-21 20:32:03.967 SyncPositionMap watchingrecording, from DB: 6 entries
2006-02-21 20:32:03.975 Filling position map from 7 to 5
2006-02-21 20:32:03.981 Position map filled from Encoder to: 6
2006-02-21 20:32:03.982 SyncPositionMap watchingrecording total: 6 entries
2006-02-21 20:32:03.982 SyncPositionMap, new totframes: 72, new length: 2,
posMap size: 6
2006-02-21 20:32:03.983 AFD: Partial position map found
2006-02-21 20:32:03.983 AFD: Successfully opened decoder for file:
"/mnt/store//2013_20060221203159.mpg". novideo(0)
2006-02-21 20:32:04.026 VideoOutputXv: ctor
2006-02-21 20:32:04.028 Over/underscan. V: 0, H: 0, XOff: 0, YOff: 0
2006-02-21 20:32:04.043 Snapping height to avoid scaling: disphoff 576,
dispyoff: 0
2006-02-21 20:32:04.043 Image size. dispxoff 0, dispyoff: 0, dispwoff:
720, disphoff: 576, dispaspect: 1.33333
2006-02-21 20:32:04.043 Image size. imgx 0, imgy: 0, imgw: 320, imgh: 576,
aspect: 1.33333
2006-02-21 20:32:04.043 VideoOutputXv: Pixel dimensions: Screen 720x576,
window 720x576
2006-02-21 20:32:04.044 VideoOutputXv: Estimated display dimensions:
244x195 mm Aspect: 1.25128
2006-02-21 20:32:04.044 VideoOutputXv: Estimated window dimensions:
244x195 mm Aspect: 1.25128
2006-02-21 20:32:04.046 VideoOutputXv: @ j=0 Looking for flag[s]: XvInputMask
2006-02-21 20:32:04.046 VideoOutputXv: Adaptor: 0 has flag[s]: XvInputMask
XvImageMask
2006-02-21 20:32:04.046 XvMCSurfaceTypes::find(w 320, h 576, chroma 1, vld
1, idct 0, mpeg2, sub-width 0, sub-height 0, disp, p<= 68, 680 <=p, port,
surfNum)
2006-02-21 20:32:04.046 Trying XvMC port 68
2006-02-21 20:32:04.046 Found a suitable XvMC surface 0
2006-02-21 20:32:04.047 VideoOutputXv: Grabbed xv port 68
2006-02-21 20:32:04.047 VideoOutputXv: XvMC surface found with VLD support
on port 68
2006-02-21 20:32:04.060 Snapping height to avoid scaling: disphoff 576,
dispyoff: 0
2006-02-21 20:32:04.060 Image size. dispxoff 0, dispyoff: 0, dispwoff:
720, disphoff: 576, dispaspect: 1.25128
2006-02-21 20:32:04.060 Image size. imgx 0, imgy: 0, imgw: 320, imgh: 576,
aspect: 1.33333
2006-02-21 20:32:04.869 TV: StartPlayer(): took 3342 ms to start player.
2006-02-21 20:32:04.870 TV: Changing from None to WatchingLiveTV
2006-02-21 20:32:04.869 NVP: ClearAfterSeek()
2006-02-21 20:32:04.871 VideoOutputXv: ClearAfterSeek()
2006-02-21 20:32:04.872 VideoOutputXv: DiscardFrames() 1: AAAAAAAAAAAAAAAA
2006-02-21 20:32:04.872 VideoOutputXv: DiscardFrames() 2: AAAAAAAAAAAAAAAA
2006-02-21 20:32:04.872 VideoOutputXv: DiscardFrames() 3: AAAAAAAAAAAAAAAA
2006-02-21 20:32:04.872 VideoOutputXv: DiscardFrames() 4: AAAAAAAAAAAAAAAA
-- done()
2006-02-21 20:32:04.873 VideoOutputXv: DiscardFrames() 1: AAAAAAAAAAAAAAAA
2006-02-21 20:32:04.873 VideoOutputXv: DiscardFrames() 2: AAAAAAAAAAAAAAAA
2006-02-21 20:32:04.873 VideoOutputXv: DiscardFrames() 3: AAAAAAAAAAAAAAAA
2006-02-21 20:32:04.873 VideoOutputXv: DiscardFrames() 4: AAAAAAAAAAAAAAAA
-- done()
2006-02-21 20:32:04.875 Realtime priority would require SUID as root.
2006-02-21 20:32:04.884 nVidiaVideoSync: Could not open device
/dev/nvidia0, No such file or directory
2006-02-21 20:32:04.935 Using audio as timebase
2006-02-21 20:32:04.936 Video timing method: DRM
2006-02-21 20:32:04.936 Refresh rate: 20000, frame interval: 40000
2006-02-21 20:32:04.989 AFD: HandleGopStart: gopset not set, syncing
positionMap
2006-02-21 20:32:04.989 Resyncing position map. posmapStarted = 0
livetv(1) watchingRec(1)
2006-02-21 20:32:04.991 Position map filled from DB to: 6
2006-02-21 20:32:04.992 SyncPositionMap watchingrecording, from DB: 6 entries
2006-02-21 20:32:05.001 Filling position map from 7 to 7
2006-02-21 20:32:05.007 Position map filled from Encoder to: 7
2006-02-21 20:32:05.008 SyncPositionMap watchingrecording total: 7 entries
2006-02-21 20:32:05.008 SyncPositionMap, new totframes: 84, new length: 3,
posMap size: 7
2006-02-21 20:32:05.008 AFD: HandleGopStart: Initial key frame distance: 12.
2006-02-21 20:32:05.102 reads allowed (131073 32768)
2006-02-21 20:32:05.782 reads allowed (131073 32768)
2006-02-21 20:32:07.160 reads allowed (131073 32768)
2006-02-21 20:32:07.594 reads allowed (131073 32768)
2006-02-21 20:32:08.096 reads allowed (131073 32768)
2006-02-21 20:32:08.127 reads allowed (131073 32768)
2006-02-21 20:32:08.240 AFD: positionMap[ 7 ] == 1614078.
2006-02-21 20:32:08.720 AFD: positionMap[ 8 ] == 1833742.
2006-02-21 20:32:08.969 reads allowed (131073 32768)
'video_output' mean = '40264.26', std. dev. = '5072.58', fps = '24.84'
2006-02-21 20:32:09.071 reads allowed (131073 32768)
2006-02-21 20:32:09.200 AFD: positionMap[ 9 ] == 2041118.
2006-02-21 20:32:09.680 AFD: positionMap[ 10 ] == 2234158.
2006-02-21 20:32:10.160 AFD: positionMap[ 11 ] == 2441534.
2006-02-21 20:32:10.640 AFD: positionMap[ 12 ] == 2657102.
2006-02-21 20:32:11.120 AFD: positionMap[ 13 ] == 2854238.
2006-02-21 20:32:11.600 AFD: positionMap[ 14 ] == 3065710.
2006-02-21 20:32:11.700 reads allowed (131073 32768)
2006-02-21 20:32:12.125 reads allowed (131073 32768)
2006-02-21 20:32:12.164 AFD: positionMap[ 15 ] == 3287422.
2006-02-21 20:32:12.560 AFD: positionMap[ 16 ] == 3482510.
'video_output' mean = '39987.61', std. dev. = '1260.89', fps = '25.01'
2006-02-21 20:32:13.040 AFD: positionMap[ 17 ] == 3675550.
2006-02-21 20:32:13.520 AFD: positionMap[ 18 ] == 3858350.
2006-02-21 20:32:14.000 AFD: positionMap[ 19 ] == 4069866.
2006-02-21 20:32:14.290 reads allowed (131073 32768)
2006-02-21 20:32:14.480 AFD: positionMap[ 20 ] == 4260902.
2006-02-21 20:32:14.899 reads allowed (131073 32768)
2006-02-21 20:32:14.960 AFD: positionMap[ 21 ] == 4413026.
2006-02-21 20:32:15.440 AFD: positionMap[ 22 ] == 4630642.
2006-02-21 20:32:15.920 AFD: positionMap[ 23 ] == 4799106.
[******************* marker **************]

Hope there is something meaningful here...

If not, I'm ready to try more.

-- 
Robin Gilks