Tuesday, April 08, 2008

Fixed: Missing 80 Seconds From the Beginning of Recordings

For over a month now, some of my recordings have been missing 80-90 seconds toward the beginning. I would notice this mainly while watching "The Daily Show", but never with "The Colbert Report." The monologue would start, and then the video would skip, and I'd hear the audience laughing, not knowing what I'd missed.

I could just write what the problem was, but I think it's useful to see how to go about solving these type of problems in Linux... Of course, that's once you get over the temporary state of depression that usually follows a Linux system problem.

Where was I.... Oh, so I checked the log files, and found occasional entries like this:

Apr 8 15:55:09 mythbox kernel: [316852.916516] ivtv0: All encoder MPEG stream buffers are full. Dropping data.
Apr 8 15:55:09 mythbox kernel: [316852.916523] ivtv0: Cause: the application is not reading fast enough.

So there's the culprit. Now what? I should mention at this point that myth writes all of its data to a networked Linux file server, mounted by NFS. So, something's going on where myth tries to write to my file server, and the file server, for whatever reason, isn't grabbing the data fast enough, and Myth gives up, dropping it. After 80-90 seconds, it's able to resume writing.

I recalled that I had recently done an "apt-get dist-upgrade", which had upgraded the kernel, as well as just about everything else in the machine. Problems after such an upgrade usually lead to a particularly depressing state of... er, depression. And any error in your log files that contains "ivtv" (or any other driver)... just makes it worse.

Since this was happening at the beginning of "The Daily Show", but not "The Colbert Show," I figured that maybe the NFS server was in some sort of state where it needed to be woken up, and that once it was recording, it was able to successfully record the rest of that show and the next one as well. Basically, I didn't want to deal with this, so I ignored it for now.

After a month of this, I still wasn't ready to fix the problem -- it was time for a hack. I changed the recording schedule for "The Daily Show" to start 5 minutes early, so I wouldn't miss anything when it decided to drop 80-90 seconds of video.

The first time I watched my new recording, I was really upset to see that the video still cut out at the same spot! But... This was a clue! It's not the case that the file server was asleep at the wheel - there's something going on at the top of the hour! This also explains why "The Colbert Report" was never affected - that starts up at half past the hour.

So I started looking through /etc/crontab, but didn't see anything that runs on an hourly schedule on my file server. I then looked through my Webmin screens. Webmin seems to have its own task scheduling system -- I could be wrong, but didn't see anything in the crontabs that point to it. I found that I had an hourly task to backup my databases.

It's entirely possible that this backup could be CPU-intensive enough to tie up the server long enough for my MythTV box to have nowhere to drop the data. So I tested this by running the backup command from the console with the "time" command.

time /etc/webmin/mysql/backup.pl --all

'time' is an awesome command. It just runs whatever is after it, keeping track of how long it takes to complete. This took.... 80 seconds.

Problem solved.

Backing up the database hourly is unnecessary anyway - I only archive that backup once a day, so the other 23 are just overwritten and forgotten. That must have been an accident.

So, I changed this to once-daily, at 3AM, and the problem went away.

It's hard for non-Linux users to understand how rewarding it is. Sure, these problems happen, and if you give up, it's hard to deal with. But, if you hang in there, it becomes a high tech riddle. Solving something like this makes the whole experience worthwhile.

No comments: