Commit fc91e303 authored by Adam Simpkins's avatar Adam Simpkins Committed by Facebook Github Bot

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
parent cf984921
......@@ -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_);
}
......
......@@ -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_;
};
}
......@@ -16,6 +16,7 @@
#include <folly/experimental/logging/LogStreamProcessor.h>
#include <folly/experimental/logging/LogStream.h>
#include <folly/experimental/logging/xlog.h>
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<true>* 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<true>* 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<true>* 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<LogStream&>(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<true>::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<LogStream&>(stream);
logStream.getProcessor()->logNow();
abort();
}
std::string LogStreamProcessor::extractMessageString(
......
......@@ -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.
......
......@@ -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";
......
......@@ -18,6 +18,6 @@
namespace logging_test {
void testXlogFile1Dbg1(folly::StringPiece msg) {
XLOG(DBG1, "file1: ", msg);
XLOG(DBG1) << "file1: " << msg;
}
}
......@@ -22,6 +22,7 @@
#include <folly/experimental/logging/test/XlogHeader2.h>
#include <folly/experimental/logging/xlog.h>
#include <folly/portability/GTest.h>
#include <folly/test/TestUtils.h>
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<TestLogHandler>();
LoggerDB::get()->getCategory("xlog_test")->addHandler(handler);
......
......@@ -85,4 +85,51 @@ std::string getXlogCategoryNameForFile(StringPiece filename) {
}
return categoryName;
}
template <bool IsInHeaderFile>
LogLevel XlogLevelInfo<IsInHeaderFile>::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 <bool IsInHeaderFile>
LogCategory* XlogCategoryInfo<IsInHeaderFile>::init(
folly::StringPiece categoryName,
bool isOverridden) {
return LoggerDB::get()->xlogInitCategory(
isOverridden ? categoryName : getXlogCategoryNameForFile(categoryName),
&category_,
&isInitialized_);
}
#ifdef __INCLUDE_LEVEL__
LogLevel XlogLevelInfo<false>::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<true>;
template class XlogCategoryInfo<true>;
}
This diff is collapsed.
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment