Detect when Timers are being mis-used, causing TimerManager to be con…

…stantly busy and potentially blocking network control

OpenHome/Http.cpp

@@ -305,7 +305,7 @@ ReaderHttpRequest::ReaderHttpRequest(Environment& aEnv, IReader& aReader)
     : ReaderHttpHeader(aEnv)
     , iReader(aReader)
 {
-    iTimer = new Timer(aEnv, MakeFunctor(*this, &ReaderHttpRequest::ReadTimeout));
+    iTimer = new Timer(aEnv, MakeFunctor(*this, &ReaderHttpRequest::ReadTimeout), "ReaderHttpRequest");
 }
 
 ReaderHttpRequest::~ReaderHttpRequest()
@@ -443,7 +443,7 @@ ReaderHttpResponse::ReaderHttpResponse(Environment& aEnv, IReader& aReader)
     : ReaderHttpHeader(aEnv)
     , iReader(aReader)
 {
-    iTimer = new Timer(aEnv, MakeFunctor(*this, &ReaderHttpResponse::ReadTimeout));
+    iTimer = new Timer(aEnv, MakeFunctor(*this, &ReaderHttpResponse::ReadTimeout), "ReaderHttpResponse");
 }
 
 ReaderHttpResponse::~ReaderHttpResponse()

OpenHome/Net/Bindings/C/ControlPoint/Tests/TestProxyC.cpp

