[mythtv-users] Scheduler runs slowly causes backend to lock up

[David Engel]

On Wed, Nov 26, 2014 at 01:01:20PM +0100, Paul Netherwood wrote:
> I've noticed that the scheduler is running very slowly which coincides with the backend locking up. The delay is in the "place" part of the scheduler. I've grep'd out the recent scheduler lines from the log:
> 
> Nov 25 03:31:18 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1144 items in 70.5 = 1.19 match + 11.91 check + 57.39 place
> Nov 25 06:49:55 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1139 items in 23.9 = 0.00 match + 0.00 check + 23.92 place
> Nov 25 07:04:27 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1137 items in 25.5 = 0.12 match + 0.27 check + 25.13 place
> Nov 25 07:04:54 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1137 items in 27.1 = 0.06 match + 0.01 check + 27.06 place
> Nov 25 08:14:44 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1132 items in 17.4 = 0.00 match + 0.00 check + 17.45 place
> Nov 25 08:34:23 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1131 items in 21.4 = 0.15 match + 0.33 check + 20.88 place
> Nov 25 08:35:44 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1131 items in 21.1 = 0.07 match + 0.01 check + 21.04 place
> Nov 25 08:36:10 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1131 items in 25.4 = 0.09 match + 0.01 check + 25.32 place
> Nov 25 13:44:49 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1122 items in 19.9 = 0.00 match + 0.00 check + 19.94 place
> Nov 25 14:24:23 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1121 items in 200.2 = 0.07 match + 0.49 check + 199.68 place
> Nov 25 14:30:36 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1121 items in 94.0 = 0.15 match + 0.08 check + 93.76 place
> Nov 25 15:08:45 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1117 items in 166.5 = 0.00 match + 0.00 check + 166.51 place
> Nov 25 15:39:22 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1113 items in 199.2 = 0.03 match + 0.03 check + 199.18 place
> Nov 25 15:52:32 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1113 items in 189.4 = 0.02 match + 0.01 check + 189.32 place
> Nov 25 15:56:03 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1113 items in 208.6 = 0.05 match + 0.02 check + 208.50 place
> Nov 25 16:06:07 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1112 items in 198.2 = 0.00 match + 0.00 check + 198.23 place
> Nov 25 16:36:58 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1111 items in 213.8 = 0.02 match + 0.22 check + 213.53 place
> Nov 25 17:09:21 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1110 items in 198.2 = 0.01 match + 0.19 check + 198.00 place
> Nov 25 18:05:35 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1109 items in 188.2 = 0.00 match + 0.00 check + 188.15 place
> Nov 25 18:43:13 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1105 items in 210.0 = 0.20 match + 0.10 check + 209.70 place
> Nov 25 19:55:41 mythbackend mythbackend: mythbackend[22634]: I Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 1099 items in 52.0 = 0.00 match + 0.00 check + 52.04 place
> 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
> 
> 200 seconds is a long time. Its been worse with it sometimes taking 800 seconds. Its been like this since upgrading from v0.27.3-5-gdbb4ef3 to v0.27.3-164-g629f711. Before that it averaged 20 seconds. I'm now on v0.27.4-6-ge0b0027 and its still happening.
> 
> Any ideas what could be causing this?

I'm afraid you'll have to run git bisect to try to identify a specific
commit that might be causing your problem.  I don't see anything
between those versions that might have caused it.  There certainly
weren't any scheduler changes.  Alternatviely, are you sure you didn't
change anything alse in your system that could have contributed to the
problem?

David
-- 
David Engel
david at istwok.net