Mercurial > hg > orthanc
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;