Improve efficiency of class Logger

Author: jmirabel

include/dynamic-graph/entity.h

@@ -92,7 +92,7 @@ class DYNAMIC_GRAPH_DLLAPI Entity : private boost::noncopyable {
   /// \brief Send messages \c msg with level \c t.
   /// Add string file and line to message.
   void sendMsg(const std::string &msg, MsgType t = MSG_TYPE_INFO,
-               const char *file = "", int line = 0);
+               const std::string &lineId = "");
 
   /// \brief Specify the verbosity level of the logger.
   void setLoggerVerbosityLevel(LoggerVerbosity lv) { logger_.setVerbosity(lv); }

include/dynamic-graph/logger.h

@@ -27,23 +27,28 @@ namespace dynamicgraph {
 /** Enum representing the different kind of messages.
  */
 enum MsgType {
-  MSG_TYPE_DEBUG = 0,
-  MSG_TYPE_INFO = 1,
-  MSG_TYPE_WARNING = 2,
-  MSG_TYPE_ERROR = 3,
-  MSG_TYPE_DEBUG_STREAM = 4,
-  MSG_TYPE_INFO_STREAM = 5,
-  MSG_TYPE_WARNING_STREAM = 6,
-  MSG_TYPE_ERROR_STREAM = 7
+  MSG_TYPE_TYPE_BITS      = 1<<0 | 1<<1 | 1<<2 | 1<<3, // 15
+  MSG_TYPE_STREAM_BIT     = 1<<4,                      // 16
+
+  MSG_TYPE_DEBUG          = 1<<0,                      // 1
+  MSG_TYPE_INFO           = 1<<1,                      // 2
+  MSG_TYPE_WARNING        = 1<<2,                      // 4
+  MSG_TYPE_ERROR          = 1<<3,                      // 8
+  MSG_TYPE_DEBUG_STREAM   = MSG_TYPE_DEBUG   | 1<<4,   // 17
+  MSG_TYPE_INFO_STREAM    = MSG_TYPE_INFO    | 1<<4,   // 18
+  MSG_TYPE_WARNING_STREAM = MSG_TYPE_WARNING | 1<<4,   // 20
+  MSG_TYPE_ERROR_STREAM   = MSG_TYPE_ERROR   | 1<<4    // 24
 };
 } // namespace dynamicgraph
 
 /* --------------------------------------------------------------------- */
 /* --- INCLUDE --------------------------------------------------------- */
 /* --------------------------------------------------------------------- */
 
-#include "boost/assign.hpp"
+#include <boost/assign.hpp>
+#include <boost/preprocessor/stringize.hpp>
 #include <dynamic-graph/linear-algebra.h>
+#include <dynamic-graph/real-time-logger-def.h>
 #include <fstream>
 #include <iomanip> // std::setprecision
 #include <map>
