diff --git a/mythtv/programs/mythbackend/scheduler.cpp b/mythtv/programs/mythbackend/scheduler.cpp index 49b291290f..a04fa53809 100644 --- a/mythtv/programs/mythbackend/scheduler.cpp +++ b/mythtv/programs/mythbackend/scheduler.cpp @@ -2084,23 +2084,36 @@ void Scheduler::run(void) bool statuschanged = false; QDateTime nextStartTime = MythDate::current().addDays(14); QDateTime nextWakeTime = nextStartTime; - + int numItersBeforeSleep = 0; while (doRun) { + ++numItersBeforeSleep; + LOG(VB_GENERAL, LOG_INFO, + QString("At top of loop with nwt %1 nst %2 current time %3").arg(nextWakeTime.toString()).arg(nextStartTime.toString()).arg(MythDate::current().toString())); + // If something changed, it might have short circuited a pass // through the list or changed the next run times. Start a // new pass immediately to take care of anything that still // needs attention right now and reset the run times. if (reclist_changed) { + LOG(VB_GENERAL, LOG_INFO, + QString("reclist_changed so resetting nextStartTime from %1").arg(nextStartTime.toString())); + nextStartTime = MythDate::current(); reclist_changed = false; } + LOG(VB_GENERAL, LOG_INFO, + QString("About to set nextWakeTime to min of %1 and %2").arg(nextWakeTime.toString()).arg(nextStartTime.toString())); nextWakeTime = min(nextWakeTime, nextStartTime); QDateTime curtime = MythDate::current(); int secs_to_next = curtime.secsTo(nextStartTime); + LOG(VB_GENERAL, LOG_INFO, + QString("secs_to_next is now %1 since nextStartTime %2 nextWakeTime %3 and schedRunTime %4 and ms2nwt %5").arg(secs_to_next).arg(nextStartTime.toString()).arg(nextWakeTime.toString()).arg(schedRunTime).arg(curtime.msecsTo(nextWakeTime))); + int sched_sleep = max(curtime.msecsTo(nextWakeTime), qint64(0)); + if (idleTimeoutSecs > 0) sched_sleep = min(sched_sleep, 15000); bool haveRequests = HaveQueuedRequests(); @@ -2114,17 +2127,38 @@ void Scheduler::run(void) { if (sched_sleep) { - LOG(VB_SCHEDULE, LOG_INFO, + LOG(VB_GENERAL, LOG_INFO, QString("sleeping for %1 ms " - "(s2n: %2 sr: %3 qr: %4 cs: %5)") + "(s2n: %2 sr: %3 qr: %4 cs: %5) numItersBeforeSleep: %6") .arg(sched_sleep).arg(secs_to_next).arg(schedRunTime) - .arg(haveRequests).arg(checkSlaves)); + .arg(haveRequests).arg(checkSlaves).arg(numItersBeforeSleep)); + numItersBeforeSleep = 0; if (reschedWait.wait(&schedLock, sched_sleep)) + { + LOG(VB_GENERAL, LOG_INFO, + QString("After sleeping for %1 ms wakeup and continue").arg(sched_sleep)); continue; + } + LOG(VB_GENERAL, LOG_INFO, + QString("After sleeping for %1 ms wakeup").arg(sched_sleep)); + } + else + { + LOG(VB_GENERAL, LOG_INFO, + QString("NOT sleeping for %1 ms " + "(s2n: %2 sr: %3 qr: %4 cs: %5)") + .arg(sched_sleep).arg(secs_to_next).arg(schedRunTime) + .arg(haveRequests).arg(checkSlaves)); } } else { + LOG(VB_GENERAL, LOG_INFO, + QString("In process segment with sched_sleep %1 ms " + "(s2n: %2 sr: %3 qr: %4 cs: %5) numItersBeforeSleep :%6") + .arg(sched_sleep).arg(secs_to_next).arg(schedRunTime) + .arg(haveRequests).arg(checkSlaves).arg(numItersBeforeSleep)); + if (haveRequests) { // The master backend is a long lived program, so @@ -2147,6 +2181,8 @@ void Scheduler::run(void) } schedRunTime = max(int(((t.elapsed() + 999) / 1000) * 1.5 + 2), schedRunTime); + LOG(VB_GENERAL, LOG_INFO, + QString("schedRunTime is now %1 with statuschanged %2").arg(schedRunTime).arg(statuschanged)); } if (firstRun) @@ -2172,6 +2208,9 @@ void Scheduler::run(void) nextStartTime = MythDate::current().addDays(14); nextWakeTime = lastSleepCheck.addSecs(kSleepCheck); + LOG(VB_GENERAL, LOG_INFO, + QString("Before skipping history with nwt %1 nst %2 lastSleepCheck %3").arg(nextWakeTime.toString()).arg(nextStartTime.toString()).arg(lastSleepCheck.toString())); + // Skip past recordings that are already history // (i.e. AddHistory() has been called setting oldrecstatus) @@ -2194,12 +2233,18 @@ void Scheduler::run(void) **it, statuschanged, nextStartTime, nextWakeTime, prerollseconds); } + LOG(VB_GENERAL, LOG_INFO, + QString("After HandleRecording with nwt %1 nst %2 prerollseconds %3 statuschanged %4 done %5 reclist_changed %6").arg(nextWakeTime.toString()).arg(nextStartTime.toString()).arg(prerollseconds).arg(statuschanged).arg(done).arg(reclist_changed)); // HandleRecording() temporarily unlocks schedLock. If // anything changed, reclist iterators could be invalidated so // start over. if (reclist_changed) + { + LOG(VB_GENERAL, LOG_INFO, + QString("reclist_changed after HandleRecording")); continue; + } /// Wake any slave backends that need waking curtime = MythDate::current(); @@ -2214,6 +2259,9 @@ void Scheduler::run(void) if (statuschanged) { + LOG(VB_GENERAL, LOG_INFO, + QString("statuschanged so SCHEDULE_CHANGE")); + MythEvent me("SCHEDULE_CHANGE"); gCoreContext->dispatch(me); // a scheduler run has nothing to do with the idle shutdown @@ -2228,6 +2276,9 @@ void Scheduler::run(void) statuschanged); if (idleSince.isValid()) { + LOG(VB_GENERAL, LOG_INFO, + QString("Updating nextWakeTime after idleSince.isValid with idleSince %1 and idleTimeoutSecs %2 and curtime %3").arg(idleSince.toString()).arg(idleTimeoutSecs).arg(curtime.toString())); + nextWakeTime = MythDate::current().addSecs( (idleSince.addSecs(idleTimeoutSecs - 10) <= curtime) ? 1 : (idleSince.addSecs(idleTimeoutSecs - 30) <= curtime) ? 5 : 10); @@ -2665,6 +2716,8 @@ bool Scheduler::HandleRecording( // nothing later can shorten nextWakeTime, so stop scanning. if (nextWakeTime.secsTo(nextrectime) - prerollseconds > 300) { + LOG(VB_GENERAL, LOG_INFO, + QString("HandleRecording !WillRecord !Pending set nextStartTime to min %1 and %2").arg(nextStartTime.toString()).arg(nextrectime.toString())); nextStartTime = min(nextStartTime, nextrectime); return true; } @@ -2683,6 +2736,9 @@ bool Scheduler::HandleRecording( // needs to be shorter than the related one in SchedLiveTV(). if (secsleft - prerollseconds > 60) { + LOG(VB_GENERAL, LOG_INFO, + QString("HandleRecording secsleft-preroll>60: set nextStartTime to min %1 and %2").arg(nextStartTime.toString()).arg(nextrectime.addSecs(-30).toString())); + nextStartTime = min(nextStartTime, nextrectime.addSecs(-30)); nextWakeTime = min(nextWakeTime, nextrectime.addSecs(-prerollseconds - 60)); @@ -2702,6 +2758,9 @@ bool Scheduler::HandleRecording( if (secsleft - prerollseconds > 35) { + LOG(VB_GENERAL, LOG_INFO, + QString("HandleRecording secleft-prefroll>35: set nextStartTime to min %1 and %2").arg(nextStartTime.toString()).arg(nextrectime.addSecs(-30).toString())); + nextStartTime = min(nextStartTime, nextrectime.addSecs(-30)); nextWakeTime = min(nextWakeTime, nextrectime.addSecs(-prerollseconds - 35)); @@ -2765,6 +2824,9 @@ bool Scheduler::HandleRecording( if (secsleft - prerollseconds > 30) { + LOG(VB_GENERAL, LOG_INFO, + QString("HandleRecording secleft-preroll>30: set nextStartTime to min %1 and %2").arg(nextStartTime.toString()).arg(nextrectime.addSecs(-30).toString())); + nextStartTime = min(nextStartTime, nextrectime.addSecs(-30)); nextWakeTime = min(nextWakeTime, nextrectime.addSecs(-prerollseconds - 30)); @@ -2803,6 +2865,9 @@ bool Scheduler::HandleRecording( EnqueuePlace("SlaveNotAwake"); } + LOG(VB_GENERAL, LOG_INFO, + QString("HandleRecording isWaking: set nextStartTime to min %1 and %2").arg(nextStartTime.toString()).arg(nextrectime.toString())); + nextStartTime = min(nextStartTime, nextrectime); nextWakeTime = min(nextWakeTime, curtime.addSecs(1)); return false; @@ -2846,6 +2911,9 @@ bool Scheduler::HandleRecording( if (secsleft - prerollseconds > 0) { + LOG(VB_GENERAL, LOG_INFO, + QString("HandleRecording secsleft-preroll>0: set nextStartTime to min %1 and %2").arg(nextStartTime.toString()).arg(nextrectime.toString())); + nextStartTime = min(nextStartTime, nextrectime); nextWakeTime = min(nextWakeTime, nextrectime.addSecs(-prerollseconds));