Opened 11 years ago

Closed 11 years ago

Last modified 11 years ago

#11108 closed Bug Report - General (fixed)

RecordPreRoll doesn't work

Reported by: mythwiki@… Owned by: gigem
Priority: minor Milestone: 0.27
Component: MythTV - Scheduling Version: 0.25.2
Severity: medium Keywords:
Cc: Ticket locked: no

Description

In mythtv/programs/mythbackend/scheduler.cpp, the method Scheduler::CalcTimeToNextHandleRecordingEvent?(). The fourth parameter, prerollseconds, is not used. So, it returns a number that assumes that parameter is zero. This means that, in Scheduler::run(), the scheduler goes to sleep for too long around the first LOG() line, so the RecordPreRoll? parameter doesn't actually work, because the scheduler sleeps through the intended start time.

I've patched my mythbackend locally to fix the problem, but I don't know whether or not my fix has unintended negative consequences. My lightly tested patch against 0.25.2 is attached.

Attachments (4)

schedpatch.diff (570 bytes) - added by mythwiki@… 11 years ago.
Lightly tested patch that solves the issue for me
PATCH-backend (1.5 KB) - added by mythwiki@… 11 years ago.
More complete patch. This should fix the bug and handle all cases. Tested on my setup.
mythtv-11108-1.patch (14.9 KB) - added by gigem 11 years ago.
Refactor, simplify and slightly enhance scheduler timing logic
mythtv-11108-2.patch (16.3 KB) - added by gigem 11 years ago.
Cleanup revision

Download all attachments as: .zip

Change History (18)

Changed 11 years ago by mythwiki@…

Attachment: schedpatch.diff added

Lightly tested patch that solves the issue for me

comment:1 Changed 11 years ago by mythwiki@…

The patch I posted isn't a general fix. If the RecordPreRoll? is set to more than about 30 seconds, it won't have the desired effect, because it is also not used in the calculation of secs_to_next. I'd suggest that the Scheduler::run() method should be revisited with a particular attention to the behaviour under non-zero values of RecordPreRoll?.

Changed 11 years ago by mythwiki@…

Attachment: PATCH-backend added

More complete patch. This should fix the bug and handle all cases. Tested on my setup.

comment:2 Changed 11 years ago by mythwiki@…

I bought new hardware for my backend, the old was sluggish. As part of the changeover, I went from LinHES to Mythbuntu, because LinHES doesn't yet ship 64-bit ISOs. While both were 0.25.2 binaries, I do not see the bug with the mythbuntu packaged binaries, so I think this can be closed as WORKSFORME. I don't see why it works, given my analysis of the function, but it seems to be working.

comment:3 Changed 11 years ago by mythwiki@…

No, doesn't work for me. I rarely see RecordPreRoll? behaviour anymore (it's a timing issue, a late wakeup request, so if something else wakes up the thread it might still behave correctly, but that's by accident). This bug is still present.

comment:4 Changed 11 years ago by gigem

Status: newinfoneeded_new

The reporter has enabled extra logging and is waiting for the problem to occur with the current code.

comment:5 Changed 11 years ago by gigem

Resolution: Works for me
Status: infoneeded_newclosed

No response from original submitter.

comment:6 Changed 11 years ago by mythwiki@…

I've been running with the enhanced logging options for over 6 weeks now, and haven't seen the issue again. I'll continue watching the logs, and reopen only if the bug reappears and we get more details from the logs.

comment:7 Changed 11 years ago by mythwiki@…

Resolution: Works for me
Status: closednew

My backend has found itself in that state again, with the enhanced logging active. Here is a logging interval around a recording that failed to start at the preroll time of 15 seconds. The program was scheduled to be broadcast starting at 14:00:00 local time.

This isn't a one-off failure, all new recordings are now starting late. The code is v0.25.2, with this patch applied: http://code.mythtv.org/trac/attachment/ticket/11328/keep-first-keyframe-v4-v0.25.patch

