diff Core/Logging.cpp @ 1495:fbe40117eb21

improve the performance of the internal logger
author Sebastien Jodogne <s.jodogne@gmail.com>
date Thu, 06 Aug 2015 18:19:32 +0200
parents a13581480b1f
children 46b2794042d6
line wrap: on
line diff
--- a/Core/Logging.cpp	Wed Aug 05 10:07:53 2015 +0200
+++ b/Core/Logging.cpp	Thu Aug 06 18:19:32 2015 +0200
@@ -94,6 +94,7 @@
  *********************************************************/
 
 #include "OrthancException.h"
+#include "Enumerations.h"
 #include "Toolbox.h"
 
 #include <fstream>
@@ -109,27 +110,36 @@
 
 namespace
 {
-  struct NullStream : public std::ostream 
+  struct LoggingState
   {
-    NullStream() : std::ios(0), std::ostream(0)
+    bool infoEnabled_;
+    bool traceEnabled_;
+
+    std::ostream* error_;
+    std::ostream* warning_;
+    std::ostream* info_;
+
+    std::auto_ptr<std::ofstream> errorFile_;
+    std::auto_ptr<std::ofstream> warningFile_;
+    std::auto_ptr<std::ofstream> infoFile_;
+
+    LoggingState() : 
+      infoEnabled_(false),
+      traceEnabled_(false),
+      error_(&std::cerr),
+      warning_(&std::cerr),
+      info_(&std::cerr)
     {
     }
   };
 }
 
 
-static boost::mutex  mutex_;
-static bool infoEnabled_ = false;
-static bool traceEnabled_ = false;
 
-static std::ostream* error_ = &std::cerr;
-static std::ostream* warning_ = &std::cerr;
-static std::ostream* info_ = &std::cerr;
-static NullStream null_;
+static std::auto_ptr<LoggingState> loggingState_;
+static boost::mutex  loggingMutex_;
 
