流式日志

了解 bRPC 流式日志。

名称

streaming_log - 将日志打印到 std::ostream

概要

#include <butil/logging.h>

LOG(FATAL) << "Fatal error occurred! contexts=" << ...;
LOG(WARNING) << "Unusual thing happened ..." << ...;
LOG(TRACE) << "Something just took place..." << ...;
LOG(TRACE) << "Items:" << noflush;
LOG_IF(NOTICE, n > 10) << "This log will only be printed when n > 10";
PLOG(FATAL) << "Fail to call function setting errno";
VLOG(1) << "verbose log tier 1";
CHECK_GT(1, 2) << "1 can't be greater than 2";

LOG_EVERY_SECOND(INFO) << "High-frequent logs";
LOG_EVERY_N(ERROR, 10) << "High-frequent logs";
LOG_FIRST_N(INFO, 20) << "Logs that prints for at most 20 times";
LOG_ONCE(WARNING) << "Logs that only prints once";

描述

流式日志是打印复杂对象或模板对象的最佳选择。由于大多数对象比较复杂，用户需要先把所有字段转换为字符串，才能配合 printf 和 %s 使用。然而这种方式非常不便（无法直接追加数字），并且需要大量临时内存（由字符串引起）。C++ 中的解决方案是将日志以流的形式发送到 std::ostream 对象。例如，为了打印对象 A，我们需要实现以下接口：

std::ostream& operator<<(std::ostream& os, const A& a);

该函数的签名意味着将对象 a 输出到 os，然后返回 os。os 的返回值使我们能够把二元运算符 << 组合起来（左结合）。因此，os << a << b << c; 表示 operator<<(operator<<(operator<<(os, a), b), c);。显然 operator<< 需要返回一个引用来完成这一过程，这也被称为链式调用。在不支持运算符重载的语言中，你会看到更繁琐的形式，例如 os.print(a).print(b).print(c)。

你在自己实现 operator<< 时也应当使用链式调用。实际上，打印一个复杂对象就像对树进行深度优先搜索（DFS）：对每个子节点调用 operator<<，然后每个子节点再对孙节点调用该函数，依此类推。例如，对象 A 有两个成员变量：B 和 C。打印 A 就变成了将 B 和 C 放入 ostream 的过程：

struct A {
    B b;
    C c;
};
std::ostream& operator<<(std::ostream& os, const A& a) {
    return os << "A{b=" << a.b << ", c=" << a.c << "}";
}

B 和 C 的数据结构及打印函数：

struct B {
    int value;
};
std::ostream& operator<<(std::ostream& os, const B& b) {
    return os << "B{value=" << b.value << "}";
}

struct C {
    string name;
};
std::ostream& operator<<(std::ostream& os, const C& c) {
    return os << "C{name=" << c.name << "}";
}

最后，打印对象 A 的结果为：

A{b=B{value=10}, c=C{name=tom}}

这样一来，我们就不需要分配临时内存，因为对象是直接传入 ostream 对象的。当然，ostream 本身的内存管理是另一个话题。

好了，现在我们通过 ostream 把整个打印过程串联了起来。最常见的 ostream 对象是 std::cout 和 std::cerr，因此实现了上述函数的对象可以直接发送到 std::cout 和 std::cerr。换句话说，如果一个日志流也继承了 ostream，那么这些对象就可以写入日志。流式日志（Streaming log）就是这样一种继承了 std::ostream 的日志流，用于将对象送入日志。在当前实现中，日志记录在线程本地的缓冲区中，一条完整的日志记录生成后会被刷新到屏幕或 logging::LogSink。当然，该实现是线程安全的。

LOG

如果你以前用过 glog，应该会觉得上手很容易。日志宏与 glog 相同。例如，要打印一条 FATAL 日志（注意这里没有 std::endl）：

LOG(FATAL) << "Fatal error occurred! contexts=" << ...;
LOG(WARNING) << "Unusual thing happened ..." << ...;
LOG(TRACE) << "Something just took place..." << ...;

与 glog 对应的流式日志级别：

流式日志	glog	用途
FATAL	FATAL（coredump）	致命错误。由于百度内部大多数致命日志实际上并不致命，因此它不会像 glog 那样直接触发 coredump，除非你开启 -crash_on_fatal_log
ERROR	ERROR	非致命错误。
WARNING	WARNING	不常见的分支。
NOTICE	-	通常你不应使用 NOTICE，它是为重要的业务日志准备的。请务必先与其他开发者确认。glog 没有 NOTICE。
INFO, TRACE	INFO	重要的副作用，例如打开/关闭某些资源。
VLOG(n)	INFO	支持多级的详细日志。
DEBUG	INFOVLOG(1) (NDEBUG)	仅用于兼容。只有在未定义 `NDEBUG` 时才打印日志。更多信息参见 DLOG/DPLOG/DVLOG。