May 28 13:57:30 <<<...>>> I Scheduler scheduler.cpp:1829 (run) sleeping for 60000 ms (interuptable)
May 28 13:58:30 <<<...>>> I Scheduler scheduler.cpp:1829 (run) sleeping for 60000 ms (interuptable)
May 28 13:58:30 <<<...>>> I CoreContext mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 12
May 28 13:59:30 <<<...>>> I Scheduler mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 12
May 28 13:59:30 <<<...>>> I Scheduler scheduler.cpp:4416 (FillRecordingDir) Scheduler: FillRecordingDir: Starting
May 28 13:59:30 <<<...>>> I Scheduler scheduler.cpp:4895 (FillRecordingDir) Scheduler: FillRecordingDir: Finished
May 28 13:59:30 <<<...>>> I Scheduler scheduler.cpp:1829 (run) sleeping for 5000 ms (interuptable)
May 28 13:59:30 <<<...>>> I TVRecEvent tv_rec.cpp:1536 (HandlePendingRecordings) TVRec(1): ASK_RECORDING 1 13 0 0
May 28 13:59:30 <<<...>>> I TVRecEvent tv_rec.cpp:1536 (HandlePendingRecordings) TVRec(3): ASK_RECORDING 3 13 0 0
May 28 13:59:35 <<<...>>> I Scheduler scheduler.cpp:1829 (run) sleeping for 5000 ms (interuptable)
May 28 13:59:40 <<<...>>> I Scheduler scheduler.cpp:1829 (run) sleeping for 2000 ms (interuptable)
May 28 13:59:42 <<<...>>> I Scheduler scheduler.cpp:1813 (run) sleeping for 16000 ms (s2n: 17 sr: 16)
May 28 13:59:58 <<<...>>> I TVRecEvent tv_rec.cpp:1029 (HandleStateChange) TVRec(1): Changing from None to RecordingOnly
May 28 13:59:58 <<<...>>> I TVRecEvent mythdbcon.cpp:395 (PurgeIdleConnections) New DB connection, total: 12
May 28 13:59:58 <<<...>>> E CoreContext programinfo.cpp:2278 (GetPlaybackURL) ProgramInfo(2590_20130528140000.mpg): GetPlaybackURL: '2590_20130528140000.mpg' should be local, but it can not be found.
May 28 13:59:58 <<<...>>> I TVRecEvent tv_rec.cpp:3495 (TuningCheckForHWChange) TVRec(1): HW Tuner: 1->1
May 28 13:59:58 <<<...>>> I TVRecEvent v4lchannel.cpp:661 (SetInputAndFormat) V4LChannel(/dev/hdpvr): SetInputAndFormat(1, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
May 28 13:59:58 <<<...>>> N Scheduler autoexpire.cpp:263 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 15 min
May 28 13:59:58 <<<...>>> I Scheduler recordinginfo.cpp:1171 (AddHistory) AddHistory: -10/0, 0, 0, Tue May 28 14:00:00 2013/Divine Design
May 28 13:59:58 <<<...>>> I Scheduler scheduler.cpp:2514 (HandleRecordingStatusChange) Tuning recording: "Divine Design":"Carol and Paul's Living Room": channel 2590 on cardid 1, sourceid 2
May 28 13:59:58 <<<...>>> I Scheduler scheduler.cpp:1813 (run) sleeping for 1000 ms (s2n: 1 sr: 16)
May 28 13:59:59 <<<...>>> I Scheduler scheduler.cpp:1813 (run) sleeping for 566 ms (s2n: 0 sr: 16)
May 28 14:00:00 <<<...>>> I Scheduler recordinginfo.cpp:1171 (AddHistory) AddHistory: 4/0, 0, 0, Tue May 28 14:00:00 2013/Divine Design
May 28 14:00:00 <<<...>>> I Scheduler scheduler.cpp:1813 (run) sleeping for 1000 ms (s2n: 0 sr: 16)
May 28 14:00:01 <<<...>>> I Scheduler scheduler.cpp:1829 (run) sleeping for 60000 ms (interuptable)
May 28 14:00:04 <<<...>>> I CoreContext scheduler.cpp:637 (UpdateRecStatus) Updating status for "Divine Design":"Carol and Paul's Living Room" on cardid 1 (Tuning => Recording)
May 28 14:00:04 <<<...>>> I CoreContext recordinginfo.cpp:1171 (AddHistory) AddHistory: -2/-10, 0, 0, Tue May 28 14:00:00 2013/Divine Design
May 28 14:00:04 <<<...>>> I TVRecEvent tv_rec.cpp:3989 (TuningNewRecorder) TVRec(1): rec->GetPathname(): '/myth/tv3/2590_20130528140000.mpg'
May 28 14:01:01 <<<...>>> I Scheduler scheduler.cpp:1829 (run) sleeping for 60000 ms (interuptable)
May 28 14:02:01 <<<...>>> I Scheduler scheduler.cpp:1829 (run) sleeping for 60000 ms (interuptable)
May 28 14:02:11 <<<...>>> I HouseKeeping housekeeper.cpp:225 (RunHouseKeeping) Running housekeeping thread
May 28 14:03:01 <<<...>>> I Scheduler scheduler.cpp:1829 (run) sleeping for 60000 ms (interuptable)

comment:8 Changed 11 years ago by stuartm

You really need to upgrade before we can help. 0.25 is old and no longer supported. 0.25.2 isn't even the most recent release of the 0.25 branch, that was 0.25.3. We are only supporting 0.26+, 0.26.0 was released 8 months ago and the 0.26-fixes branch contains 171 commits (fixes) on top of that.

comment:9 Changed 11 years ago by Raymond Wagner

Resolution: Works for me
Status: newclosed

Please re-open this ticket if you can reproduce the issue on a recent version of MythTV.

comment:10 Changed 11 years ago by gigem

Resolution: Works for me
Status: closednew

comment:11 Changed 11 years ago by gigem

Status: newassigned

Changed 11 years ago by gigem

Attachment: mythtv-11108-1.patch added

Refactor, simplify and slightly enhance scheduler timing logic

Changed 11 years ago by gigem

Attachment: mythtv-11108-2.patch added

Cleanup revision

comment:12 Changed 11 years ago by David Engel <dengel@…>

Resolution: fixed
Status: assignedclosed

In a2eb931221b0d1fac76da884e779e1120b8a2b81/mythtv:

Refactor timing/sleep handling in the scheduler.

The first main change is to use HandleRecordiing?() and HandleTuning?()
to set the sleep time. The previous code used mostly duplicate code
in CalcTimeToNextHandleRecordingEvent?(). That meant there were two
places that needed to be checked/kept in sync when analyzing/fixing
timing issues.

The next main change is to sleep as long as possible. The previous
code would never sleep for longer than 60 seconds, even if it had
nothing to do.

The last main change is to be more persistent in tyring to apply long
preroll when the tuner is initially busy. The previous code didn't
specifically try to do this and it was hit and miss whether or not
preroll was used in these situations.

The rest is various stylistic changes.

Fixes #11108

comment:13 Changed 11 years ago by gigem

Milestone: unknown0.27

comment:14 Changed 11 years ago by David Engel <dengel@…>

In 27c6b4ed5328db6483f4d6848cdabd37434950d4/mythtv:

Fix issues with earlier scheduler timing refactor.

Fix a few issues, that were intruduced in SHA1:a2eb9312, including the
failure to put inactive slaves to sleep.

Fixes #11578
Refs #11108

Note: See TracTickets for help on using tickets.