From fc91e3033ab178ae85b54594f7dd09594de19b57 Mon Sep 17 00:00:00 2001 From: Adam Simpkins Date: Tue, 20 Jun 2017 19:44:20 -0700 Subject: [PATCH] logging: reduce the amount of code emitted for log statements Summary: This refactors the logging code with the aim of reducing the amount of assembly code emitted for each log statement, particularly for `XLOG()` statements. Ideally it should be possible to put debug `XLOG()` statements throughout your code without having to worry about the performance overhead. Therefore we should attempt to make sure that `XLOG()` statements do not generate a lot of assembly and hurt icache performance. This diff does not have any code behavior changes--it just moves code around a bit. The high-level summary is: - Move as much code as possible into the LogStreamProcessor constructors and destructor. Make sure these methods are defined in LogStreamProcessor.cpp to avoid having them be emitted inline at each log statement. - Move some of the XLOG level checking logic into separate non-inline functions defined in xlog.cpp - Pass xlog category information around as a pair of (categoryName, isOverridden) parameters. If isOverridden is true then the categoryName parameter should be used as the category name directly. If isOverridden is false, then categoryName is a filename that needs to go through filename to category name string processing. This allows the category name processing to be done in non-inlined code. Reviewed By: wez Differential Revision: D5269976 fbshipit-source-id: 7a7877ddfed66cd27ed82f052330b6aa2be4b37b --- folly/experimental/logging/LogStream.cpp | 3 +- folly/experimental/logging/LogStream.h | 9 +- .../logging/LogStreamProcessor.cpp | 152 +++++++-- .../experimental/logging/LogStreamProcessor.h | 260 +++++++++++++--- folly/experimental/logging/Logger.h | 22 +- .../logging/test/LogStreamTest.cpp | 4 +- folly/experimental/logging/test/XlogFile1.cpp | 2 +- folly/experimental/logging/test/XlogTest.cpp | 6 + folly/experimental/logging/xlog.cpp | 47 +++ folly/experimental/logging/xlog.h | 288 ++++++++++-------- 10 files changed, 579 insertions(+), 214 deletions(-) diff --git a/folly/experimental/logging/LogStream.cpp b/folly/experimental/logging/LogStream.cpp index f3ecbbe7..6b851099 100644 --- a/folly/experimental/logging/LogStream.cpp +++ b/folly/experimental/logging/LogStream.cpp @@ -46,7 +46,8 @@ LogStreamBuffer::int_type LogStreamBuffer::overflow(int_type ch) { } } -LogStream::LogStream() : std::ostream(nullptr) { +LogStream::LogStream(LogStreamProcessor* processor) + : std::ostream(nullptr), processor_{processor} { rdbuf(&buffer_); } diff --git a/folly/experimental/logging/LogStream.h b/folly/experimental/logging/LogStream.h index 82987f1f..9906ae61 100644 --- a/folly/experimental/logging/LogStream.h +++ b/folly/experimental/logging/LogStream.h @@ -49,6 +49,8 @@ class LogStreamBuffer : public std::streambuf { std::string str_; }; +class LogStreamProcessor; + /** * A std::ostream implementation for use by the logging macros. * @@ -62,7 +64,7 @@ class LogStream : public std::ostream { // each FB_LOG() or XLOG() statement. Inlining them just causes extra code // bloat, with minimal benefit--for debug log statements these never even get // called in the common case where the log statement is disabled. - LogStream(); + explicit LogStream(LogStreamProcessor* processor); ~LogStream(); bool empty() const { @@ -73,7 +75,12 @@ class LogStream : public std::ostream { return buffer_.extractString(); } + LogStreamProcessor* getProcessor() const { + return processor_; + } + private: LogStreamBuffer buffer_; + LogStreamProcessor* const processor_; }; } diff --git a/folly/experimental/logging/LogStreamProcessor.cpp b/folly/experimental/logging/LogStreamProcessor.cpp index ad4f9f19..ae5d8246 100644 --- a/folly/experimental/logging/LogStreamProcessor.cpp +++ b/folly/experimental/logging/LogStreamProcessor.cpp @@ -16,6 +16,7 @@ #include #include +#include namespace folly { @@ -25,25 +26,140 @@ LogStreamProcessor::LogStreamProcessor( folly::StringPiece filename, unsigned int lineNumber, AppendType) noexcept + : LogStreamProcessor( + category, + level, + filename, + lineNumber, + INTERNAL, + std::string()) {} + +LogStreamProcessor::LogStreamProcessor( + XlogCategoryInfo* categoryInfo, + LogLevel level, + folly::StringPiece categoryName, + bool isCategoryNameOverridden, + folly::StringPiece filename, + unsigned int lineNumber, + AppendType) noexcept + : LogStreamProcessor( + categoryInfo, + level, + categoryName, + isCategoryNameOverridden, + filename, + lineNumber, + INTERNAL, + std::string()) {} + +LogStreamProcessor::LogStreamProcessor( + XlogFileScopeInfo* fileScopeInfo, + LogLevel level, + folly::StringPiece filename, + unsigned int lineNumber, + AppendType) noexcept + : LogStreamProcessor( + fileScopeInfo, + level, + filename, + lineNumber, + INTERNAL, + std::string()) {} + +LogStreamProcessor::LogStreamProcessor( + const LogCategory* category, + LogLevel level, + folly::StringPiece filename, + unsigned int lineNumber, + InternalType, + std::string&& msg) noexcept : category_{category}, level_{level}, filename_{filename}, - lineNumber_{lineNumber} {} + lineNumber_{lineNumber}, + message_{std::move(msg)}, + stream_{this} {} + +namespace { +LogCategory* getXlogCategory( + XlogCategoryInfo* categoryInfo, + folly::StringPiece categoryName, + bool isCategoryNameOverridden) { + if (!categoryInfo->isInitialized()) { + return categoryInfo->init(categoryName, isCategoryNameOverridden); + } + return categoryInfo->getCategory(&xlog_detail::xlogFileScopeInfo); +} + +LogCategory* getXlogCategory(XlogFileScopeInfo* fileScopeInfo) { + // By the time a LogStreamProcessor is created, the XlogFileScopeInfo object + // should have already been initialized to perform the log level check. + // Therefore we never need to check if it is initialized here. + return fileScopeInfo->category; +} +} + +/** + * Construct a LogStreamProcessor from an XlogCategoryInfo. + * + * We intentionally define this in LogStreamProcessor.cpp instead of + * LogStreamProcessor.h to avoid having it inlined at every XLOG() call site, + * to reduce the emitted code size. + */ +LogStreamProcessor::LogStreamProcessor( + XlogCategoryInfo* categoryInfo, + LogLevel level, + folly::StringPiece categoryName, + bool isCategoryNameOverridden, + folly::StringPiece filename, + unsigned int lineNumber, + InternalType, + std::string&& msg) noexcept + : category_{getXlogCategory( + categoryInfo, + categoryName, + isCategoryNameOverridden)}, + level_{level}, + filename_{filename}, + lineNumber_{lineNumber}, + message_{std::move(msg)}, + stream_{this} {} +/** + * Construct a LogStreamProcessor from an XlogFileScopeInfo. + * + * We intentionally define this in LogStreamProcessor.cpp instead of + * LogStreamProcessor.h to avoid having it inlined at every XLOG() call site, + * to reduce the emitted code size. + */ LogStreamProcessor::LogStreamProcessor( - const LogCategory* category, + XlogFileScopeInfo* fileScopeInfo, LogLevel level, - const char* filename, + folly::StringPiece filename, unsigned int lineNumber, InternalType, std::string&& msg) noexcept - : category_{category}, + : category_{getXlogCategory(fileScopeInfo)}, level_{level}, filename_{filename}, lineNumber_{lineNumber}, - message_{std::move(msg)} {} + message_{std::move(msg)}, + stream_{this} {} -void LogStreamProcessor::operator&(std::ostream& stream) noexcept { +/* + * We intentionally define the LogStreamProcessor destructor in + * LogStreamProcessor.cpp instead of LogStreamProcessor.h to avoid having it + * emitted inline at every log statement site. This helps reduce the emitted + * code size for each log statement. + */ +LogStreamProcessor::~LogStreamProcessor() noexcept { + // The LogStreamProcessor destructor is responsible for logging the message. + // Doing this in the destructor avoids an separate function call to log the + // message being emitted inline at every log statement site. + logNow(); +} + +void LogStreamProcessor::logNow() noexcept { // Note that admitMessage() is not noexcept and theoretically may throw. // However, the only exception that should be possible is std::bad_alloc if // we fail to allocate memory. We intentionally let our noexcept specifier @@ -52,23 +168,25 @@ void LogStreamProcessor::operator&(std::ostream& stream) noexcept { // // Any other error here is unexpected and we also want to fail hard // in that situation too. - auto& logStream = static_cast(stream); category_->admitMessage(LogMessage{category_, level_, filename_, lineNumber_, - extractMessageString(logStream)}); + extractMessageString(stream_)}); } -void LogStreamProcessor::operator&(LogStream&& stream) noexcept { - // This version of operator&() is generally only invoked when - // no streaming arguments were supplied to the logging macro. - // Therefore we don't bother calling extractMessageString(stream), - // and just directly use message_. - DCHECK(stream.empty()); - - category_->admitMessage(LogMessage{ - category_, level_, filename_, lineNumber_, std::move(message_)}); +void LogStreamVoidify::operator&(std::ostream& stream) { + // Non-fatal log messages wait until the LogStreamProcessor destructor to log + // the message. However for fatal messages we log immediately in the & + // operator, since it is marked noreturn. + // + // This does result in slightly larger emitted code for fatal log messages + // (since the operator & call cannot be completely omitted). However, fatal + // log messages should typically be much more rare than non-fatal messages, + // so the small amount of extra overhead shouldn't be a big deal. + auto& logStream = static_cast(stream); + logStream.getProcessor()->logNow(); + abort(); } std::string LogStreamProcessor::extractMessageString( diff --git a/folly/experimental/logging/LogStreamProcessor.h b/folly/experimental/logging/LogStreamProcessor.h index b9f78b9b..21d45947 100644 --- a/folly/experimental/logging/LogStreamProcessor.h +++ b/folly/experimental/logging/LogStreamProcessor.h @@ -15,18 +15,18 @@ */ #pragma once +#include #include #include #include #include #include #include +#include #include namespace folly { -class LogStream; - /* * Helper functions for fallback-formatting of arguments if folly::format() * throws an exception. @@ -70,6 +70,10 @@ inline void fallbackFormatOneArg(std::string* str, const Arg* arg, long) { } } +template +class XlogCategoryInfo; +class XlogFileScopeInfo; + /** * LogStreamProcessor receives a LogStream and logs it. * @@ -103,6 +107,41 @@ class LogStreamProcessor { unsigned int lineNumber, AppendType) noexcept; + /** + * LogStreamProcessor constructors for use with XLOG() macros with no extra + * arguments. + * + * These are defined separately from the above constructor so that the work + * of initializing the XLOG LogCategory data is done in a separate function + * body defined in LogStreamProcessor.cpp. We intentionally want to avoid + * inlining this work at every XLOG() statement, to reduce the emitted code + * size. + */ + LogStreamProcessor( + XlogCategoryInfo* categoryInfo, + LogLevel level, + folly::StringPiece categoryName, + bool isCategoryNameOverridden, + folly::StringPiece filename, + unsigned int lineNumber, + AppendType) noexcept; + LogStreamProcessor( + XlogFileScopeInfo* fileScopeInfo, + LogLevel level, + folly::StringPiece filename, + unsigned int lineNumber, + AppendType) noexcept; + LogStreamProcessor( + XlogFileScopeInfo* fileScopeInfo, + LogLevel level, + folly::StringPiece /* categoryName */, + bool /* isCategoryNameOverridden */, + folly::StringPiece filename, + unsigned int lineNumber, + AppendType) noexcept + : LogStreamProcessor(fileScopeInfo, level, filename, lineNumber, APPEND) { + } + /** * LogStreamProcessor constructor for use with a LOG() macro with arguments * to be concatenated with folly::to() @@ -116,16 +155,57 @@ class LogStreamProcessor { LogStreamProcessor( const LogCategory* category, LogLevel level, - const char* filename, + folly::StringPiece filename, unsigned int lineNumber, AppendType, Args&&... args) noexcept - : LogStreamProcessor{category, - level, - filename, - lineNumber, - INTERNAL, - createLogString(std::forward(args)...)} {} + : LogStreamProcessor( + category, + level, + filename, + lineNumber, + INTERNAL, + createLogString(std::forward(args)...)) {} + + /** + * Versions of the above constructor for use in XLOG() statements. + */ + template + LogStreamProcessor( + XlogCategoryInfo* categoryInfo, + LogLevel level, + folly::StringPiece categoryName, + bool isCategoryNameOverridden, + folly::StringPiece filename, + unsigned int lineNumber, + AppendType, + Args&&... args) noexcept + : LogStreamProcessor( + categoryInfo, + level, + categoryName, + isCategoryNameOverridden, + filename, + lineNumber, + INTERNAL, + createLogString(std::forward(args)...)) {} + template + LogStreamProcessor( + XlogFileScopeInfo* fileScopeInfo, + LogLevel level, + folly::StringPiece /* categoryName */, + bool /* isCategoryNameOverridden */, + folly::StringPiece filename, + unsigned int lineNumber, + AppendType, + Args&&... args) noexcept + : LogStreamProcessor( + fileScopeInfo, + level, + filename, + lineNumber, + INTERNAL, + createLogString(std::forward(args)...)) {} /** * LogStreamProcessor constructor for use with a LOG() macro with arguments @@ -140,17 +220,63 @@ class LogStreamProcessor { LogStreamProcessor( const LogCategory* category, LogLevel level, - const char* filename, + folly::StringPiece filename, unsigned int lineNumber, FormatType, folly::StringPiece fmt, Args&&... args) noexcept - : LogStreamProcessor{category, - level, - filename, - lineNumber, - INTERNAL, - formatLogString(fmt, std::forward(args)...)} {} + : LogStreamProcessor( + category, + level, + filename, + lineNumber, + INTERNAL, + formatLogString(fmt, std::forward(args)...)) {} + + /** + * Versions of the above constructor for use in XLOG() statements. + */ + template + LogStreamProcessor( + XlogCategoryInfo* categoryInfo, + LogLevel level, + folly::StringPiece categoryName, + bool isCategoryNameOverridden, + folly::StringPiece filename, + unsigned int lineNumber, + FormatType, + folly::StringPiece fmt, + Args&&... args) noexcept + : LogStreamProcessor( + categoryInfo, + level, + categoryName, + isCategoryNameOverridden, + filename, + lineNumber, + INTERNAL, + formatLogString(fmt, std::forward(args)...)) {} + + template + LogStreamProcessor( + XlogFileScopeInfo* fileScopeInfo, + LogLevel level, + folly::StringPiece /* categoryName */, + bool /* isCategoryNameOverridden */, + folly::StringPiece filename, + unsigned int lineNumber, + FormatType, + folly::StringPiece fmt, + Args&&... args) noexcept + : LogStreamProcessor( + fileScopeInfo, + level, + filename, + lineNumber, + INTERNAL, + formatLogString(fmt, std::forward(args)...)) {} + + ~LogStreamProcessor() noexcept; /** * This version of operator&() is typically used when the user specifies @@ -166,12 +292,34 @@ class LogStreamProcessor { */ void operator&(LogStream&& stream) noexcept; + std::ostream& stream() noexcept { + return stream_; + } + + void logNow() noexcept; + private: enum InternalType { INTERNAL }; LogStreamProcessor( const LogCategory* category, LogLevel level, - const char* filename, + folly::StringPiece filename, + unsigned int lineNumber, + InternalType, + std::string&& msg) noexcept; + LogStreamProcessor( + XlogCategoryInfo* categoryInfo, + LogLevel level, + folly::StringPiece categoryName, + bool isCategoryNameOverridden, + folly::StringPiece filename, + unsigned int lineNumber, + InternalType, + std::string&& msg) noexcept; + LogStreamProcessor( + XlogFileScopeInfo* fileScopeInfo, + LogLevel level, + folly::StringPiece filename, unsigned int lineNumber, InternalType, std::string&& msg) noexcept; @@ -187,7 +335,7 @@ class LogStreamProcessor { * exceptions, but instead just log an error string when something goes wrong. */ template - std::string createLogString(Args&&... args) noexcept { + FOLLY_NOINLINE std::string createLogString(Args&&... args) noexcept { try { return folly::to(std::forward(args)...); } catch (const std::exception& ex) { @@ -212,7 +360,7 @@ class LogStreamProcessor { * exceptions, but instead just log an error string when something goes wrong. */ template - std::string formatLogString( + FOLLY_NOINLINE std::string formatLogString( folly::StringPiece fmt, const Args&... args) noexcept { try { @@ -261,44 +409,58 @@ class LogStreamProcessor { folly::StringPiece filename_; unsigned int lineNumber_; std::string message_; + LogStream stream_; }; -/* - * This template subclass of LogStreamProcessor exists primarily so that - * we can specify the [[noreturn]] attribute correctly on operator&() - * This lets the compiler know that code after LOG(FATAL) is unreachable. +/** + * LogStreamVoidify() is a helper class used in the FB_LOG() and XLOG() macros. + * + * It's only purpose is to provide an & operator overload that returns void. + * This allows the log macros to expand roughly to: + * + * (logEnabled) ? (void)0 + * : LogStreamVoidify{} & LogStreamProcessor{}.stream() << "msg"; + * + * This enables the right hand (':') side of the ternary ? expression to have a + * void type, and allows various streaming operator expressions to be placed on + * the right hand side of the expression. + * + * Operator & is used since it has higher precedence than ?:, but lower + * precedence than <<. + * + * This class is templated on whether the log message is fatal so that the + * operator& can be declared [[noreturn]] for fatal log messages. This + * prevents the compiler from complaining about functions that do not return a + * value after a fatal log statement. */ template -class LogStreamProcessorT : public LogStreamProcessor { +class LogStreamVoidify { public: - using LogStreamProcessor::LogStreamProcessor; - - void operator&(std::ostream& stream) noexcept { - LogStreamProcessor::operator&(stream); - } - void operator&(LogStream&& stream) noexcept { - LogStreamProcessor::operator&(std::move(stream)); - } + /** + * In the default (non-fatal) case, the & operator implementation is a no-op. + * + * We perform the actual logging in the LogStreamProcessor destructor. It + * feels slightly hacky to perform logging in the LogStreamProcessor + * destructor instead of here, since the LogStreamProcessor destructor is not + * evaluated until the very end of the statement. In practice log + * statements really shouldn't be in the middle of larger statements with + * other side effects, so this ordering distinction shouldn't make much + * difference. + * + * However, by keeping this function a no-op we reduce the amount of code + * generated for log statements. This function call can be completely + * eliminated by the compiler, leaving only the LogStreamProcessor destructor + * invocation, which cannot be eliminated. + */ + void operator&(std::ostream&)noexcept {} }; template <> -class LogStreamProcessorT : public LogStreamProcessor { +class LogStreamVoidify { public: - using LogStreamProcessor::LogStreamProcessor; - - [[noreturn]] void operator&(std::ostream& stream) noexcept { - LogStreamProcessor::operator&(stream); - // We'll never actually reach here: the LogCategory code is responsible for - // crashing on FATAL messages. However, add an abort() call so the - // compiler knows we really cannot return here. - std::abort(); - } - [[noreturn]] void operator&(LogStream&& stream) noexcept { - LogStreamProcessor::operator&(std::move(stream)); - // We'll never actually reach here: the LogCategory code is responsible for - // crashing on FATAL messages. However, add an abort() call so the - // compiler knows we really cannot return here. - std::abort(); - } + /** + * A specialized noreturn version of operator&() for fatal log statements. + */ + [[noreturn]] void operator&(std::ostream&); }; } diff --git a/folly/experimental/logging/Logger.h b/folly/experimental/logging/Logger.h index 2fae9e2a..ed346470 100644 --- a/folly/experimental/logging/Logger.h +++ b/folly/experimental/logging/Logger.h @@ -27,17 +27,17 @@ * * This macro generally should not be used directly by end users. */ -#define FB_LOG_IMPL(logger, level, type, ...) \ - (!(logger).getCategory()->logCheck(level)) \ - ? (void)0 \ - : ::folly::LogStreamProcessorT<::folly::isLogLevelFatal( \ - level)>{(logger).getCategory(), \ - (level), \ - __FILE__, \ - __LINE__, \ - (type), \ - ##__VA_ARGS__} & \ - ::folly::LogStream() +#define FB_LOG_IMPL(logger, level, type, ...) \ + (!(logger).getCategory()->logCheck(level)) \ + ? (void)0 \ + : ::folly::LogStreamVoidify<::folly::isLogLevelFatal(level)>{} & \ + ::folly::LogStreamProcessor{(logger).getCategory(), \ + (level), \ + __FILE__, \ + __LINE__, \ + (type), \ + ##__VA_ARGS__} \ + .stream() /** * Log a message to the specified logger. diff --git a/folly/experimental/logging/test/LogStreamTest.cpp b/folly/experimental/logging/test/LogStreamTest.cpp index 29fea09e..f7ac9ab8 100644 --- a/folly/experimental/logging/test/LogStreamTest.cpp +++ b/folly/experimental/logging/test/LogStreamTest.cpp @@ -19,7 +19,7 @@ using namespace folly; TEST(LogStream, simple) { - LogStream ls; + LogStream ls{nullptr}; ls << "test"; ls << " foobar"; @@ -29,7 +29,7 @@ TEST(LogStream, simple) { TEST(LogStream, largeMessage) { std::string largeString(4096, 'a'); - LogStream ls; + LogStream ls{nullptr}; ls << "prefix "; ls << largeString; ls << " suffix"; diff --git a/folly/experimental/logging/test/XlogFile1.cpp b/folly/experimental/logging/test/XlogFile1.cpp index 2d43930e..b24085b4 100644 --- a/folly/experimental/logging/test/XlogFile1.cpp +++ b/folly/experimental/logging/test/XlogFile1.cpp @@ -18,6 +18,6 @@ namespace logging_test { void testXlogFile1Dbg1(folly::StringPiece msg) { - XLOG(DBG1, "file1: ", msg); + XLOG(DBG1) << "file1: " << msg; } } diff --git a/folly/experimental/logging/test/XlogTest.cpp b/folly/experimental/logging/test/XlogTest.cpp index 4cca9faf..32e96438 100644 --- a/folly/experimental/logging/test/XlogTest.cpp +++ b/folly/experimental/logging/test/XlogTest.cpp @@ -22,6 +22,7 @@ #include #include #include +#include using namespace folly; using std::make_shared; @@ -35,6 +36,11 @@ XLOG_SET_CATEGORY_NAME("xlog_test.main_file"); // settings for the entire program. Fortunately all of the other unit tests do // use testing LoggerDB objects. +TEST(Xlog, xlogName) { + EXPECT_EQ("xlog_test.main_file", XLOG_GET_CATEGORY_NAME()); + EXPECT_EQ("xlog_test.main_file", XLOG_GET_CATEGORY()->getName()); +} + TEST(Xlog, xlog) { auto handler = make_shared(); LoggerDB::get()->getCategory("xlog_test")->addHandler(handler); diff --git a/folly/experimental/logging/xlog.cpp b/folly/experimental/logging/xlog.cpp index 92390a2b..3468c29f 100644 --- a/folly/experimental/logging/xlog.cpp +++ b/folly/experimental/logging/xlog.cpp @@ -85,4 +85,51 @@ std::string getXlogCategoryNameForFile(StringPiece filename) { } return categoryName; } + +template +LogLevel XlogLevelInfo::loadLevelFull( + folly::StringPiece categoryName, + bool isOverridden) { + auto currentLevel = level_.load(std::memory_order_acquire); + if (UNLIKELY(currentLevel == ::folly::LogLevel::UNINITIALIZED)) { + return LoggerDB::get()->xlogInit( + isOverridden ? categoryName : getXlogCategoryNameForFile(categoryName), + &level_, + nullptr); + } + return currentLevel; +} + +template +LogCategory* XlogCategoryInfo::init( + folly::StringPiece categoryName, + bool isOverridden) { + return LoggerDB::get()->xlogInitCategory( + isOverridden ? categoryName : getXlogCategoryNameForFile(categoryName), + &category_, + &isInitialized_); +} + +#ifdef __INCLUDE_LEVEL__ +LogLevel XlogLevelInfo::loadLevelFull( + folly::StringPiece categoryName, + bool isOverridden, + XlogFileScopeInfo* fileScopeInfo) { + auto currentLevel = fileScopeInfo->level.load(std::memory_order_acquire); + if (UNLIKELY(currentLevel == ::folly::LogLevel::UNINITIALIZED)) { + return LoggerDB::get()->xlogInit( + isOverridden ? categoryName : getXlogCategoryNameForFile(categoryName), + &fileScopeInfo->level, + &fileScopeInfo->category); + } + return currentLevel; +} +#endif + +// Explicitly instantiations of XlogLevelInfo and XlogCategoryInfo +// If __INCLUDE_LEVEL__ is not available only the "true" variants ever get +// used, because we cannot determine if we are ever in the .cpp file being +// compiled or not. +template class XlogLevelInfo; +template class XlogCategoryInfo; } diff --git a/folly/experimental/logging/xlog.h b/folly/experimental/logging/xlog.h index 3c17d6bf..ca229af5 100644 --- a/folly/experimental/logging/xlog.h +++ b/folly/experimental/logging/xlog.h @@ -112,17 +112,25 @@ * initialized. On all subsequent calls, disabled log statements can be * skipped with just a single check of the LogLevel. */ -#define XLOG_IMPL(level, type, ...) \ - (!XLOG_IS_ON_IMPL(level)) \ - ? static_cast(0) \ - : ::folly::LogStreamProcessorT<::folly::isLogLevelFatal(level)>( \ - XLOG_GET_CATEGORY_INTERNAL(), \ - (level), \ - __FILE__, \ - __LINE__, \ - (type), \ - ##__VA_ARGS__) & \ - ::folly::LogStream() +#define XLOG_IMPL(level, type, ...) \ + (!XLOG_IS_ON_IMPL(level)) \ + ? static_cast(0) \ + : ::folly::LogStreamVoidify<::folly::isLogLevelFatal(level)>{} & \ + ::folly::LogStreamProcessor( \ + [] { \ + static ::folly::XlogCategoryInfo \ + _xlogCategory_; \ + return _xlogCategory_.getInfo( \ + &xlog_detail::xlogFileScopeInfo); \ + }(), \ + (level), \ + xlog_detail::getXlogCategoryName(__FILE__, 0), \ + xlog_detail::isXlogCategoryOverridden(0), \ + __FILE__, \ + __LINE__, \ + (type), \ + ##__VA_ARGS__) \ + .stream() /** * Check if and XLOG() statement with the given log level would be enabled. @@ -142,50 +150,26 @@ * automatically keeps it up-to-date when the category's effective level is * changed. * - * Most of this code must live in the macro definition itself, and cannot be - * moved into a helper function: The getXlogCategoryName() call must be made as - * part of the macro expansion in order to work correctly. We also want to - * avoid calling it whenever possible. Therefore most of the logic must be - * done in the macro expansion. - * * See XlogLevelInfo for the implementation details. */ -#define XLOG_IS_ON_IMPL(level) \ - ([] { \ - static ::folly::XlogLevelInfo _xlogLevel_; \ - const auto _xlogLevelToCheck_ = (level); \ - /* \ - * Do an initial relaxed check. If this fails we know the category level \ - * is initialized and the log admittance check failed. \ - * Use LIKELY() to optimize for the case of disabled debug statements: \ - * we disabled debug statements to be cheap. If the log message is \ - * enabled then this check will still be minimal perf overhead compared to \ - * the overall cost of logging it. \ - */ \ - if (LIKELY( \ - _xlogLevelToCheck_ < \ - _xlogLevel_.getLevel( \ - &_xlogFileScopeInfo_, std::memory_order_relaxed))) { \ - return false; \ - } \ - /* \ - * Load the level value with memory_order_acquire, and check \ - * to see if it is initialized or not. \ - */ \ - auto _xlogCurrentLevel_ = \ - _xlogLevel_.getLevel(&_xlogFileScopeInfo_, std::memory_order_acquire); \ - if (UNLIKELY(_xlogCurrentLevel_ == ::folly::LogLevel::UNINITIALIZED)) { \ - _xlogCurrentLevel_ = _xlogLevel_.init( \ - getXlogCategoryName(__FILE__), &_xlogFileScopeInfo_); \ - } \ - return _xlogLevelToCheck_ >= _xlogCurrentLevel_; \ +#define XLOG_IS_ON_IMPL(level) \ + ([] { \ + static ::folly::XlogLevelInfo _xlogLevel_; \ + return _xlogLevel_.check( \ + (level), \ + xlog_detail::getXlogCategoryName(__FILE__, 0), \ + xlog_detail::isXlogCategoryOverridden(0), \ + &xlog_detail::xlogFileScopeInfo); \ }()) /** * Get the name of the log category that will be used by XLOG() statements * in this file. */ -#define XLOG_GET_CATEGORY_NAME() getXlogCategoryName(__FILE__) +#define XLOG_GET_CATEGORY_NAME() \ + (xlog_detail::isXlogCategoryOverridden(0) \ + ? xlog_detail::getXlogCategoryName(__FILE__, 0) \ + : ::folly::getXlogCategoryNameForFile(__FILE__)) /** * Get a pointer to the LogCategory that will be used by XLOG() statements in @@ -198,34 +182,6 @@ #define XLOG_GET_CATEGORY() \ folly::LoggerDB::get()->getCategory(XLOG_GET_CATEGORY_NAME()) -/** - * Internal version of XLOG_GET_CATEGORY() that is used in the XLOG() macro. - * - * This macro is used in the XLOG() implementation, and therefore must be as - * cheap as possible. It stores the LogCategory* pointer as a local static - * variable. Only the first invocation has to look up the log category by - * name. Subsequent invocations re-use the already looked-up LogCategory - * pointer. - * - * This is only safe to call after XlogLevelInfo::init() has been called. - * - * Most of this code must live in the macro definition itself, and cannot be - * moved into a helper function: The getXlogCategoryName() call must be made as - * part of the macro expansion in order to work correctly. We also want to - * avoid calling it whenever possible. Therefore most of the logic must be - * done in the macro expansion. - * - * See XlogCategoryInfo for the implementation details. - */ -#define XLOG_GET_CATEGORY_INTERNAL() \ - [] { \ - static ::folly::XlogCategoryInfo _xlogCategory_; \ - if (!_xlogCategory_.isInitialized()) { \ - return _xlogCategory_.init(getXlogCategoryName(__FILE__)); \ - } \ - return _xlogCategory_.getCategory(&_xlogFileScopeInfo_); \ - }() - /** * XLOG_SET_CATEGORY_NAME() can be used to explicitly define the log category * name used by all XLOG() and XLOGF() calls in this translation unit. @@ -239,24 +195,29 @@ * XLOG_SET_CATEGORY_NAME() cannot be used inside header files. */ #ifdef __INCLUDE_LEVEL__ -#define XLOG_SET_CATEGORY_NAME(category) \ - namespace { \ - static_assert( \ - __INCLUDE_LEVEL__ == 0, \ - "XLOG_SET_CATEGORY_NAME() should not be used in header files"); \ - inline std::string getXlogCategoryName(const char*) { \ - return category; \ - } \ - } +#define XLOG_SET_CATEGORY_CHECK \ + static_assert( \ + __INCLUDE_LEVEL__ == 0, \ + "XLOG_SET_CATEGORY_NAME() should not be used in header files"); #else -#define XLOG_SET_CATEGORY_NAME(category) \ - namespace { \ - inline std::string getXlogCategoryName(const char*) { \ - return category; \ - } \ - } +#define XLOG_SET_CATEGORY_CHECK #endif +#define XLOG_SET_CATEGORY_NAME(category) \ + namespace { \ + namespace xlog_detail { \ + XLOG_SET_CATEGORY_CHECK \ + constexpr inline folly::StringPiece getXlogCategoryName( \ + folly::StringPiece, \ + int) { \ + return category; \ + } \ + constexpr inline bool isXlogCategoryOverridden(int) { \ + return true; \ + } \ + } \ + } + /** * XLOG_IS_IN_HEADER_FILE evaluates to false if we can definitively tell if we * are not in a header file. Otherwise, it evaluates to true. @@ -289,37 +250,64 @@ class XlogFileScopeInfo { * used during dynamic object initialization before main(). */ template -struct XlogLevelInfo { +class XlogLevelInfo { public: - inline LogLevel getLevel(XlogFileScopeInfo*, std::memory_order order) { - return level_.load(order); - } + bool check( + LogLevel levelToCheck, + folly::StringPiece categoryName, + bool isOverridden, + XlogFileScopeInfo*) { + // Do an initial relaxed check. If this fails we know the category level + // is initialized and the log admittance check failed. + // Use LIKELY() to optimize for the case of disabled debug statements: + // we disabled debug statements to be cheap. If the log message is + // enabled then this check will still be minimal perf overhead compared to + // the overall cost of logging it. + if (LIKELY(levelToCheck < level_.load(std::memory_order_relaxed))) { + return false; + } - inline LogLevel init(folly::StringPiece categoryName, XlogFileScopeInfo*) { - return LoggerDB::get()->xlogInit(categoryName, &level_, nullptr); + // If we are still here, then either: + // - The log level check actually passed, or + // - level_ has not been initialized yet, and we have to initialize it and + // then re-perform the check. + // + // Do this work in a separate helper method. It is intentionally defined + // in the xlog.cpp file to avoid inlining, to reduce the amount of code + // emitted for each XLOG() statement. + auto currentLevel = loadLevelFull(categoryName, isOverridden); + return levelToCheck >= currentLevel; } private: + LogLevel loadLevelFull(folly::StringPiece categoryName, bool isOverridden); + + // XlogLevelInfo objects are always defined with static storage. // This member will always be zero-initialized on program start. std::atomic level_; }; template -struct XlogCategoryInfo { +class XlogCategoryInfo { public: bool isInitialized() const { return isInitialized_.load(std::memory_order_acquire); } - LogCategory* init(folly::StringPiece categoryName) { - return LoggerDB::get()->xlogInitCategory( - categoryName, &category_, &isInitialized_); - } + LogCategory* init(folly::StringPiece categoryName, bool isOverridden); LogCategory* getCategory(XlogFileScopeInfo*) { return category_; } + /** + * Get a pointer to pass into the LogStreamProcessor constructor, + * so that it is able to look up the LogCategory information. + */ + XlogCategoryInfo* getInfo(XlogFileScopeInfo*) { + return this; + } + private: // These variables will always be zero-initialized on program start. std::atomic isInitialized_; @@ -333,20 +321,33 @@ struct XlogCategoryInfo { * for the entire file, rather than defining one for each XLOG() statement. */ template <> -struct XlogLevelInfo { +class XlogLevelInfo { public: - inline LogLevel getLevel( - XlogFileScopeInfo* fileScopeInfo, - std::memory_order order) { - return fileScopeInfo->level.load(order); - } - - inline LogLevel init( + static bool check( + LogLevel levelToCheck, folly::StringPiece categoryName, + bool isOverridden, XlogFileScopeInfo* fileScopeInfo) { - return LoggerDB::get()->xlogInit( - categoryName, &fileScopeInfo->level, &fileScopeInfo->category); + // As above in the non-specialized XlogFileScopeInfo code, do a simple + // relaxed check first. + if (LIKELY( + levelToCheck < + fileScopeInfo->level.load(::std::memory_order_relaxed))) { + return false; + } + + // If we are still here we the file-scope log level either needs to be + // initalized, or the log level check legitimately passed. + auto currentLevel = + loadLevelFull(categoryName, isOverridden, fileScopeInfo); + return levelToCheck >= currentLevel; } + + private: + static LogLevel loadLevelFull( + folly::StringPiece categoryName, + bool isOverridden, + XlogFileScopeInfo* fileScopeInfo); }; /** @@ -356,20 +357,14 @@ struct XlogLevelInfo { * statement. */ template <> -struct XlogCategoryInfo { +class XlogCategoryInfo { public: - constexpr bool isInitialized() const { - // XlogLevelInfo::init() is always called before XlogCategoryInfo - // is used, and it will have already initialized fileScopeInfo. - // Therefore we never have to check if it is initialized yet here. - return true; - } - [[noreturn]] LogCategory* init(folly::StringPiece /* categoryName */) { - // This method is never used given that isInitialized() always returns true - ::std::abort(); - } - LogCategory* getCategory(XlogFileScopeInfo* fileScopeInfo) { - return fileScopeInfo->category; + /** + * Get a pointer to pass into the LogStreamProcessor constructor, + * so that it is able to look up the LogCategory information. + */ + XlogFileScopeInfo* getInfo(XlogFileScopeInfo* fileScopeInfo) { + return fileScopeInfo; } }; #endif @@ -390,17 +385,45 @@ std::string getXlogCategoryNameForFile(folly::StringPiece filename); * implementation of the following functions and variables. */ namespace { +namespace xlog_detail { +/** + * The default getXlogCategoryName() function. + * + * By default this simply returns the filename argument passed in. + * The default isXlogCategoryOverridden() function returns false, indicating + * that the return value from getXlogCategoryName() needs to be converted + * using getXlogCategoryNameForFile(). + * + * These are two separate steps because getXlogCategoryName() itself needs to + * remain constexpr--it is always evaluated in XLOG() statements, but we only + * want to call getXlogCategoryNameForFile() the very first time through, when + * we have to initialize the LogCategory object. + * + * This is a template function purely so that XLOG_SET_CATEGORY_NAME() can + * define a more specific version of this function that will take precedence + * over this one. + */ +template +constexpr inline folly::StringPiece getXlogCategoryName( + folly::StringPiece filename, + T) { + return filename; +} + /** - * The default getXlogCategoryName() implementation. - * This will be used if XLOG_SET_CATEGORY_NAME() has not been used yet. + * The default isXlogCategoryOverridden() function. * - * This is a template purely so that XLOG_SET_CATEGORY_NAME() can define a more - * specific version if desired, allowing XLOG_SET_CATEGORY_NAME() to override - * this implementation once it has been used. + * This returns false indicating that the category name has not been + * overridden, so getXlogCategoryName() returns a raw filename that needs + * to be translated with getXlogCategoryNameForFile(). + * + * This is a template function purely so that XLOG_SET_CATEGORY_NAME() can + * define a more specific version of this function that will take precedence + * over this one. */ template -inline std::string getXlogCategoryName(const T* filename) { - return ::folly::getXlogCategoryNameForFile(filename); +constexpr inline bool isXlogCategoryOverridden(T) { + return false; } /** @@ -411,5 +434,6 @@ inline std::string getXlogCategoryName(const T* filename) { * entire .cpp file, rather than needing a separate copy for each XLOG() * statement. */ -::folly::XlogFileScopeInfo _xlogFileScopeInfo_; +::folly::XlogFileScopeInfo xlogFileScopeInfo; +} } -- 2.34.1