PLOG

PLOG 与 LOG 的区别在于，它会在日志末尾追加错误信息。这有点像 printf 中的 %m。在 POSIX 环境下，错误码是 errno。

int fd = open("foo.conf", O_RDONLY);   // foo.conf does not exist, errno was set to ENOENT
if (fd < 0) {
    PLOG(FATAL) << "Fail to open foo.conf";    // "Fail to open foo.conf: No such file or directory"
    return -1;
}

noflush

如果你不想立即刷新日志，可以追加 noflush。它通常在循环内部使用：

LOG(TRACE) << "Items:" << noflush;
for (iterator it = items.begin(); it != items.end(); ++it) {
    LOG(TRACE) << ' ' << *it << noflush;
}
LOG(TRACE);

前两条 LOG(TRACE) 不会将日志刷新到屏幕上，它们被记录在线程本地缓冲区中。第三条 LOG(TRACE) 会将所有日志刷新到屏幕上。如果 items 中有 3 个元素，而我们不追加 noflush，结果将是：

TRACE: ... Items:
TRACE: ...  item1
TRACE: ...  item2
TRACE: ...  item3

添加 noflush 之后：

TRACE: ... Items: item1 item2 item3

noflush 特性同样支持 bthread，这样我们就可以从服务端的各个 bthread 中推送大量日志而不实际打印它们（使用 noflush），并在 RPC 结束时一次性刷新整段日志。注意，在实现异步方法时不应使用 noflush，因为它会切换底层的 bthread，导致 noflush 失效。

LOG_IF

LOG_IF(log_level, condition) 仅在条件为真时打印。它的作用与 if (condition) { LOG() << ...; } 相同，但代码更简洁：

LOG_IF(NOTICE, n > 10) << "This log will only be printed when n > 10";

XXX_EVERY_SECOND

XXX 代表 LOG、LOG_IF、PLOG、SYSLOG、VLOG、DLOG 等日志宏。这些日志宏每秒最多打印一次日志。你可以用它们来检查热点区域内的运行状态。第一次调用该宏会立即打印日志，与普通的 LOG 相比会额外消耗 30ns（由 gettimeofday 引起）。

LOG_EVERY_SECOND(INFO) << "High-frequent logs";

XXX_EVERY_N

XXX 代表 LOG、LOG_IF、PLOG、SYSLOG、VLOG、DLOG 等。这些日志宏每 N 次打印一次日志。你可以用它们来检查热点区域内的运行状态。首次调用该宏时会立即打印日志，并且与普通 LOG 相比会额外执行一次原子操作（宽松内存序）。该宏是线程安全的，即来自多个线程的计数也是准确的，而 glog 则做不到这一点。

LOG_EVERY_N(ERROR, 10) << "High-frequent logs";

XXX_FIRST_N

XXX 代表 LOG、LOG_IF、PLOG、SYSLOG、VLOG、DLOG 等。这些日志宏最多打印 N 次日志。与普通的 LOG 相比，在达到 N 次之前会额外执行一次原子操作（宽松内存序），之后则无任何开销。

LOG_FIRST_N(ERROR, 20) << "Logs that prints for at most 20 times";

XXX_ONCE

XX 代表 LOG、LOG_IF、PLOG、SYSLOG、VLOG、DLOG 等。这些日志宏最多打印一次日志，其行为与 XXX_FIRST_N(..., 1) 相同。

LOG_ONCE(ERROR) << "Logs that only prints once";

VLOG

VLOG(verbose_level) 是支持多级详细程度的日志。它使用两个 gflags：–verbose 和 –verbose_module 来控制你想要的日志级别（注意 glog 使用的是 –v 和 –vmodule）。仅当 --verbose >= verbose_level 时，日志才会被打印：

VLOG(0) << "verbose log tier 0";
VLOG(1) << "verbose log tier 1";
VLOG(2) << "verbose log tier 2";

当 --verbose=1 时，前两条日志会被打印，而最后一条不会。Module 指不带扩展名的文件名或文件路径，且 --verbose_module 的值会覆盖 --verbose。例如：

--verbose=1 --verbose_module="channel=2,server=3"    # print VLOG of those with verbose value:
                                                     # channel.cpp <= 2
                                                     # server.cpp <= 3
                                                     # other files <= 1
--verbose=1 --verbose_module="src/brpc/channel=2,server=3"
                                                    # For files with same names, add paths

