changeset 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 d6618f63e50d
files Core/Enumerations.cpp Core/Enumerations.h Core/Logging.cpp Core/Logging.h
diffstat 4 files changed, 194 insertions(+), 61 deletions(-) [+]
line wrap: on
line diff
--- a/Core/Enumerations.cpp	Wed Aug 05 10:07:53 2015 +0200
+++ b/Core/Enumerations.cpp	Thu Aug 06 18:19:32 2015 +0200
@@ -36,6 +36,8 @@
 #include "OrthancException.h"
 #include "Toolbox.h"
 
+#include <string.h>
+
 namespace Orthanc
 {
   const char* EnumerationToString(HttpMethod method)
@@ -368,6 +370,28 @@
   }
 
 
+  const char* EnumerationToString(LogLevel level)
+  {
+    switch (level)
+    {
+      case LogLevel_Error:
+        return "ERROR";
+
+      case LogLevel_Warning:
+        return "WARNING";
+
+      case LogLevel_Info:
+        return "INFO";
+
+      case LogLevel_Trace:
+        return "TRACE";
+
+      default:
+        throw OrthancException(ErrorCode_ParameterOutOfRange);
+    }
+  }
+
+
   Encoding StringToEncoding(const char* encoding)
   {
     std::string s(encoding);
@@ -493,6 +517,31 @@
   }
 
 
+  LogLevel StringToLogLevel(const char *level)
+  {
+    if (strcmp(level, "ERROR") == 0)
+    {
+      return LogLevel_Error;
+    }
+    else if (strcmp(level, "WARNING") == 0)
+    {
+      return LogLevel_Warning;
+    }
+    else if (strcmp(level, "INFO") == 0)
+    {
+      return LogLevel_Info;
+    }
+    else if (strcmp(level, "TRACE") == 0)
+    {
+      return LogLevel_Trace;
+    }
+    else 
+    {
+      throw OrthancException(ErrorCode_InternalError);
+    }
+  }
+
+
   unsigned int GetBytesPerPixel(PixelFormat format)
   {
     switch (format)
--- a/Core/Enumerations.h	Wed Aug 05 10:07:53 2015 +0200
+++ b/Core/Enumerations.h	Thu Aug 06 18:19:32 2015 +0200
@@ -76,6 +76,14 @@
     ErrorCode_Plugin
   };
 
+  enum LogLevel
+  {
+    LogLevel_Error,
+    LogLevel_Warning,
+    LogLevel_Info,
+    LogLevel_Trace
+  };
+
 
   /**
    * {summary}{The memory layout of the pixels (resp. voxels) of a 2D (resp. 3D) image.}
@@ -330,12 +338,16 @@
 
   const char* EnumerationToString(PhotometricInterpretation photometric);
 
+  const char* EnumerationToString(LogLevel level);
+
   Encoding StringToEncoding(const char* encoding);
 
   ResourceType StringToResourceType(const char* type);
 
   ImageFormat StringToImageFormat(const char* format);
 
+  LogLevel StringToLogLevel(const char* format);
+
   unsigned int GetBytesPerPixel(PixelFormat format);
 
   bool GetDicomEncoding(Encoding& encoding,
--- 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;
     }
   }
 }
--- a/Core/Logging.h	Wed Aug 05 10:07:53 2015 +0200
+++ b/Core/Logging.h	Thu Aug 06 18:19:32 2015 +0200
@@ -35,12 +35,12 @@
 #if ORTHANC_ENABLE_LOGGING == 1
 
 #if ORTHANC_ENABLE_GOOGLE_LOG == 1
-#  include <stdlib.h>  // This fixes a problem in glog for recent releases of MinGW
+#  include <stdlib.h>  // Including this fixes a problem in glog for recent releases of MinGW
 #  include <glog/logging.h>
 #else
 #  include <iostream>
 #  include <boost/thread/mutex.hpp>
-#  define LOG(level)  ::Orthanc::Logging::InternalLogger(#level, __FILE__, __LINE__)
+#  define LOG(level)  ::Orthanc::Logging::InternalLogger(#level,  __FILE__, __LINE__)
 #  define VLOG(level) ::Orthanc::Logging::InternalLogger("TRACE", __FILE__, __LINE__)
 #endif
 
@@ -59,13 +59,22 @@
 
     void SetTargetFolder(const std::string& path);
 
+#if ORTHANC_ENABLE_GOOGLE_LOG != 1
+    struct NullStream : public std::ostream 
+    {
+      NullStream() : 
+        std::ios(0), 
+        std::ostream(0)
+      {
+      }
+    };
 
-#if ORTHANC_ENABLE_GOOGLE_LOG != 1
     class InternalLogger
     {
     private:
-      boost::mutex::scoped_lock  lock_;
-      std::ostream*              stream_;
+      boost::mutex::scoped_lock lock_;
+      NullStream                null_;
+      std::ostream*             stream_;
 
     public:
       InternalLogger(const char* level,
@@ -80,7 +89,7 @@
         *stream_ << "\n";
 #endif
       }
-
+      
       std::ostream& operator<< (const std::string& message)
       {
         return (*stream_) << message;