Ringbuffer fails to switch at end of program during livetv (huge recording file)

[anonymous]

While watching livetv, occaisionally the program info fails to update, and it continues to use the same ringbuffer to recording multiple programs. Something in the backend is failing to signal and execute a ring buffer switch at the end of the viewed program. I will submit log files as soon as I have more time to replicate the problem with adequate verbosity.

[Nick Morrott <<knowledgejunkie [at] gmail [dot] com>>]

What sort of TV card are you using to record LiveTV from? I see the exact same behaviour if I apply the patch from #2335 (see ​http://svn.mythtv.org/trac/ticket/2335#comment:65) to temporarily fix the LiveTV freezing issue on my ivtv card.

The first program change is fine (new ringbuffer, new prog info), but subsequently the same ringbuffer is used for the rest of the LiveTV session and the program info is never updated.

[stuartm]

Could you please attach a log using "-v all" showing the failed programme transition? It should include a couple of minutes before and after.

[eric.bosch@…]

I will try to get that taken care of in the next couple of days. I'm out of town for a wedding right now, and I'll work to reproduce the problem on my return. Thanks.

[eric.bosch@…]

Ok, I've made it back to town, and started a debug=all session this morning, and the problem produced itself at 11:30 AM. I will get an extract of the log file posted shortly after I get off work and can cut out the extra junk from the logs.

[stuartm]

I'm particularly curious about the database statements around the time of the failed transition. They may show nothing, but it would rule out at least one possibility.

[eric.bosch@…]

mythbackend log for failed program transition.

[eric.bosch@…]

Ok, Here's the log file from about a minute before to a minute or so after the transition of the program that should have taken place at 11:30. Additionally, I found a problem in the log pertaining to duplicate entry of key 1 on mythlog. Backend Saruman was trying to create entry with key 1 = 146190, however there already was an entry in mythlog with that key from backend Gandalf. I actually see several instances of that same log entry for other show transition times in the log. Should I purge the mythlog table?

INSERT INTO mythlog (module, priority, logdate, host, message, details) values ('autoexpire', 5, now(), 'saruman', 'Expiring Program', 'Expiring 1016 MBytes for 1006 @ Thu Aug 16 10:00:00 2007 => Dr. Keith Ablow' ); Driver error was [2/1062]: QMYSQL3: Unable to execute query Database error was: Duplicate entry '146190' for key 1

[stuartm]

Thanks for the log.

The most strange part of the log is the inuseprograms table bit which happens when we should be switching buffers. There are three places that MarkAsInUse?(true, "recorder") might be called on the backend however each of those should be accompanied by a debugging message e.g. RingBufferChanged?() so that's a little strange.

There are no transition related debug messages in that log at all which as far as I can tell means just one thing - we are never meeting the conditions for a ringbuffer transition.

Either: {{ else if (!has_rec && !rec_soon && curRecording && (now >= curRecording->endts)) }}

Or: {{ if (lastRecording != curRecording) }}

The second one seems more likely and I'm not even sure what it's meant to do, but it's pretty sure to screw things up if it's ever true.

Could someone apply the patch I've attached, then create a backend log with -v record

[stuartm]

Debugging patch for the failure to switch buffers at a livetv transition

[eric.bosch@…]

I've added the patch, and have tv play going now. I'll watch for another transition failure and attach the log.

[stuartm]

I'm attaching a patch which we believe should fix this problem (not other livetv transition issues). Gnome42 aka Shane should get credit for this, he was well ahead of me in spotting the problem and he even told me, I was just wasn't paying enough attention.

[stuartm]

Fix for failure to switch livetv buffers (without the typo this time)

[eric.bosch@…]

Ok, I finally reproduced the problem with the recommended settings, and it seems it entered where no program should go! See the following.

2007-08-17 15:29:58.725 has_rec: 0 rec_soon: 0 endtime: Fri Aug 17 15:30:00 2007 now: Fri Aug 17 15:29:58 2007 2007-08-17 15:29:59.727 has_rec: 0 rec_soon: 0 endtime: Fri Aug 17 15:30:00 2007 now: Fri Aug 17 15:29:59 2007 2007-08-17 15:30:00.741 has_rec: 0 rec_soon: 0 endtime: Fri Aug 17 15:30:00 2007 now: Fri Aug 17 15:30:00 2007 2007-08-17 15:30:00.751 LastRecord? == CurRecording? 2007-08-17 15:30:00.752 TVRec(1): Enabling Full LiveTV UI. 2007-08-17 15:30:01.753 has_rec: 0 rec_soon: 0 endtime: Fri Aug 17 15:30:00 2007 now: Fri Aug 17 15:30:01 2007 2007-08-17 15:30:01.760 LastRecord? == CurRecording? 2007-08-17 15:30:01.761 TVRec(1): Enabling Full LiveTV UI. 2007-08-17 15:30:02.764 has_rec: 0 rec_soon: 0 endtime: Fri Aug 17 15:30:00 2007 now: Fri Aug 17 15:30:02 2007 2007-08-17 15:30:02.768 LastRecord? == CurRecording? 2007-08-17 15:30:02.769 TVRec(1): Enabling Full LiveTV UI. 2007-08-17 15:30:03.772 has_rec: 0 rec_soon: 0 endtime: Fri Aug 17 15:30:00 2007 now: Fri Aug 17 15:30:03 2007

Which the post 15:30:00 messages recur every second.

[eric.bosch@…]

Let me post that as an attachment so it is formatted better.

[eric.bosch@…]

Program transition failure after VERBOSE patch.

[eric.bosch@…]

Thanks for the patch, Stuart. I'm recompiling mythtv now, and I'll continue to watch for this problem. In my case, the (line 1310) SwitchLiveTVRingBuffer (false,true), I am leaving as (true, true) as I have ivtv, and this causes the hang on program transition. I'll let you know if I run into more issues with this functionality.

[stuartm]

(In [14209]) Fixes #3789 and #2948

Fix for buffer/programinfo switch problem in livetv.

This was tested successfully overnight on my two backends one using dvb and the other ivtv.

[eric.bosch@…]

I think this same fix should be applied to the mythtv-vid branch, as this will resolve the same issue on that branch. I read a post yesterday or the day before in which they were experiencing similar issues with that branch, and the same code exists there which was just replaced.

[shane]

(In [20645]) Refs #3789 Allow recovery from bad buffer switch.

The original problem is still fixed but now the backend can recover from bad ringbuffer switches or a channel change at the wrong time.

This helps to recover when the backend gets in an infinite loop logging, 'Enabling Full LiveTV UI.'

[shane]

(In [20781]) Refs #3789, Refs #6612. Fix race when switching LiveTV buffers.