svn commit: r799272 - /qpid/trunk/qpid/cpp/src/qpid/sys/Timer.cpp

[as...@apache.org]

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-subscribe@qpid.apache.org