Commit da41ae50 authored by Victor Zverovich's avatar Victor Zverovich Committed by Facebook Github Bot

Replace Folly Format with fmt in logger to reduce binary size

Summary:
Now that fmt is available in Folly builds (D14813810), use it to reduce binary code size in Folly Logger. This is done by moving most of the formatting logic behind the type-erased `vformat` API. Previously it was instantiated for all combinations of formatting argument types used in calls to `FB_LOGF` and `XLOGF` in a program.

The effect of this change can be illustrated by looking at symbol sizes as given by `nm -S -td` for the following test function:

```
void test_log() {
  FB_LOGF(logger, WARN, "num events: {:06d}, duration: {:6.3f}", 1234, 5.6789);
}
```
compiled in `opt` mode.

`nm` before:

```
0000000004236736 0000000000000231 T test_log()
0000000004236992 0000000000001002 W std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > folly::LogStreamProcessor::formatLogString<int, double>(folly::Range<char const*>, int const&, double const&)
```

`nm` after:

```
0000000004237536 0000000000000231 T test_log()
0000000004237792 0000000000000251 W std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > folly::LogStreamProcessor::formatLogString<int, double>(folly::Range<char const*>, int const&, double const&)
0000000004238048 0000000000000740 W folly::LogStreamProcessor::vformatLogString[abi:cxx11](folly::Range<char const*>, fmt::v5::format_args, bool&)
```

Before we had one 1002 byte instantiation of `formatLogString<int, double>`. With this change it was reduced 4x to 251 bytes and non-template function `vformatLogString` was added which is shared among all logging calls. The size of `test_log` remained unchanged. There are even bigger savings from Folly Formatter instantiations which are no longer needed, e.g.

```
0000000004238032 0000000000001363 W _ZNK5folly13BaseFormatterINS_9FormatterILb0EJRKiRKdEEELb0EJS3_S5_EEclIZNKS7_8appendToINSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEEENSt9enable_ifIXsr12IsSomeStringIT_EE5valueEvE4typeERSH_EUlNS_5RangeIPKcEEE_EEvSK_
```

So in total this change results in ~5x per-call/instantiation binary size. It is possible to reduce binary size even further but it is not done in the current diff to keep it manageable.

In addition to binary size improvements, switching to fmt will potentially

