[mythtv-commits] Ticket #12314: mythbackend deadlocked during record, EIT scan and reschedule. CPU goes to 100%.

[MythTV]

#12314: mythbackend deadlocked during record, EIT scan and reschedule. CPU goes to
100%.
----------------------------------------+------------------------
 Reporter:  Paul Netherwood <paul@…>    |          Owner:
     Type:  Bug Report - Hang/Deadlock  |         Status:  new
 Priority:  major                       |      Milestone:  0.27.5
Component:  MythTV - General            |        Version:  0.27.4
 Severity:  medium                      |     Resolution:
 Keywords:  deadlock 100% CPU           |  Ticket locked:  0
----------------------------------------+------------------------

Comment (by Paul Netherwood <paul@…>):

 I've added a graph showing the time spent in "place" by the scheduler.
 Since the upgrade to version v0.27.3-164-g629f711 on Sep 25th, the place
 time goes up significantly. Prior to that the place time was consistently
 below 20 seconds. This was on version v0.27.3-5-gdbb4ef3. After that the
 place time has some very high number including up to 800 seconds.  So I
 suspect a change between version v0.27.3-5-gdbb4ef3 and version
 v0.27.3-164-g629f711 has caused the problem.

 Logs for Scheduler prior on version v0.27.3-5-gdbb4ef3:

 {{{
 Aug  2 06:25:41 mythbackend mythbackend: mythbackend[2575]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1423 items in 19.9 = 0.58
 match + 0.05 check + 19.26 place
 Aug  2 06:31:27 mythbackend mythbackend: mythbackend[2575]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1423 items in 19.9 = 0.59
 match + 0.06 check + 19.23 place
 Aug  2 06:33:34 mythbackend mythbackend: mythbackend[2575]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1423 items in 19.3 = 0.00
 match + 0.00 check + 19.31 place
 Aug  2 06:35:21 mythbackend mythbackend: mythbackend[2575]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1421 items in 21.0 = 0.04
 match + 0.01 check + 20.93 place
 Aug  2 06:41:39 mythbackend mythbackend: mythbackend[2575]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1420 items in 21.3 = 0.05
 match + 0.17 check + 21.07 place
 Aug  2 06:49:18 mythbackend mythbackend: mythbackend[2575]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1420 items in 21.3 = 0.01
 match + 0.01 check + 21.31 place
 Aug  2 06:49:39 mythbackend mythbackend: mythbackend[2575]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1420 items in 21.1 = 0.03
 match + 0.01 check + 21.10 place
 Aug  2 06:56:23 mythbackend mythbackend: mythbackend[2575]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1417 items in 21.4 = 0.02
 match + 0.01 check + 21.40 place
 Aug  2 07:04:18 mythbackend mythbackend: mythbackend[2575]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1414 items in 20.9 = 0.02
 match + 0.01 check + 20.82 place
 Aug  2 07:04:39 mythbackend mythbackend: mythbackend[2575]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1414 items in 21.2 = 0.03
 match + 0.01 check + 21.17 place
 }}}

 Recent logs for schedule place time:

 {{{
 Nov 25 21:08:58 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1093 items in 225.0 = 0.00
 match + 0.00 check + 224.98 place
 Nov 25 21:12:26 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1092 items in 203.6 = 0.01
 match + 0.10 check + 203.49 place
 Nov 25 22:06:39 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1089 items in 215.2 = 0.00
 match + 0.00 check + 215.22 place
 Nov 25 22:14:20 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1086 items in 196.1 = 0.01
 match + 0.04 check + 196.05 place
 Nov 25 22:44:46 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1085 items in 206.0 = 0.00
 match + 0.02 check + 206.02 place
 Nov 25 22:52:13 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1085 items in 211.7 = 0.00
 match + 0.01 check + 211.69 place
 Nov 25 22:56:03 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1085 items in 227.7 = 0.00
 match + 0.02 check + 227.72 place
 Nov 25 23:09:01 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1084 items in 214.8 = 0.00
 match + 0.00 check + 214.83 place
 Nov 25 23:38:18 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1082 items in 165.4 = 0.00
 match + 0.00 check + 165.45 place
 Nov 25 23:51:32 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1079 items in 223.3 = 0.00
 match + 0.00 check + 223.33 place
 Nov 26 00:14:51 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1075 items in 227.0 = 0.22
 match + 0.12 check + 226.67 place
 Nov 26 00:24:14 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1072 items in 192.4 = 0.02
 match + 0.08 check + 192.29 place
 Nov 26 00:30:44 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1071 items in 164.9 = 0.03
 match + 0.04 check + 164.87 place
 Nov 26 02:28:36 mythbackend mythbackend: mythbackend[22634]: I Scheduler
 scheduler.cpp:2252 (HandleReschedule) Scheduled 1157 items in 263.1 = 3.33
 match + 18.19 check + 241.55 place

 }}}

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