Ticket #2916: output_polar_express

File output_polar_express, 42.1 KB (added by bhuffman@…, 17 years ago)
Line 
12007-02-13 22:04:46.618 TV: Attempting to change from None to WatchingPreRecorded
22007-02-13 22:04:46.619 RingBuf(dvd://dev/dvd): OpenFile(dvd://dev/dvd, 12)
3libdvdnav: Using dvdnav version 0.1.10-xine from http://xine.sf.net
4libdvdread: Using libdvdcss version 1.2.9 for DVD access
5libdvdnav: DVD Title: THE_POLAR_EXPRESS_DISC_1
6libdvdnav: DVD Serial Number: 32C77145
7libdvdnav: DVD Title (Alternative): THE_POLAR_EXPRESS_DISC_1
8libdvdnav: Unable to find map file '/home/mythtv/.dvdnav/THE POLAR EXPRESS DISC 1.map'
9libdvdnav: DVD disk reports itself with Region mask 0x00fe0000. Regions: 1
102007-02-13 22:04:47.025 Opened DVD device at //dev/dvd
112007-02-13 22:04:47.093 There are 8 titles on the disk
122007-02-13 22:04:47.094 Title 0 has 0 parts.
132007-02-13 22:04:47.094 Title 1 has 24 parts.
142007-02-13 22:04:47.094 Title 2 has 24 parts.
152007-02-13 22:04:47.094 Title 3 has 24 parts.
162007-02-13 22:04:47.094 Title 4 has 1 parts.
172007-02-13 22:04:47.094 Title 5 has 1 parts.
182007-02-13 22:04:47.095 Title 6 has 1 parts.
192007-02-13 22:04:47.095 Title 7 has 1 parts.
202007-02-13 22:04:47.099 DVDRB: Limit DVD Speed to 16200Kb/s
212007-02-13 22:04:47.100 DVDRB: Limiting DVD Speed Successful
222007-02-13 22:04:47.100 RingBuf(//dev/dvd): CalcReadAheadThresh(4000 KB)
23                         -> threshhold(64 KB) min read(32 KB) blk size(64 KB)
242007-02-13 22:04:47.128 DVDNAV_HIGHLIGHT: display==1, palette==88, sx==88, sy==0, ex==65535, ey==32767, pts==0, buttonN==1
25
26libdvdread: Attempting to retrieve all CSS keys
27libdvdread: This can take a _long_ time, please be patient
28
29libdvdread: Get key for /VIDEO_TS/VTS_01_0.VOB at 0x000001e1
30libdvdread: Elapsed time 0
31libdvdread: Get key for /VIDEO_TS/VTS_01_1.VOB at 0x00012ab3
32libdvdread: Elapsed time 0
33libdvdread: Get key for /VIDEO_TS/VTS_02_1.VOB at 0x002b8f8a
34libdvdread: Elapsed time 0
35libdvdread: Found 2 VTS's
36libdvdread: Elapsed time 0
372007-02-13 22:04:47.147 DVDNAV_VTS_CHANGE: old_vtsN==0, new_vtsN==1, aspect: 3, perm: 2
382007-02-13 22:04:47.147 DVDNAV_CELL_CHANGE: pg_length == 1080000, pgc_length == 1080000, cell_start == 0, pg_start == 0, title == 5, part == 1 titleParts 1
392007-02-13 22:04:47.147 DVDNAV_SPU_CLUT_CHANGE happened.
402007-02-13 22:04:47.147 DVDNAV_SPU_STREAM_CHANGE: physical_wide==-1, physical_letterbox==-1, physical_pan_scan==-1, logical==8421504
412007-02-13 22:04:47.148 DVDNAV_AUDIO_STREAM_CHANGE: physical==0, logical==-1
422007-02-13 22:04:47.278 DVDNAV_HOP_CHANNEL happened.
432007-02-13 22:04:47.279 DVDNAV_CELL_CHANGE: pg_length == 1080000, pgc_length == 1080000, cell_start == 0, pg_start == 0, title == 5, part == 1 titleParts 1
442007-02-13 22:04:47.279 DVDNAV_SPU_CLUT_CHANGE happened.
452007-02-13 22:04:47.279 DVDNAV_SPU_STREAM_CHANGE: physical_wide==-1, physical_letterbox==-1, physical_pan_scan==-1, logical==8421504
462007-02-13 22:04:47.279 DVDNAV_AUDIO_STREAM_CHANGE: physical==0, logical==-1
472007-02-13 22:04:47.301 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video, bitrate 7500000 at 0x0xb1748b0
482007-02-13 22:04:47.304 detectInterlace(Detect Scan, Interlaced Scan, 29.97, 480) ->Interlaced Scan
492007-02-13 22:04:47.304 AFD: Looking for decoder for MPEG2VIDEO
502007-02-13 22:04:47.305 AFD: Opened codec 0xb1749b0, id(MPEG2VIDEO) type(Video)
512007-02-13 22:04:47.305 RingBuf(//dev/dvd): CalcReadAheadThresh(7500 KB)
52                         -> threshhold(64 KB) min read(32 KB) blk size(128 KB)
532007-02-13 22:04:47.305 NVP: Disabling Audio, params(-1,-1,-1)
542007-02-13 22:04:47.305 NVP: Disabling Audio, params(0,-1,-1)
552007-02-13 22:04:47.306 Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(0)
562007-02-13 22:04:47.331 Position map filled from DB to: 359
572007-02-13 22:04:47.331 SyncPositionMap prerecorded, from DB: 1 entries
582007-02-13 22:04:47.331 SyncPositionMap, new totframes: 359, new length: 12, posMap size: 1
592007-02-13 22:04:47.331 AFD: Position map found
602007-02-13 22:04:47.332 AFD: Successfully opened decoder for file: "//dev/dvd". novideo(0)
612007-02-13 22:04:47.371 VideoOutputXv: ctor
622007-02-13 22:04:47.372 Over/underscan. V: 0, H: 0, XOff: 0, YOff: 0
632007-02-13 22:04:47.373 Display Rect  left: 0, top: 95, width: 1360, height: 574, aspect: 1.33333
642007-02-13 22:04:47.373 Video Rect    left: 0, top: 0, width: 720, height: 480, aspect: 1.77778
652007-02-13 22:04:47.373 VideoOutputXv: Pixel dimensions: Screen 1360x765, window 1360x765
662007-02-13 22:04:47.374 VideoOutputXv: Estimated display dimensions: 1114x627 mm  Aspect: 1.77671
672007-02-13 22:04:47.374 VideoOutputXv: Estimated window dimensions: 1114x627 mm  Aspect: 1.77671
682007-02-13 22:04:47.377 VideoOutputXv: XvMCTex: Init failed
692007-02-13 22:04:47.377 VideoOutputXv: @ j=3 Looking for flag[s]: XvInputMask XvImageMask
702007-02-13 22:04:47.378 VideoOutputXv: Adaptor#0: NV17 Video Texture has flag[s]: XvInputMask XvImageMask
712007-02-13 22:04:47.378 VideoOutputXv: Grabbed xv port 245
722007-02-13 22:04:47.378 VideoOutputXv: XVideo surface found on port 245
732007-02-13 22:04:47.378 VideoOutputXv: XVideo Adaptor Name: 'NV17 Video Texture'
742007-02-13 22:04:47.379 VideoOutputXv: XVideo Format #0 is 'YUY2'
752007-02-13 22:04:47.379 VideoOutputXv: XVideo Format #1 is 'YV12'
762007-02-13 22:04:47.379 VideoOutputXv: XVideo Format #2 is 'UYVY'
772007-02-13 22:04:47.379 VideoOutputXv: XVideo Format #3 is 'I420'
782007-02-13 22:04:47.380 VideoOutputXv: Using XVideo Format 'I420'
792007-02-13 22:04:47.380 VideoOutputXv: CreateShmImages(32): video_dim: 720x480
80X Error: BadMatch (invalid parameter attributes) 8
81  Major opcode:  140
82  Minor opcode:  14
83  Resource id:  0x14b
842007-02-13 22:04:47.454 VideoOutputXv: Chromakeying not possible with this XVideo port.
852007-02-13 22:04:47.454 Display Rect  left: 0, top: 0, width: 1360, height: 765, aspect: 1.77778
862007-02-13 22:04:47.454 Video Rect    left: 0, top: 0, width: 720, height: 480, aspect: 1.77778
872007-02-13 22:04:48.973 NVP: ClearAfterSeek(1)
882007-02-13 22:04:48.973 VideoOutputXv: ClearAfterSeek()
892007-02-13 22:04:48.974 VideoOutputXv: DiscardFrames(0)
902007-02-13 22:04:48.974 VideoBuffers::DiscardFrames(0): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
912007-02-13 22:04:48.974 VideoBuffers::DiscardFrames(0): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
922007-02-13 22:04:48.974 VideoOutputXv: DiscardFrames() 3: AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
932007-02-13 22:04:48.975 TV: StartPlayer(): took 1847 ms to start player.
942007-02-13 22:04:48.975 TV: Changing from None to WatchingPreRecorded
952007-02-13 22:04:48.980 Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(0)
962007-02-13 22:04:48.980 Position map filled from DB to: 359
972007-02-13 22:04:48.980 SyncPositionMap prerecorded, from DB: 1 entries
982007-02-13 22:04:48.981 SyncPositionMap, new totframes: 359, new length: 12, posMap size: 1
992007-02-13 22:04:48.981 AFD: DVD Title Changed
1002007-02-13 22:04:48.981 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video, bitrate 7500000 at 0x0xb1748b0
1012007-02-13 22:04:48.981 AFD: Looking for decoder for MPEG2VIDEO
1022007-02-13 22:04:48.981 RingBuf(//dev/dvd): CalcReadAheadThresh(7500 KB)
103                         -> threshhold(64 KB) min read(32 KB) blk size(128 KB)
1042007-02-13 22:04:48.981 AFD: DVD Cell Changed. Update framesPlayed: 0
1052007-02-13 22:04:48.982 DVDNAV_HOP_CHANNEL happened.
1062007-02-13 22:04:48.982 DVDNAV_CELL_CHANGE: pg_length == 1080000, pgc_length == 1080000, cell_start == 0, pg_start == 0, title == 5, part == 1 titleParts 1
1072007-02-13 22:04:48.982 DVDNAV_SPU_CLUT_CHANGE happened.
1082007-02-13 22:04:48.982 DVDNAV_SPU_STREAM_CHANGE: physical_wide==-1, physical_letterbox==-1, physical_pan_scan==-1, logical==8421504
1092007-02-13 22:04:48.982 DVDNAV_AUDIO_STREAM_CHANGE: physical==0, logical==-1
1102007-02-13 22:04:48.992 AFD: HandleStreamChange(): streams_changed 0xb1721a8 -- stream count 2
1112007-02-13 22:04:48.993 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video, bitrate 7500000 at 0x0xb1748b0
1122007-02-13 22:04:48.994 AFD: Warning, video codec 0xb1749b0 id(MPEG2VIDEO) type (Video) already open.
1132007-02-13 22:04:48.995 AFD: Looking for decoder for MPEG2VIDEO
1142007-02-13 22:04:48.995 AFD: Stream #1, has id 0x130 codec id AC3, type Audio, bitrate 0 at 0x0xbf0b4a0
1152007-02-13 22:04:48.995 AFD: Looking for decoder for AC3
1162007-02-13 22:04:48.996 AFD: Opened codec 0xbf0bd00, id(AC3) type(Audio)
1172007-02-13 22:04:48.996 RingBuf(//dev/dvd): CalcReadAheadThresh(7500 KB)
118                         -> threshhold(64 KB) min read(32 KB) blk size(128 KB)
1192007-02-13 22:04:48.997 AFD: HandleStreamChange(): streams_changed 0xb1721a8 -- stream count 3
1202007-02-13 22:04:48.997 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video, bitrate 7500000 at 0x0xb1748b0
1212007-02-13 22:04:48.999 AFD: Warning, video codec 0xb1749b0 id(MPEG2VIDEO) type (Video) already open.
1222007-02-13 22:04:48.999 AFD: Looking for decoder for MPEG2VIDEO
1232007-02-13 22:04:48.999 AFD: Stream #1, has id 0x130 codec id AC3, type Audio, bitrate 384000 at 0x0xbf0b4a0
1242007-02-13 22:04:49.000 AFD: Warning, audio codec 0xbf0bd00 id(AC3) type (Audio) already open, leaving it alone.
1252007-02-13 22:04:49.000 AFD: Looking for decoder for AC3
1262007-02-13 22:04:49.000 AFD: Stream #2, has id 0x128 codec id AC3, type Audio, bitrate 0 at 0x0xbf0a630
1272007-02-13 22:04:49.000 AFD: Looking for decoder for AC3
1282007-02-13 22:04:49.001 AFD: Opened codec 0xbf0c060, id(AC3) type(Audio)
1292007-02-13 22:04:49.001 RingBuf(//dev/dvd): CalcReadAheadThresh(7884 KB)
130                         -> threshhold(64 KB) min read(32 KB) blk size(128 KB)
1312007-02-13 22:04:49.007 Opening ALSA audio device 'spdif'.
1322007-02-13 22:04:49.009 Using deinterlace method bobdeint
1332007-02-13 22:04:49.058 NVP: Enabling Audio
1342007-02-13 22:04:49.111 nVidiaVideoSync: VBlank ioctl did not work, unimplemented in this driver?
1352007-02-13 22:04:49.111 DRMVideoSync: Could not open device /dev/dri/card0, No such file or directory
1362007-02-13 22:04:49.111 RTCVideoSync: Could not set RTC frequency, Permission denied.
1372007-02-13 22:04:49.112 Using audio as timebase
1382007-02-13 22:04:49.112 Video timing method: USleep with busy wait
1392007-02-13 22:04:49.112 Refresh rate: 16667, frame interval: 33366
1402007-02-13 22:04:49.231 NVP: Video is 3.09423 frames behind audio (too slow), dropping frame to catch up.
1412007-02-13 22:04:49.231 NVP: Video is 3.1973 frames behind audio (too slow), dropping frame to catch up.
1422007-02-13 22:04:49.232 NVP: Video is 3.01984 frames behind audio (too slow), dropping frame to catch up.
1432007-02-13 22:04:49.234 AFD: HandleGopStart: gopset not set, syncing positionMap
1442007-02-13 22:04:49.234 Resyncing position map. posmapStarted = 1 livetv(0) watchingRec(0)
1452007-02-13 22:04:49.234 AFD: HandleGopStart: Initial key frame distance: 15.
146'video_output' mean = '32262.66', std. dev. = '8718.88', fps = '31.00'
147'video_output' mean = '33313.99', std. dev. = '2388.22', fps = '30.02'
148'video_output' mean = '33357.23', std. dev. = '2897.60', fps = '29.98'
1492007-02-13 22:05:00.714 DVDNAV_CELL_CHANGE: pg_length == 1083000, pgc_length == 1083000, cell_start == 0, pg_start == 0, title == 4, part == 1 titleParts 1
1502007-02-13 22:05:00.714 DVDNAV_SPU_CLUT_CHANGE happened.
1512007-02-13 22:05:00.714 DVDNAV_SPU_STREAM_CHANGE: physical_wide==-1, physical_letterbox==-1, physical_pan_scan==-1, logical==8421504
1522007-02-13 22:05:00.715 DVDNAV_AUDIO_STREAM_CHANGE: physical==0, logical==-1
1532007-02-13 22:05:00.759 Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(0)
1542007-02-13 22:05:00.759 Position map filled from DB to: 359
1552007-02-13 22:05:00.759 SyncPositionMap prerecorded, from DB: 1 entries
1562007-02-13 22:05:00.759 SyncPositionMap, new totframes: 359, new length: 12, posMap size: 1
1572007-02-13 22:05:00.759 AFD: DVD Title Changed
1582007-02-13 22:05:00.759 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video, bitrate 7500000 at 0x0xb1748b0
1592007-02-13 22:05:00.759 AFD: Looking for decoder for MPEG2VIDEO
1602007-02-13 22:05:00.760 AFD: Stream #1, has id 0x130 codec id AC3, type Audio, bitrate 384000 at 0x0xbf0b4a0
1612007-02-13 22:05:00.760 AFD: Warning, audio codec 0xbf0bd00 id(AC3) type (Audio) already open, leaving it alone.
1622007-02-13 22:05:00.760 AFD: Looking for decoder for AC3
1632007-02-13 22:05:00.760 AFD: Stream #2, has id 0x128 codec id AC3, type Audio, bitrate 448000 at 0x0xbf0a630
1642007-02-13 22:05:00.760 AFD: Warning, audio codec 0xbf0c060 id(AC3) type (Audio) already open, leaving it alone.
1652007-02-13 22:05:00.760 AFD: Looking for decoder for AC3
1662007-02-13 22:05:00.760 RingBuf(//dev/dvd): CalcReadAheadThresh(8332 KB)
167                         -> threshhold(64 KB) min read(32 KB) blk size(128 KB)
1682007-02-13 22:05:00.760 AFD: DVD Cell Changed. Update framesPlayed: 0
1692007-02-13 22:05:00.869 NVP: Video is 30 frames ahead of audio,
170                        doubling video frame interval to slow down.
1712007-02-13 22:05:00.870 NVP: progressive frame seen after 358 interlaced  frames
1722007-02-13 22:05:00.936 NVP: Video is 30 frames ahead of audio,
173                        doubling video frame interval to slow down.
1742007-02-13 22:05:01.004 NVP: Video is 30 frames ahead of audio,
175                        doubling video frame interval to slow down.
1762007-02-13 22:05:01.004 Disabled deinterlacing
1772007-02-13 22:05:01.075 NVP: Video is 30 frames ahead of audio,
178                        doubling video frame interval to slow down.
1792007-02-13 22:05:01.140 NVP: Video is 27.3418 frames ahead of audio,
180                        doubling video frame interval to slow down.
1812007-02-13 22:05:01.208 AFD: HandleGopStart: gopset not set, syncing positionMap
1822007-02-13 22:05:01.208 Resyncing position map. posmapStarted = 1 livetv(0) watchingRec(0)
1832007-02-13 22:05:01.208 AFD: HandleGopStart: Initial key frame distance: 15.
1842007-02-13 22:05:01.219 NVP: Video is 19.8096 frames ahead of audio,
185                        doubling video frame interval to slow down.
1862007-02-13 22:05:01.271 NVP: Video is 13.8157 frames ahead of audio,
187                        doubling video frame interval to slow down.
1882007-02-13 22:05:01.337 NVP: Video is 9.30528 frames ahead of audio,
189                        doubling video frame interval to slow down.
1902007-02-13 22:05:01.404 NVP: Video is 5.67524 frames ahead of audio,
191                        doubling video frame interval to slow down.
1922007-02-13 22:05:01.554 NVP: Video is 3.13622 frames behind audio (too slow), dropping frame to catch up.
1932007-02-13 22:05:01.554 NVP: Video is 3.39363 frames behind audio (too slow), dropping frame to catch up.
1942007-02-13 22:05:01.554 NVP: Video is 3.21207 frames behind audio (too slow), dropping frame to catch up.
195'video_output' mean = '37521.06', std. dev. = '16011.43', fps = '26.65'
1962007-02-13 22:05:03.105 NVP: interlaced frame seen after 55 progressive frames
1972007-02-13 22:05:03.229 Set video sync frame interval to 33366
1982007-02-13 22:05:03.229 Enabled deinterlacing
199'video_output' mean = '34494.66', std. dev. = '7844.85', fps = '28.99'
200'video_output' mean = '33337.66', std. dev. = '4118.28', fps = '30.00'
2012007-02-13 22:05:11.214 NVP: progressive frame seen after 240 interlaced  frames
2022007-02-13 22:05:11.280 Set video sync frame interval to 33366
2032007-02-13 22:05:11.280 Disabled deinterlacing
2042007-02-13 22:05:12.584 NVP: interlaced frame seen after 35 progressive frames
2052007-02-13 22:05:12.657 Set video sync frame interval to 33366
2062007-02-13 22:05:12.657 Enabled deinterlacing
2072007-02-13 22:05:12.746 DVDNAV_VTS_CHANGE: old_vtsN==1, new_vtsN==1, aspect: 3, perm: 1
2082007-02-13 22:05:12.746 Display Rect  left: 0, top: 0, width: 1360, height: 765, aspect: 1.77778
2092007-02-13 22:05:12.746 Video Rect    left: 0, top: 0, width: 720, height: 480, aspect: 1.77778
2102007-02-13 22:05:12.746 DVDNAV_CELL_CHANGE: pg_length == 2901000, pgc_length == 8007000, cell_start == 0, pg_start == 0, title == 0, part == 3 titleParts 0
2112007-02-13 22:05:12.746 DVDNAV_SPU_CLUT_CHANGE happened.
2122007-02-13 22:05:12.746 DVDNAV_SPU_STREAM_CHANGE: physical_wide==0, physical_letterbox==0, physical_pan_scan==1, logical==8421504
2132007-02-13 22:05:12.746 DVDNAV_AUDIO_STREAM_CHANGE: physical==0, logical==0
2142007-02-13 22:05:12.747 Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(0)
2152007-02-13 22:05:12.747 Position map filled from DB to: 2637
2162007-02-13 22:05:12.747 SyncPositionMap prerecorded, from DB: 1 entries
2172007-02-13 22:05:12.747 SyncPositionMap, new totframes: 2637, new length: 88, posMap size: 1
2182007-02-13 22:05:12.747 AFD: DVD Title Changed
2192007-02-13 22:05:12.747 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video, bitrate 7500000 at 0x0xb1748b0
2202007-02-13 22:05:12.747 AFD: Looking for decoder for MPEG2VIDEO
2212007-02-13 22:05:12.747 AFD: Stream #1, has id 0x130 codec id AC3, type Audio, bitrate 384000 at 0x0xbf0b4a0
2222007-02-13 22:05:12.747 AFD: Warning, audio codec 0xbf0bd00 id(AC3) type (Audio) already open, leaving it alone.
2232007-02-13 22:05:12.748 AFD: Looking for decoder for AC3
2242007-02-13 22:05:12.748 AFD: Stream #2, has id 0x128 codec id AC3, type Audio, bitrate 448000 at 0x0xbf0a630
2252007-02-13 22:05:12.748 AFD: Warning, audio codec 0xbf0c060 id(AC3) type (Audio) already open, leaving it alone.
2262007-02-13 22:05:12.748 AFD: Looking for decoder for AC3
2272007-02-13 22:05:12.748 RingBuf(//dev/dvd): CalcReadAheadThresh(8332 KB)
228                         -> threshhold(64 KB) min read(32 KB) blk size(128 KB)
2292007-02-13 22:05:12.748 AFD: DVD Cell Changed. Update framesPlayed: 0
2302007-02-13 22:05:12.898 VideoOutputXv: InputChanged(720,480,1.77778)
2312007-02-13 22:05:12.899 VideoOutputXv: DiscardFrames(1)
2322007-02-13 22:05:12.899 VideoBuffers::DiscardFrames(1): AALAAAAAAAAAAAAAAAAAAAAAAAAAAuA
2332007-02-13 22:05:12.899 VideoBuffers::DiscardFrames(): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2342007-02-13 22:05:12.900 VideoBuffers::DiscardFrames(1): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2352007-02-13 22:05:12.900 VideoOutputXv: DiscardFrames() 3: AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2362007-02-13 22:05:13.650 NVP: ClearAfterSeek(1)
2372007-02-13 22:05:13.650 VideoOutputXv: ClearAfterSeek()
2382007-02-13 22:05:13.650 VideoOutputXv: DiscardFrames(0)
2392007-02-13 22:05:13.651 VideoBuffers::DiscardFrames(0): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2402007-02-13 22:05:13.651 VideoBuffers::DiscardFrames(0): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
2412007-02-13 22:05:13.651 VideoOutputXv: DiscardFrames() 3: AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
2422007-02-13 22:05:13.651 WriteAudio: buffer underrun
2432007-02-13 22:05:13.652 detectInterlace(Detect Scan, Interlaced Scan, 29.97, 480) ->Interlaced Scan
2442007-02-13 22:05:13.703 NVP: progressive frame seen after 2 interlaced  frames
2452007-02-13 22:05:13.765 Set video sync frame interval to 33366
2462007-02-13 22:05:13.765 Disabled deinterlacing
2472007-02-13 22:05:13.944 AFD: HandleGopStart: gopset not set, syncing positionMap
2482007-02-13 22:05:13.944 Resyncing position map. posmapStarted = 1 livetv(0) watchingRec(0)
2492007-02-13 22:05:13.944 AFD: HandleGopStart: Initial key frame distance: 15.
250'video_output' mean = '44593.27', std. dev. = '93320.06', fps = '22.42'
2512007-02-13 22:05:14.464 AFD: HandleGopStart: Key frame distance changed from 13 to 15.
252'video_output' mean = '33367.86', std. dev. = '2294.62', fps = '29.97'
253'video_output' mean = '33260.50', std. dev. = '4746.99', fps = '30.07'
254'video_output' mean = '33398.78', std. dev. = '5678.80', fps = '29.94'
2552007-02-13 22:05:26.986 NVP: 400 progressive frames seen.
256'video_output' mean = '33343.65', std. dev. = '5606.82', fps = '29.99'
257'video_output' mean = '33358.49', std. dev. = '5542.18', fps = '29.98'
258'video_output' mean = '33545.67', std. dev. = '5669.67', fps = '29.81'
259'video_output' mean = '33248.98', std. dev. = '4670.40', fps = '30.08'
2602007-02-13 22:05:40.332 NVP: 800 progressive frames seen.
261'video_output' mean = '33392.92', std. dev. = '5504.53', fps = '29.95'
262'video_output' mean = '33342.17', std. dev. = '4772.07', fps = '29.99'
2632007-02-13 22:05:45.689 DVDNAV_CELL_CHANGE: pg_length == 2646000, pgc_length == 8007000, cell_start == 2901000, pg_start == 2901000, title == 0, part == 3 titleParts 0
2642007-02-13 22:05:45.689 DVDNAV_SPU_CLUT_CHANGE happened.
2652007-02-13 22:05:45.690 DVDNAV_SPU_STREAM_CHANGE: physical_wide==0, physical_letterbox==0, physical_pan_scan==1, logical==8421504
2662007-02-13 22:05:45.690 DVDNAV_AUDIO_STREAM_CHANGE: physical==0, logical==0
2672007-02-13 22:05:45.738 AFD: DVD Cell Changed. Update framesPlayed: 959
2682007-02-13 22:05:45.791 AFD: HandleGopStart: Key frame distance changed from 15 to 3.
2692007-02-13 22:05:45.801 AFD: HandleStreamChange(): streams_changed 0xb1721a8 -- stream count 4
2702007-02-13 22:05:45.801 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video, bitrate 5500000 at 0x0xb1748b0
2712007-02-13 22:05:45.806 AFD: Warning, video codec 0xb1749b0 id(MPEG2VIDEO) type (Video) already open.
2722007-02-13 22:05:45.806 AFD: Looking for decoder for MPEG2VIDEO
2732007-02-13 22:05:45.807 AFD: Stream #1, has id 0x130 codec id AC3, type Audio, bitrate 384000 at 0x0xbf0b4a0
2742007-02-13 22:05:45.807 AFD: Warning, audio codec 0xbf0bd00 id(AC3) type (Audio) already open, leaving it alone.
2752007-02-13 22:05:45.807 AFD: Looking for decoder for AC3
2762007-02-13 22:05:45.807 AFD: Stream #2, has id 0x128 codec id AC3, type Audio, bitrate 192000 at 0x0xbf0a630
2772007-02-13 22:05:45.807 AFD: Warning, audio codec 0xbf0c060 id(AC3) type (Audio) already open, leaving it alone.
2782007-02-13 22:05:45.807 AFD: Looking for decoder for AC3
2792007-02-13 22:05:45.807 AFD: Stream #3, has id 0x33 codec id DVD_SUBTITLE, type Subtitle, bitrate 0 at 0x0xbf0b380
2802007-02-13 22:05:45.807 AFD: subtitle codec (Subtitle)
2812007-02-13 22:05:45.807 AFD: Looking for decoder for DVD_SUBTITLE
2822007-02-13 22:05:45.807 AFD: Opened codec 0xbf76060, id(DVD_SUBTITLE) type(Subtitle)
2832007-02-13 22:05:45.807 AFD: Subtitle track #1 is A/V stream #3 and is in the Unknown language(0).
2842007-02-13 22:05:45.808 RingBuf(//dev/dvd): CalcReadAheadThresh(6076 KB)
285                         -> threshhold(64 KB) min read(32 KB) blk size(128 KB)
2862007-02-13 22:05:45.808 AFD: HandleStreamChange(): streams_changed 0xb1721a8 -- stream count 5
2872007-02-13 22:05:45.808 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video, bitrate 5500000 at 0x0xb1748b0
2882007-02-13 22:05:45.810 AFD: Warning, video codec 0xb1749b0 id(MPEG2VIDEO) type (Video) already open.
2892007-02-13 22:05:45.810 AFD: Looking for decoder for MPEG2VIDEO
2902007-02-13 22:05:45.810 AFD: Stream #1, has id 0x130 codec id AC3, type Audio, bitrate 384000 at 0x0xbf0b4a0
2912007-02-13 22:05:45.810 AFD: Warning, audio codec 0xbf0bd00 id(AC3) type (Audio) already open, leaving it alone.
2922007-02-13 22:05:45.810 AFD: Looking for decoder for AC3
2932007-02-13 22:05:45.810 AFD: Stream #2, has id 0x128 codec id AC3, type Audio, bitrate 192000 at 0x0xbf0a630
2942007-02-13 22:05:45.810 AFD: Warning, audio codec 0xbf0c060 id(AC3) type (Audio) already open, leaving it alone.
2952007-02-13 22:05:45.810 AFD: Looking for decoder for AC3
2962007-02-13 22:05:45.810 AFD: Stream #3, has id 0x33 codec id DVD_SUBTITLE, type Subtitle, bitrate 0 at 0x0xbf0b380
2972007-02-13 22:05:45.810 AFD: subtitle codec (Subtitle)
2982007-02-13 22:05:45.810 AFD: Looking for decoder for DVD_SUBTITLE
2992007-02-13 22:05:45.811 AFD: Subtitle track #1 is A/V stream #3 and is in the Unknown language(0).
3002007-02-13 22:05:45.811 AFD: Stream #4, has id 0x32 codec id DVD_SUBTITLE, type Subtitle, bitrate 0 at 0x0xb2b2060
3012007-02-13 22:05:45.811 AFD: subtitle codec (Subtitle)
3022007-02-13 22:05:45.811 AFD: Looking for decoder for DVD_SUBTITLE
3032007-02-13 22:05:45.811 AFD: Opened codec 0xbf4d6d0, id(DVD_SUBTITLE) type(Subtitle)
3042007-02-13 22:05:45.811 AFD: Subtitle track #2 is A/V stream #4 and is in the Unknown language(0).
3052007-02-13 22:05:45.811 RingBuf(//dev/dvd): CalcReadAheadThresh(6076 KB)
306                         -> threshhold(64 KB) min read(32 KB) blk size(128 KB)
3072007-02-13 22:05:45.812 DVDNAV_HIGHLIGHT: display==1, palette==0, sx==1, sy==0, ex==32896, ey==128, pts==8421504, buttonN==1
3082007-02-13 22:05:46.295 AFD: HandleGopStart: Key frame distance changed from 3 to 15.
309'video_output' mean = '33359.53', std. dev. = '4966.14', fps = '29.98'
310'video_output' mean = '33353.64', std. dev. = '4734.80', fps = '29.98'
3112007-02-13 22:05:53.676 NVP: 1200 progressive frames seen.
312'video_output' mean = '33390.36', std. dev. = '4704.14', fps = '29.95'
313'video_output' mean = '33370.82', std. dev. = '3949.07', fps = '29.97'
314'video_output' mean = '33337.00', std. dev. = '4111.84', fps = '30.00'
315'video_output' mean = '33352.55', std. dev. = '3637.35', fps = '29.98'
3162007-02-13 22:06:07.022 NVP: 1600 progressive frames seen.
317'video_output' mean = '33460.64', std. dev. = '5195.74', fps = '29.89'
318'video_output' mean = '33287.00', std. dev. = '4751.45', fps = '30.04'
319'video_output' mean = '33347.33', std. dev. = '4309.14', fps = '29.99'
3202007-02-13 22:06:15.241 DVDNAV_CELL_CHANGE: pg_length == 2460000, pgc_length == 8007000, cell_start == 5547000, pg_start == 5547000, title == 0, part == 3 titleParts 0
3212007-02-13 22:06:15.241 DVDNAV_SPU_CLUT_CHANGE happened.
3222007-02-13 22:06:15.241 DVDNAV_SPU_STREAM_CHANGE: physical_wide==0, physical_letterbox==0, physical_pan_scan==1, logical==8421504
3232007-02-13 22:06:15.241 DVDRB: Clearing Menu SPU Packet
3242007-02-13 22:06:15.241 DVDNAV_AUDIO_STREAM_CHANGE: physical==0, logical==0
3252007-02-13 22:06:15.285 AFD: DVD Cell Changed. Update framesPlayed: 1828
3262007-02-13 22:06:15.294 WriteAudio: buffer underrun
3272007-02-13 22:06:15.315 DVDNAV_HIGHLIGHT: display==1, palette==0, sx==1, sy==0, ex==32896, ey==128, pts==8421504, buttonN==1
328'video_output' mean = '33333.45', std. dev. = '8180.01', fps = '30.00'
3292007-02-13 22:06:20.368 NVP: 2000 progressive frames seen.
330'video_output' mean = '33365.01', std. dev. = '4797.53', fps = '29.97'
331'video_output' mean = '33370.15', std. dev. = '5140.82', fps = '29.97'
332'video_output' mean = '33358.75', std. dev. = '4134.44', fps = '29.98'
333'video_output' mean = '33360.81', std. dev. = '5537.14', fps = '29.98'
3342007-02-13 22:06:32.830 DVDNAV_HOP_CHANNEL happened.
3352007-02-13 22:06:32.830 DVDNAV_CELL_CHANGE: pg_length == 564000, pgc_length == 564000, cell_start == 0, pg_start == 0, title == 0, part == 0 titleParts 0
3362007-02-13 22:06:32.830 DVDNAV_SPU_CLUT_CHANGE happened.
3372007-02-13 22:06:32.830 DVDNAV_SPU_STREAM_CHANGE: physical_wide==0, physical_letterbox==0, physical_pan_scan==0, logical==8421504
3382007-02-13 22:06:32.830 DVDRB: Clearing Menu SPU Packet
3392007-02-13 22:06:32.830 DVDNAV_AUDIO_STREAM_CHANGE: physical==0, logical==0
3402007-02-13 22:06:32.889 AFD: DVD Cell Changed. Update framesPlayed: 0
3412007-02-13 22:06:33.099 NVP: Video is 30 frames ahead of audio,
342                        doubling video frame interval to slow down.
3432007-02-13 22:06:33.177 NVP: Video is 30 frames ahead of audio,
344                        doubling video frame interval to slow down.
3452007-02-13 22:06:33.235 NVP: Video is 30 frames ahead of audio,
346                        doubling video frame interval to slow down.
3472007-02-13 22:06:33.300 NVP: Video is 30 frames ahead of audio,
348                        doubling video frame interval to slow down.
3492007-02-13 22:06:33.314 AFD: HandleGopStart: Key frame distance changed from 15 to 13.
3502007-02-13 22:06:33.367 NVP: Video is 30 frames ahead of audio,
351                        doubling video frame interval to slow down.
3522007-02-13 22:06:33.433 NVP: Video is 30 frames ahead of audio,
353                        doubling video frame interval to slow down.
3542007-02-13 22:06:33.500 NVP: Video is 30 frames ahead of audio,
355                        doubling video frame interval to slow down.
3562007-02-13 22:06:33.566 NVP: Video is 30 frames ahead of audio,
357                        doubling video frame interval to slow down.
3582007-02-13 22:06:33.633 NVP: Video is 30 frames ahead of audio,
359                        doubling video frame interval to slow down.
3602007-02-13 22:06:33.700 NVP: Video is 30 frames ahead of audio,
361                        doubling video frame interval to slow down.
3622007-02-13 22:06:33.767 NVP: Video is 24.0982 frames ahead of audio,
363                        doubling video frame interval to slow down.
3642007-02-13 22:06:33.827 AFD: HandleGopStart: Key frame distance changed from 13 to 15.
3652007-02-13 22:06:33.843 NVP: Video is 14.7769 frames ahead of audio,
366                        doubling video frame interval to slow down.
3672007-02-13 22:06:33.901 NVP: Video is 7.45618 frames ahead of audio,
368                        doubling video frame interval to slow down.
3692007-02-13 22:06:33.984 NVP: Video is 5.9486 frames behind audio (too slow), dropping frame to catch up.
3702007-02-13 22:06:33.984 NVP: Video is 8.13283 frames behind audio (too slow), dropping frame to catch up.
3712007-02-13 22:06:33.984 NVP: Video is 9.52377 frames behind audio (too slow), dropping frame to catch up.
3722007-02-13 22:06:33.984 NVP: Video is 10.3122 frames behind audio (too slow), dropping frame to catch up.
3732007-02-13 22:06:33.984 NVP: Video is 10.6563 frames behind audio (too slow), dropping frame to catch up.
3742007-02-13 22:06:33.984 NVP: Video is 10.6671 frames behind audio (too slow), dropping frame to catch up.
3752007-02-13 22:06:33.984 NVP: Video is 10.4204 frames behind audio (too slow), dropping frame to catch up.
3762007-02-13 22:06:33.984 NVP: Video is 9.99565 frames behind audio (too slow), dropping frame to catch up.
3772007-02-13 22:06:33.985 NVP: Video is 9.42984 frames behind audio (too slow), dropping frame to catch up.
3782007-02-13 22:06:33.985 NVP: 2400 progressive frames seen.
3792007-02-13 22:06:33.985 NVP: Video is 8.75073 frames behind audio (too slow), dropping frame to catch up.
3802007-02-13 22:06:33.985 NVP: Video is 7.99413 frames behind audio (too slow), dropping frame to catch up.
3812007-02-13 22:06:33.985 NVP: Video is 7.17194 frames behind audio (too slow), dropping frame to catch up.
3822007-02-13 22:06:33.985 NVP: Video is 6.30804 frames behind audio (too slow), dropping frame to catch up.
3832007-02-13 22:06:33.985 NVP: Video is 5.41285 frames behind audio (too slow), dropping frame to catch up.
3842007-02-13 22:06:33.985 NVP: Video is 4.48669 frames behind audio (too slow), dropping frame to catch up.
3852007-02-13 22:06:33.985 NVP: Video is 3.54484 frames behind audio (too slow), dropping frame to catch up.
386'video_output' mean = '33931.72', std. dev. = '23666.42', fps = '29.47'
387'video_output' mean = '33555.55', std. dev. = '6022.42', fps = '29.80'
3882007-02-13 22:06:39.105 DVDNAV_VTS_CHANGE: old_vtsN==1, new_vtsN==1, aspect: 3, perm: 2
3892007-02-13 22:06:39.105 DVDNAV_CELL_CHANGE: pg_length == 630000, pgc_length == 630000, cell_start == 0, pg_start == 0, title == 7, part == 1 titleParts 1
3902007-02-13 22:06:39.105 DVDNAV_SPU_CLUT_CHANGE happened.
3912007-02-13 22:06:39.105 DVDNAV_SPU_STREAM_CHANGE: physical_wide==-1, physical_letterbox==-1, physical_pan_scan==-1, logical==8421504
3922007-02-13 22:06:39.105 DVDNAV_AUDIO_STREAM_CHANGE: physical==0, logical==-1
3932007-02-13 22:06:39.183 Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(0)
3942007-02-13 22:06:39.183 Position map filled from DB to: 209
3952007-02-13 22:06:39.183 SyncPositionMap prerecorded, from DB: 1 entries
3962007-02-13 22:06:39.184 SyncPositionMap, new totframes: 209, new length: 7, posMap size: 1
3972007-02-13 22:06:39.184 AFD: DVD Title Changed
3982007-02-13 22:06:39.184 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video, bitrate 5500000 at 0x0xb1748b0
3992007-02-13 22:06:39.184 AFD: Looking for decoder for MPEG2VIDEO
4002007-02-13 22:06:39.184 AFD: Stream #1, has id 0x130 codec id AC3, type Audio, bitrate 384000 at 0x0xbf0b4a0
4012007-02-13 22:06:39.184 AFD: Warning, audio codec 0xbf0bd00 id(AC3) type (Audio) already open, leaving it alone.
4022007-02-13 22:06:39.184 AFD: Looking for decoder for AC3
4032007-02-13 22:06:39.184 AFD: Stream #2, has id 0x128 codec id AC3, type Audio, bitrate 192000 at 0x0xbf0a630
4042007-02-13 22:06:39.184 AFD: Warning, audio codec 0xbf0c060 id(AC3) type (Audio) already open, leaving it alone.
4052007-02-13 22:06:39.184 AFD: Looking for decoder for AC3
4062007-02-13 22:06:39.184 AFD: Stream #3, has id 0x33 codec id DVD_SUBTITLE, type Subtitle, bitrate 0 at 0x0xbf0b380
4072007-02-13 22:06:39.184 AFD: subtitle codec (Subtitle)
4082007-02-13 22:06:39.185 AFD: Looking for decoder for DVD_SUBTITLE
4092007-02-13 22:06:39.185 AFD: Subtitle track #1 is A/V stream #3 and is in the Unknown language(0).
4102007-02-13 22:06:39.185 AFD: Stream #4, has id 0x32 codec id DVD_SUBTITLE, type Subtitle, bitrate 0 at 0x0xb2b2060
4112007-02-13 22:06:39.185 AFD: subtitle codec (Subtitle)
4122007-02-13 22:06:39.185 AFD: Looking for decoder for DVD_SUBTITLE
4132007-02-13 22:06:39.185 AFD: Subtitle track #2 is A/V stream #4 and is in the Unknown language(0).
4142007-02-13 22:06:39.185 RingBuf(//dev/dvd): CalcReadAheadThresh(6076 KB)
415                         -> threshhold(64 KB) min read(32 KB) blk size(128 KB)
4162007-02-13 22:06:39.185 AFD: DVD Cell Changed. Update framesPlayed: 0
4172007-02-13 22:06:39.221 VideoOutputXv: InputChanged(720,480,1.77778)
4182007-02-13 22:06:39.222 VideoOutputXv: DiscardFrames(1)
4192007-02-13 22:06:39.222 VideoBuffers::DiscardFrames(1): AAAAAAAAAAAAAAULAAAuAAAAAAAAAAA
4202007-02-13 22:06:39.222 VideoBuffers::DiscardFrames(): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
4212007-02-13 22:06:39.222 VideoBuffers::DiscardFrames(1): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
4222007-02-13 22:06:39.222 VideoOutputXv: DiscardFrames() 3: AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
4232007-02-13 22:06:39.975 NVP: ClearAfterSeek(1)
4242007-02-13 22:06:39.975 VideoOutputXv: ClearAfterSeek()
4252007-02-13 22:06:39.975 VideoOutputXv: DiscardFrames(0)
4262007-02-13 22:06:39.975 VideoBuffers::DiscardFrames(0): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
4272007-02-13 22:06:39.976 VideoBuffers::DiscardFrames(0): AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done
4282007-02-13 22:06:39.976 VideoOutputXv: DiscardFrames() 3: AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA -- done()
4292007-02-13 22:06:39.976 detectInterlace(Detect Scan, Progressive Scan, 29.97, 480) ->Interlaced Scan
4302007-02-13 22:06:39.976 Set video sync frame interval to 33366
4312007-02-13 22:06:39.976 Enabled deinterlacing
4322007-02-13 22:06:39.978 WriteAudio: buffer underrun
4332007-02-13 22:06:40.024 NVP: progressive frame seen after 2 interlaced  frames
4342007-02-13 22:06:40.081 Set video sync frame interval to 33366
4352007-02-13 22:06:40.081 Disabled deinterlacing
4362007-02-13 22:06:40.811 AFD: HandleGopStart: gopset not set, syncing positionMap
4372007-02-13 22:06:40.812 Resyncing position map. posmapStarted = 1 livetv(0) watchingRec(0)
4382007-02-13 22:06:40.812 AFD: HandleGopStart: Initial key frame distance: 15.
4392007-02-13 22:06:40.934 NVP: interlaced frame seen after 23 progressive frames
4402007-02-13 22:06:41.022 Set video sync frame interval to 33366
4412007-02-13 22:06:41.023 Enabled deinterlacing
4422007-02-13 22:06:41.438 NVP: progressive frame seen after 14 interlaced  frames
4432007-02-13 22:06:41.502 Set video sync frame interval to 33366
4442007-02-13 22:06:41.502 Disabled deinterlacing
445'video_output' mean = '44721.22', std. dev. = '85762.38', fps = '22.36'
4462007-02-13 22:06:45.455 NVP: interlaced frame seen after 97 progressive frames
4472007-02-13 22:06:45.521 Set video sync frame interval to 33366
4482007-02-13 22:06:45.521 Enabled deinterlacing
4492007-02-13 22:06:45.965 NVP: progressive frame seen after 14 interlaced  frames
450'video_output' mean = '40666.42', std. dev. = '18436.34', fps = '24.59'
4512007-02-13 22:06:46.071 Set video sync frame interval to 33366
4522007-02-13 22:06:46.071 Disabled deinterlacing
4532007-02-13 22:06:46.776 DVDNAV_CELL_CHANGE: pg_length == 27180000, pgc_length == 538668000, cell_start == 0, pg_start == 0, title == 1, part == 1 titleParts 24
4542007-02-13 22:06:46.776 DVDNAV_SPU_CLUT_CHANGE happened.
4552007-02-13 22:06:46.776 DVDNAV_SPU_STREAM_CHANGE: physical_wide==-1, physical_letterbox==-1, physical_pan_scan==-1, logical==8421504
4562007-02-13 22:06:46.776 DVDNAV_AUDIO_STREAM_CHANGE: physical==0, logical==-1
4572007-02-13 22:06:46.779 Resyncing position map. posmapStarted = 0 livetv(0) watchingRec(0)
4582007-02-13 22:06:46.779 Position map filled from DB to: 179370
4592007-02-13 22:06:46.780 SyncPositionMap prerecorded, from DB: 1 entries
4602007-02-13 22:06:46.780 SyncPositionMap, new totframes: 179370, new length: 5985, posMap size: 1
4612007-02-13 22:06:46.780 AFD: DVD Title Changed
4622007-02-13 22:06:46.780 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video, bitrate 7500000 at 0x0xb1748b0
4632007-02-13 22:06:46.780 AFD: Looking for decoder for MPEG2VIDEO
4642007-02-13 22:06:46.780 AFD: Stream #1, has id 0x130 codec id AC3, type Audio, bitrate 384000 at 0x0xbf0b4a0
4652007-02-13 22:06:46.780 AFD: Warning, audio codec 0xbf0bd00 id(AC3) type (Audio) already open, leaving it alone.
4662007-02-13 22:06:46.780 AFD: Looking for decoder for AC3
4672007-02-13 22:06:46.780 AFD: Stream #2, has id 0x128 codec id AC3, type Audio, bitrate 448000 at 0x0xbf0a630
4682007-02-13 22:06:46.780 AFD: Warning, audio codec 0xbf0c060 id(AC3) type (Audio) already open, leaving it alone.
4692007-02-13 22:06:46.780 AFD: Looking for decoder for AC3
4702007-02-13 22:06:46.780 AFD: Stream #3, has id 0x33 codec id DVD_SUBTITLE, type Subtitle, bitrate 0 at 0x0xbf0b380
4712007-02-13 22:06:46.781 AFD: subtitle codec (Subtitle)
4722007-02-13 22:06:46.781 AFD: Looking for decoder for DVD_SUBTITLE
4732007-02-13 22:06:46.781 AFD: Subtitle track #1 is A/V stream #3 and is in the Unknown language(0).
4742007-02-13 22:06:46.781 AFD: Stream #4, has id 0x32 codec id DVD_SUBTITLE, type Subtitle, bitrate 0 at 0x0xb2b2060
4752007-02-13 22:06:46.781 AFD: subtitle codec (Subtitle)
4762007-02-13 22:06:46.781 AFD: Looking for decoder for DVD_SUBTITLE
4772007-02-13 22:06:46.781 AFD: Subtitle track #2 is A/V stream #4 and is in the Unknown language(0).
4782007-02-13 22:06:46.781 RingBuf(//dev/dvd): CalcReadAheadThresh(8332 KB)
479                         -> threshhold(64 KB) min read(32 KB) blk size(128 KB)
4802007-02-13 22:06:46.781 AFD: DVD Cell Changed. Update framesPlayed: 0
4812007-02-13 22:06:46.782 AFD: HandleStreamChange(): streams_changed 0xb1721a8 -- stream count 6
4822007-02-13 22:06:46.782 AFD: Stream #0, has id 0x480 codec id MPEG2VIDEO, type Video, bitrate 7500000 at 0x0xb1748b0
4832007-02-13 22:06:46.782 NVP: prebuffering pause
4842007-02-13 22:06:46.782 NVP: Waiting for prebuffer.. 0 AAAAAAuAAAAAAAAAAaAALAAAAAAAAAA
4852007-02-13 22:06:46.784 AFD: Warning, video codec 0xb1749b0 id(MPEG2VIDEO) type (Video) already open.
4862007-02-13 22:06:46.785 AFD: Looking for decoder for MPEG2VIDEO
4872007-02-13 22:06:46.785 AFD: Stream #1, has id 0x130 codec id AC3, type Audio, bitrate 384000 at 0x0xbf0b4a0
4882007-02-13 22:06:46.785 AFD: Warning, audio codec 0xbf0bd00 id(AC3) type (Audio) already open, leaving it alone.
4892007-02-13 22:06:46.785 AFD: Looking for decoder for AC3
4902007-02-13 22:06:46.785 AFD: Stream #2, has id 0x128 codec id AC3, type Audio, bitrate 448000 at 0x0xbf0a630
4912007-02-13 22:06:46.785 AFD: Warning, audio codec 0xbf0c060 id(AC3) type (Audio) already open, leaving it alone.
4922007-02-13 22:06:46.786 AFD: Looking for decoder for AC3
4932007-02-13 22:06:46.786 AFD: Stream #3, has id 0x33 codec id DVD_SUBTITLE, type Subtitle, bitrate 0 at 0x0xbf0b380
4942007-02-13 22:06:46.786 AFD: subtitle codec (Subtitle)
4952007-02-13 22:06:46.786 AFD: Looking for decoder for DVD_SUBTITLE
4962007-02-13 22:06:46.786 AFD: Subtitle track #1 is A/V stream #3 and is in the Unknown language(0).
4972007-02-13 22:06:46.786 AFD: Stream #4, has id 0x32 codec id DVD_SUBTITLE, type Subtitle, bitrate 0 at 0x0xb2b2060
4982007-02-13 22:06:46.786 AFD: subtitle codec (Subtitle)
4992007-02-13 22:06:46.787 AFD: Looking for decoder for DVD_SUBTITLE
5002007-02-13 22:06:46.787 AFD: Subtitle track #2 is A/V stream #4 and is in the Unknown language(0).
5012007-02-13 22:06:46.787 AFD: Stream #5, has id 0x129 codec id AC3, type Audio, bitrate 0 at 0x0xbf7a8d0
5022007-02-13 22:06:46.787 AFD: Looking for decoder for AC3
5032007-02-13 22:06:46.788 AFD: Opened codec 0xb2318c0, id(AC3) type(Audio)
5042007-02-13 22:06:46.788 RingBuf(//dev/dvd): CalcReadAheadThresh(8332 KB)
505                         -> threshhold(64 KB) min read(32 KB) blk size(128 KB)
5062007-02-13 22:06:46.792 Dec: Trying to select track (w/lang)
5072007-02-13 22:06:46.793 Dec: Selecting first track
5082007-02-13 22:06:46.793 Dec: Selected track #1 in the Unknown language(0)
5092007-02-13 22:06:46.793 Dec: Trying to select track (w/lang)
5102007-02-13 22:06:46.793 Dec: Selecting first track
5112007-02-13 22:06:46.793 Dec: Selected track #1 in the Unknown language(0)
5122007-02-13 22:06:46.820 NVP: interlaced frame seen after 21 progressive frames
5132007-02-13 22:06:46.825 AFD: HandleGopStart: Key frame distance changed from 15 to 12.
5142007-02-13 22:06:46.872 NVP: Video is 30 frames ahead of audio,
515                        doubling video frame interval to slow down.
5162007-02-13 22:06:46.873 NVP: progressive frame seen after 2 interlaced  frames
5172007-02-13 22:06:46.939 NVP: Video is 30 frames ahead of audio,
518                        doubling video frame interval to slow down.
5192007-02-13 22:06:47.005 NVP: Video is 30 frames ahead of audio,
520                        doubling video frame interval to slow down.
5212007-02-13 22:06:47.072 NVP: Video is 22.7008 frames ahead of audio,
522                        doubling video frame interval to slow down.
5232007-02-13 22:06:47.139 NVP: Video is 16.7034 frames ahead of audio,
524                        doubling video frame interval to slow down.
5252007-02-13 22:06:47.206 NVP: Video is 12.078 frames ahead of audio,
526                        doubling video frame interval to slow down.
5272007-02-13 22:06:47.272 NVP: Video is 8.36163 frames ahead of audio,
528                        doubling video frame interval to slow down.
5292007-02-13 22:06:47.339 NVP: Video is 5.44701 frames ahead of audio,
530                        doubling video frame interval to slow down.
5312007-02-13 22:06:47.406 NVP: Video is 3.01379 frames ahead of audio,
532                        doubling video frame interval to slow down.
5332007-02-13 22:06:47.573 NVP: Video is 3.18396 frames behind audio (too slow), dropping frame to catch up.
5342007-02-13 22:06:47.640 NVP: Video is 3.04037 frames behind audio (too slow), dropping frame to catch up.
535'video_output' mean = '40926.83', std. dev. = '14876.82', fps = '24.43'
5362007-02-13 22:06:50.674 NVP: Changing speed to 0
5372007-02-13 22:06:50.674 rate: 29.97 speed: 1 skip: 1 = interval 33366
5382007-02-13 22:06:50.674 Set video sync frame interval to 33366
5392007-02-13 22:08:22.770 NVP: Play(  1.0, normal 1, unpause audio 1)
5402007-02-13 22:08:22.771 NVP: Changing speed to 1
5412007-02-13 22:08:22.771 RingBuf(//dev/dvd): CalcReadAheadThresh(8332 KB)
542                         -> threshhold(64 KB) min read(32 KB) blk size(128 KB)
5432007-02-13 22:08:22.771 NVP: DoPlay: rate: 29.97 speed: 1 skip: 1 => new interval 33366
5442007-02-13 22:08:22.771 Set video sync frame interval to 33366
5452007-02-13 22:08:22.771 NVP: Stretch Factor 1, allow passthru
5462007-02-13 22:08:23.091 AFD: HandleGopStart: Key frame distance changed from 12 to 38.
5472007-02-13 22:08:23.564 AFD: HandleGopStart: Key frame distance changed from 38 to 12.
548'video_output' mean = '961335.71', std. dev. = '9205328.51', fps = '1.04'
549'video_output' mean = '41694.49', std. dev. = '8356.89', fps = '23.98'
5502007-02-13 22:08:33.715 Disabled deinterlacing
551'video_output' mean = '41698.06', std. dev. = '8418.15', fps = '23.98'
5522007-02-13 22:08:35.433 NVP: 400 progressive frames seen.
553