可以通过 google::SetCommandLineOption 动态设置 --verbose 和 --verbose_module。

VLOG 还有另一种形式 VLOG2，允许用户指定虚拟路径：

// public/foo/bar.cpp
VLOG2("a/b/c", 2) << "being filtered by a/b/c rather than public/foo/bar";

VLOG 与 VLOG2 也分别有对应的 VLOG_IF 和 VLOG2_IF。

DLOG

所有日志宏都有调试版本，以 D 开头，例如 DLOG、DVLOG。当定义了 NDEBUG 时，这些日志不会被打印。

不要把有重要副作用的操作放在以 D 开头的日志流中。

不打印意味着连参数都不会被求值。如果你的参数有副作用，当定义了 NDEBUG 时它们就不会执行。例如 DLOG(FATAL) << foo();，其中 foo 是一个函数，或者它会修改一个字典，无论哪种情况，它都很重要。然而，当定义了 NDEBUG 时，它不会被求值。

CHECK

日志的另一个重要变体是 CHECK(expression)。当表达式的值为假时，它会打印一条致命日志。它有点类似于 gtest 中的 ASSERT，还有其他形式，例如 CHECK_EQ、CHECK_GT 等。当检查失败时，其后的消息会被打印出来。

CHECK_LT(1, 2) << "This is definitely true, this log will never be seen";
CHECK_GT(1, 2) << "1 can't be greater than 2";

运行上面的代码，你应该会看到一条 fatal 日志以及调用栈：

FATAL: ... Check failed: 1 > 2 (1 vs 2). 1 can't be greater than 2
#0 0x000000afaa23 butil::debug::StackTrace::StackTrace()
#1 0x000000c29fec logging::LogStream::FlushWithoutReset()
#2 0x000000c2b8e6 logging::LogStream::Flush()
#3 0x000000c2bd63 logging::DestroyLogStream()
#4 0x000000c2a52d logging::LogMessage::~LogMessage()
#5 0x000000a716b2 (anonymous namespace)::StreamingLogTest_check_Test::TestBody()
#6 0x000000d16d04 testing::internal::HandleSehExceptionsInMethodIfSupported<>()
#7 0x000000d19e96 testing::internal::HandleExceptionsInMethodIfSupported<>()
#8 0x000000d08cd4 testing::Test::Run()
#9 0x000000d08dfe testing::TestInfo::Run()
#10 0x000000d08ec4 testing::TestCase::Run()
#11 0x000000d123c7 testing::internal::UnitTestImpl::RunAllTests()
#12 0x000000d16d94 testing::internal::HandleSehExceptionsInMethodIfSupported<>()

调用栈的第二列是代码段的地址。你可以使用 addr2line 来查看对应的文件与行号：

$ addr2line -e ./test_base 0x000000a716b2
/home/gejun/latest_baidu_rpc/public/common/test/test_streaming_log.cpp:223

你应该使用 CHECK_XX 来表达算术条件，这样当检查失败时可以看到更详细的信息。

int x = 1;
int y = 2;
CHECK_GT(x, y);  // Check failed: x > y (1 vs 2).
CHECK(x > y);    // Check failed: x > y.

与 DLOG 一样，你不应该在 DCHECK 中包含重要的副作用。

LogSink

流式日志的默认输出目标是屏幕。你可以通过 logging::SetLogSink 来更改它。用户可以继承 LogSink 并实现自己的输出逻辑。我们提供了一个内部的 LogSink 作为示例：

StringSink

同时继承 LogSink 和 string。将日志内容存储在 string 中，主要用于单元测试。下面的示例展示了 StringSink 的经典用法：

TEST_F(StreamingLogTest, log_at) {
    ::logging::StringSink log_str;
    ::logging::LogSink* old_sink = ::logging::SetLogSink(&log_str);
    LOG_AT(FATAL, "specified_file.cc", 12345) << "file/line is specified";
    // the file:line part should be using the argument given by us.
    ASSERT_NE(std::string::npos, log_str.find("specified_file.cc:12345"));
    // restore the old sink.
    ::logging::SetLogSink(old_sink);
}

最后修改于 2022 年 2 月 26 日：[brpc 网站 1.0 修复概览页面中的链接跳转问题 (14eec1ac1)]](https://github.com/apache/brpc-website/commit/14eec1ac1805c1dde9f10d0353984bde2127294c)

流式日志

流式日志

名称

概要

描述

LOG

PLOG

noflush

LOG_IF

XXX_EVERY_SECOND

XXX_EVERY_N

XXX_FIRST_N

XXX_ONCE

VLOG

DLOG

CHECK

LogSink

StringSink

评论