RecordPreRoll doesn't work

[mythwiki@…]

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.

[mythwiki@…]

Lightly tested patch that solves the issue for me

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

[mythwiki@…]

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

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

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

[gigem]

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

[gigem]

No response from original submitter.

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

[mythwiki@…]

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)

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

[Raymond Wagner]

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

[gigem]

Refactor, simplify and slightly enhance scheduler timing logic

[gigem]

Cleanup revision

[David Engel <dengel@…>]

In a2eb931221b0d1fac76da884e779e1120b8a2b81/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available

[David Engel <dengel@…>]

In 27c6b4ed5328db6483f4d6848cdabd37434950d4/mythtv:

Error: Processor CommitTicketReference failed

GIT backend not available