Ticket #13072: schedulebusyloop2.patch

File schedulebusyloop2.patch, 9.6 KB (added by lucylangthorne55@…, 8 years ago)

Patch for extra logging used in schedulebusyloop2.log.gz

  • mythtv/programs/mythbackend/scheduler.cpp 

    diff --git a/mythtv/programs/mythbackend/scheduler.cpp b/mythtv/programs/mythbackend/scheduler.cpp
index 49b291290f..a04fa53809 100644
    a b void Scheduler::run(void)  
    20842084    bool      statuschanged   = false;
    20852085    QDateTime nextStartTime   = MythDate::current().addDays(14);
    20862086    QDateTime nextWakeTime    = nextStartTime;
    2087 
     2087    int numItersBeforeSleep = 0;
    20882088    while (doRun)
    20892089    {
     2090        ++numItersBeforeSleep;
     2091        LOG(VB_GENERAL, LOG_INFO,
     2092            QString("At top of loop with nwt %1 nst %2 current time %3").arg(nextWakeTime.toString()).arg(nextStartTime.toString()).arg(MythDate::current().toString()));
     2093
    20902094        // If something changed, it might have short circuited a pass
    20912095        // through the list or changed the next run times.  Start a
    20922096        // new pass immediately to take care of anything that still
    20932097        // needs attention right now and reset the run times.
    20942098        if (reclist_changed)
    20952099        {
     2100            LOG(VB_GENERAL, LOG_INFO,
     2101                QString("reclist_changed so resetting nextStartTime from %1").arg(nextStartTime.toString()));
     2102
    20962103            nextStartTime = MythDate::current();
    20972104            reclist_changed = false;
    20982105        }
    20992106
     2107        LOG(VB_GENERAL, LOG_INFO,
     2108            QString("About to set nextWakeTime to min of %1 and %2").arg(nextWakeTime.toString()).arg(nextStartTime.toString()));
    21002109        nextWakeTime = min(nextWakeTime, nextStartTime);
    21012110        QDateTime curtime = MythDate::current();
    21022111        int secs_to_next = curtime.secsTo(nextStartTime);
     2112        LOG(VB_GENERAL, LOG_INFO,
     2113            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)));
     2114
    21032115        int sched_sleep = max(curtime.msecsTo(nextWakeTime), qint64(0));
     2116
    21042117        if (idleTimeoutSecs > 0)
    21052118            sched_sleep = min(sched_sleep, 15000);
    21062119        bool haveRequests = HaveQueuedRequests();
    … … void Scheduler::run(void)  
    21142127        {
    21152128            if (sched_sleep)
    21162129            {
    2117                 LOG(VB_SCHEDULE, LOG_INFO,
     2130                LOG(VB_GENERAL, LOG_INFO,
    21182131                    QString("sleeping for %1 ms "
    2119                             "(s2n: %2 sr: %3 qr: %4 cs: %5)")
     2132                            "(s2n: %2 sr: %3 qr: %4 cs: %5) numItersBeforeSleep: %6")
    21202133                    .arg(sched_sleep).arg(secs_to_next).arg(schedRunTime)
    2121                     .arg(haveRequests).arg(checkSlaves));
     2134                    .arg(haveRequests).arg(checkSlaves).arg(numItersBeforeSleep));
     2135                numItersBeforeSleep = 0;
    21222136                if (reschedWait.wait(&schedLock, sched_sleep))
     2137                {
     2138                    LOG(VB_GENERAL, LOG_INFO,
     2139                        QString("After sleeping for %1 ms wakeup and continue").arg(sched_sleep));
    21232140                    continue;
     2141                }
     2142                LOG(VB_GENERAL, LOG_INFO,
     2143                    QString("After sleeping for %1 ms wakeup").arg(sched_sleep));
     2144            }
     2145            else
     2146            {
     2147                LOG(VB_GENERAL, LOG_INFO,
     2148                    QString("NOT sleeping for %1 ms "
     2149                            "(s2n: %2 sr: %3 qr: %4 cs: %5)")
     2150                    .arg(sched_sleep).arg(secs_to_next).arg(schedRunTime)
     2151                    .arg(haveRequests).arg(checkSlaves));
    21242152            }
    21252153        }
    21262154        else
    21272155        {
     2156            LOG(VB_GENERAL, LOG_INFO,
     2157                QString("In process segment with sched_sleep %1 ms "
     2158                    "(s2n: %2 sr: %3 qr: %4 cs: %5) numItersBeforeSleep :%6")
     2159                .arg(sched_sleep).arg(secs_to_next).arg(schedRunTime)
     2160                .arg(haveRequests).arg(checkSlaves).arg(numItersBeforeSleep));
     2161
    21282162            if (haveRequests)
    21292163            {
    21302164                // The master backend is a long lived program, so
    … … void Scheduler::run(void)  
    21472181                }
    21482182                schedRunTime = max(int(((t.elapsed() + 999) / 1000) * 1.5 + 2),
    21492183                                   schedRunTime);
     2184                LOG(VB_GENERAL, LOG_INFO,
     2185                    QString("schedRunTime is now %1 with statuschanged %2").arg(schedRunTime).arg(statuschanged));
    21502186            }
    21512187
    21522188            if (firstRun)
    … … void Scheduler::run(void)  
    21722208
    21732209        nextStartTime = MythDate::current().addDays(14);
    21742210        nextWakeTime = lastSleepCheck.addSecs(kSleepCheck);
     2211        LOG(VB_GENERAL, LOG_INFO,
     2212            QString("Before skipping history with nwt %1 nst %2 lastSleepCheck %3").arg(nextWakeTime.toString()).arg(nextStartTime.toString()).arg(lastSleepCheck.toString()));
     2213
    21752214
    21762215        // Skip past recordings that are already history
    21772216        // (i.e. AddHistory() has been called setting oldrecstatus)
    … … void Scheduler::run(void)  
    21942233                **it, statuschanged, nextStartTime, nextWakeTime,
    21952234                prerollseconds);
    21962235        }
     2236        LOG(VB_GENERAL, LOG_INFO,
     2237            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));
    21972238
    21982239        // HandleRecording() temporarily unlocks schedLock.  If
    21992240        // anything changed, reclist iterators could be invalidated so
    22002241        // start over.
    22012242        if (reclist_changed)
     2243        {
     2244            LOG(VB_GENERAL, LOG_INFO,
     2245                QString("reclist_changed after HandleRecording"));
    22022246            continue;
     2247        }
    22032248
    22042249        /// Wake any slave backends that need waking
    22052250        curtime = MythDate::current();
    … … void Scheduler::run(void)  
    22142259
    22152260        if (statuschanged)
    22162261        {
     2262            LOG(VB_GENERAL, LOG_INFO,
     2263                QString("statuschanged so SCHEDULE_CHANGE"));
     2264
    22172265            MythEvent me("SCHEDULE_CHANGE");
    22182266            gCoreContext->dispatch(me);
    22192267// a scheduler run has nothing to do with the idle shutdown
    … … void Scheduler::run(void)  
    22282276                               statuschanged);
    22292277            if (idleSince.isValid())
    22302278            {
     2279                LOG(VB_GENERAL, LOG_INFO,
     2280                    QString("Updating nextWakeTime after idleSince.isValid with idleSince %1 and idleTimeoutSecs %2 and curtime %3").arg(idleSince.toString()).arg(idleTimeoutSecs).arg(curtime.toString()));
     2281
    22312282                nextWakeTime = MythDate::current().addSecs(
    22322283                    (idleSince.addSecs(idleTimeoutSecs - 10) <= curtime) ? 1 :
    22332284                    (idleSince.addSecs(idleTimeoutSecs - 30) <= curtime) ? 5 : 10);
    … … bool Scheduler::HandleRecording(  
    26652716        // nothing later can shorten nextWakeTime, so stop scanning.
    26662717        if (nextWakeTime.secsTo(nextrectime) - prerollseconds > 300)
    26672718        {
     2719            LOG(VB_GENERAL, LOG_INFO,
     2720                QString("HandleRecording !WillRecord !Pending set nextStartTime to min %1 and %2").arg(nextStartTime.toString()).arg(nextrectime.toString()));
    26682721            nextStartTime = min(nextStartTime, nextrectime);
    26692722            return true;
    26702723        }
    … … bool Scheduler::HandleRecording(  
    26832736    // needs to be shorter than the related one in SchedLiveTV().
    26842737    if (secsleft - prerollseconds > 60)
    26852738    {
     2739        LOG(VB_GENERAL, LOG_INFO,
     2740            QString("HandleRecording secsleft-preroll>60: set nextStartTime to min %1 and %2").arg(nextStartTime.toString()).arg(nextrectime.addSecs(-30).toString()));
     2741
    26862742        nextStartTime = min(nextStartTime, nextrectime.addSecs(-30));
    26872743        nextWakeTime = min(nextWakeTime,
    26882744                            nextrectime.addSecs(-prerollseconds - 60));
    … … bool Scheduler::HandleRecording(  
    27022758
    27032759    if (secsleft - prerollseconds > 35)
    27042760    {
     2761        LOG(VB_GENERAL, LOG_INFO,
     2762            QString("HandleRecording secleft-prefroll>35:  set nextStartTime to min %1 and %2").arg(nextStartTime.toString()).arg(nextrectime.addSecs(-30).toString()));
     2763
    27052764        nextStartTime = min(nextStartTime, nextrectime.addSecs(-30));
    27062765        nextWakeTime = min(nextWakeTime,
    27072766                            nextrectime.addSecs(-prerollseconds - 35));
    … … bool Scheduler::HandleRecording(  
    27652824
    27662825    if (secsleft - prerollseconds > 30)
    27672826    {
     2827        LOG(VB_GENERAL, LOG_INFO,
     2828            QString("HandleRecording secleft-preroll>30:  set nextStartTime to min %1 and %2").arg(nextStartTime.toString()).arg(nextrectime.addSecs(-30).toString()));
     2829
    27682830        nextStartTime = min(nextStartTime, nextrectime.addSecs(-30));
    27692831        nextWakeTime = min(nextWakeTime,
    27702832                            nextrectime.addSecs(-prerollseconds - 30));
    … … bool Scheduler::HandleRecording(  
    28032865            EnqueuePlace("SlaveNotAwake");
    28042866        }
    28052867
     2868        LOG(VB_GENERAL, LOG_INFO,
     2869            QString("HandleRecording isWaking: set nextStartTime to min %1 and %2").arg(nextStartTime.toString()).arg(nextrectime.toString()));
     2870
    28062871        nextStartTime = min(nextStartTime, nextrectime);
    28072872        nextWakeTime = min(nextWakeTime, curtime.addSecs(1));
    28082873        return false;
    … … bool Scheduler::HandleRecording(  
    28462911
    28472912    if (secsleft - prerollseconds > 0)
    28482913    {
     2914        LOG(VB_GENERAL, LOG_INFO,
     2915            QString("HandleRecording secsleft-preroll>0: set nextStartTime to min %1 and %2").arg(nextStartTime.toString()).arg(nextrectime.toString()));
     2916
    28492917        nextStartTime = min(nextStartTime, nextrectime);
    28502918        nextWakeTime = min(nextWakeTime,
    28512919                            nextrectime.addSecs(-prerollseconds));