[mythtv] ringbuffer.cpp

Jonas Arndt jonas.arndt at thearndtfamily.com
Sat Feb 22 03:52:35 UTC 2014 

> best to guess what's going on would be to run the backend with the extra option:
> -v file --loglevel=debug
>
> the logs are going to be extremely verbose, I suggest you comment in
> mythtv/libs/libmythbase/threadedfilewriter.cpp
>
> line 291 at the end of the ThreadedFileWriter::Write() function, comment
> the line:
>      LOG(VB_FILE, LOG_DEBUG, LOC + QString("Write(*, %1) total %2 cnt %3")
>              .arg(count,4).arg(totalBufferUse).arg(writeBuffers.size()));
>
> change it to:
> //    LOG(VB_FILE, LOG_DEBUG, LOC + QString("Write(*, %1) total %2 cnt %3")
> //            .arg(count,4).arg(totalBufferUse).arg(writeBuffers.size()));
>
> that will reduce the verbosity by about 90% as that log is displayed
> whenever you write 188 bytes to disk (but will still very verbose).
>
>
> After that, run some basic disk speed test:
>
> dd if=/dev/zero of=/data1/Recordings/test.mpg bs=64k count=1M
>
> that will write 64gig on your disk and report the writing speed
>
> then do the opposite:
> dd if=/data1/Recordings/test.mpg  of=/dev/null bs=64k count=1M
>
> that will read the 64gig and report the reading speed.
>
> will take over 10 minutes on a disk sustaining 100MB/s
>
> I'll push some unit test that report the reading and writing speed
> using the existing mythtv buffer class.
> _______________________________________________
>

So my friend had another freeze. I was running the flags -v file 
--loglevel=debug
This was in the back-end log:

===============================================================
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:912 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): total read so far: 
208359648 bytes
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:968 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): @ end of read ahead loop
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:871 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): 
safe_read(... at 2838752, 1048576) -- begin
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
fileringbuffer.cpp:475 (safe_read) 
FileRingBuf(/data1/Recordings/2655_20140222010733.mpg): not reading, 
reached EOF
Feb 21 18:10:44  mythbackend: last message repeated 3 times
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D TFWWrite 
threadedfilewriter.cpp:489 (DiskLoop) 
TFW(/data1/Recordings/2655_20140222010733.mpg:49): write(65424) cnt 0 
total 0
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D TFWWrite 
threadedfilewriter.cpp:526 (DiskLoop) 
TFW(/data1/Recordings/2655_20140222010733.mpg:49): total written so far: 
208425072 bytes
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
fileringbuffer.cpp:486 (safe_read) 
FileRingBuf(/data1/Recordings/2655_20140222010733.mpg): About to reach 
EOF, reading 65424 wanted 1048576
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
fileringbuffer.cpp:494 (safe_read) 
FileRingBuf(/data1/Recordings/2655_20140222010733.mpg): read(65424) -- begin
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
fileringbuffer.cpp:497 (safe_read) 
FileRingBuf(/data1/Recordings/2655_20140222010733.mpg): read(65424) -> 
65424 end
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: I RingBuffer 
ringbuffer.cpp:892 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): 
safe_read(... at 2838752, 1048576) -> 65424, took 240 ms (2.1808Mbps)
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:905 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): rbwpos +=  63K 
requested 1024K in read
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:912 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): total read so far: 
208425072 bytes
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:968 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): @ end of read ahead loop
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:871 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): 
safe_read(... at 2904176, 1048576) -- begin
Feb 21 18:10:44 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
fileringbuffer.cpp:475 (safe_read) 
FileRingBuf(/data1/Recordings/2655_20140222010733.mpg): not reading, 
reached EOF
Feb 21 18:10:45  mythbackend: last message repeated 16 times
Feb 21 18:10:45 howarddvr mythbackend: mythbackend[5006]: W 
ProcessRequest ringbuffer.cpp:1055 (WaitForReadsAllowed) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): Taking too long to 
be allowed to read..
Feb 21 18:10:45 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
fileringbuffer.cpp:475 (safe_read) 
FileRingBuf(/data1/Recordings/2655_20140222010733.mpg): not reading, 
reached EOF
Feb 21 18:10:46  mythbackend: last message repeated 16 times
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: W 
ProcessRequest ringbuffer.cpp:1055 (WaitForReadsAllowed) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): Taking too long to 
be allowed to read..
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
fileringbuffer.cpp:475 (safe_read) 
FileRingBuf(/data1/Recordings/2655_20140222010733.mpg): not reading, 
reached EOF
Feb 21 18:10:46  mythbackend: last message repeated 5 times
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: I RingBuffer 
ringbuffer.cpp:892 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): 
safe_read(... at 2904176, 1048576) -> 0, took 2343 ms (0Mbps)
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:905 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): rbwpos +=   0K 
requested 1024K in read
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:912 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): total read so far: 
208425072 bytes
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:958 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): setting ateof 
(read_return == 0)
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:968 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): @ end of read ahead loop
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: W 
ProcessRequest ringbuffer.cpp:1055 (WaitForReadsAllowed) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): ..Taking too long to 
be allowed to read
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:921 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): We are not reading 
anything (totfree: 4009871 commserror:0 ateof:1 setswitchtonext:0
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D RingBuffer 
ringbuffer.cpp:968 (run) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): @ end of read ahead loop
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D 
ProcessRequest ringbuffer.cpp:1298 (ReadPriv) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): ReadPriv(..294912, 
normal) -- copying data
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D 
ProcessRequest ringbuffer.cpp:1313 (ReadPriv) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): ReadPriv(..294912, 
normal) -- checksum 45194
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D 
ProcessRequest ringbuffer.cpp:1214 (ReadPriv) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): ReadPriv(..294912, 
normal) @2904176 -- begin
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: N 
ProcessRequest ringbuffer.cpp:1288 (ReadPriv) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): ReadPriv(..294912, 
normal): ReadBufAvail() == 0
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D 
ProcessRequest ringbuffer.cpp:1214 (ReadPriv) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): ReadPriv(..262144, 
normal) @2904176 -- begin
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: N 
ProcessRequest ringbuffer.cpp:1288 (ReadPriv) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): ReadPriv(..262144, 
normal): ReadBufAvail() == 0
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D 
ProcessRequest ringbuffer.cpp:1214 (ReadPriv) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): ReadPriv(..262144, 
normal) @2904176 -- begin
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: N 
ProcessRequest ringbuffer.cpp:1288 (ReadPriv) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): ReadPriv(..262144, 
normal): ReadBufAvail() == 0
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D 
ProcessRequest ringbuffer.cpp:1214 (ReadPriv) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): ReadPriv(..262144, 
normal) @2904176 -- begin
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: N 
ProcessRequest ringbuffer.cpp:1288 (ReadPriv) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): ReadPriv(..262144, 
normal): ReadBufAvail() == 0
Feb 21 18:10:46 howarddvr mythbackend: mythbackend[5006]: D 
ProcessRequest ringbuffer.cpp:1214 (ReadPriv) 
RingBuf(/data1/Recordings/2655_20140222010733.mpg): ReadPriv(..262144, 
normal) @2904176 -- begin
=========================================

