Skip to content

Commit

Permalink
Logging: improve performance by not generating message unnecessarily
Browse files Browse the repository at this point in the history 
Avoid building an ostringstream, writing all logged values to it and converting
it to a string, for log messages that no logger is currently interested in
(e.g. TRACE logging most of the time). Cache this "lowest common log level" and
update it when any logger is reconfigured, added or removed.
  • Loading branch information
@qris
qris committed Feb 18, 2018
1 parent 745f6b5 commit adc054b
Show file tree
Hide file tree
Showing 3 changed files with 149 additions and 21 deletions.
51 changes: 48 additions & 3 deletions lib/common/Logging.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -44,10 +44,13 @@ std::vector<Logger*> Logging::sLoggers;
std::string Logging::sContext;
Console* Logging::spConsole = NULL;
Syslog* Logging::spSyslog = NULL;
// initialise before sGlobalLogging, which adds Console and Syslog loggers and thus checks
// sLogLevelOverrideByFileGuards:
std::vector<LogLevelOverrideByFileGuard> Logging::sLogLevelOverrideByFileGuards;
Logging Logging::sGlobalLogging; // automatic initialisation
std::string Logging::sProgramName;
Log::Level Logging::sLowestCommonLevel = Log::EVERYTHING;
const Log::Category Logging::UNCATEGORISED("Uncategorised");
std::vector<LogLevelOverrideByFileGuard> Logging::sLogLevelOverrideByFileGuards;

HideSpecificExceptionGuard::SuppressedExceptions_t
HideSpecificExceptionGuard::sSuppressedExceptions;
Expand Down Expand Up @@ -124,6 +127,7 @@ void Logging::Add(Logger* pNewLogger)
}

sLoggers.insert(sLoggers.begin(), pNewLogger);
UpdateLowestCommonLevel();
}

void Logging::Remove(Logger* pOldLogger)
Expand All @@ -137,12 +141,45 @@ void Logging::Remove(Logger* pOldLogger)
return;
}
}
UpdateLowestCommonLevel();
}

void Logging::Log(Log::Level level, const std::string& file, int line,
void Logging::UpdateLowestCommonLevel()
{
sLowestCommonLevel = Log::NOTHING;

for (std::vector<Logger*>::iterator i = sLoggers.begin();
i != sLoggers.end(); i++)
{
Log::Level new_level = (*i)->GetLowestLevel();
// Higher levels -> more logging
if(sLowestCommonLevel < new_level)
{
sLowestCommonLevel = new_level;
}
}

for (std::vector<LogLevelOverrideByFileGuard>::const_iterator
i = sLogLevelOverrideByFileGuards.begin();
i != sLogLevelOverrideByFileGuards.end(); i++)
{
Log::Level new_level = i->GetNewLevel();
if(sLowestCommonLevel < new_level)
{
sLowestCommonLevel = new_level;
}
}
}

bool Logging::Log(Log::Level level, const std::string& file, int line,
const std::string& function, const Log::Category& category,
const std::string& message)
{
if(level > Logging::GetLowestCommonLevel())
{
return false;
}

std::string newMessage;

if (sContextSet)
Expand All @@ -159,9 +196,11 @@ void Logging::Log(Log::Level level, const std::string& file, int line,
newMessage);
if (!result)
{
return;
return false;
}
}

return true; // message was not suppressed
}

void Logging::LogToSyslog(Log::Level level, const std::string& rFile, int line,
Expand Down Expand Up @@ -251,6 +290,12 @@ bool Logger::IsEnabled(Log::Level level)
return (int)mCurrentLevel >= (int)level;
}

void Logger::Filter(Log::Level level)
{
mCurrentLevel = level;
Logging::UpdateLowestCommonLevel();
}

bool Console::sShowTime = false;
bool Console::sShowTimeMicros = false;
bool Console::sShowTag = false;
Expand Down
63 changes: 45 additions & 18 deletions lib/common/Logging.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,26 +24,38 @@

#define BOX_LOG(level, stuff) \
{ \
std::ostringstream _box_log_line; \
_box_log_line << stuff; \
Logging::Log(level, __FILE__, __LINE__, __FUNCTION__, \
Logging::UNCATEGORISED, _box_log_line.str()); \
if(level <= Logging::GetLowestCommonLevel()) \
{ \
std::ostringstream _box_log_line; \
_box_log_line << stuff; \
Logging::Log(level, __FILE__, __LINE__, __FUNCTION__, \
Logging::UNCATEGORISED, _box_log_line.str()); \
} \
}

// Higher levels -> more logging. So only build the log message if the level if the level is
// lower or equal to the level that any logger is interested in.

#define BOX_LOG_CATEGORY(level, category, stuff) \
{ \
std::ostringstream _box_log_line; \
_box_log_line << stuff; \
Logging::Log(level, __FILE__, __LINE__, __FUNCTION__, \
category, _box_log_line.str()); \
if(level <= Logging::GetLowestCommonLevel()) \
{ \
std::ostringstream _box_log_line; \
_box_log_line << stuff; \
Logging::Log(level, __FILE__, __LINE__, __FUNCTION__, \
category, _box_log_line.str()); \
} \
}

#define BOX_SYSLOG(level, stuff) \
{ \
std::ostringstream _box_log_line; \
_box_log_line << stuff; \
Logging::LogToSyslog(level, __FILE__, __LINE__, __FUNCTION__, \
Logging::UNCATEGORISED, _box_log_line.str()); \
if(level <= Logging::GetLowestCommonLevel()) \
{ \
std::ostringstream _box_log_line; \
_box_log_line << stuff; \
Logging::LogToSyslog(level, __FILE__, __LINE__, __FUNCTION__, \
Logging::UNCATEGORISED, _box_log_line.str()); \
} \
}

