[mythtv] [mythtv-commits] Ticket #1404: Invalid file error at file

[Bob Cottingham]

On 2/26/06, Chris Pinkham <cpinkham at bc2va.org> wrote:
> > #1404: Invalid file error at file change with LiveTV
> > Changes (by bobnvic at gmail.com):
> >  Your assumption is incorrect. As stated, the frontend is streaming from
> >  the SBE, the NFS share is not mounted on the frontend. The slave backend
> >  is writing to an NFS share which is mounted with actimeo=0.
>
> Yes, my fault, sorry about that.
>
> This could be either database or fileserver related.  From looking at your
> logs, it appears that it took 49 seconds for the old recording to end and the
> new one to start:
>
> 2006-02-26 12:30:00.972 Chain: Appended at 5 '1025_20060226123000'
>
> This is caused by line 4130 in tv_rec.cpp (tvchain->AppendNewProgram())
>
> Then the next recording-related entry is 49 seconds later here:
>
> 2006-02-26 12:30:49.033 RecBase(/dev/video0): SetRingBuffer(0xb058d4c8) '/var/mythtv/tv/1025_20060226123000.mpg'
>
> Then we have these:
>
> 2006-02-26 12:30:49.112 TVRec(3): SetFlags(RingBufferReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,AskAllowRecording,RecorderRunning,RingBufferReady,
> 2006-02-26 12:30:49.585 TVRec(3): RingBufferChanged()
>
> In MpegRecoder::SetNextRecording(), we save the positionmap to the
> database then force the ringbuffer's writer to flush to disk.  The we
> acquire the nextRingBufferLock and set the nextnextringbuffer.
>
> The ringbuffer gets cutover at the next keyframe, and I doubt that was
> 49 seconds later, so it appears that the 49-second delay was inside of
> MpegRecorder::SetNextRecording() either in writing the positionmap to
> the database or in flushing the old ringbuffer data to the nfs server.
> That is if I'm following this right, if not Daniel or Isaac will set
> me straight. :)
>
> Are you using NFS v3 with synchronous writes?  Do you see any odd
> entries in you mysql or nfs server logs around the 12:30:00-12:30:49
> timeframe to indicate that either was being hit hard around that time?
>
> --
> Chris

I am using NFS v3 with sync writes, however, I do not have mysql or
nfs logging enabled. I went through my syslog and found that a cron
job kicked off at 12:30 to backup my mysql database on the MBE server
to the SBE server so I suspect that is the culprit.  Could a 23MB file
(my mythconverg database in gzip) transfer between the machines at the
wrong time cause this problem?

If I follow you right, the slave backend got stuck waiting too long in
SetNextRecording() due to network traffic since whether it was writing
to the database or the nfs server it was still going across the
network which was busy transferring the 24MB file.  If transfer
happens at any other time I suppose it may just cause some prebuffer
pauses that it can recover from?  I changed the time for the cron job
to 4:40am so that it will not likely occur at the time of a file
change again. I am going to leave the FE watching livetv all night to
see what happens at 4:40am.  Since I frequently copy 1GB files across
the network to either of the MBE or SBE servers I am concerned what
might happen to a SBE recording with so much network traffic.

This question should obviously have been asked on the mythtv-users
list and I apologize.  I was caught up in testing livetv and just
assumed I had found another livetv issue. I'll close my ticket with
the expectation that this was the problem.  Thank you for your time in
reviewing the logs and explaining what was going on. I appreciate it.

Bob C