Author: astitcher Date: Thu Jul 30 14:06:39 2009 New Revision: 799272 URL: http://svn.apache.org/viewvc?rev=799272&view=rev Log: Added diagnostics to tell if timer callbacks overrun their allowed time
Modified: qpid/trunk/qpid/cpp/src/qpid/sys/Timer.cpp Modified: qpid/trunk/qpid/cpp/src/qpid/sys/Timer.cpp URL: http://svn.apache.org/viewvc/qpid/trunk/qpid/cpp/src/qpid/sys/Timer.cpp?rev=799272&r1=799271&r2=799272&view=diff ============================================================================== --- qpid/trunk/qpid/cpp/src/qpid/sys/Timer.cpp (original) +++ qpid/trunk/qpid/cpp/src/qpid/sys/Timer.cpp Thu Jul 30 14:06:39 2009 @@ -20,7 +20,8 @@ */ #include "qpid/sys/Timer.h" #include "qpid/sys/Mutex.h" -#include <iostream> +#include "qpid/log/Statement.h" + #include <numeric> using boost::intrusive_ptr; @@ -58,6 +59,8 @@ if (period && readyToFire()) { nextFireTime = AbsTime(nextFireTime, period); cancelled = false; + } else { + QPID_LOG(error, "Couldn't setup next timer firing: " << Duration(nextFireTime, AbsTime::now()) << "[" << period << "]"); } } @@ -91,19 +94,34 @@ } else { intrusive_ptr<TimerTask> t = tasks.top(); tasks.pop(); + assert(!(t->nextFireTime < t->sortTime)); + + // warn on extreme lateness + AbsTime start(AbsTime::now()); + Duration late(t->sortTime, start); + if (late > 500 * TIME_MSEC) { + QPID_LOG(warning, "Timer delayed by " << late / TIME_MSEC << "ms"); + } { ScopedLock<Mutex> l(t->callbackLock); if (t->cancelled) { continue; - } else if(t->readyToFire()) { + } else if(Duration(t->nextFireTime, start) >= 0) { Monitor::ScopedUnlock u(monitor); t->fireTask(); + // Warn on callback overrun + AbsTime end(AbsTime::now()); + Duration overrun(tasks.top()->nextFireTime, end); + if (overrun > 1 * TIME_MSEC) { + QPID_LOG(warning, + "Timer callback overran by " << overrun / TIME_MSEC << "ms [taking " + << Duration(start, end) << "]"); + } continue; } else { // If the timer was adjusted into the future it might no longer // be the next event, so push and then get top to make sure // You can only push events into the future - assert(!(t->nextFireTime < t->sortTime)); t->sortTime = t->nextFireTime; tasks.push(t); } --------------------------------------------------------------------- Apache Qpid - AMQP Messaging Implementation Project: http://qpid.apache.org Use/Interact: mailto:commits-subscr...@qpid.apache.org