* allow catching errors in format strings at compile time,
* simplify future migration to C++20 [`std::format`](http://eel.is/c++draft/format).

Reviewed By: simpkins

Differential Revision: D15485589

fbshipit-source-id: 06db4436839f11c2c3dbed7b36658e2193343411
parent 8e0ca467
......@@ -210,3 +210,6 @@ target_link_libraries(folly_deps INTERFACE
${FOLLY_SHINY_DEPENDENCIES}
${FOLLY_ASAN_FLAGS}
)
find_package(fmt CONFIG REQUIRED)
target_link_libraries(folly_deps INTERFACE fmt::fmt)
......@@ -5,9 +5,9 @@ from __future__ import division
from __future__ import print_function
from __future__ import unicode_literals
import specs.folly as folly
import specs.fizz as fizz
import specs.fmt as fmt
import specs.folly as folly
import specs.rsocket as rsocket
import specs.sodium as sodium
import specs.wangle as wangle
......@@ -16,7 +16,7 @@ import specs.zstd as zstd
def fbcode_builder_spec(builder):
return {
'depends_on': [folly, fizz, fmt, sodium, rsocket, wangle, zstd],
'depends_on': [fmt, folly, fizz, sodium, rsocket, wangle, zstd],
'steps': [
builder.fb_github_cmake_install('fbthrift/thrift'),
],
......
......@@ -6,6 +6,7 @@ from __future__ import print_function
from __future__ import unicode_literals
import specs.fbthrift as fbthrift
import specs.fmt as fmt
import specs.folly as folly
import specs.gmock as gmock
import specs.sodium as sodium
......@@ -17,7 +18,7 @@ from shell_quoting import ShellQuoted
def fbcode_builder_spec(builder):
builder.add_option('zeromq/libzmq:git_hash', 'v4.2.2')
return {
'depends_on': [folly, fbthrift, gmock, sodium, sigar],
'depends_on': [fmt, folly, fbthrift, gmock, sodium, sigar],
'steps': [
builder.github_project_workdir('zeromq/libzmq', '.'),
builder.step('Build and install zeromq/libzmq', [
......
......@@ -5,6 +5,7 @@ from __future__ import division
from __future__ import print_function
from __future__ import unicode_literals
import specs.fmt as fmt
import specs.folly as folly
import specs.sodium as sodium
......@@ -20,7 +21,7 @@ def fbcode_builder_spec(builder):
}
)
return {
'depends_on': [folly, sodium],
'depends_on': [fmt, folly, sodium],
'steps': [
builder.fb_github_cmake_install(
'fizz/fizz/build',
......
......@@ -5,6 +5,7 @@ from __future__ import division
from __future__ import print_function
from __future__ import unicode_literals
import specs.fmt as fmt
import specs.folly as folly
import specs.fizz as fizz
import specs.mvfst as mvfst
......@@ -26,6 +27,6 @@ def fbcode_builder_spec(builder):
)
return {
"depends_on": [folly, wangle, fizz, sodium, zstd, mvfst],
"depends_on": [fmt, folly, wangle, fizz, sodium, zstd, mvfst],
"steps": [builder.fb_github_cmake_install("proxygen/proxygen", "..")],
}
......@@ -6,12 +6,13 @@ from __future__ import print_function
from __future__ import unicode_literals
import specs.gmock as gmock
import specs.fmt as fmt
import specs.folly as folly
def fbcode_builder_spec(builder):
return {
'depends_on': [folly],
'depends_on': [fmt, folly],
'steps': [
builder.fb_github_cmake_install(
'rsocket-cpp/rsocket',
......
......@@ -5,6 +5,7 @@ from __future__ import division
from __future__ import print_function
from __future__ import unicode_literals
import specs.fmt as fmt
import specs.folly as folly
import specs.fizz as fizz
import specs.sodium as sodium
......@@ -20,7 +21,7 @@ def fbcode_builder_spec(builder):
}
)
return {
'depends_on': [folly, fizz, sodium],
'depends_on': [fmt, folly, fizz, sodium],
'steps': [
builder.fb_github_cmake_install('wangle/wangle/build'),
],
......
......@@ -16,9 +16,9 @@
#pragma once
#include <fmt/core.h>
#include <folly/CPortability.h>
#include <folly/Conv.h>
#include <folly/Format.h>
#include <folly/Portability.h>
#include <folly/logging/LogCategory.h>
#include <folly/logging/LogMessage.h>
......@@ -336,20 +336,12 @@ class LogStreamProcessor {
}
}
/**
* Construct a log message string using folly::sformat()
*
* This function attempts to avoid throwing exceptions. If an error occurs
* during formatting, a message including the error details is returned
* instead. This is done to help ensure that log statements do not generate
* exceptions, but instead just log an error string when something goes wrong.
*/
template <typename... Args>
FOLLY_NOINLINE std::string formatLogString(
FOLLY_NOINLINE std::string vformatLogString(
folly::StringPiece fmt,
const Args&... args) noexcept {
fmt::format_args args,
bool& failed) noexcept {
try {
return folly::sformat(fmt, args...);
return fmt::vformat(fmt::string_view(fmt.data(), fmt.size()), args);
} catch (const std::exception& ex) {
// This most likely means that the caller had a bug in their format
// string/arguments. Handle the exception here, rather than letting it
......@@ -358,17 +350,38 @@ class LogStreamProcessor {
//
// Log the format string and as much of the arguments as we can convert,
// to aid debugging.
failed = true;
std::string result;
result.append("error formatting log message: ");
result.append(ex.what());
result.append("; format string: \"");
result.append(fmt.data(), fmt.size());
result.append("\", arguments: ");
folly::logging::appendToString(result, args...);
return result;
}
}
/**
* Construct a log message string using fmt::format()
*
* This function attempts to avoid throwing exceptions. If an error occurs
* during formatting, a message including the error details is returned
* instead. This is done to help ensure that log statements do not generate
* exceptions, but instead just log an error string when something goes wrong.
*/
template <typename... Args>
FOLLY_NOINLINE std::string formatLogString(
folly::StringPiece fmt,
const Args&... args) noexcept {
bool failed = false;
std::string result =
vformatLogString(fmt, fmt::make_format_args(args...), failed);
if (failed) {
folly::logging::appendToString(result, args...);
}
return result;
}
const LogCategory* const category_;
LogLevel const level_;
folly::StringPiece filename_;
......
......@@ -16,8 +16,6 @@
#pragma once
#include <folly/Conv.h>
#include <folly/Format.h>
#include <folly/logging/LogCategory.h>
#include <folly/logging/LogLevel.h>
#include <folly/logging/LogStream.h>
......@@ -40,9 +38,9 @@
##__VA_ARGS__)
/**
* Log a message to the specified logger, using a folly::format() string.
* Log a message to the specified logger, using a fmt::format() string.
*
* The arguments will be processed using folly::format(). The format syntax
* The arguments will be processed using fmt::format(). The format syntax
* is similar to Python format strings.
*
* This macro avoids evaluating the log arguments unless the log level check
......@@ -85,7 +83,7 @@
/**
* FB_LOGF_RAW() is similar to FB_LOG_RAW(), but formats the log arguments
* using folly::format().
* using fmt::format().
*/
#define FB_LOGF_RAW( \
logger, level, filename, linenumber, functionName, fmt, arg1, ...) \
......
......@@ -97,11 +97,11 @@ Other Advantages
Beyond the primary goals mentioned above, this log library does have some other
advantages over glog:
## Support for using `folly::format()` to generate formatted log messages
## Support for using `fmt::format()` to generate formatted log messages
Two separate mechanisms are provided for formatting log messages: basic
concatenation of arguments into string (using `folly::to<std::string>()`),
and more flexible formatting using `folly::format()`. This provides convenient
and more flexible formatting using `fmt::format()`. This provides convenient
and type-safe mechanisms for formatting log messages.
## Escapes unprintable characters in log messages by default.
......
......@@ -83,12 +83,12 @@ This can help ensure that all logs of a certain level or above are persisted
before a potential crash while ensuring that all logs below that level remain
non-blocking.
## Support for folly::format()
## Support for fmt::format()
The `XLOGF()` and `FB_LOGF()` macros format their arguments using
`folly::format()`. This allows log statements to use the powerful Python-like
`fmt::format()`. This allows log statements to use the powerful Python-like
format syntax supported by
[`folly::format()`](https://github.com/facebook/folly/blob/master/folly/docs/Format.md)
[`fmt::format()`](https://fmt.dev/latest/syntax.html).
Additionally he `XLOG()` and `FB_LOG()` macros concatenate any log arguments
using `folly::to<string>()`, and also accept arguments via iostream-style `<<`
......
......@@ -67,8 +67,8 @@ mechanism.
XLOGF(DBG1, "cannot engage {} thruster: {}", thruster.name(), err.what());
```
This uses [`folly::format()`](https://github.com/facebook/folly/blob/master/folly/docs/Format.md)
to perform the formatting internally.
This uses [`fmt::format()`](https://fmt.dev/latest/api.html) to perform the
formatting internally.
# Log Category Selection
......
......@@ -20,6 +20,6 @@ namespace example {
ExampleObject::~ExampleObject() {
// All XLOG() statements in this file will log to the category
// folly.logging.example.lib
XLOGF(DBG1, "ExampleObject({}) at {} destroyed", value_, this);
XLOGF(DBG1, "ExampleObject({}) at {} destroyed", value_, fmt::ptr(this));
}
} // namespace example
......@@ -16,6 +16,7 @@
#pragma once
#include <fmt/format.h>
#include <folly/Range.h>
#include <folly/logging/xlog.h>
......@@ -26,7 +27,7 @@ class ExampleObject {
explicit ExampleObject(folly::StringPiece str) : value_{str.str()} {
// All XLOG() statements in this file will log to the category
// folly.experimental.logging.example.lib
XLOGF(DBG1, "ExampleObject({}) constructed at {}", value_, this);
XLOGF(DBG1, "ExampleObject({}) constructed at {}", value_, fmt::ptr(this));
}
~ExampleObject();
......
......@@ -16,6 +16,7 @@
#include <cstdlib>
#include <folly/Format.h>
#include <folly/init/Init.h>
#include <folly/logging/CustomLogFormatter.h>
#include <folly/logging/LogMessage.h>
......
......@@ -16,6 +16,7 @@
#include <cstdlib>
#include <folly/Format.h>
#include <folly/init/Init.h>
#include <folly/logging/GlogStyleFormatter.h>
#include <folly/logging/LogMessage.h>
......
......@@ -15,6 +15,7 @@
*/
#include <folly/logging/Logger.h>
#include <fmt/format.h>
#include <folly/logging/LogCategory.h>
#include <folly/logging/LogHandler.h>
#include <folly/logging/LogMessage.h>
......@@ -100,7 +101,7 @@ TEST_F(LoggerTest, formatMessage) {
EXPECT_EQ(logger_.getCategory(), messages[0].second);
}
TEST_F(LoggerTest, follyFormatError) {
TEST_F(LoggerTest, formatError) {
// If we pass in a bogus format string, logf() should not throw.
// It should instead log a message, just complaining about the format error.
FB_LOGF(
......@@ -112,7 +113,7 @@ TEST_F(LoggerTest, follyFormatError) {
// differently on different platforms.
EXPECT_EQ(
R"(error formatting log message: )"
R"(invalid format argument {:6.3f}: invalid specifier 'f'; )"
R"(invalid type specifier; )"
R"(format string: "param1: {:06d}, param2: {:6.3f}", )"
R"(arguments: 1234, hello world!)",
messages[0].first.getMessage());
......@@ -146,37 +147,30 @@ class FormattableButNoToString {
uint32_t value = 0;
};
// clang-format off
[[noreturn]] void toAppend(
const ToStringFailure& /* arg */,
std::string* /* result */) {
throw std::runtime_error(
"error converting ToStringFailure object to a string");
}
namespace folly {
namespace fmt {
template <>
class FormatValue<ToStringFailure> {
public:
explicit FormatValue(ToStringFailure) {}
template <class FormatCallback>
void format(FormatArg& arg, FormatCallback& cb) const {
FormatValue<std::string>("ToStringFailure").format(arg, cb);
struct formatter<ToStringFailure> : formatter<std::string> {
auto format(ToStringFailure, format_context& ctx) {
return ctx.out();
}
};
template <>
class FormatValue<FormattableButNoToString> {
public:
explicit FormatValue(FormattableButNoToString) {}
template <class FormatCallback>
void format(FormatArg&, FormatCallback&) const {
struct formatter<FormattableButNoToString> : formatter<std::string> {
auto format(FormattableButNoToString, format_context& ctx) {
throw std::runtime_error("test");
return ctx.out();
}
};
} // namespace folly
} // namespace fmt
// clang-format off
[[noreturn]] void toAppend(
const ToStringFailure& /* arg */,
std::string* /* result */) {
throw std::runtime_error(
"error converting ToStringFailure object to a string");
}
// clang-format on
TEST_F(LoggerTest, toStringError) {
......@@ -213,8 +207,7 @@ TEST_F(LoggerTest, formatFallbackError) {
EXPECT_THAT(
messages[0].first.getMessage(),
MatchesRegex(
R"(error formatting log message: invalid format argument \{\}: )"
R"(argument index out of range, max=2; )"
R"(error formatting log message: argument index out of range; )"
R"(format string: "param1: \{\}, param2: \{\}, \{\}", )"
R"(arguments: 1234, )"
R"(\[(.*ToStringFailure.*|object) of size (.*):.*\])"));
......@@ -351,8 +344,7 @@ TEST_F(LoggerTest, logMacros) {
FB_LOGF(footest1234, ERR, "whoops: {}, {}", getValue());
ASSERT_EQ(1, messages.size());
EXPECT_EQ(
R"(error formatting log message: invalid format argument {}: )"
R"(argument index out of range, max=1; )"
R"(error formatting log message: argument index out of range; )"
R"(format string: "whoops: {}, {}", arguments: 5)",
messages[0].first.getMessage());
messages.clear();
......
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