Aggregate Timer warnings.

The Timer code logs a warning if a timer callback is started late or
overruns the start time for the next callback. In cases where there
are a lot of these warnings, the time taken to do the logging itself
severly worsens the situation.

This commit aggregates timer warnings and give a statistical report
every 5 seconds at most.

git-svn-id: https://svn.apache.org/repos/asf/qpid/trunk/qpid@1036169 13f79535-47bb-0310-9956-ffa450edef68

6 files changed, 194 insertions, 18 deletions

diff --git a/cpp/include/qpid/log/Statement.h b/cpp/include/qpid/log/Statement.h
index 8f73175630..7b3ab60b81 100644
--- a/cpp/include/qpid/log/Statement.h
+++ b/cpp/include/qpid/log/Statement.h
@@ -96,6 +96,24 @@ struct Statement {
     } while(0)
 
 /**
+ * FLAG must be a boolean variable. Assigns FLAG to true iff logging
+ * is enabled for LEVEL in the calling context.  Use when extra
+ * support code is needed to generate log messages, to ensure that it
+ * is only run if the logging level is enabled.
+ * e.g.
+ * bool logWarning;
+ * QPID_LOG_TEST(LEVEL, logWarning);
+ * if (logWarning) { do stuff needed for warning log messages }
+ */
+#define QPID_LOG_TEST(LEVEL, FLAG)                              \
+    do {                                                        \
+        using ::qpid::log::Statement;                           \
+        static Statement stmt_= QPID_LOG_STATEMENT_INIT(LEVEL); \
+        static Statement::Initializer init_(stmt_);             \
+        FLAG = stmt_.enabled;                                   \
+    } while(0)
+
+/**
  * Macro for log statements. Example of use:
  * @code
  * QPID_LOG(debug, "There are " << foocount << " foos in the bar.");
diff --git a/cpp/src/Makefile.am b/cpp/src/Makefile.am
index d8e604c41a..9f97b94b8a 100644
--- a/cpp/src/Makefile.am
+++ b/cpp/src/Makefile.am
@@ -478,6 +478,8 @@ libqpidcommon_la_SOURCES +=			\
   qpid/sys/TimeoutHandler.h			\
   qpid/sys/Timer.cpp				\
   qpid/sys/Timer.h				\
+  qpid/sys/TimerWarnings.cpp			\
+  qpid/sys/TimerWarnings.h			\
   qpid/sys/Waitable.h				\
   qpid/sys/alloca.h				\
   qpid/sys/uuid.h				\
diff --git a/cpp/src/qpid/sys/Timer.cpp b/cpp/src/qpid/sys/Timer.cpp
index 76e8b3dc0b..a97ccd1bd1 100644
--- a/cpp/src/qpid/sys/Timer.cpp
+++ b/cpp/src/qpid/sys/Timer.cpp
@@ -79,7 +79,8 @@ Timer::Timer() :
     active(false),
     late(50 * TIME_MSEC),
     overran(2 * TIME_MSEC),
-    lateCancel(500 * TIME_MSEC)
+    lateCancel(500 * TIME_MSEC),
+    warn(5 * TIME_SEC)
 {
     start();
 }
@@ -127,23 +128,15 @@ void Timer::run()
                 if (!tasks.empty()) {
                     overrun = Duration(tasks.top()->nextFireTime, end);
                 }
-                if (delay > late) {
-                    if (overrun > overran) {
-                        QPID_LOG(warning, t->name <<
-                                 " timer woken up " << delay / TIME_MSEC <<
-                                 "ms late, overrunning by " <<
-                                 overrun / TIME_MSEC << "ms [taking " <<
-                                 Duration(start, end) << "]");
-                    } else {
-                        QPID_LOG(warning, t->name <<
-                                 " timer woken up " << delay / TIME_MSEC <<
-                                 "ms late");
-                    }
-                } else if (overrun > overran) {
-                    QPID_LOG(warning,t->name <<
-                             " timer callback overran by " <<
-                             overrun / TIME_MSEC <<
-                             "ms [taking " << Duration(start, end) << "]");
+                bool warningsEnabled;
+                QPID_LOG_TEST(warning, warningsEnabled);
+                if (warningsEnabled) {
+                    if (delay > late && overrun > overran)
+                        warn.lateAndOverran(t->name, delay, overrun, Duration(start, end));
+                    else if (delay > late)
+                        warn.late(t->name, delay);
+                    else if (overrun > overran)
+                        warn.overran(t->name, overrun, Duration(start, end));
                 }
                 continue;
             } else {
diff --git a/cpp/src/qpid/sys/Timer.h b/cpp/src/qpid/sys/Timer.h
index 531bae0f52..98ba39ce38 100644
--- a/cpp/src/qpid/sys/Timer.h
+++ b/cpp/src/qpid/sys/Timer.h
@@ -21,6 +21,7 @@
 #ifndef sys_Timer
 #define sys_Timer
 
+#include "qpid/sys/TimerWarnings.h"
 #include "qpid/sys/Monitor.h"
 #include "qpid/sys/Mutex.h"
 #include "qpid/sys/Thread.h"
@@ -96,6 +97,7 @@ class Timer : private Runnable {
     Duration late;
     Duration overran;
     Duration lateCancel;
+    TimerWarnings warn;
 };
 
 
diff --git a/cpp/src/qpid/sys/TimerWarnings.cpp b/cpp/src/qpid/sys/TimerWarnings.cpp
new file mode 100644
index 0000000000..48a56eb472
--- /dev/null
+++ b/cpp/src/qpid/sys/TimerWarnings.cpp
@@ -0,0 +1,80 @@
+/*
+ *
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ *
+ */
+#include "TimerWarnings.h"
+#include "qpid/log/Statement.h"
+
+namespace qpid {
+namespace sys {
+
+TimerWarnings::TimerWarnings(Duration reportInterval) :
+    interval(reportInterval),
+    nextReport(now(), reportInterval)
+{}
+
+void TimerWarnings::late(const std::string& task, Duration delay) {
+    taskStats[task].lateDelay.add(delay);
+    log();
+}
+
+void TimerWarnings::overran(const std::string& task, Duration overrun, Duration time)
+{
+    taskStats[task].overranOverrun.add(overrun);
+    taskStats[task].overranTime.add(time);
+    log();
+}
+
+void TimerWarnings::lateAndOverran(
+    const std::string& task, Duration delay, Duration overrun, Duration time)
+{
+    taskStats[task].lateAndOverranDelay.add(delay);
+    taskStats[task].lateAndOverranOverrun.add(overrun);
+    taskStats[task].lateAndOverranTime.add(time);
+    log();
+}
+
+void TimerWarnings::log() {
+    if (!taskStats.empty() && nextReport < now()) {
+        for (TaskStatsMap::iterator i = taskStats.begin(); i != taskStats.end(); ++i) {
+            std::string task = i->first;
+            TaskStats& stats = i->second;
+            if (stats.lateDelay.count)
+                QPID_LOG(warning, task << " task late "
+                         << stats.lateDelay.count << " times by "
+                         << stats.lateDelay.average()/TIME_MSEC << "ms on average.");
+            if (stats.overranOverrun.count)
+                QPID_LOG(warning, task << " task overran "
+                         << stats.overranOverrun.count << " times by "
+                         << stats.overranOverrun.average()/TIME_MSEC << "ms (taking "
+                         << stats.overranTime.average() << "ns) on average.");
+
+            if (stats.lateAndOverranDelay.count)
+                QPID_LOG(warning, task << " task overran "
+                         << stats.overranOverrun.count << " times by "
+                         << stats.overranOverrun.average()/TIME_MSEC << "ms (taking "
+                         << stats.overranTime.average() << "ns) on average.");
+
+        }
+        nextReport = AbsTime(now(), interval);
+        taskStats.clear();
+    }
+}
+
+}} // namespace qpid::sys
diff --git a/cpp/src/qpid/sys/TimerWarnings.h b/cpp/src/qpid/sys/TimerWarnings.h
new file mode 100644
index 0000000000..337a434ab5
--- /dev/null
+++ b/cpp/src/qpid/sys/TimerWarnings.h
@@ -0,0 +1,81 @@
+#ifndef QPID_SYS_TIMERWARNINGS_H
+#define QPID_SYS_TIMERWARNINGS_H
+
+/*
+ *
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements.  See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership.  The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License.  You may obtain a copy of the License at
+ *
+ *   http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing,
+ * software distributed under the License is distributed on an
+ * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+ * KIND, either express or implied.  See the License for the
+ * specific language governing permissions and limitations
+ * under the License.
+ *
+ */
+
+#include "qpid/sys/Time.h"
+#include <map>
+#include <string>
+
+namespace qpid {
+namespace sys {
+
+/**
+ * The Timer class logs warnings when timer tasks are late and/or overrun.
+ *
+ * It is too expensive to log a warning for every late/overrun
+ * incident, doing so aggravates the problem of tasks over-running and
+ * being late.
+ *
+ * This class collects statistical data about each incident and prints
+ * an aggregated report at regular intervals.
+ */
+class TimerWarnings
+{
+  public:
+    TimerWarnings(Duration reportInterval);
+
+    void late(const std::string& task, Duration delay);
+
+    void overran(const std::string& task, Duration overrun, Duration time);
+
+    void lateAndOverran(const std::string& task,
+                        Duration delay, Duration overrun, Duration time);
+
+  private:
+    struct Statistic {
+        Statistic() : total(0), count(0) {}
+        void add(int64_t value) { total += value; ++count; }
+        int64_t average() const { return count ? total/count : 0; }
+        int64_t total;
+        int64_t count;
+    };
+
+    // Keep statistics for 3 classes of incident:  late, overrun and both.
+    struct TaskStats {
+        Statistic lateDelay;    // Just late
+        Statistic overranOverrun, overranTime; // Just overrun
+        // Both
+        Statistic lateAndOverranDelay, lateAndOverranOverrun, lateAndOverranTime;
+    };
+
+    typedef std::map<std::string, TaskStats> TaskStatsMap;
+
+    void log();
+
+    Duration interval;
+    AbsTime nextReport;
+    TaskStatsMap taskStats;
+};
+}} // namespace qpid::sys
+
+#endif  /*!QPID_SYS_TIMERWARNINGS_H*/