@@ -124,7 +124,7 @@ void DeviceList::InvokeSync()
 
 void DeviceList::PollInvoke()
 {
-    Timer timer(*gEnv, MakeFunctor(*this, &DeviceList::TimerExpired));
+    Timer timer(*gEnv, MakeFunctor(*this, &DeviceList::TimerExpired), "TestProxyC");
     for (TUint i=0; i<iList.size(); i++) {
         CpDeviceC device = iList[i];
         TUint countBefore = gActionCount;

OpenHome/Net/Bindings/Cpp/ControlPoint/Tests/TestInvocationStd.cpp

@@ -99,7 +99,7 @@ void DeviceList::TestSync()
 
 void DeviceList::Poll()
 {
-    Timer timer(*gEnv, MakeFunctor(*this, &DeviceList::TimerExpired));
+    Timer timer(*gEnv, MakeFunctor(*this, &DeviceList::TimerExpired), "TestInvocationStd");
     FunctorAsync callback = MakeFunctorAsync(*this, &DeviceList::GetProtocolInfoComplete);
     const TUint count = (TUint)iList.size();
     for (TUint i=0; i<count; i++) {

OpenHome/Net/Bindings/Cpp/ControlPoint/Tests/TestPerformanceCp.cpp

@@ -55,7 +55,7 @@ PerformanceTests::PerformanceTests(uint32_t aTimeoutSecs)
     , iDeviceList(NULL)
     , iDevice(NULL)
 {
-    iTimer = new Timer(*gEnv, MakeFunctor(*this, &PerformanceTests::TimerExpired));
+    iTimer = new Timer(*gEnv, MakeFunctor(*this, &PerformanceTests::TimerExpired), "TestPerformanceCp");
 }
 
 PerformanceTests::~PerformanceTests()

OpenHome/Net/ControlPoint/CpiSubscription.cpp

@@ -172,7 +172,7 @@ CpiSubscription::CpiSubscription(CpiDevice& aDevice, IEventProcessor& aEventProc
     , iInterruptHandler(NULL)
     , iSuspended(false)
 {
-    iTimer = new Timer(iEnv, MakeFunctor(*this, &CpiSubscription::Renew));
+    iTimer = new Timer(iEnv, MakeFunctor(*this, &CpiSubscription::Renew), "CpiSubscription");
     iDevice.AddRef();
     iRejectFutureOperations = false;
     iEnv.AddObject(this);
@@ -583,7 +583,7 @@ CpiSubscriptionManager::~CpiSubscriptionManager()
         // wait 1 minute then proceed
         // we'll have leaked some subscriptions but this'll be logged later during shutdown
         iCleanShutdown = true;
-        Timer timer(iCpStack.Env(), MakeFunctor(*this, &CpiSubscriptionManager::ShutdownHasHung));
+        Timer timer(iCpStack.Env(), MakeFunctor(*this, &CpiSubscriptionManager::ShutdownHasHung), "SubscriptionManagerShutdown");
         timer.FireIn(60*1000);
         iShutdownSem.Wait();
         if (iCleanShutdown) {

OpenHome/Net/ControlPoint/Tests/TestInvocation.cpp

@@ -104,7 +104,7 @@ void DeviceListTI::TestSync()
 
 void DeviceListTI::Poll()
 {
-    Timer timer(iEnv, MakeFunctor(*this, &DeviceListTI::TimerExpired));
+    Timer timer(iEnv, MakeFunctor(*this, &DeviceListTI::TimerExpired), "TestInvocation");
     FunctorAsync callback = MakeFunctorAsync(*this, &DeviceListTI::GetProtocolInfoComplete);
     Brh tmp;
     const TUint count = (TUint)iList.size();

OpenHome/Net/ControlPoint/Upnp/CpiDeviceUpnp.cpp

@@ -45,7 +45,7 @@ CpiDeviceUpnp::CpiDeviceUpnp(CpStack& aCpStack, const Brx& aUdn, const Brx& aLoc
     Environment& env = aCpStack.Env();
     iHostUdpIsLowQuality = env.InitParams()->IsHostUdpLowQuality();
     iDevice = new CpiDevice(aCpStack, aUdn, *this, *this, this);
-    iTimer = new Timer(env, MakeFunctor(*this, &CpiDeviceUpnp::TimerExpired));
+    iTimer = new Timer(env, MakeFunctor(*this, &CpiDeviceUpnp::TimerExpired), "CpiDeviceUpnp");
     UpdateMaxAge(aMaxAgeSecs);
     iInvocable = new Invocable(*this);
 }
@@ -485,8 +485,8 @@ CpiDeviceListUpnp::CpiDeviceListUpnp(CpStack& aCpStack, FunctorCpiDevice aAdded,
     NetworkAdapterList& ifList = aCpStack.Env().NetworkAdapterList();
     AutoNetworkAdapterRef ref(iEnv, "CpiDeviceListUpnp ctor");
     const NetworkAdapter* current = ref.Adapter();
-    iRefreshTimer = new Timer(iEnv, MakeFunctor(*this, &CpiDeviceListUpnp::RefreshTimerComplete));
-    iResumedTimer = new Timer(iEnv, MakeFunctor(*this, &CpiDeviceListUpnp::ResumedTimerComplete));
+    iRefreshTimer = new Timer(iEnv, MakeFunctor(*this, &CpiDeviceListUpnp::RefreshTimerComplete), "DeviceListRefresh");
+    iResumedTimer = new Timer(iEnv, MakeFunctor(*this, &CpiDeviceListUpnp::ResumedTimerComplete), "DeviceListResume");
     iRefreshRepeatCount = 0;
     iInterfaceChangeListenerId = ifList.AddCurrentChangeListener(MakeFunctor(*this, &CpiDeviceListUpnp::CurrentNetworkAdapterChanged));
     iSubnetListChangeListenerId = ifList.AddSubnetListChangeListener(MakeFunctor(*this, &CpiDeviceListUpnp::SubnetListChanged));

OpenHome/Net/Device/Bonjour/MdnsPlatform.cpp

@@ -144,7 +144,7 @@ MdnsPlatform::MdnsPlatform(Environment& aEnv, const TChar* aHost)
     , iTimerDisabled(false)
 {
     LOG(kBonjour, "Bonjour             Constructor\n");
-    iTimer = new Timer(iEnv, MakeFunctor(*this, &MdnsPlatform::TimerExpired));
+    iTimer = new Timer(iEnv, MakeFunctor(*this, &MdnsPlatform::TimerExpired), "MdnsPlatform");
     iThreadListen = new ThreadFunctor("Bonjour", MakeFunctor(*this, &MdnsPlatform::Listen));
     iNextServiceIndex = 0;
     iMdns = new mDNS();

OpenHome/Net/Device/DviSubscription.cpp

@@ -56,7 +56,7 @@ DviSubscription::DviSubscription(DvStack& aDvStack, DviDevice& aDevice, IPropert
     aSid.TransferTo(iSid);
     iWriterFactory.NotifySubscriptionCreated(iSid);
     Functor functor = MakeFunctor(*this, &DviSubscription::Expired);
-    iTimer = new Timer(iDvStack.Env(), functor);
+    iTimer = new Timer(iDvStack.Env(), functor, "DviSubscription");
     iDvStack.Env().AddObject(this);
 }
 

OpenHome/Net/Device/Upnp/DviProtocolUpnp.cpp

@@ -68,7 +68,7 @@ DviProtocolUpnp::DviProtocolUpnp(DviDevice& aDevice)
         }
     }
     NetworkAdapterList::DestroySubnetList(subnetList);
-    iAliveTimer = new Timer(iDvStack.Env(), MakeFunctor(*this, &DviProtocolUpnp::SendAliveNotifications));
+    iAliveTimer = new Timer(iDvStack.Env(), MakeFunctor(*this, &DviProtocolUpnp::SendAliveNotifications), "DviProtocolUpnp");
     iLock.Signal();
 }
 

OpenHome/Net/Device/Upnp/DviSsdpNotifier.cpp

@@ -29,7 +29,7 @@ SsdpNotifierScheduler::SsdpNotifierScheduler(DvStack& aDvStack, ISsdpNotifyListe
     , iListener(aListener)
 {
     Functor functor = MakeFunctor(*this, &SsdpNotifierScheduler::SendNextMsg);
-    iTimer = new Timer(iDvStack.Env(), functor);
+    iTimer = new Timer(iDvStack.Env(), functor, "SsdpNotifierScheduler");
 }
 
 void SsdpNotifierScheduler::Start(TUint aDuration, TUint aMsgCount)

OpenHome/Net/Tests/TestSsdpMListen.cpp

@@ -206,7 +206,7 @@ SuiteListen::SuiteListen(Environment& aEnv, TUint aDurationSeconds, TUint aInter
     , iDuration(1000 * aDurationSeconds)
     , iInterfaceIndex(aInterfaceIndex)
 {
-    iTimer = new Timer(aEnv, MakeFunctor(*this, &SuiteListen::TimerExpired));
+    iTimer = new Timer(aEnv, MakeFunctor(*this, &SuiteListen::TimerExpired), "SuiteListen");
 }
 
 SuiteListen::~SuiteListen()

OpenHome/TestFramework/TestFramework.cpp

@@ -197,7 +197,7 @@ void OpenHome::TestFramework::RandomiseUdn(Environment& aEnv, Bwh& aUdn)
 Blocker::Blocker(Environment& aEnv)
     : iSem("SBLK", 0)
 {
-    iTimer = new Timer(aEnv, MakeFunctor(*this, &Blocker::TimerExpired));
+    iTimer = new Timer(aEnv, MakeFunctor(*this, &Blocker::TimerExpired), "Blocker");
 }
 
 Blocker::~Blocker()

OpenHome/Tests/TestTimer.cpp

@@ -12,7 +12,7 @@ using namespace OpenHome::TestFramework;
 class MyTimer : public Timer
 {
 public:
-    MyTimer(Environment& aEnv) : Timer(aEnv, MakeFunctor(*this, &MyTimer::Run)), iCount(0), iSemaphore("TIMR", 0) {}
+    MyTimer(Environment& aEnv) : Timer(aEnv, MakeFunctor(*this, &MyTimer::Run), "MyTimer"), iCount(0), iSemaphore("TIMR", 0) {}
     void Wait() { iSemaphore.Wait(); }
     TUint Count() { return (iCount); }
     ~MyTimer() { iCount = 0xffffffff; }
@@ -26,7 +26,7 @@ class MyTimer : public Timer
 class MicrosecondTimer
 {
 public:
-    MicrosecondTimer(Environment& aEnv) : iTimer(aEnv, MakeFunctor(*this, &MicrosecondTimer::Expired)), iSemaphore("MICR", 0) {}
+    MicrosecondTimer(Environment& aEnv) : iTimer(aEnv, MakeFunctor(*this, &MicrosecondTimer::Expired), "MicrosecondTimer"), iSemaphore("MICR", 0) {}
     void Calibrate();
     void FireIn(TUint aMicroseconds);
 private:
@@ -211,7 +211,7 @@ void SuiteTimerThrash::Test()
     Functor f = MakeFunctor(*this, &SuiteTimerThrash::Fire);
 
     for (TUint i = 0; i < 10000; i++) {
-        iTimers[i] = new Timer(iEnv, f);
+        iTimers[i] = new Timer(iEnv, f, "SuiteTimerThrash");
     }
 
     Print("Firing 10000 timers over 10 seconds\n");

OpenHome/Timer.cpp

@@ -42,9 +42,10 @@ TInt Time::TimeToWaitFor(Environment& aEnv, TUint aTime)
 
 // Timer
 
-Timer::Timer(Environment& aEnv, Functor aFunctor)
+Timer::Timer(Environment& aEnv, Functor aFunctor, const TChar* aId)
     : iMgr(aEnv.TimerManager())
     , iFunctor(aFunctor)
+    , iId(aId)
 {
 }
 
@@ -78,6 +79,11 @@ void Timer::Cancel()
     LOG(kTimer, "<Timer::Cancel()\n");
 }
 
+const TChar* Timer::Id() const
+{
+    return iId;
+}
+
 TBool Timer::IsInManagerThread(OpenHome::Environment& aEnv)
 { // static
     return IsInManagerThread(aEnv.TimerManager());
@@ -106,6 +112,9 @@ TimerManager::TimerManager(Environment& aEnv)
     , iStopped("MTS2", 0)
     , iCallbackMutex("TMCB")
     , iThreadHandle(NULL)
+    , iBusyStartTimeMs(0)
+    , iLastRunTimeMs(0)
+    , iCallbacksPerTick(0)
 {
     LOG(kTimer, ">TimerManager::TimerManager()\n");
     iThread = new ThreadFunctor("TimerManager", MakeFunctor(*this, &TimerManager::Run), kPriorityHigh);
@@ -197,7 +206,24 @@ void TimerManager::HeadChanged(QueueSortedEntry& aEntry)
 
 void TimerManager::Fire()
 {
-    TUint now = Os::TimeInMs(iEnv.OsCtx());
+    const TUint now = Os::TimeInMs(iEnv.OsCtx());
+    if (iLastRunTimeMs > now) { // wrapped
+        iLastRunTimeMs = 0;
+        iCallbacksPerTick = 0;
+    }
+    else if (iLastRunTimeMs == now) {
+    }
+    else if (iLastRunTimeMs - now > kMaxTimerGranularityMs) {
+        iBusyStartTimeMs = now;
+        iCallbacksPerTick = 0;
+    }
+    if (iBusyStartTimeMs == 0 || iBusyStartTimeMs > now) { // Clock has wrapped.  Reset our busy counter for the sake of simplicity
+        iBusyStartTimeMs = now;
+    }
+    else if (now - iBusyStartTimeMs > kMaxBusyTimeMs) {
+        iCallbackList.Log();
+        ASSERTS();
+    }
     iMutexNow.Wait();
     iRemoving = true;
     iNow.iTime = now + 1; // will go after all the entries before or at now
@@ -222,6 +248,11 @@ void TimerManager::Fire()
             LOG(kTimer, "-TimerManager::Fire() done signalling\n");
             break;
         }
+        iCallbackList.Add(head);
+        if (++iCallbacksPerTick > kMaxCallbacksPerTick) {
+            iCallbackList.Log();
+            ASSERTS();
+        }
         head.iFunctor(); // run the timer's callback
         LOG(kTimer, "-TimerManager::Fire() signaling consumer\n");
     }
@@ -263,3 +294,70 @@ void TimerManager::Run()
     iStopped.Signal();
 }
 
+
+// TimerManager::Callback
+
+TimerManager::Callback::Callback()
+    : iPtr(NULL)
+    , iId(NULL)
+{
+}
+
+void TimerManager::Callback::Set(void* aPtr, const TChar* aId)
+{
+    iPtr = &aPtr;
+    iId = aId;
+}
+
+void TimerManager::Callback::Log() const
+{
+    Log::Print("Timer: %s (%p)\n", iId, iPtr);
+}
+
+
+// TimerManager::CallbackList
+
+TimerManager::CallbackList::CallbackList()
+    : iHead(0)
+    , iTail(0)
+{
+    (void)memset(iList, 0, sizeof(iList));
+}
+
+void TimerManager::CallbackList::Add(Timer& aTimer)
+{
+    iList[iTail].Set(&aTimer, aTimer.Id());
+    IncIndex(iTail);
+    if (iTail == iHead) {
+        IncIndex(iHead);
+    }
+}
+
+void TimerManager::CallbackList::Log() const
+{
+    Log::Print("Suspicious (implausible) activity in TimerManager.  Recent timers are:\n");
+    if (iHead == iTail) {
+        ASSERT(iHead == 0); // i.e. no timers have ever run
+        return;
+    }
+    TUint tail = iTail;
+    do {
+        DecIndex(tail);
+        iList[tail].Log();
+    } while (tail != iHead);
+}
+
+void TimerManager::CallbackList::IncIndex(TUint aIndex)
+{ // static
+    if (++aIndex == kElements) {
+        aIndex = 0;
+    }
+}
+
+void TimerManager::CallbackList::DecIndex(TUint& aIndex)
+{ // static
+    if (aIndex == 0) {
+        aIndex = kElements-1;
+    }
+    --aIndex;
+}

OpenHome/Timer.h

@@ -35,17 +35,19 @@ class Timer : public QueueSortedEntryTimer
 {
     friend class TimerManager;
 public:
-    Timer(Environment& aEnv, Functor aFunctor);
+    Timer(Environment& aEnv, Functor aFunctor, const TChar* aId);
     void FireIn(TUint aTime); // Relative (milliseconds from now)
     void FireAt(TUint aTime); // Absolute (at specified millisecond)
     void Cancel();
+    const TChar* Id() const;
     ~Timer();
     static TBool IsInManagerThread(Environment& aEnv);
 private:
     static TBool IsInManagerThread(TimerManager& aMgr);
 private:
     TimerManager& iMgr;
     Functor iFunctor;
+    const TChar* iId;
 };
 
 class TimerManager : public QueueSorted<Timer>
@@ -57,6 +59,32 @@ class TimerManager : public QueueSorted<Timer>
     ~TimerManager();
     void CallbackLock();
     void CallbackUnlock();
+private:
+    class Callback
+    {
+    public:
+        Callback();
+        void Set(void* aPtr, const TChar* aId);
+        void Log() const;
+    private:
+        void* iPtr;
+        const TChar* iId;
+    };
+    class CallbackList
+    {
+        static const TUint kElements = 100;
+    public:
+        CallbackList();
+        void Add(Timer& aTimer);
+        void Log() const;
+    private:
+        static void IncIndex(TUint aIndex);
+        static void DecIndex(TUint& aIndex);
+    private:
+        Callback iList[kElements];
+        TUint iHead;
+        TUint iTail;
+    };
 private:
     void Run();
     void Fire();
@@ -76,6 +104,13 @@ class TimerManager : public QueueSorted<Timer>
     Semaphore iStopped;
     Mutex iCallbackMutex;
     Thread* iThreadHandle;
+    static const TUint kMaxBusyTimeMs = 1000 * 60 * 30; // 30 minutes
+    static const TUint kMaxTimerGranularityMs = 10;
+    static const TUint kMaxCallbacksPerTick = 1000;
+    TUint iBusyStartTimeMs;
+    TUint iLastRunTimeMs;
+    TUint iCallbacksPerTick;
+    CallbackList iCallbackList;
 };
 
 } // namespace OpenHome