Seems like we are hitting EOF multiple times and then we get "Taking too 
long to be allowed to read"

So the front seem to not like that:

=================== Front End =================
Feb 21 18:10:47 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 611ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:47 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 713ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:47 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 815ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:47 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 917ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:47 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:47  mythfrontend.real: last message repeated 5 times
Feb 21 18:10:47 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 1019ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:47 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:47  mythfrontend.real: last message repeated 5 times
Feb 21 18:10:47 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 1120ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:47 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:47  mythfrontend.real: last message repeated 5 times
Feb 21 18:10:47 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 1222ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:47 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:48  mythfrontend.real: last message repeated 6 times
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 1323ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:48  mythfrontend.real: last message repeated 5 times
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 1424ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:48  mythfrontend.real: last message repeated 5 times
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 1526ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:48  mythfrontend.real: last message repeated 6 times
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 1627ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:48  mythfrontend.real: last message repeated 5 times
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 1730ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:48  mythfrontend.real: last message repeated 5 times
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 1831ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:48  mythfrontend.real: last message repeated 6 times
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 1933ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:48  mythfrontend.real: last message repeated 5 times
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 2035ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:48  mythfrontend.real: last message repeated 6 times
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 2136ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:48 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:49  mythfrontend.real: last message repeated 5 times
Feb 21 18:10:49 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 2239ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:49 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:49  mythfrontend.real: last message repeated 5 times
Feb 21 18:10:49 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 2340ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:49 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
....................
Feb 21 18:10:53 zbox mythfrontend.real: mythfrontend[10937]: N 
CoreContext mythplayer.cpp:2130 (PrebufferEnoughFrames) Player(0): 
Waited 7023ms for video buffers AAAAffALAAAAAA
Feb 21 18:10:53 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:53 zbox mythfrontend.real: mythfrontend[10937]: W Decoder 
ringbuffer.cpp:1035 (WaitForReadsAllowed) 
RingBuf(myth://192.168.1.9:6543/2655_20140222010733.mpg): Taking too 
long to be allowed to read..
Feb 21 18:10:57 zbox mythfrontend.real: mythfrontend[10937]: I 
CoreContext tv_play.cpp:2201 (HandleStateChange) TV: Attempting to 
change from WatchingLiveTV to None
===================================================================

Can this be some issue with the HDHomerun feeding MythTV? Like an 
underrun. I did start tshark to filter on that traffic but the rotation 
of the logs replaced the interesting log unfortunately.

Cheers,

// Jonas

More information about the mythtv-dev mailing list