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

[Jon Heizer]

On Wed, Dec 3, 2014 at 9:40 AM, David Engel <david at istwok.net> wrote:

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

I am on the exact same git version here and no problems.  2 sources, but
SSD, 6 cores, and lots of ram.

Dec  3 03:01:02 mythmasterbackend mythbackend: mythbackend[30359]: I
Scheduler scheduler.cpp:2252 (HandleReschedule) Scheduled 986 items in 1.2
= 0.01 match + 0.01 check + 1.18 place


Jon
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.mythtv.org/pipermail/mythtv-users/attachments/20141203/b4dfaf54/attachment.html>