@@ -54,13 +59,36 @@ namespace dynamicgraph {
 //#define LOGGER_VERBOSITY_INFO_WARNING_ERROR
 #define LOGGER_VERBOSITY_ALL
 
-#define SEND_MSG(msg, type) sendMsg(msg, type, __FILE__, __LINE__)
+#define SEND_MSG(msg, type)                                                    \
+  sendMsg(msg, type, __FILE__ ":" BOOST_PP_STRINGIZE(__LINE__))
 
 #define SEND_DEBUG_STREAM_MSG(msg) SEND_MSG(msg, MSG_TYPE_DEBUG_STREAM)
 #define SEND_INFO_STREAM_MSG(msg) SEND_MSG(msg, MSG_TYPE_INFO_STREAM)
 #define SEND_WARNING_STREAM_MSG(msg) SEND_MSG(msg, MSG_TYPE_WARNING_STREAM)
 #define SEND_ERROR_STREAM_MSG(msg) SEND_MSG(msg, MSG_TYPE_ERROR_STREAM)
 
+#define _DYNAMIC_GRAPH_ENTITY_MSG(entity, type)                                \
+  (entity).logger().stream(type, __FILE__ BOOST_PP_STRINGIZE(__LINE__))
+
+#define DYNAMIC_GRAPH_ENTITY_DEBUG(entity)                                     \
+  _DYNAMIC_GRAPH_ENTITY_MSG(entity, MSG_TYPE_DEBUG)
+#define DYNAMIC_GRAPH_ENTITY_INFO(entity)                                      \
+  _DYNAMIC_GRAPH_ENTITY_MSG(entity, MSG_TYPE_INFO)
+#define DYNAMIC_GRAPH_ENTITY_WARNING(entity)                                   \
+  _DYNAMIC_GRAPH_ENTITY_MSG(entity, MSG_TYPE_WARNING)
+#define DYNAMIC_GRAPH_ENTITY_ERROR(entity)                                     \
+  _DYNAMIC_GRAPH_ENTITY_MSG(entity, MSG_TYPE_ERROR)
+
+#define DYNAMIC_GRAPH_ENTITY_DEBUG_STREAM(entity)                              \
+  _DYNAMIC_GRAPH_ENTITY_MSG(entity, MSG_TYPE_DEBUG_STREAM)
+#define DYNAMIC_GRAPH_ENTITY_INFO_STREAM(entity)                               \
+  _DYNAMIC_GRAPH_ENTITY_MSG(entity, MSG_TYPE_INFO_STREAM)
+#define DYNAMIC_GRAPH_ENTITY_WARNING_STREAM(entity)                            \
+  _DYNAMIC_GRAPH_ENTITY_MSG(entity, MSG_TYPE_WARNING_STREAM)
+#define DYNAMIC_GRAPH_ENTITY_ERROR_STREAM(entity)                              \
+  _DYNAMIC_GRAPH_ENTITY_MSG(entity, MSG_TYPE_ERROR_STREAM)
+
+
 template <typename T>
 std::string toString(const T &v, const int precision = 3,
                      const int width = -1) {
@@ -111,11 +139,11 @@ std::string toString(const Eigen::MatrixBase<T> &v, const int precision = 3,
 }
 
 enum LoggerVerbosity {
-  VERBOSITY_ALL,
-  VERBOSITY_INFO_WARNING_ERROR,
-  VERBOSITY_WARNING_ERROR,
-  VERBOSITY_ERROR,
-  VERBOSITY_NONE
+  VERBOSITY_ALL                = MSG_TYPE_DEBUG,
+  VERBOSITY_INFO_WARNING_ERROR = MSG_TYPE_INFO,
+  VERBOSITY_WARNING_ERROR      = MSG_TYPE_WARNING,
+  VERBOSITY_ERROR              = MSG_TYPE_ERROR,
+  VERBOSITY_NONE               = 0
 };
 
 /// \ingroup debug
@@ -139,8 +167,14 @@ enum LoggerVerbosity {
 ///   VERBOSITY_WARNING_ERROR;
 /// entity.setLoggerVerbosityLevel(aLoggerVerbosityLevel);
 /// ...
-/// std::string aMsg=aBaseMsg+" WARNING";
-/// entity.sendMsg(aMsg,dynamicgraph::MSG_TYPE_WARNING, __FILE__,__LINE__);
+/// // using macros
+/// DYNAMIC_GRAPH_ENTITY_WARNING(entity) << "your message\n";
+///
+/// // or the equivalent code without macros:
+/// // Please use '\n' instead of std::endl and flushing will have no effect
+/// entity.logger.stream(dynamicgraph::MSG_TYPE_WARNING,
+///                      __FILE__ BOOST_PP_STRINGIZE(__LINE__))
+///   << your message << '\n';
 ///
 /// \endcode
 ///
@@ -157,13 +191,49 @@ class Logger {
    * to decrement the internal Logger's counter. */
   void countdown();
 
+  /** Check whether next message should be accepted.
+   * \note See Logger::stream to see how to use it.
+   *       This will modify the counter associated to lineId as if it was
+   *       published. It should thus be used in conjunction with Logger::stream.
+   */
+  bool acceptMsg (MsgType m, const std::string& lineId) {
+    if ((m & MSG_TYPE_TYPE_BITS) < m_lv)
+      return false;
+
+    // if print is allowed by current verbosity level
+    if (isStreamMsg(m)) return checkStreamPeriod(lineId);
+    return true;
+  }
+
+  /** The most efficient logging method is
+   * \code
+   *   if (logger.acceptMsg(type, lineId))
+   *     logger.stream() << "my message\n";
+   * \endcode
+   */
+  RTLoggerStream stream() {
+    return ::dynamicgraph::RealTimeLogger::instance().emptyStream();
+  }
+
   /** Print the specified message on standard output if the verbosity level
-   * allows it. The file name and the line number are used to identify
-   * the point where sendMsg is called so that streaming messages are
-   * printed only every streamPrintPeriod iterations.
+   * allows it. The lineId is used to identify the point where sendMsg is
+   * called so that streaming messages are printed only every streamPrintPeriod
+   * iterations.
+   * \param lineId typically __FILE__ ":" BOOST_PP_STRINGIZE(__LINE__)
    */
-  void sendMsg(std::string msg, MsgType type, const char *file = "",
-               int line = 0);
+  RTLoggerStream stream(MsgType type, const std::string& lineId = "") {
+    RealTimeLogger &rtlogger = ::dynamicgraph::RealTimeLogger::instance();
+    if (acceptMsg(type, lineId))
+      return rtlogger.front();
+    return rtlogger.emptyStream();
+  }
+
+  /** \deprecated instead, use
+   *  \code
+   *    stream(type, lineId) << msg << '\n';
+   *  \endcode
+   */
+  void sendMsg(std::string msg, MsgType type, const std::string& lineId = "");
 
   /** Set the sampling time at which the method countdown()
    * is going to be called. */
@@ -193,13 +263,13 @@ class Logger {
   double m_printCountdown;
   /// every time this is < 0 (i.e. every _streamPrintPeriod sec) print stuff
 
+  typedef std::map<std::string, double> StreamCounterMap_t;
   /** Pointer to the dynamic structure which holds
       the collection of streaming messages */
-  std::map<std::string, double> m_stream_msg_counters;
+  StreamCounterMap_t m_stream_msg_counters;
 
-  bool isStreamMsg(MsgType m) {
-    return m == MSG_TYPE_ERROR_STREAM || m == MSG_TYPE_DEBUG_STREAM ||
-           m == MSG_TYPE_INFO_STREAM || m == MSG_TYPE_WARNING_STREAM;
+  inline bool isStreamMsg(MsgType m) {
+    return (m & MSG_TYPE_STREAM_BIT);
   }
 
   bool isDebugMsg(MsgType m) {
@@ -217,6 +287,8 @@ class Logger {
   bool isErrorMsg(MsgType m) {
     return m == MSG_TYPE_ERROR_STREAM || m == MSG_TYPE_ERROR;
   }
+
+  bool checkStreamPeriod (const std::string& lineId);
 };
 
 } // namespace dynamicgraph

src/debug/logger.cpp

@@ -22,8 +22,6 @@
 
 namespace dynamicgraph {
 
-using namespace std;
-
 Logger::Logger(double timeSample, double streamPrintPeriod)
     : m_timeSample(timeSample), m_streamPrintPeriod(streamPrintPeriod),
       m_printCountdown(0.0) {
@@ -41,38 +39,8 @@ void Logger::countdown() {
   m_printCountdown -= m_timeSample;
 }
 
-void Logger::sendMsg(string msg, MsgType type, const char *file, int line) {
-  if (m_lv == VERBOSITY_NONE ||
-      (m_lv == VERBOSITY_ERROR && !isErrorMsg(type)) ||
-      (m_lv == VERBOSITY_WARNING_ERROR &&
-       !(isWarningMsg(type) || isErrorMsg(type))) ||
-      (m_lv == VERBOSITY_INFO_WARNING_ERROR && isDebugMsg(type)))
-    return;
-
-  // if print is allowed by current verbosity level
-  if (isStreamMsg(type)) {
-    // check whether counter already exists
-    std::ostringstream oss;
-    oss << file << line;
-    std::string id(oss.str());
-    map<string, double>::iterator it = m_stream_msg_counters.find(id);
-    if (it == m_stream_msg_counters.end()) {
-      // if counter doesn't exist then add one
-      m_stream_msg_counters.insert(make_pair(id, 0.0));
-      it = m_stream_msg_counters.find(id);
-    }
-
-    // if counter is greater than 0 then decrement it and do not print
-    if (it->second > 0.0) {
-      it->second -= m_timeSample;
-      if (it->second <= 0.0)
-        it->second = m_streamPrintPeriod;
-      else
-        return;
-    } else // otherwise reset counter and print
-      it->second = m_streamPrintPeriod;
-  }
-  dgRTLOG() << msg.c_str() << "\n";
+void Logger::sendMsg(std::string msg, MsgType type, const std::string &lineId) {
+  stream(type, lineId) << msg << '\n';
 }
 
 bool Logger::setTimeSample(double t) {
@@ -92,4 +60,21 @@ bool Logger::setStreamPrintPeriod(double s) {
 double Logger::getTimeSample() { return m_timeSample; }
 
 double Logger::getStreamPrintPeriod() { return m_streamPrintPeriod; }
+
+bool Logger::checkStreamPeriod(const std::string &lineId) {
+  // insert element with value 0 if it does not exist.
+  // otherwise, return a counter to the existing one.
+  std::pair<StreamCounterMap_t::iterator, bool> result =
+      m_stream_msg_counters.insert(std::make_pair(lineId, 0.));
+
+  // if counter is greater than 0 then decrement it and do not print
+  double &counter = result.first->second;
+  if (counter > 0.0) {
+    counter -= m_timeSample;
+    return false;
+  } else // otherwise reset counter and print
+    counter = m_streamPrintPeriod;
+  return true;
+}
+
 } // namespace dynamicgraph

src/dgraph/entity.cpp

@@ -207,7 +207,7 @@ Command *Entity::getNewStyleCommand(const std::string &commandName) {
   return commandMap[commandName];
 }
 
-void Entity::sendMsg(const std::string &msg, MsgType t, const char *file,
-                     int line) {
-  logger_.sendMsg("[" + name + "]" + msg, t, file, line);
+void Entity::sendMsg(const std::string &msg, MsgType t,
+                     const std::string &lineId) {
+  logger_.sendMsg("[" + name + "]" + msg, t, lineId);
 }

tests/entity.cpp

@@ -216,15 +216,16 @@ BOOST_AUTO_TEST_CASE(sendMsg) {
       if (entity.getLoggerVerbosityLevel() != aLoggerVerbosityLevel)
         output << "Mismatch output";
 
-      std::string aBaseMsg = "Auto Test Case";
-      std::string aMsg = aBaseMsg + " DEBUG";
-      entity.sendMsg(aMsg, dynamicgraph::MSG_TYPE_DEBUG, __FILE__, __LINE__);
-      aMsg = aBaseMsg + " INFO";
-      entity.sendMsg(aMsg, dynamicgraph::MSG_TYPE_INFO, __FILE__, __LINE__);
-      aMsg = aBaseMsg + " WARNING";
-      entity.sendMsg(aMsg, dynamicgraph::MSG_TYPE_WARNING, __FILE__, __LINE__);
-      aMsg = aBaseMsg + " DEBUG";
-      entity.sendMsg(aMsg, dynamicgraph::MSG_TYPE_ERROR, __FILE__, __LINE__);
+#define __FILELINE__ __FILE__ BOOST_PP_STRINGIZE(__LINE__)
+      entity.logger().stream(dynamicgraph::MSG_TYPE_DEBUG, __FILELINE__)
+        << "Auto Test Case" << " DEBUG" << '\n';
+      entity.logger().stream(dynamicgraph::MSG_TYPE_INFO, __FILELINE__)
+        << "Auto Test Case" << " INFO" << '\n';
+      entity.logger().stream(dynamicgraph::MSG_TYPE_WARNING, __FILELINE__)
+        << "Auto Test Case" << " WARNING" << '\n';
+      entity.logger().stream(dynamicgraph::MSG_TYPE_ERROR, __FILELINE__)
+        << "Auto Test Case" << " ERROR" << '\n';
+#undef __FILELINE__
     };
   };