[mythtv] mythplayer.cpp query

Tue Mar 13 17:40:33 UTC 2012

On 13 Mar 2012, at 16:01, Stuart Morgan wrote:

> On Tuesday 13 Mar 2012 15:25:02 Russell Gower wrote:
>> Just to be clear, I'm not talking about channel changes, I'm talking about
>> the delay when one program ends and the next one starts  - i.e the
>> transition from 8441_20120312180956.mpg to 8441_20120312183001.mpg
> 
> I'm unable to reproduce a delay on programme transitions ... and historically 
> no-one has ever reported a delay there.
> 
> Still if you are seeing a delay then something is going wrong.

I'm really hoping this is a setup issue, it's persisted over 3 hardware "upgrades" and I've experienced it ever since the switch to creating individual recording files for live tv, so i'm doubt full.

Bellow is an typical example from the frontend log - on this occasion SwitchToProgram took 7.6 seconds, during which the screen was frozen.

2012-03-13 09:15:01.343816 I  Player(0): SwitchToProgram - start
2012-03-13 09:15:01.510896 I  Player(0): LoadFilters(''..) -> 0x0
2012-03-13 09:15:01.510907 I  AO: Pause 1
2012-03-13 09:15:01.521439 I  Player(0): Play speed: rate: 25 speed: 0 skip: 0 => new interval 40000
2012-03-13 09:15:01.521503 I  VDP: GetFilteredDeint(none) : xv-blit -> 'none'
2012-03-13 09:15:01.522186 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libadjust.so'
2012-03-13 09:15:01.522269 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libbobdeint.so'
2012-03-13 09:15:01.522302 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libcrop.so'
2012-03-13 09:15:01.522333 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libdenoise3d.so'
2012-03-13 09:15:01.522364 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libfieldorder.so'
2012-03-13 09:15:01.522394 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libforce.so'
2012-03-13 09:15:01.522431 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libgreedyhdeint.so'
2012-03-13 09:15:01.522464 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libinvert.so'
2012-03-13 09:15:01.522495 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libivtc.so'
2012-03-13 09:15:01.522526 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libkerneldeint.so'
2012-03-13 09:15:01.522559 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/liblinearblend.so'
2012-03-13 09:15:01.522592 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libonefield.so'
2012-03-13 09:15:01.522625 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libpostprocess.so'
2012-03-13 09:15:01.522683 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libquickdnr.so'
2012-03-13 09:15:01.522733 I  FilterManager: Loading filter '/usr/lib64/mythtv/filters/libyadif.so'
2012-03-13 09:15:01.522777 E  VideoOutput: Couldn't load deinterlace filter none
2012-03-13 09:15:01.522783 I  VideoOutput: Using deinterlace method 
2012-03-13 09:15:01.525242 N  SG(LiveTV): Unable to find storage group 'LiveTV', trying 'Default' group!
2012-03-13 09:15:01.530305 I  ProgramInfo(8441_20120313091500.mpg): GetPlaybackURL: File is local: '/mythtv/kvm02/Recordings/8441_20120313091500.mpg'
2012-03-13 09:15:01.530322 I  FileRingBuf(/mythtv/kvm02/Recordings/8441_20120313083045.mpg): OpenFile(/mythtv/kvm02/Recordings/8441_20120313091500.mpg, 10000 ms)
2012-03-13 09:15:01.535417 I  AO: OutputAudioLoop: audio paused
2012-03-13 09:15:05.544482 I  FileRingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): OpenFile() made 346 attempts in 4014 ms
2012-03-13 09:15:05.544502 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): CalcReadAheadThresh(8000 Kb)
2012-03-13 09:15:05.544524 I  Player(0): newid: 2 decoderEof: 0
2012-03-13 09:15:05.544563 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Reset(1,0,0)
2012-03-13 09:15:05.544572 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): ResetReadAhead(internalreadpos = 2374243728->0)
2012-03-13 09:15:05.544582 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): CalcReadAheadThresh(8000 Kb)
2012-03-13 09:15:05.544600 W  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Not starting read ahead thread, already running
2012-03-13 09:15:05.610378 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 0, 1048576) -> 349116, took 66 ms (42.3171Mbps)
2012-03-13 09:15:05.612113 I  AFD: Buffer size: 32768, streamed 1
2012-03-13 09:15:05.612335 I  FileRingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Seek(0,SEEK_SET,unlocked)
2012-03-13 09:15:05.612350 I  FileRingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Seek(): rbrpos: 196608 rbwpos: 349116
2012-03-13 09:15:05.612365 I  FileRingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Seek(): internal_backbuf: 196608 sba: 196608
2012-03-13 09:15:05.612375 I  FileRingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Seek(): OPT1 rbrpos: 0 rbwpos: 349116
2012-03-13 09:15:05.621910 I  FileRingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Seek(0,SEEK_SET,unlocked)
2012-03-13 09:15:05.675579 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 349116, 1048576) -> 0, took 60 ms (0Mbps)
2012-03-13 09:15:05.675622 I  FileRingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Seek(): rbrpos: 327680 rbwpos: 349116
2012-03-13 09:15:05.675662 I  FileRingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Seek(): internal_backbuf: 327680 sba: 327680
2012-03-13 09:15:05.675673 I  FileRingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Seek(): OPT1 rbrpos: 0 rbwpos: 349116
2012-03-13 09:15:05.981138 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 349116, 1048576) -> 0, took 301 ms (0Mbps)
2012-03-13 09:15:06.237066 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Waited 0.2 seconds for data 
2012-03-13 09:15:06.286617 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 349116, 1048576) -> 0, took 300 ms (0Mbps)
2012-03-13 09:15:06.286690 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Waited 0.2 seconds for data 
2012-03-13 09:15:06.536811 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Waited 0.5 seconds for data 
2012-03-13 09:15:06.592141 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 349116, 1048576) -> 0, took 301 ms (0Mbps)
2012-03-13 09:15:06.592192 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Waited 0.5 seconds for data 
2012-03-13 09:15:06.897687 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 349116, 1048576) -> 0, took 300 ms (0Mbps)
2012-03-13 09:15:07.147847 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Waited 1.0 seconds for data 
2012-03-13 09:15:07.203214 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 349116, 1048576) -> 0, took 301 ms (0Mbps)
2012-03-13 09:15:07.203266 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Waited 1.0 seconds for data 
2012-03-13 09:15:07.508765 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 349116, 1048576) -> 0, took 300 ms (0Mbps)
2012-03-13 09:15:07.814295 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 349116, 1048576) -> 0, took 301 ms (0Mbps)
2012-03-13 09:15:08.064446 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Waited 2.0 seconds for data 
2012-03-13 09:15:08.119849 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 349116, 1048576) -> 0, took 300 ms (0Mbps)
2012-03-13 09:15:08.119901 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): Waited 2.0 seconds for data 
2012-03-13 09:15:08.425382 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 349116, 1048576) -> 0, took 301 ms (0Mbps)
2012-03-13 09:15:08.564542 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 349116, 1048576) -> 1048576, took 134 ms (62.6016Mbps)
2012-03-13 09:15:08.580782 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 1397692, 1048576) -> 1048576, took 11 ms (762.601Mbps)
2012-03-13 09:15:08.588215 I  AFD: Stream #0, has id 0x1644 codec id MPEG2VIDEO, type Video, bitrate 15000000 at 0x282ce10
2012-03-13 09:15:08.596015 N  VDP: Ignoring profile item 182 (renderer quartz-blit is not supported w/decoder ffmpeg (supported: null,xlib,xshm,xv-blit,opengl,opengl-lite,vdpau,nullvdpau,openglvaapi,nullvaapi))
2012-03-13 09:15:08.596063 N  VDP: Ignoring profile item 183 (renderer quartz-blit is not supported w/decoder ffmpeg (supported: null,xlib,xshm,xv-blit,opengl,opengl-lite,vdpau,nullvdpau,openglvaapi,nullvaapi))
2012-03-13 09:15:08.596163 I  VDP: Accepting: cmp(>= 1280 720) dec(ffmpeg) cpus(2) skiploop(enabled) rend(xv-blit) osd(softblend) osdfade(enabled) deint(greedyhdoubleprocessdeint,none) filt()
2012-03-13 09:15:08.596198 I  VDP: Accepting: cmp(> 0 0) dec(ffmpeg) cpus(2) skiploop(enabled) rend(xv-blit) osd(softblend) osdfade(enabled) deint(greedyhdoubleprocessdeint,none) filt()
2012-03-13 09:15:08.596213 I  VDP: LoadBestPreferences(2048x2048, 0)
2012-03-13 09:15:08.596235 I  VDP: LoadBestPreferences(2048x2048, 60)
2012-03-13 09:15:08.596251 I  VDP: LoadBestPreferences(720x576, 60)
2012-03-13 09:15:08.596289 I  AFD: Using 2 CPUs for decoding
2012-03-13 09:15:08.596300 I  AFD: InitVideoCodec() 0x282bba0 id(MPEG2VIDEO) type (Video).
2012-03-13 09:15:08.596338 I  AFD: Selected FPS is 25 (avg 25 codec 25 container 90000 estimated 25)
2012-03-13 09:15:08.596351 I  Player(0): SetFrameInterval ps:0 scan:3
2012-03-13 09:15:08.596366 I  VideoOutputXv: InputChanged(720,576,1.77778) 'MPEG2'->'MPEG2'
2012-03-13 09:15:08.597343 I  Player(0): detectInterlace(Detect Scan, Interlaced Scan, 25, 576) ->Interlaced Scan
2012-03-13 09:15:08.597376 I  AFD: Using ffmpeg for video decoding
2012-03-13 09:15:08.597389 I  AFD: Looking for decoder for MPEG2VIDEO
2012-03-13 09:15:08.597493 I  AFD: Opened codec 0x282bba0, id(MPEG2VIDEO) type(Video)
2012-03-13 09:15:08.597516 I  AFD: Stream #1, has id 0x1645 codec id MP2, type Audio, bitrate 256000 at 0x1118890
2012-03-13 09:15:08.597530 I  AFD: codec MP2 has 2 channels
2012-03-13 09:15:08.597538 I  AFD: Looking for decoder for MP2
2012-03-13 09:15:08.597573 I  AFD: Opened codec 0x2813cf0, id(MP2) type(Audio)
2012-03-13 09:15:08.597600 I  AFD: Audio Track #1 is A/V stream #1 and has 2 channels in the English language(6647399).
2012-03-13 09:15:08.597620 I  AFD: Stream #2, has id 0x1647 codec id DVB_TELETEXT, type Subtitle, bitrate 0 at 0x36ea500
2012-03-13 09:15:08.597659 I  AFD: Teletext stream #0 (Menu) is in the English language on page 8 136.
2012-03-13 09:15:08.597684 I  AFD: Teletext stream #1 (Caption) is in the English language on page 8 136.
2012-03-13 09:15:08.597692 I  AFD: subtitle codec (Subtitle)
2012-03-13 09:15:08.597716 I  AFD: Stream #3, has id 0xf05 codec id DSMCC_B, type Data, bitrate 0 at 0x2815720
2012-03-13 09:15:08.597723 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 2446268, 1048576) -> 1048576, took 12 ms (699.051Mbps)
2012-03-13 09:15:08.597732 I  AFD: data codec (Data)
2012-03-13 09:15:08.597745 I  AFD: Stream #4, has id 0xf07 codec id DSMCC_B, type Data, bitrate 0 at 0x281ac30
2012-03-13 09:15:08.597749 I  AFD: data codec (Data)
2012-03-13 09:15:08.597757 I  AFD: Stream #5, has id 0xf08 codec id DSMCC_B, type Data, bitrate 0 at 0x2825ff0
2012-03-13 09:15:08.597764 I  AFD: data codec (Data)
2012-03-13 09:15:08.597776 I  AFD: Stream #6, has id 0xf09 codec id DSMCC_B, type Data, bitrate 0 at 0x1aef3c0
2012-03-13 09:15:08.597780 I  AFD: data codec (Data)
2012-03-13 09:15:08.597789 I  AFD: Stream #7, has id 0x1648 codec id DVB_SUBTITLE, type Subtitle, bitrate 0 at 0x28225a0
2012-03-13 09:15:08.597794 I  AFD: subtitle codec (Subtitle)
2012-03-13 09:15:08.597798 I  AFD: Looking for decoder for DVB_SUBTITLE
2012-03-13 09:15:08.597822 I  AFD: Opened codec 0x2826550, id(DVB_SUBTITLE) type(Subtitle)
2012-03-13 09:15:08.597834 I  AFD: Subtitle track #1 is A/V stream #7 and is in the English language(6647399).
2012-03-13 09:15:08.597841 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): UpdateRawBitrate(15256Kb)
2012-03-13 09:15:08.597852 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): CalcReadAheadThresh(15256 Kb)
2012-03-13 09:15:08.597869 I  AFD: Selected track 1: English MP2 2ch (A/V Stream #1)
2012-03-13 09:15:08.597880 I  AFD: Initializing audio parms from audio track #1
2012-03-13 09:15:08.597899 I  AFD: Audio format changed 
2012-03-13 09:15:08.597909 I  AO: Reconfigure(): No change -> exiting
2012-03-13 09:15:08.597920 I  Dec: Selected track #1 in the Unknown language(0)
2012-03-13 09:15:08.597928 I  Dec: Selected track #1 in the English language(6647399)
2012-03-13 09:15:08.597934 I  Dec: Selected track #1 in the English language(6647399)
2012-03-13 09:15:08.597940 I  Dec: Selected track #1 in the English language(6647399)
2012-03-13 09:15:08.597949 I  Dec: Resyncing position map. posmapStarted = 0 livetv(1) watchingRec(0)
2012-03-13 09:15:08.601237 I  Dec: Position map filled from DB to: 99
2012-03-13 09:15:08.601246 I  Dec: SyncPositionMap watchingrecording, from DB: 8 entries
2012-03-13 09:15:08.601256 I  Player(0): Filling position map from 100 to end
2012-03-13 09:15:08.601945 I  Dec: Position map filled from Encoder to: 111
2012-03-13 09:15:08.601959 I  Dec: SyncPositionMap watchingrecording total: 9 entries
2012-03-13 09:15:08.601971 I  Dec: SyncPositionMap, new totframes: 111, new length: 4, posMap size: 9
2012-03-13 09:15:08.608189 I  AFD: Partial position map found
2012-03-13 09:15:08.608200 I  AFD: Successfully opened decoder for file: "/mythtv/kvm02/Recordings/8441_20120313091500.mpg". novideo(0)
2012-03-13 09:15:08.664939 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 3494844, 699460) -> 326068, took 62 ms (42.0733Mbps)
2012-03-13 09:15:08.793618 N  AFD: Resetting byte context eof (livetv 1 was eof 0)
2012-03-13 09:15:08.793643 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): UpdateRawBitrate(15256Kb)
2012-03-13 09:15:08.970497 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): safe_read(... at 3820912, 373392) -> 0, took 300 ms (0Mbps)
2012-03-13 09:15:08.970538 I  RingBuf(/mythtv/kvm02/Recordings/8441_20120313091500.mpg): CalcReadAheadThresh(15256 Kb)
2012-03-13 09:15:08.970571 I  Player(0): Play(  1.0, normal 1, unpause audio 1)
2012-03-13 09:15:08.970600 I  AO: Pause 0
2012-03-13 09:15:08.970608 I  Player(0): SwitchToProgram - end