[mythtv-users] Problems in load-balancing commflagging
f-myth-users at media.mit.edu
f-myth-users at media.mit.edu
Wed Dec 7 00:14:57 EST 2005
Date: Tue, 6 Dec 2005 23:42:00 -0500 (EST)
From: f-myth-users at media.mit.edu
-Now- what happens is the following:
(a) The instant recording was due to commence, the backend logged a
bunch of "Skipping "Flag Commercials" job for chanid 1002 @
20051206213500, should be run on 'sbe' instead"; it logged one of
these page channel I'd scheduled (with appropriate chanid's, of
course).
Whoops, I misspoke: 10 seconds after recording started (e.g., the
next time my every-10s job queue got checked), I got the Skipping
messages, -and- I -also- got one of "Found "Flag Commercials" job for
chanid 1002 @ 20051206213500 in Running state" and 5 of "Found
"Flag Commercials" job for chanid 100x @ 20051206213500 in Queued
state", for x in 2,3,4,5,6,7 (yes, including 7, despite the later
error running that job). That sort of thing persisted for each later
iteration. Each iteration -also- said "Currently Running 0 jobs.",
which makes no sense.
3 different sets of logging output are below, to try to make sense of
all this.
Here's the backend just after I started it:
2005-12-06 21:22:39.727 New DB connection, total: 1
Starting up as the master server.
2005-12-06 21:22:39.747 New DB connection, total: 2
2005-12-06 21:22:39.748 mythbackend: MythBackend started as master server
2005-12-06 21:22:39.755 New DB connection, total: 3
2005-12-06 21:22:40.710 New DB scheduler connection
2005-12-06 21:22:40.713 JobQueue::RecoverQueue: Checking for unfinished jobs to recover.
2005-12-06 21:22:40.714 mythbackend version: 0.18.1.20050510-1 www.mythtv.org
2005-12-06 21:22:40.714 Enabled verbose msgs : important general jobqueue
2005-12-06 21:22:40.718 JobQueue::GetJobsInQueue: findJobs search bitmask 4, found 10 total jobs
2005-12-06 21:22:40.719 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1002 @ 20051204142500 in Finished state.
2005-12-06 21:22:40.719 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1003 @ 20051204142500 in Finished state.
2005-12-06 21:22:40.719 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1004 @ 20051204142500 in Finished state.
2005-12-06 21:22:40.721 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1005 @ 20051204142500 in Finished state.
2005-12-06 21:22:40.721 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1006 @ 20051204142500 in Finished state.
2005-12-06 21:22:40.721 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1007 @ 20051204142500 in Finished state.
2005-12-06 21:22:40.721 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1002 @ 20051205043000 in Finished state.
2005-12-06 21:22:40.722 JobQueue::GetJobsInQueue: Ignore 'Transcode' Job for 1002 @ 20051205043000 in Errored state.
2005-12-06 21:22:40.722 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1002 @ 20051206172000 in Finished state.
2005-12-06 21:22:40.722 JobQueue::GetJobsInQueue: Ignore 'Transcode' Job for 1002 @ 20051206172000 in Errored state.
2005-12-06 21:22:40.873 adding: sbe as a slave backend server
2005-12-06 21:22:42.713 Reschedule requested for id 0.
2005-12-06 21:22:42.713 Reschedule requested for id -1.
2005-12-06 21:22:42.800 Scheduled 0 items in 0.1 = 0.08 match + 0.00 place
2005-12-06 21:22:42.804 scheduler: Scheduled items
2005-12-06 21:22:42.806 Seem to be woken up by USER
...and here's what happened just after recording commenced, including
the start of the recordings and the first 10s update. (And yes, it
-does- appear that ch7 was recorded on the SBE's tuner, and ch7 is the
one that later got the error transcoding---since I'm pretty sure that
cardid 6 is the SBE's 350, since that was the card I defined last when
running mythtv-setup.)
Note that there was never an entry showing the start or end of
transcoding for ch7 (the one that errored).
2005-12-06 21:35:02.944 Started recording "2 WGBH - 21:35 (Manual Record)" on channel: 1002 on cardid: 1, sourceid 1
2005-12-06 21:35:02.948 New DB connection, total: 4
2005-12-06 21:35:02.951 New DB connection, total: 5
2005-12-06 21:35:02.971 scheduler: Last message repeated 8 times
2005-12-06 21:35:02.974 scheduler: Schedule Change
2005-12-06 21:35:02.975 Started recording "3 LOOR003 - 21:35 (Manual Record)" on channel: 1003 on cardid: 2, sourceid 1
2005-12-06 21:35:02.977 Started recording "4 WBZ - 21:35 (Manual Record)" on channel: 1004 on cardid: 3, sourceid 1
2005-12-06 21:35:02.978 Started recording "5 WCVB - 21:35 (Manual Record)" on channel: 1005 on cardid: 4, sourceid 1
2005-12-06 21:35:02.979 Started recording "6 WFXT - 21:35 (Manual Record)" on channel: 1006 on cardid: 5, sourceid 1
2005-12-06 21:35:02.981 New DB connection, total: 6
2005-12-06 21:35:03.014 New DB connection, total: 7
2005-12-06 21:35:03.016 New DB connection, total: 8
2005-12-06 21:35:03.018 New DB connection, total: 9
2005-12-06 21:35:03.021 New DB connection, total: 10
2005-12-06 21:35:03.022 Started recording "7 WHDH - 21:35 (Manual Record)" on channel: 1007 on cardid: 6, sourceid 1
2005-12-06 21:35:03.024 New DB connection, total: 11
2005-12-06 21:35:03.026 New DB connection, total: 12
2005-12-06 21:35:03.029 New DB connection, total: 13
2005-12-06 21:35:03.299 Changing from None to RecordingOnly
2005-12-06 21:35:03.473 Changing from None to RecordingOnly
2005-12-06 21:35:03.538 Changing from None to RecordingOnly
2005-12-06 21:35:03.574 Changing from None to RecordingOnly
2005-12-06 21:35:03.736 Changing from None to RecordingOnly
2005-12-06 21:35:08.040 MainServer::HandleAnnounce Playback
2005-12-06 21:35:08.040 adding: sbe as a client (events: 0)
2005-12-06 21:35:10.838 JobQueue currently set at 5 job(s) max and to run new jobs from 00:00 to 23:59
2005-12-06 21:35:10.840 JobQueue::GetJobsInQueue: findJobs search bitmask 4, found 16 total jobs
2005-12-06 21:35:10.840 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1002 @ 20051204142500 in Finished state.
2005-12-06 21:35:10.840 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1003 @ 20051204142500 in Finished state.
2005-12-06 21:35:10.841 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1004 @ 20051204142500 in Finished state.
2005-12-06 21:35:10.841 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1005 @ 20051204142500 in Finished state.
2005-12-06 21:35:10.841 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1006 @ 20051204142500 in Finished state.
2005-12-06 21:35:10.842 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1007 @ 20051204142500 in Finished state.
2005-12-06 21:35:10.842 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1002 @ 20051205043000 in Finished state.
2005-12-06 21:35:10.842 JobQueue::GetJobsInQueue: Ignore 'Transcode' Job for 1002 @ 20051205043000 in Errored state.
2005-12-06 21:35:10.843 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1002 @ 20051206172000 in Finished state.
2005-12-06 21:35:10.843 JobQueue::GetJobsInQueue: Ignore 'Transcode' Job for 1002 @ 20051206172000 in Errored state.
2005-12-06 21:35:10.843 JobQueue::GetJobsInQueue: Found 'Flag Commercials' Job for 1002 @ 20051206213500 in Running state.
2005-12-06 21:35:10.844 JobQueue::GetJobsInQueue: Found 'Flag Commercials' Job for 1003 @ 20051206213500 in Queued state.
2005-12-06 21:35:10.845 JobQueue::GetJobsInQueue: Found 'Flag Commercials' Job for 1004 @ 20051206213500 in Queued state.
2005-12-06 21:35:10.845 JobQueue::GetJobsInQueue: Found 'Flag Commercials' Job for 1005 @ 20051206213500 in Queued state.
2005-12-06 21:35:10.846 JobQueue::GetJobsInQueue: Found 'Flag Commercials' Job for 1006 @ 20051206213500 in Queued state.
2005-12-06 21:35:10.846 JobQueue::GetJobsInQueue: Found 'Flag Commercials' Job for 1007 @ 20051206213500 in Queued state.
2005-12-06 21:35:10.846 JobQueue: Currently Running 0 jobs.
2005-12-06 21:35:10.846 JobQueue: Skipping 'Flag Commercials' job for chanid 1002 @ 20051206213500, should run on 'sbe' instead
2005-12-06 21:35:10.847 JobQueue: Skipping 'Flag Commercials' job for chanid 1003 @ 20051206213500, should run on 'sbe' instead
2005-12-06 21:35:10.847 JobQueue: Skipping 'Flag Commercials' job for chanid 1004 @ 20051206213500, should run on 'sbe' instead
2005-12-06 21:35:10.847 JobQueue: Skipping 'Flag Commercials' job for chanid 1005 @ 20051206213500, should run on 'sbe' instead
2005-12-06 21:35:10.847 JobQueue: Skipping 'Flag Commercials' job for chanid 1006 @ 20051206213500, should run on 'sbe' instead
2005-12-06 21:35:10.847 JobQueue: Skipping 'Flag Commercials' job for chanid 1007 @ 20051206213500, should run on 'sbe' instead
...and here's immediately after recordings finished and the first
transcoding job started:
2005-12-06 21:40:00.034 Finished recording 3 LOOR003 - 21:35 (Manual Record) on channel: 1003
2005-12-06 21:40:00.034 Finished recording 6 WFXT - 21:35 (Manual Record) on channel: 1006
2005-12-06 21:40:00.034 Finished recording 2 WGBH - 21:35 (Manual Record) on channel: 1002
2005-12-06 21:40:00.034 Finished recording 5 WCVB - 21:35 (Manual Record) on channel: 1005
2005-12-06 21:40:00.035 Finished recording 4 WBZ - 21:35 (Manual Record) on channel: 1004
2005-12-06 21:40:00.075 scheduler: Last message repeated 5 times
2005-12-06 21:40:00.077 scheduler: Last message repeated 5 times
2005-12-06 21:40:00.080 scheduler: Last message repeated 5 times
2005-12-06 21:40:00.082 scheduler: Last message repeated 5 times
2005-12-06 21:40:00.090 scheduler: Finished recording
2005-12-06 21:40:00.091 scheduler: Finished recording
2005-12-06 21:40:00.151 Changing from RecordingOnly to None
2005-12-06 21:40:00.152 Reschedule requested for id 0.
2005-12-06 21:40:00.172 Changing from RecordingOnly to None
2005-12-06 21:40:00.174 scheduler: Last message repeated 5 times
2005-12-06 21:40:00.175 scheduler: Finished recording
2005-12-06 21:40:00.177 Changing from RecordingOnly to None
2005-12-06 21:40:00.184 scheduler: Finished recording
2005-12-06 21:40:00.186 scheduler: Finished recording
2005-12-06 21:40:00.188 Changing from RecordingOnly to None
2005-12-06 21:40:00.191 Changing from RecordingOnly to None
2005-12-06 21:40:00.340 Scheduled 6 items in 0.2 = 0.00 match + 0.18 place
2005-12-06 21:40:00.364 scheduler: Scheduled items
2005-12-06 21:40:00.369 Reschedule requested for id 0.
2005-12-06 21:40:00.370 Reschedule requested for id 0.
2005-12-06 21:40:00.370 Reschedule requested for id 0.
2005-12-06 21:40:00.370 Reschedule requested for id 0.
2005-12-06 21:40:00.370 Reschedule requested for id 0.
2005-12-06 21:40:00.432 Scheduled 6 items in 0.1 = 0.00 match + 0.06 place
2005-12-06 21:40:01.027 JobQueue currently set at 5 job(s) max and to run new jobs from 00:00 to 23:59
2005-12-06 21:40:01.029 JobQueue::GetJobsInQueue: findJobs search bitmask 4, found 22 total jobs
2005-12-06 21:40:01.030 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1002 @ 20051204142500 in Finished state.
2005-12-06 21:40:01.030 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1003 @ 20051204142500 in Finished state.
2005-12-06 21:40:01.030 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1004 @ 20051204142500 in Finished state.
2005-12-06 21:40:01.030 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1005 @ 20051204142500 in Finished state.
2005-12-06 21:40:01.030 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1006 @ 20051204142500 in Finished state.
2005-12-06 21:40:01.031 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1007 @ 20051204142500 in Finished state.
2005-12-06 21:40:01.031 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1002 @ 20051205043000 in Finished state.
2005-12-06 21:40:01.031 JobQueue::GetJobsInQueue: Ignore 'Transcode' Job for 1002 @ 20051205043000 in Errored state.
2005-12-06 21:40:01.031 JobQueue::GetJobsInQueue: Ignore 'Flag Commercials' Job for 1002 @ 20051206172000 in Finished state.
2005-12-06 21:40:01.032 JobQueue::GetJobsInQueue: Ignore 'Transcode' Job for 1002 @ 20051206172000 in Errored state.
2005-12-06 21:40:01.032 JobQueue::GetJobsInQueue: Found 'Flag Commercials' Job for 1002 @ 20051206213500 in Running state.
2005-12-06 21:40:01.032 JobQueue::GetJobsInQueue: Found 'Transcode' Job for 1002 @ 20051206213500 in Queued state.
2005-12-06 21:40:01.032 JobQueue::GetJobsInQueue: Found 'Flag Commercials' Job for 1003 @ 20051206213500 in Queued state.
2005-12-06 21:40:01.033 JobQueue::GetJobsInQueue: Found 'Transcode' Job for 1003 @ 20051206213500 in Queued state.
2005-12-06 21:40:01.033 JobQueue::GetJobsInQueue: Found 'Flag Commercials' Job for 1004 @ 20051206213500 in Queued state.
2005-12-06 21:40:01.033 JobQueue::GetJobsInQueue: Found 'Transcode' Job for 1004 @ 20051206213500 in Queued state.
2005-12-06 21:40:01.033 JobQueue::GetJobsInQueue: Found 'Flag Commercials' Job for 1005 @ 20051206213500 in Queued state.
2005-12-06 21:40:01.034 JobQueue::GetJobsInQueue: Found 'Transcode' Job for 1005 @ 20051206213500 in Queued state.
2005-12-06 21:40:01.034 JobQueue::GetJobsInQueue: Found 'Flag Commercials' Job for 1006 @ 20051206213500 in Queued state.
2005-12-06 21:40:01.034 JobQueue::GetJobsInQueue: Found 'Transcode' Job for 1006 @ 20051206213500 in Queued state.
2005-12-06 21:40:01.034 JobQueue::GetJobsInQueue: Found 'Flag Commercials' Job for 1007 @ 20051206213500 in Queued state.
2005-12-06 21:40:01.035 JobQueue::GetJobsInQueue: Found 'Transcode' Job for 1007 @ 20051206213500 in Queued state.
2005-12-06 21:40:01.035 JobQueue: Currently Running 0 jobs.
2005-12-06 21:40:01.035 JobQueue: Skipping 'Flag Commercials' job for chanid 1002 @ 20051206213500, should run on 'sbe' instead
2005-12-06 21:40:01.057 JobQueue: Processing 'Transcode' job for chanid 1002 @ 20051206213500, current status is 'Queued'
2005-12-06 21:40:01.062 JobQueue: Skipping 'Flag Commercials' job for chanid 1003 @ 20051206213500, should run on 'sbe' instead
2005-12-06 21:40:01.064 JobQueue: Skipping 'Flag Commercials' job for chanid 1004 @ 20051206213500, should run on 'sbe' instead
2005-12-06 21:40:01.065 JobQueue: Skipping 'Flag Commercials' job for chanid 1005 @ 20051206213500, should run on 'sbe' instead
2005-12-06 21:40:01.067 JobQueue: Skipping 'Flag Commercials' job for chanid 1006 @ 20051206213500, should run on 'sbe' instead
2005-12-06 21:40:01.068 JobQueue: Skipping 'Flag Commercials' job for chanid 1007 @ 20051206213500, should run on 'sbe' instead
2005-12-06 21:40:01.938 New DB connection, total: 2
2005-12-06 21:40:01.953 Transcoding from /myth/tv/1002_20051206213500_20051206214000.nuv to /myth/tv/1002_20051206213500_20051206214000.nuv.tmp
[End]
More information about the mythtv-users
mailing list