[mythtv] mythplayer.cpp query

[Raymond Wagner]

On 3/13/2012 13:40, Russell Gower wrote:
> 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.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)

It would appear roughly 7.1 of that 7.6 seconds is sitting there waiting 
for the data to get written to your filesystem.  If the data isn't 
available for the frontend to read it, then nothing you change in the 
frontend is going to make the slightest bit of difference.  We need to 
see backend logs to see where the actual stall is.

We also need to know more about how your system is actually configured.  
Looking through the mailing list archives, you appear to be running 
independent frontends, which means if you are reading off the 
filesystem, you are reading over NFS.  Is it possible your problem is 
caused by nothing more than NFS caching issues that would be resolved by 
merely not mounting those disks and letting MythTV stream its content 
internally?