-static std::auto_ptr<std::ofstream> errorFile_;
-static std::auto_ptr<std::ofstream> warningFile_;
-static std::auto_ptr<std::ofstream> infoFile_;
+
 
 namespace Orthanc
 {
@@ -201,77 +211,76 @@
 
     void Initialize()
     {
-      infoEnabled_ = false;
-      traceEnabled_ = false;
+      boost::mutex::scoped_lock lock(loggingMutex_);
+      loggingState_.reset(new LoggingState);
     }
 
     void Finalize()
     {
-      errorFile_.reset(NULL);
-      warningFile_.reset(NULL);
-      infoFile_.reset(NULL);
+      boost::mutex::scoped_lock lock(loggingMutex_);
+      loggingState_.reset(NULL);
     }
 
     void EnableInfoLevel(bool enabled)
     {
-      boost::mutex::scoped_lock lock(mutex_);
-      infoEnabled_ = enabled;
+      boost::mutex::scoped_lock lock(loggingMutex_);
+      assert(loggingState_.get() != NULL);
+
+      loggingState_->infoEnabled_ = enabled;
     }
 
     void EnableTraceLevel(bool enabled)
     {
-      boost::mutex::scoped_lock lock(mutex_);
-      traceEnabled_ = enabled;
+      boost::mutex::scoped_lock lock(loggingMutex_);
+      assert(loggingState_.get() != NULL);
+
+      loggingState_->traceEnabled_ = enabled;
       
       if (enabled)
       {
         // Also enable the "INFO" level when trace-level debugging is enabled
-        infoEnabled_ = true;
+        loggingState_->infoEnabled_ = true;
       }
     }
 
     void SetTargetFolder(const std::string& path)
     {
-      boost::mutex::scoped_lock lock(mutex_);
-      PrepareLogFile(error_, errorFile_, "ERROR", path);
-      PrepareLogFile(warning_, warningFile_, "WARNING", path);
-      PrepareLogFile(info_, infoFile_, "INFO", path);
+      boost::mutex::scoped_lock lock(loggingMutex_);
+      assert(loggingState_.get() != NULL);
+
+      PrepareLogFile(loggingState_->error_,   loggingState_->errorFile_,   "ERROR", path);
+      PrepareLogFile(loggingState_->warning_, loggingState_->warningFile_, "WARNING", path);
+      PrepareLogFile(loggingState_->info_,    loggingState_->infoFile_,    "INFO", path);
     }
 
     InternalLogger::InternalLogger(const char* level,
                                    const char* file,
                                    int line) : 
-      lock_(mutex_)
+      lock_(loggingMutex_), 
+      stream_(&null_)  // By default, logging to "/dev/null" is simulated
     {
-      char c;
-
-      if (strcmp(level, "ERROR") == 0)
-      {
-        stream_ = error_;
-        c = 'E';
-      }
-      else if (strcmp(level, "WARNING") == 0)
+      if (loggingState_.get() == NULL)
       {
-        stream_ = warning_;
-        c = 'W';
-      }
-      else if (strcmp(level, "INFO") == 0)
-      {
-        stream_ = infoEnabled_ ? info_ : &null_;
-        c = 'I';
-      }
-      else if (strcmp(level, "TRACE") == 0)
-      {
-        stream_ = traceEnabled_ ? info_ : &null_;
-        c = 'T';
-      }
-      else 
-      {
-        // Unknown logging level
-        throw OrthancException(ErrorCode_InternalError);
+        fprintf(stderr, "ERROR: Trying to log a message after the finalization of the logging engine\n");
+        return;
       }
 
-      if (stream_ != &null_)
+      LogLevel l = StringToLogLevel(level);
+      
+      if ((l == LogLevel_Info  && !loggingState_->infoEnabled_) ||
+          (l == LogLevel_Trace && !loggingState_->traceEnabled_))
+      {
+        // This logging level is disabled, directly exit and unlock
+        // the mutex to speed-up things. The stream is set to "/dev/null"
+        lock_.unlock();
+        return;
+      }
+
+      // Compute the header of the line, temporary release the lock as
+      // this is a time-consuming operation
+      lock_.unlock();
+      std::string header;
+
       {
         boost::filesystem::path path(file);
         boost::posix_time::ptime now = boost::posix_time::microsec_clock::local_time();
@@ -299,7 +308,8 @@
          **/
 
         char date[32];
-        sprintf(date, "%c%02d%02d %02d:%02d:%02d.%06d ", c, 
+        sprintf(date, "%c%02d%02d %02d:%02d:%02d.%06d ",
+                level[0],
                 now.date().month().as_number(),
                 now.date().day().as_number(),
                 duration.hours(),
@@ -307,8 +317,61 @@
                 duration.seconds(),
                 static_cast<int>(duration.fractional_seconds()));
 
-        *stream_ << date << path.filename().string() << ":" << line << "] ";
+        header = std::string(date) + path.filename().string() + ":" + boost::lexical_cast<std::string>(line) + "] ";
+      }
+
+
+      // The header is computed, we now re-lock the mutex to access
+      // the stream objects. Pay attention that "loggingState_",
+      // "infoEnabled_" or "traceEnabled_" might have changed while
+      // the mutex was unlocked.
+      lock_.lock();
+
+      if (loggingState_.get() == NULL)
+      {
+        fprintf(stderr, "ERROR: Trying to log a message after the finalization of the logging engine\n");
+        return;
       }
+
+      switch (l)
+      {
+        case LogLevel_Error:
+          stream_ = loggingState_->error_;
+          break;
+
+        case LogLevel_Warning:
+          stream_ = loggingState_->warning_;
+          break;
+
+        case LogLevel_Info:
+          if (loggingState_->infoEnabled_)
+          {
+            stream_ = loggingState_->info_;
+          }
+
+          break;
+
+        case LogLevel_Trace:
+          if (loggingState_->traceEnabled_)
+          {
+            stream_ = loggingState_->info_;
+          }
+
+          break;
+
+        default:
+          throw OrthancException(ErrorCode_InternalError);
+      }
+
+      if (stream_ == &null_)
+      {
+        // The logging is disabled for this level. The stream is the
+        // "null_" member of this object, so we can release the global
+        // mutex.
+        lock_.unlock();
+      }
+
+      (*stream_) << header;
     }
   }
 }