[mythtv-users] Playback of recordings ends a short way into them
Richard Townsend
townsend at astro.wisc.edu
Wed Nov 12 06:37:27 UTC 2014
> On Nov 10, 2014, at 10:43 AM, Hika van den Hoven <hikavdh at gmail.com> wrote:
>
> Hoi Richard,
>
> Monday, November 10, 2014, 4:51:22 PM, you wrote:
>
>> Hi folks —
>
>
>> I’m having problems with playing back recordings on Mythtv 0.27
>> (running on Gentoo; tuner is an HD Home Run). A couple of minutes
>> into a recording, playback will abruptly halt. Judging from the file
>> size of the recording, and also the log output, this is occurring
>> well before the actual end of the recording.
>
>> Here’s the relevant (I think) portion of the frontend logfile:
>
>> 2014-11-10 08:02:23.330317 I Player(0): FPS: 30.01 Mean: 33327 Std.Dev: 197 CPUs: 16% 45%
>> 2014-11-10 08:02:27.296933 I Player(0): FPS: 30.00 Mean: 33327 Std.Dev: 221 CPUs: 14% 49%
>> 2014-11-10 08:02:31.263549 I Player(0): FPS: 30.01 Mean: 33327 Std.Dev: 212 CPUs: 13% 45%
>> 2014-11-10 08:02:34.078375 E decoding error
>> eno: Unknown error 541478725 (541478725)
>> 2014-11-10 08:02:34.146823 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:34.213548 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:34.280240 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:34.346866 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:34.347021 I Player(0): 6400 interlaced frames seen.
>> 2014-11-10 08:02:34.413562 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:34.480190 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:34.546924 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:34.613606 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:34.680221 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:34.746944 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:34.813477 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:34.880200 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:34.946938 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.013555 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.096901 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.163571 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.230265 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.296893 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.363587 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.430274 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.496866 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.563609 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.630218 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.696870 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.763539 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.830201 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.896868 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:35.963518 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:36.030205 I Player(0): Video is 30 frames ahead of audio,
>> doubling video frame interval to slow down.
>> 2014-11-10 08:02:36.030339 I waiting for no video frames 0
>> 2014-11-10 08:02:36.030355 I HasReachedEof() at framesPlayed=6422 totalFrames=55644
>> 2014-11-10 08:02:36.078560 I Player(0): Play speed: rate: 29.97
>> speed: 0 skip: 0 => new interval 33366
>> 2014-11-10 08:02:36.095356 E decoding error
>> eno: Unknown error 541478725 (541478725)
>> 2014-11-10 08:02:36.112141 I VideoOutputXv: UpdatePauseFrame() AAAAAAfAALAAAAAAAAAAAAFuAAAAAAAP
>> 2014-11-10 08:02:36.129564 I TV: HandleStateChange(0) -- begin
>> 2014-11-10 08:02:36.129601 I TV: Attempting to change from WatchingPreRecorded to None
>> 2014-11-10 08:02:36.129633 I TV: StopStuff() for player ctx 0 -- begin
>> 2014-11-10 08:02:36.129653 I TV: SetActive(0,w/o OSD) 0 -> 0 -- begin
>> 2014-11-10 08:02:36.129701 I TV: SetActive(0,w/o OSD) 0 -> 0 -- end
>> 2014-11-10 08:02:36.129719 I Player(0): StopPlaying - begin
>> 2014-11-10 08:02:36.131690 I Player(0): Decoder thread exiting.
>> 2014-11-10 08:02:36.131898 I Player(0): Exited decoder loop.
>> 2014-11-10 08:02:36.134487 I VideoOutputXv: dtor
>> 2014-11-10 08:02:36.134524 I VideoOutputXv: DiscardFrames(1)
>> 2014-11-10 08:02:36.134599 I VideoBuffers::DiscardFrames(1): AAAAAAFAAAAAAAAAAAAAAAFUAAAAAAAP
>> 2014-11-10 08:02:36.134655 I VideoBuffers::DiscardFrames(1):
>> AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAP -- done
>> 2014-11-10 08:02:36.134697 I VideoOutputXv: DiscardFrames() 3:
>> AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAP -- done()
>> 2014-11-10 08:02:36.141554 I VideoOutputXv: Closing XVideo port 72
>> 2014-11-10 08:02:36.141604 I Setup Interrupt handler
>> 2014-11-10 08:02:36.141616 I Setup Terminated handler
>> 2014-11-10 08:02:36.204467 I Player(0): StopPlaying - end
>> 2014-11-10 08:02:36.204487 I TV: StopStuff(): stopping ring buffer
>> 2014-11-10 08:02:36.204520 I TV: StopStuff(): stopping player
>> 2014-11-10 08:02:36.204527 I TV: StopStuff() -- end
>> 2014-11-10 08:02:36.204569 I TV: Changing from WatchingPreRecorded to None
>> 2014-11-10 08:02:36.204593 I TV: HandleStateChange(0) -- end
>> 2014-11-10 08:02:36.204627 I TV: Exiting main playback loop.
>> 2014-11-10 08:02:36.204639 I TV: StartTV -- process events 2 begin
>> 2014-11-10 08:02:36.205431 I TV: StartTV -- process events 2 end
>> 2014-11-10 08:02:36.205449 I TV::~TV() -- begin
>> 2014-11-10 08:02:36.238591 I TV::~TV() -- lock
>> 2014-11-10 08:02:36.238799 I Player(0): StopPlaying - begin
>> 2014-11-10 08:02:36.238826 I Player(0): Exited decoder loop.
>> 2014-11-10 08:02:36.238840 I Player(0): StopPlaying - end
>> 2014-11-10 08:02:36.250036 I TV::~TV() -- end
>> 2014-11-10 08:02:36.250242 N Resuming idle timer
>> 2014-11-10 08:02:36.250399 I TV: StartTV -- end
>
>> The point at which the playback ceased is during a commercial
>> break, and could be at the end of the break. Is this a commflag issue? If so, how do I resolve?
>
>> cheers,
>
>> Rich
>
> Can you play the recording with VLC or mplayer or others?
>
Aha, it seems the recordings *are* actually truncated. And here is what’s going wrong: during the recording, I get something like this:
2014-11-11 23:34:30.575011 W [2187/4171] TFWWrite threadedfilewriter.cpp:571 (DiskLoop) - TFW(/mnt/mythtv/tv/1571_20141112053000.mpg:68): write(65424) cnt 95 total 5614996 -- took a long time, 5185 ms
2014-11-11 23:34:38.634735 W [2187/4171] TFWWrite threadedfilewriter.cpp:571 (DiskLoop) - TFW(/mnt/mythtv/tv/1571_20141112053000.mpg:68): write(52264) cnt 92 total 5196132 -- took a long time, 3686 ms
2014-11-11 23:34:49.444311 W [2187/4171] TFWWrite threadedfilewriter.cpp:571 (DiskLoop) - TFW(/mnt/mythtv/tv/1571_20141112053000.mpg:68): write(65424) cnt 114 total 6504048 -- took a long time, 4516 ms
2014-11-11 23:35:00.749412 W [2187/4171] TFWWrite threadedfilewriter.cpp:571 (DiskLoop) - TFW(/mnt/mythtv/tv/1571_20141112053000.mpg:68): write(65424) cnt 79 total 4669544 -- took a long time, 3466 ms
2014-11-11 23:35:46.609513 W [2187/4171] TFWWrite threadedfilewriter.cpp:571 (DiskLoop) - TFW(/mnt/mythtv/tv/1571_20141112053000.mpg:68): write(65424) cnt 25 total 1376912 -- took a long time, 1011 ms
2014-11-11 23:36:03.523222 W [2187/4171] TFWWrite threadedfilewriter.cpp:571 (DiskLoop) - TFW(/mnt/mythtv/tv/1571_20141112053000.mpg:68): write(65424) cnt 51 total 3029244 -- took a long time, 2370 ms
2014-11-11 23:37:15.747353 E [2187/4174] HDHRStreamHandler threadedfilewriter.cpp:239 (Write) - TFW(/mnt/mythtv/tv/1571_20141112053000.mpg:68): Maximum buffer size exceeded.
file will be truncated, no further writing will be done.
This generally indicates your disk performance
is insufficient to deal with the number of on-going
recordings, or you have a disk failure.
2014-11-11 23:40:09.661866 W [2187/4171] TFWWrite threadedfilewriter.cpp:571 (DiskLoop) - TFW(/mnt/mythtv/tv/1571_20141112053000.mpg:68): write(58092) cnt 1149 total 67108856 -- took a long time, 231384 ms
I’ve been trying to see if my NFS performance is a bottleneck, but it doesn’t seem to be. Is this possibly an issue with the HD HomeRun?
cheers,
Rich
More information about the mythtv-users
mailing list