Further stream optimizations

This commit is contained in:
Alexey Rybalchenko 2019-08-21 15:46:43 +02:00
parent ea7ad58d42
commit 946e807f79
3 changed files with 79 additions and 142 deletions

View File

@ -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<string, Verbosity> 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<string, Severity> Logger::fSeverityMap =
@ -176,20 +150,6 @@ map<Verbosity, VSpec> 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<chrono::system_clock> now = chrono::system_clock::now();
fInfos.timestamp = chrono::system_clock::to_time_t(now);
fInfos.us = chrono::duration_cast<chrono::microseconds>(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<mutex> 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<int>(fConsoleSeverity);
if (current == static_cast<int>(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<int>(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<int>(fVerbosity);
if (current == static_cast<int>(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<int>(fVerbosity);
if (current == 0) {
@ -654,4 +611,14 @@ Logger& Logger::operator<<(ostream& (*manip) (ostream&))
return *this;
}
void Logger::FillTimeInfos()
{
if (!fTimeCalculated) {
chrono::time_point<chrono::system_clock> now = chrono::system_clock::now();
fInfos.timestamp = chrono::system_clock::to_time_t(now);
fInfos.us = chrono::duration_cast<chrono::microseconds>(now.time_since_epoch()) % 1000000;
fTimeCalculated = true;
}
}
} // namespace fair

View File

@ -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<int>(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<int>(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<int>(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<int>(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<const char*>(BOOST_CURRENT_FUNCTION)
#define MSG_ORIGIN __FILE__, CONVERTTOSTRING(__LINE__), static_cast<const char*>(BOOST_CURRENT_FUNCTION)
#else
#define MESSAGE_ORIGIN __FILE__, CONVERTTOSTRING(__LINE__), static_cast<const char*>(__FUNCTION__)
#define MSG_ORIGIN __FILE__, CONVERTTOSTRING(__LINE__), static_cast<const char*>(__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) \

View File

@ -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 <Logger.h>
#include <iostream>
@ -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;