#define BOX_FATAL(stuff) BOX_LOG(Log::FATAL, stuff)
Expand Down Expand Up @@ -237,13 +249,16 @@ class Logger
const std::string& function, const Log::Category& category,
const std::string& message) = 0;

void Filter(Log::Level level)
{
mCurrentLevel = level;
}
void Filter(Log::Level level);

virtual const char* GetType() = 0;
Log::Level GetLevel() { return mCurrentLevel; }

// mCurrentLevel is the default for GetLowestLevel(). Subclasses can override it if they
// need to, for example if the user can configure them in ways that would increase
// sensitivity to certain messages that isn't reflected in mCurrentLevel:
virtual Log::Level GetLowestLevel() { return mCurrentLevel; }

bool IsEnabled(Log::Level level);

virtual void SetProgramName(const std::string& rProgramName) = 0;
Expand Down Expand Up @@ -448,7 +463,7 @@ class LogLevelOverrideByFileGuard
bool IsOverridden(Log::Level level, const std::string& file, int line,
const std::string& function, const Log::Category& category,
const std::string& message);
Log::Level GetNewLevel() { return mNewLevel; }
Log::Level GetNewLevel() const { return mNewLevel; }
bool operator==(const LogLevelOverrideByFileGuard& rOther)
{
return (mFileNames == rOther.mFileNames) &&
Expand Down Expand Up @@ -481,6 +496,11 @@ class Logging
static Logging sGlobalLogging;
static std::string sProgramName;
static std::vector<LogLevelOverrideByFileGuard> sLogLevelOverrideByFileGuards;

// Caches the lowest common level (no higher than needed by any Logger or
// LogLevelOverrideByFileGuard), since it could be expensive to recompute:
static Log::Level sLowestCommonLevel;

friend class LogLevelOverrideByFileGuard;

public:
Expand All @@ -495,7 +515,7 @@ class Logging
static bool ShouldLog(Log::Level default_level, Log::Level message_level,
const std::string& file, int line, const std::string& function,
const Log::Category& category, const std::string& message);
static void Log(Log::Level level, const std::string& file, int line,
static bool Log(Log::Level level, const std::string& file, int line,
const std::string& function, const Log::Category& category,
const std::string& message);
static void LogToSyslog(Log::Level level, const std::string& rFile, int line,
Expand All @@ -510,6 +530,13 @@ class Logging
static Console& GetConsole() { return *spConsole; }
static Syslog& GetSyslog() { return *spSyslog; }

// Returns the lowest level which needs to be enabled because at least one Logger (or
// LogLevelOverrideByFileGuard) wants to see messages of that level:
static Log::Level GetLowestCommonLevel() { return sLowestCommonLevel; }

// Updates the cached lowest common level:
static void UpdateLowestCommonLevel();

class ShowTagOnConsole
{
private:
Expand Down
56 changes: 56 additions & 0 deletions test/common/testcommon.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1107,6 +1107,61 @@ bool test_remove_prefix_suffix()
TEARDOWN();
}

// Test that logging works properly
bool test_logging()
{
SETUP();

#define TMP_LOG(level, message) \
Logging::Log(level, __FILE__, __LINE__, __FUNCTION__, Logging::UNCATEGORISED, message)

{
Logger::LevelGuard console_trace(Logging::GetConsole(), Log::TRACE);
TEST_THAT(TMP_LOG(Log::TRACE, "trace level"));
TEST_THAT(TMP_LOG(Log::INFO, "info level"));
TEST_THAT(TMP_LOG(Log::NOTICE, "notice level"));

Capture capture;
capture.Filter(Logging::GetConsole().GetLevel());
BOX_TRACE("trace level");
BOX_INFO("info level");
BOX_NOTICE("notice level");
TEST_EQUAL(3, capture.GetMessages().size());
}

{
Logger::LevelGuard console_trace(Logging::GetConsole(), Log::INFO);
TEST_THAT(!TMP_LOG(Log::TRACE, "trace level"));
TEST_THAT( TMP_LOG(Log::INFO, "info level"));
TEST_THAT( TMP_LOG(Log::NOTICE, "notice level"));

Capture capture;
capture.Filter(Logging::GetConsole().GetLevel());
BOX_TRACE("trace level");
BOX_INFO("info level");
BOX_NOTICE("notice level");
TEST_EQUAL(2, capture.GetMessages().size());
}

{
Logger::LevelGuard console_trace(Logging::GetConsole(), Log::NOTICE);
TEST_THAT(!TMP_LOG(Log::TRACE, "trace level"));
TEST_THAT(!TMP_LOG(Log::INFO, "info level"));
TEST_THAT( TMP_LOG(Log::NOTICE, "notice level"));

Capture capture;
capture.Filter(Logging::GetConsole().GetLevel());
BOX_TRACE("trace level");
BOX_INFO("info level");
BOX_NOTICE("notice level");
TEST_EQUAL(1, capture.GetMessages().size());
}

#undef TMP_LOG

TEARDOWN();
}

int test(int argc, const char *argv[])
{
if(argc == 2 && strcmp(argv[1], "lockwait") == 0)
Expand All @@ -1132,6 +1187,7 @@ int test(int argc, const char *argv[])
test_archive();
test_box_strtoui64();
test_remove_prefix_suffix();
test_logging();

return finish_test_suite();
}

0 comments on commit adc054b

Please sign in to comment.