Opened 12 years ago

Closed 12 years ago

Last modified 10 years ago

#3789 closed defect (fixed)

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

Reported by: anonymous Owned by: stuartm
Priority: major Milestone: 0.21
Component: mythtv Version: head
Severity: medium Keywords: mythbackend long recording
Cc: eric.bosch@… Ticket locked: no

Description

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.

Attachments (4)

mythbackendextract.log (200.5 KB) - added by eric.bosch@… 12 years ago.
mythbackend log for failed program transition.
transitionfailure.diff (1.2 KB) - added by stuartm 12 years ago.
Debugging patch for the failure to switch buffers at a livetv transition
livetv_ringbuffer_switch_fail_fix.diff (2.1 KB) - added by stuartm 12 years ago.
Fix for failure to switch livetv buffers (without the typo this time)
mythbackendextract.2.log (3.2 KB) - added by eric.bosch@… 12 years ago.
Program transition failure after VERBOSE patch.

Download all attachments as: .zip

Change History (20)

comment:1 Changed 12 years ago by 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.

comment:2 Changed 12 years ago by 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.

comment:3 Changed 12 years ago by 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.

comment:4 Changed 12 years ago by 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.

comment:5 Changed 12 years ago by 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.

Changed 12 years ago by eric.bosch@…

Attachment: mythbackendextract.log added

mythbackend log for failed program transition.

comment:6 Changed 12 years ago by 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

comment:7 Changed 12 years ago by 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

Changed 12 years ago by stuartm

Attachment: transitionfailure.diff added

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

comment:8 Changed 12 years ago by eric.bosch@…

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

comment:9 Changed 12 years ago by stuartm

Owner: changed from Isaac Richards to 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.

Changed 12 years ago by stuartm

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

comment:10 Changed 12 years ago by 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.

comment:11 Changed 12 years ago by eric.bosch@…

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

Changed 12 years ago by eric.bosch@…

Attachment: mythbackendextract.2.log added

Program transition failure after VERBOSE patch.

comment:12 Changed 12 years ago by 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.

comment:13 Changed 12 years ago by stuartm

Resolution: fixed
Status: newclosed

(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.

comment:14 Changed 12 years ago by 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.

comment:15 Changed 11 years ago by 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.'

comment:16 Changed 10 years ago by shane

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

Note: See TracTickets for help on using tickets.