From 946e807f792725ed99a939335ca9634f4b2df4fe Mon Sep 17 00:00:00 2001 From: Alexey Rybalchenko Date: Wed, 21 Aug 2019 15:46:43 +0200 Subject: [PATCH] Further stream optimizations --- logger/Logger.cxx | 157 +++++++++++++++++--------------------------- logger/Logger.h | 56 +++++----------- test/loggerTest.cxx | 8 +-- 3 files changed, 79 insertions(+), 142 deletions(-) diff --git a/logger/Logger.cxx b/logger/Logger.cxx index 5c0bf21..36c33d0 100644 --- a/logger/Logger.cxx +++ b/logger/Logger.cxx @@ -22,45 +22,19 @@ using VSpec = VerbositySpec; string GetColoredSeverityString(Severity severity) { switch (severity) { - case Severity::nolog: - return "\033[01;39mNOLOG\033[0m"; - break; - case Severity::fatal: - return "\033[01;31mFATAL\033[0m"; - break; - case Severity::error: - return "\033[01;39mERROR\033[0m"; - break; - case Severity::warn: - return "\033[01;33mWARN\033[0m"; - break; - case Severity::state: - return "\033[01;35mSTATE\033[0m"; - break; - case Severity::info: - return "\033[01;32mINFO\033[0m"; - break; - case Severity::debug: - return "\033[01;34mDEBUG\033[0m"; - break; - case Severity::debug1: - return "\033[01;34mDEBUG1\033[0m"; - break; - case Severity::debug2: - return "\033[01;34mDEBUG2\033[0m"; - break; - case Severity::debug3: - return "\033[01;34mDEBUG3\033[0m"; - break; - case Severity::debug4: - return "\033[01;34mDEBUG4\033[0m"; - break; - case Severity::trace: - return "\033[01;36mTRACE\033[0m"; - break; - default: - return "UNKNOWN"; - break; + case Severity::nolog: return "\033[01;39mNOLOG\033[0m"; break; + case Severity::fatal: return "\033[01;31mFATAL\033[0m"; break; + case Severity::error: return "\033[01;31mERROR\033[0m"; break; + case Severity::warn: return "\033[01;33mWARN\033[0m"; break; + case Severity::state: return "\033[01;35mSTATE\033[0m"; break; + case Severity::info: return "\033[01;32mINFO\033[0m"; break; + case Severity::debug: return "\033[01;34mDEBUG\033[0m"; break; + case Severity::debug1: return "\033[01;34mDEBUG1\033[0m"; break; + case Severity::debug2: return "\033[01;34mDEBUG2\033[0m"; break; + case Severity::debug3: return "\033[01;34mDEBUG3\033[0m"; break; + case Severity::debug4: return "\033[01;34mDEBUG4\033[0m"; break; + case Severity::trace: return "\033[01;36mTRACE\033[0m"; break; + default: return "UNKNOWN"; break; } } @@ -86,20 +60,20 @@ const string Logger::fProcessName = "?"; const unordered_map Logger::fVerbosityMap = { - { "veryhigh", Verbosity::veryhigh }, - { "high", Verbosity::high }, - { "medium", Verbosity::medium }, - { "low", Verbosity::low }, - { "verylow", Verbosity::verylow }, - { "VERYHIGH", Verbosity::veryhigh }, - { "HIGH", Verbosity::high }, - { "MEDIUM", Verbosity::medium }, - { "LOW", Verbosity::low }, - { "VERYLOW", Verbosity::verylow }, - { "user1", Verbosity::user1 }, - { "user2", Verbosity::user2 }, - { "user3", Verbosity::user3 }, - { "user4", Verbosity::user4 } + { "veryhigh", Verbosity::veryhigh }, + { "high", Verbosity::high }, + { "medium", Verbosity::medium }, + { "low", Verbosity::low }, + { "verylow", Verbosity::verylow }, + { "VERYHIGH", Verbosity::veryhigh }, + { "HIGH", Verbosity::high }, + { "MEDIUM", Verbosity::medium }, + { "LOW", Verbosity::low }, + { "VERYLOW", Verbosity::verylow }, + { "user1", Verbosity::user1 }, + { "user2", Verbosity::user2 }, + { "user3", Verbosity::user3 }, + { "user4", Verbosity::user4 } }; const unordered_map Logger::fSeverityMap = @@ -176,20 +150,6 @@ map Logger::fVerbosities = { Verbosity::user4, VSpec::Make(VSpec::Info::severity) } }; -Logger::Logger(Severity severity, const string& file, const string& line, const string& func) - : Logger(severity, fVerbosity, file, line, func) -{} - -void Logger::FillTimeInfos() -{ - if (!fTimeCalculated) { - chrono::time_point now = chrono::system_clock::now(); - fInfos.timestamp = chrono::system_clock::to_time_t(now); - fInfos.us = chrono::duration_cast(now.time_since_epoch()) % 1000000; - fTimeCalculated = true; - } -} - Logger::Logger(Severity severity, Verbosity verbosity, const string& file, const string& line, const string& func) : fTimeCalculated(false) { @@ -211,27 +171,27 @@ Logger::Logger(Severity severity, Verbosity verbosity, const string& file, const for (const auto info : spec.fInfos) { switch (info) { case VSpec::Info::process_name: - fBWOut << fmt::format("[{}]", fInfos.process_name); + fmt::format_to(fBWPrefix, "[{}]", fInfos.process_name); break; case VSpec::Info::timestamp_us: FillTimeInfos(); - fBWOut << fmt::format("[{:%H:%M:%S}.{:06}]", fmt::localtime(fInfos.timestamp), fInfos.us.count()); + fmt::format_to(fBWPrefix, "[{:%H:%M:%S}.{:06}]", fmt::localtime(fInfos.timestamp), fInfos.us.count()); break; case VSpec::Info::timestamp_s: FillTimeInfos(); - fBWOut << fmt::format("[{:%H:%M:%S}]", fmt::localtime(fInfos.timestamp)); + fmt::format_to(fBWPrefix, "[{:%H:%M:%S}]", fmt::localtime(fInfos.timestamp)); break; case VSpec::Info::severity: - fBWOut << fmt::format("[{}]", fInfos.severity_name); + fmt::format_to(fBWPrefix, "[{}]", fInfos.severity_name); break; case VSpec::Info::file_line_function: - fBWOut << fmt::format("[{}:{}:{}]", fInfos.file, fInfos.line, fInfos.func); + fmt::format_to(fBWPrefix, "[{}:{}:{}]", fInfos.file, fInfos.line, fInfos.func); break; case VSpec::Info::file_line: - fBWOut << fmt::format("[{}:{}]", fInfos.file, fInfos.line); + fmt::format_to(fBWPrefix, "[{}:{}]", fInfos.file, fInfos.line); break; case VSpec::Info::file: - fBWOut << fmt::format("[{}]", fInfos.file); + fmt::format_to(fBWPrefix, "[{}]", fInfos.file); break; default: break; @@ -239,7 +199,7 @@ Logger::Logger(Severity severity, Verbosity verbosity, const string& file, const } if (spec.fSize > 0) { - fBWOut << " "; + fmt::format_to(fBWPrefix, " "); } } @@ -247,27 +207,27 @@ Logger::Logger(Severity severity, Verbosity verbosity, const string& file, const for (const auto info : spec.fInfos) { switch (info) { case VSpec::Info::process_name: - fColorOut << fmt::format("[{}]", ColorOut(Color::fgBlue, fInfos.process_name)); + fmt::format_to(fColorPrefix, "[{}]", ColorOut(Color::fgBlue, fInfos.process_name)); break; case VSpec::Info::timestamp_us: FillTimeInfos(); - fColorOut << fmt::format("[{}{:%H:%M:%S}.{:06}{}]", startColor(Color::fgCyan), fmt::localtime(fInfos.timestamp), fInfos.us.count(), endColor()); + fmt::format_to(fColorPrefix, "[{}{:%H:%M:%S}.{:06}{}]", startColor(Color::fgCyan), fmt::localtime(fInfos.timestamp), fInfos.us.count(), endColor()); break; case VSpec::Info::timestamp_s: FillTimeInfos(); - fColorOut << fmt::format("[{}{:%H:%M:%S}{}]", startColor(Color::fgCyan), fmt::localtime(fInfos.timestamp), endColor()); + fmt::format_to(fColorPrefix, "[{}{:%H:%M:%S}{}]", startColor(Color::fgCyan), fmt::localtime(fInfos.timestamp), endColor()); break; case VSpec::Info::severity: - fColorOut << fmt::format("[{}]", GetColoredSeverityString(fInfos.severity)); + fmt::format_to(fColorPrefix, "[{}]", GetColoredSeverityString(fInfos.severity)); break; case VSpec::Info::file_line_function: - fColorOut << fmt::format("[{}:{}:{}]", ColorOut(Color::fgBlue, fInfos.file), ColorOut(Color::fgYellow, fInfos.line), ColorOut(Color::fgBlue, fInfos.func)); + fmt::format_to(fColorPrefix, "[{}:{}:{}]", ColorOut(Color::fgBlue, fInfos.file), ColorOut(Color::fgYellow, fInfos.line), ColorOut(Color::fgBlue, fInfos.func)); break; case VSpec::Info::file_line: - fColorOut << fmt::format("[{}:{}]", ColorOut(Color::fgBlue, fInfos.file), ColorOut(Color::fgYellow, fInfos.line)); + fmt::format_to(fColorPrefix, "[{}:{}]", ColorOut(Color::fgBlue, fInfos.file), ColorOut(Color::fgYellow, fInfos.line)); break; case VSpec::Info::file: - fColorOut << fmt::format("[{}]", ColorOut(Color::fgBlue, fInfos.file)); + fmt::format_to(fColorPrefix, "[{}]", ColorOut(Color::fgBlue, fInfos.file)); break; default: break; @@ -275,14 +235,13 @@ Logger::Logger(Severity severity, Verbosity verbosity, const string& file, const } if (spec.fSize > 0) { - fColorOut << " "; + fmt::format_to(fColorPrefix, " "); } } if (!fCustomSinks.empty()) { FillTimeInfos(); } - } } @@ -300,23 +259,21 @@ Logger::~Logger() noexcept(false) } } - fContent << "\n"; // "\n" + flush instead of endl makes output thread safe. - - fBWOut << fContent.str(); + // "\n" + flush instead of endl makes output thread safe. if (LoggingToConsole()) { if (fColored) { - fColorOut << fContent.str(); - cout << fColorOut.str() << flush; + fmt::print("{}{}\n", to_string(fColorPrefix), fContent.str()); } else { - cout << fBWOut.str() << flush; + fmt::print("{}{}\n", to_string(fBWPrefix), fContent.str()); } + cout << flush; } if (LoggingToFile()) { lock_guard lock(fMtx); if (fFileStream.is_open()) { - fFileStream << fBWOut.str() << flush; + fFileStream << fmt::format("{}{}\n", to_string(fBWPrefix), fContent.str()) << flush; } } @@ -386,7 +343,7 @@ void Logger::SetCustomSeverity(const string& key, const string& severityStr) } } -auto Logger::CycleConsoleSeverityUp() -> void +void Logger::CycleConsoleSeverityUp() { int current = static_cast(fConsoleSeverity); if (current == static_cast(fSeverityNames.size()) - 1) { @@ -405,7 +362,7 @@ auto Logger::CycleConsoleSeverityUp() -> void cout << ss.str() << flush; } -auto Logger::CycleConsoleSeverityDown() -> void +void Logger::CycleConsoleSeverityDown() { int current = static_cast(fConsoleSeverity); if (current == 0) { @@ -424,7 +381,7 @@ auto Logger::CycleConsoleSeverityDown() -> void cout << ss.str() << flush; } -auto Logger::CycleVerbosityUp() -> void +void Logger::CycleVerbosityUp() { int current = static_cast(fVerbosity); if (current == static_cast(fVerbosityNames.size() - 1)) { @@ -443,7 +400,7 @@ auto Logger::CycleVerbosityUp() -> void cout << ss.str() << flush; } -auto Logger::CycleVerbosityDown() -> void +void Logger::CycleVerbosityDown() { int current = static_cast(fVerbosity); if (current == 0) { @@ -654,4 +611,14 @@ Logger& Logger::operator<<(ostream& (*manip) (ostream&)) return *this; } +void Logger::FillTimeInfos() +{ + if (!fTimeCalculated) { + chrono::time_point now = chrono::system_clock::now(); + fInfos.timestamp = chrono::system_clock::to_time_t(now); + fInfos.us = chrono::duration_cast(now.time_since_epoch()) % 1000000; + fTimeCalculated = true; + } +} + } // namespace fair diff --git a/logger/Logger.h b/logger/Logger.h index 249eaaf..85935b1 100644 --- a/logger/Logger.h +++ b/logger/Logger.h @@ -1,5 +1,5 @@ /******************************************************************************** - * Copyright (C) 2014 GSI Helmholtzzentrum fuer Schwerionenforschung GmbH * + * Copyright (C) 2014-2019 GSI Helmholtzzentrum fuer Schwerionenforschung GmbH * * * * This software is distributed under the terms of the * * GNU Lesser General Public Licence (LGPL) version 3, * @@ -142,12 +142,10 @@ struct VerbositySpec ++i; } - spec.fSize = i; - return Make(spec, i, options ...); } - static VerbositySpec Make(VerbositySpec spec, int) { return spec; } + static VerbositySpec Make(VerbositySpec spec, int i) { spec.fSize = i; return spec; } }; // non-std exception to avoid undesirable catches - fatal should exit in a way we want. @@ -178,8 +176,10 @@ struct LogMetaData class Logger { public: - Logger(Severity severity, const std::string& file, const std::string& line, const std::string& func); Logger(Severity severity, Verbosity verbosity, const std::string& file, const std::string& line, const std::string& func); + Logger(Severity severity, const std::string& file, const std::string& line, const std::string& func) + : Logger(severity, fVerbosity, file, line, func) + {} virtual ~Logger() noexcept(false); Logger& Log() { return *this; } @@ -232,35 +232,9 @@ class Logger bgWhite = 107 }; - static std::string startColor(Color color) - { - std::ostringstream os; - os << "\033[01;" << static_cast(color) << "m"; - return os.str(); - } - - static std::string endColor() - { - return "\033[0m"; - } - - class ColorOut - { - public: - ColorOut(Color color, const std::string& str) - : fColor(color) - , fStr(str) - {} - - friend std::ostream& operator<<(std::ostream& os, const ColorOut& w) - { - return os << "\033[01;" << static_cast(w.fColor) << "m" << w.fStr << "\033[0m"; - } - - private: - Color fColor; - const std::string& fStr; - }; + static std::string startColor(Color color) { return fmt::format("\033[01;{}m", static_cast(color)); } + static std::string endColor() { return "\033[0m"; } + static std::string ColorOut(Color c, const std::string& s) { return fmt::format("\033[01;{}m{}\033[0m", static_cast(c), s); } static void SetConsoleSeverity(const Severity severity); static void SetConsoleSeverity(const std::string& severityStr); @@ -343,8 +317,8 @@ class Logger LogMetaData fInfos; std::ostringstream fContent; - std::ostringstream fColorOut; - std::ostringstream fBWOut; + fmt::memory_buffer fColorPrefix; + fmt::memory_buffer fBWPrefix; static const std::string fProcessName; static bool fColored; static std::fstream fFileStream; @@ -377,20 +351,20 @@ class Logger #define CONVERTTOSTRING(s) IMP_CONVERTTOSTRING(s) #ifdef FAIRLOGGER_USE_BOOST_PRETTY_FUNCTION -#define MESSAGE_ORIGIN __FILE__, CONVERTTOSTRING(__LINE__), static_cast(BOOST_CURRENT_FUNCTION) +#define MSG_ORIGIN __FILE__, CONVERTTOSTRING(__LINE__), static_cast(BOOST_CURRENT_FUNCTION) #else -#define MESSAGE_ORIGIN __FILE__, CONVERTTOSTRING(__LINE__), static_cast(__FUNCTION__) +#define MSG_ORIGIN __FILE__, CONVERTTOSTRING(__LINE__), static_cast(__FUNCTION__) #endif // Log line if the provided severity is below or equals the configured one #define LOG(severity) \ for (bool fairLOggerunLikelyvariable = false; fair::Logger::Logging(fair::Severity::severity) && !fairLOggerunLikelyvariable; fairLOggerunLikelyvariable = true) \ - fair::Logger(fair::Severity::severity, MESSAGE_ORIGIN) + fair::Logger(fair::Severity::severity, MSG_ORIGIN) // Log line with the given verbosity if the provided severity is below or equals the configured one #define LOGV(severity, verbosity) \ for (bool fairLOggerunLikelyvariable = false; fair::Logger::Logging(fair::Severity::severity) && !fairLOggerunLikelyvariable; fairLOggerunLikelyvariable = true) \ - fair::Logger(fair::Severity::severity, fair::Verbosity::verbosity, MESSAGE_ORIGIN) + fair::Logger(fair::Severity::severity, fair::Verbosity::verbosity, MSG_ORIGIN) // Log with fmt- or printf-like formatting #define LOGF(severity, ...) LOG(severity) << fmt::format(__VA_ARGS__) @@ -399,7 +373,7 @@ class Logger // Log an empty line #define LOGN(severity) \ for (bool fairLOggerunLikelyvariable = false; fair::Logger::Logging(fair::Severity::severity) && !fairLOggerunLikelyvariable; fairLOggerunLikelyvariable = true) \ - fair::Logger(fair::Severity::severity, fair::Verbosity::verylow, MESSAGE_ORIGIN).LogEmptyLine() + fair::Logger(fair::Severity::severity, fair::Verbosity::verylow, MSG_ORIGIN).LogEmptyLine() // Log with custom file, line, function #define LOGD(severity, file, line, f) \ diff --git a/test/loggerTest.cxx b/test/loggerTest.cxx index 17e7e9d..16cd33a 100644 --- a/test/loggerTest.cxx +++ b/test/loggerTest.cxx @@ -5,10 +5,6 @@ * GNU Lesser General Public Licence (LGPL) version 3, * * copied verbatim in the file "LICENSE" * ********************************************************************************/ - -// WARNING : pragma commands to hide boost warning -// TODO : remove these pragma commands when boost will fix this issue in future release - #include #include @@ -134,8 +130,8 @@ int main() cout << "cout: is logging fatal: " << fair::Logger::Logging(Severity::fatal) << endl; cout << "cout: is logging nolog: " << fair::Logger::Logging(Severity::nolog) << endl; - for (int i = 0; i < 100000; ++i) { - silentlyPrintAllVerbositiesWithSeverity(Severity::trace); + for (int i = 0; i < 1000000; ++i) { + silentlyPrintAllVerbositiesWithSeverity(Severity::nolog); } cout << endl; cout << "cout: setting severity to 'trace' and verbosity to 'veryhigh'" << endl;