[mythtv-commits] Ticket #13062: Backend does not schedule new recordings unless restarted

Sat Jul 20 10:27:13 UTC 2019

#13062: Backend does not schedule new recordings unless restarted
----------------------------------+----------------------------
 Reporter:  hobbes1069@…          |          Owner:  jpoet
     Type:  Bug Report - General  |         Status:  infoneeded
 Priority:  minor                 |      Milestone:  unknown
Component:  MythTV - Scheduling   |        Version:  0.28.1
 Severity:  medium                |     Resolution:
 Keywords:                        |  Ticket locked:  0
----------------------------------+----------------------------

Comment (by wispfrog):

 This is happening to me as well, often recordings would start a minute or
 two late as well when the backend was not very responsive. (Why is this
 not marked failed?) I took to running a script to restart it regularly and
 when frozen. I was running the 0.28.0+fixes... version from ubuntu 16.04,
 I recently upgraded to ubuntu 18.04 with version
 "29.1+fixes.20180414.329c235-0ubuntu" in the hope of fixing it, but the
 scheduler problem is still there, though the late recordings seem only
 very occaisional, and I have not had a complete backend freeze.

 In the logs, I see very long delayed, schedule interrupted will retry
 messages. I am running purely EIT off UK freeview with two USB recorders.
 Here is a section of log going from working to non-working.

 If someone can point me to likely sections of code I can compile up a
 version with extra instrumenting and see what is happening.

 {{{
 Jul 20 05:03:36 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2469 (HandleReschedule) Scheduled 777 items in 90.7 = 90.13
 match + 0.18 check + 0.37 place
 Jul 20 05:07:07 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T07:00:00Z EITScanner
 Jul 20 05:08:46 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2469 (HandleReschedule) Scheduled 775 items in 95.9 = 95.38
 match + 0.11 check + 0.40 place
 Jul 20 05:11:12 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-21T03:00:00Z EITScanner
 Jul 20 05:12:46 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:00:00Z EITScanner
 Jul 20 05:14:25 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2469 (HandleReschedule) Scheduled 775 items in 190.2 =
 189.57 match + 0.24 check + 0.44 place
 Jul 20 05:28:30 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:319 (RecordPending) TVRec[12]: RecordPending on inputid 12
 Jul 20 05:28:30 morgul mythbackend: mythbackend[3378]: I Scheduler
 cardutil.cpp:1448 (GetConflictingInputs) CardUtil: GetConflictingInputs()
 input 12
 Jul 20 05:29:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:433 (StartRecording) TVRec[12]: StartRecording("The Travel
 Show")
 Jul 20 05:29:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:730 (SetRecordingStatus) TVRec[12]:
 SetRecordingStatus(Recording->Aborted) on line 439
 Jul 20 05:29:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:829 (StartedRecording) TVRec[12]:
 StartedRecording(2107_2019-07-20T04:29:00Z)
 fn(/m3/mythtv/2107_20190720042900.ts)
 Jul 20 05:29:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:4123 (LoadProfile) TVRec[12]: Using profile 'Default' to record
 Jul 20 05:29:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:4407 (ClearFlags) TVRec[12]: ClearFlags(CancelNextRecording,)
 -> RunMainLoop,SignalMonitorRunning,EITScannerRunning,RingBufferReady, @
 tv_rec.cpp:629
 Jul 20 05:29:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:730 (SetRecordingStatus) TVRec[12]:
 SetRecordingStatus(Aborted->Tuning) on line 632
 Jul 20 05:29:01 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2923 (HandleRecordingStatusChange) Tuning recording: "The
 Travel Show": channel 2107 on cardid [12], sourceid 2
 Jul 20 05:29:01 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T07:00:00Z EITScanner
 Jul 20 05:30:34 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T06:25:00Z EITScanner
 Jul 20 05:32:08 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:00:00Z EITScanner
 Jul 20 05:33:39 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T06:00:00Z EITScanner
 Jul 20 05:35:15 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:00:00Z EITScanner
 Jul 20 05:36:47 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T21:00:00Z EITScanner
 Jul 20 05:38:21 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for PLACE
 PrepareToRecord
 Jul 20 05:38:21 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:00:00Z EITScanner
 Jul 20 05:39:56 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T17:58:00Z EITScanner
 Jul 20 05:41:28 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T07:00:00Z EITScanner
 Jul 20 05:43:05 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:30:00Z EITScanner
 Jul 20 05:44:43 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T06:00:00Z EITScanner
 Jul 20 05:46:18 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2460 (HandleReschedule) Reschedule interrupted, will retry
 Jul 20 05:59:30 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:319 (RecordPending) TVRec[12]: RecordPending on inputid 12
 Jul 20 05:59:30 morgul mythbackend: mythbackend[3378]: I Scheduler
 cardutil.cpp:1448 (GetConflictingInputs) CardUtil: GetConflictingInputs()
 input 12
 Jul 20 06:00:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:433 (StartRecording) TVRec[12]: StartRecording("Le Salvager")
 Jul 20 06:00:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:730 (SetRecordingStatus) TVRec[12]:
 SetRecordingStatus(Recording->Aborted) on line 439
 Jul 20 06:00:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:4736 (SwitchRecordingRingBuffer) TVRec[12]:
 SwitchRecordingRingBuffer()
 Jul 20 06:00:00 morgul mythbackend: mythbackend[3378]: E Scheduler
 tv_rec.cpp:4762 (SwitchRecordingRingBuffer) TVRec[12]:
 SwitchRecordingRingBuffer -> Not the same channel.
 Jul 20 06:00:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:4407 (ClearFlags) TVRec[12]:
 ClearFlags(CancelNextRecording,KillRec,) -> RunMainLoop,RingBufferReady, @
 tv_rec.cpp:755
 Jul 20 06:00:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:730 (SetRecordingStatus) TVRec[12]:
 SetRecordingStatus(Aborted->Unknown) on line 757
 Jul 20 06:00:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:829 (StartedRecording) TVRec[12]:
 StartedRecording(2114_2019-07-20T05:00:00Z)
 fn(/n2/mythtv/2114_20190720050000.ts)
 Jul 20 06:00:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:4123 (LoadProfile) TVRec[12]: Using profile 'Default' to record
 Jul 20 06:00:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:4407 (ClearFlags) TVRec[12]: ClearFlags(CancelNextRecording,)
 -> RunMainLoop,RingBufferReady, @ tv_rec.cpp:629
 Jul 20 06:00:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:730 (SetRecordingStatus) TVRec[12]:
 SetRecordingStatus(Unknown->Tuning) on line 632
 Jul 20 06:00:01 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2923 (HandleRecordingStatusChange) Tuning recording: "Le
 Salvager": channel 2114 on cardid [12], sourceid 2
 Jul 20 06:00:01 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for PLACE
 Interrupted
 Jul 20 06:00:01 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:00:00Z EITScanner
 Jul 20 06:01:29 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T04:50:00Z EITScanner
 Jul 20 06:02:59 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:15:00Z EITScanner
 Jul 20 06:04:36 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:05:00Z EITScanner
 Jul 20 06:06:10 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for PLACE
 PrepareToRecord
 Jul 20 06:06:10 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for CHECK -3
 17374 0 UpdateRecStatus2 | The Travel Show |  | To mark the 50th
 anniversary of the Apollo moon landing, Rajan Datar travels to the Kennedy
 Space Centre in Florida. | fp.bbc.co.uk/m/4fpe
 Jul 20 06:06:10 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for CHECK -14
 14177 0 UpdateRecStatus2 | Le Salvager |  | In his very own well-tended
 back garden, Rico Daniels begins building a greenhouse using reclaimed
 timber and doors. | www.questtv.co.uk/e278211
 Jul 20 06:06:10 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for CHECK -3
 17374 0 ForgetHistory | The Travel Show |  | Join the team on their
 journey of discovery as they explore new destinations around the globe and
 uncover hidden sides to some of the world's favourite holiday hotspots. |
 fp.bbc.co.uk/m/33hy
 Jul 20 06:06:10 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for CHECK 0
 17374 0 DoHandleDelete1 | The Travel Show |  | Join the team on their
 journey of discovery as they explore new destinations around the globe and
 uncover hidden sides to some of the world's favourite holiday hotspots. |
 fp.bbc.co.uk/m/33hy
 Jul 20 06:06:10 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T23:00:00Z EITScanner
 Jul 20 06:07:45 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:20:00Z EITScanner
 Jul 20 06:09:19 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T23:00:00Z EITScanner
 Jul 20 06:10:51 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:30:00Z EITScanner
 Jul 20 06:12:28 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:10:00Z EITScanner
 Jul 20 06:14:01 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T11:00:00Z EITScanner
 Jul 20 06:15:37 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:10:00Z EITScanner
 Jul 20 06:17:12 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T05:15:00Z EITScanner
 Jul 20 06:18:44 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2 0
 2019-07-20T09:00:00Z EITScanner
 Jul 20 06:20:20 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 2
 20 2019-07-20T05:25:00Z EITScanner
 Jul 20 06:20:34 morgul mythbackend: mythbackend[3378]: I Scheduler
 scheduler.cpp:2460 (HandleReschedule) Reschedule interrupted, will retry
 Jul 20 06:29:30 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:319 (RecordPending) TVRec[12]: RecordPending on inputid 12
 Jul 20 06:29:30 morgul mythbackend: mythbackend[3378]: I Scheduler
 cardutil.cpp:1448 (GetConflictingInputs) CardUtil: GetConflictingInputs()
 input 12
 Jul 20 06:30:00 morgul mythbackend: mythbackend[3378]: I Scheduler
 tv_rec.cpp:433 (StartRecording) TVRec[12]: StartRecording("Le Salvager")
 }}}

-- 
Ticket URL: <https://code.mythtv.org/trac/ticket/13062#comment:31>
MythTV <http://www.mythtv.org>
MythTV Media Center