Author: aconway
Date: Wed Nov 17 19:12:08 2010
New Revision: 1036169
URL: http://svn.apache.org/viewvc?rev=1036169&view=rev
Log:
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.
Added:
qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.cpp (with props)
qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.h (with props)
Modified:
qpid/trunk/qpid/cpp/include/qpid/log/Statement.h
qpid/trunk/qpid/cpp/src/Makefile.am
qpid/trunk/qpid/cpp/src/qpid/sys/Timer.cpp
qpid/trunk/qpid/cpp/src/qpid/sys/Timer.h
Modified: qpid/trunk/qpid/cpp/include/qpid/log/Statement.h
URL:
http://svn.apache.org/viewvc/qpid/trunk/qpid/cpp/include/qpid/log/Statement.h?rev=1036169&r1=1036168&r2=1036169&view=diff
==============================================================================
--- qpid/trunk/qpid/cpp/include/qpid/log/Statement.h (original)
+++ qpid/trunk/qpid/cpp/include/qpid/log/Statement.h Wed Nov 17 19:12:08 2010
@@ -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.");
Modified: qpid/trunk/qpid/cpp/src/Makefile.am
URL:
http://svn.apache.org/viewvc/qpid/trunk/qpid/cpp/src/Makefile.am?rev=1036169&r1=1036168&r2=1036169&view=diff
==============================================================================
--- qpid/trunk/qpid/cpp/src/Makefile.am (original)
+++ qpid/trunk/qpid/cpp/src/Makefile.am Wed Nov 17 19:12:08 2010
@@ -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 \
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=1036169&r1=1036168&r2=1036169&view=diff
==============================================================================
--- qpid/trunk/qpid/cpp/src/qpid/sys/Timer.cpp (original)
+++ qpid/trunk/qpid/cpp/src/qpid/sys/Timer.cpp Wed Nov 17 19:12:08 2010
@@ -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 {
Modified: qpid/trunk/qpid/cpp/src/qpid/sys/Timer.h
URL:
http://svn.apache.org/viewvc/qpid/trunk/qpid/cpp/src/qpid/sys/Timer.h?rev=1036169&r1=1036168&r2=1036169&view=diff
==============================================================================
--- qpid/trunk/qpid/cpp/src/qpid/sys/Timer.h (original)
+++ qpid/trunk/qpid/cpp/src/qpid/sys/Timer.h Wed Nov 17 19:12:08 2010
@@ -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;
};
Added: qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.cpp
URL:
http://svn.apache.org/viewvc/qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.cpp?rev=1036169&view=auto
==============================================================================
--- qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.cpp (added)
+++ qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.cpp Wed Nov 17 19:12:08 2010
@@ -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
Propchange: qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.cpp
------------------------------------------------------------------------------
svn:eol-style = native
Propchange: qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.cpp
------------------------------------------------------------------------------
svn:keywords = Rev Date
Added: qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.h
URL:
http://svn.apache.org/viewvc/qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.h?rev=1036169&view=auto
==============================================================================
--- qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.h (added)
+++ qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.h Wed Nov 17 19:12:08 2010
@@ -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*/
Propchange: qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.h
------------------------------------------------------------------------------
svn:eol-style = native
Propchange: qpid/trunk/qpid/cpp/src/qpid/sys/TimerWarnings.h
------------------------------------------------------------------------------
svn:keywords = Rev Date
---------------------------------------------------------------------
Apache Qpid - AMQP Messaging Implementation
Project: http://qpid.apache.org
Use/Interact: mailto:[email protected]
