05高效的多线程日志

最后修改:

日志 logging:

  • 诊断日志。即 log4j、logback、slf4j、glog、g2log、log4cxx、log4cpp、log4cplus、Pantheios、ezlogger 等常用日志库
  • 交易日志。即数据库的 write-ahead log、文件系统的journaling等,用于基类状态变更,通过回放日志可以逐步恢复每一次修改后的状态

通常记录:

  • 收到的每条内部消息的 id ,包括关键字段、长度、hash 等。
  • 收到的每条外部消息的全文
  • 发出的每条消息的全文,每条消息都有全局唯一的id
  • 关键内部状态的变更。。。

每条日志都有时间戳,这样能完整追踪分布式系统中一个事件的来龙去脉

一个日志库大体分为前端(muduo/base/Logging)和后端(muduo/base/LogFile)两部分

前端:应用程序使用的接口 (API),并生成日志消息(log message)。

后端:负责把日志消息写入目的地。

这两部分可能简单到只用一个回调函数

1
void output(const char* message, int len);

多线程程序中,前后端与单线程程序无区别,无非就是每个线程有自己的前端,整个程序共用一个后端。难点在于将日志数据从多个前端高效的传输到后端。(muduo/base/AsyncLogging)。典型的多生产者-单消费者。

C++ 日志库前端大体两种 API 风格:

  1. C/Java 的 printf(fmt, …) 风格。log_info(“Received %d bytes from %s”, len, getClientName().c_str());
  2. C++ 的 stream « 风格。LOG_INFO « “Received " « len « " bytes from " « getClientName();

muduo/base/LogStream C++ 风格

功能需求

  1. 日志消息级别,如 TRACE、DEBUG、INFO、WARN、ERROR、FATAL等。
  2. 日志消息由可能多个目的地。如文件、socket、SMTP等。
  3. 日志消息的格式可配置。如 org.apache.log4j.PatternLayout
  4. 可设置运行时过滤器,控制不同组件的日志消息级别和目的地。

1 必须,其他非必须

日志滚动条件两个:

  1. 文件大小
  2. 时间

文件名组成:

logfile_test.20120603-144022.hostname.3605.log

  1. logfile_test 进程名。通常 main() 函数参数中 argv[0] 的 basename(3), 容易区分哪个服务程序的日志。必要时加入版本
  2. 文件创建的时间(GMT时区)。方便选择时间范围, .20120603-14
  3. 机器名称。
  4. 进程id。
  5. 统一后缀名。

日志压缩归档交给单独脚本做,不在服务程序中做,这样机器上其他程序的也可以一起解决。

日志库不能每条消息都 flush 磁盘,都 open/close 文件,这样开销太大,muduo 两个方法应对:

  1. 定期(默认3s)将缓冲区内日志消息 flush 到硬盘
  2. 每条内存中的日志都有 cookie(或者叫哨兵值/sentry),某值为某个函数的地址,通过在 core dump 文件中查找 cookie (gdb find 指令。用 strings(1) 也能从core 文件找到不少有用信息)就能找到尚未来得及写入磁盘的消息

muduo 日志库默认消息格式:

1
2
日期        时间        微妙   线程   级别   正文   源文件名:行号
20120603    08:42:46.125779Z  23261  INFO   Hello -  test.cc:51

日志格式要点:

  • 尽量每条日志占一行。
  • 时间戳精确到微秒。gettimeofday(2) 获取当前时间。不是系统调用,不会陷入内核(Timestamp_unittest.ccTimestamp_unittest.cc)
  • 始终使用 GMT 时区(Z)。
  • 打印线程 id
  • 打印日志级别
  • 打印源文件名和行号

前 4 个字段固定,字段间使用空格隔开。日志消息避免出现正则表达式的元字符(对于 base64 编码的消息 id,可能将其中 + 替换为 - RFC4648 第 5 节)

性能需求

高效性体现在:

  1. 每秒写几千上万条日志的时候没有明显的性能损失
  2. 能应对一个进程产生的大量日志数据的场景。
  3. 不阻塞正常的执行流程。
  4. 多线程程序中不造成争用

具体性能体现:

  • 磁盘带宽 110MB/s,应该瞬间写满带宽
  • 如果每条日志平均长度 110 字节,意味着每秒写100万条日志。

测试(muduo/base/tests/Logging_test.cc)

几点优化措施:

  1. 时间戳字符串中的日期和时间两部分是缓存的。一秒内只需要重写微秒
  2. 日志消息前4个字段是定长的。编译器认识 memcpy 函数,对于定长内存的复制会在编译期 inline 展开为高效代码
  3. 线程 id 是预先格式化的字符串,输出日志消息时,只需简单拷贝几个字节
  4. 每行日志消息的源文件部分采用编译期计算来获得 basename,避免运行期 strrchr(3) 开销。

多线程异步日志

用一个背景线程负责收集日志,并写入日志文件,其他业务线程只管往这个“日志线程”发送日志消息,这称为异步日志。

muduo 日志库采用双缓存技术,基本思路就是:准备两块 buffer A 和 B。前端负责往 buffer A 填数据(日志消息),后端负责将 buffer B 的数据写入文件。当 buffer A 写满后,交换 A 和 B,让后端将 buffer A 的数据写入文件,而前端则往 buffer B填入新的日志消息,如此反复。

两个buffer 好处:新建日志消息时不必等待磁盘文件操作,也避免了每条新日志消息都触发(唤醒)后端日志线程。前端不是将一条条日志消息分别传送给后端,而是将多条日志消息拼成一个大的buffer传递给后端。相当于批处理。减少线程唤醒的频率,降低开销。

实际代码实现采用四个缓冲区,见(muduo/base/AsyncLogging.h)

如果前端疯狂写日志,后端处理缓慢,则可能会导致内存溢出的情况或分配内存失败导致程序崩溃,优化点,丢日志。

其他方案

也可以使用 BlockingQueue 或 BoundedBlockingQueue 方式。这种做法每条日志消息都需要分配内存。前端开辟的内存要求后端释放,对 malloc 的要求较高。

传递指针方案(recipes/logging/AsyncLogging)

性能需要测试,不是拍脑袋定方案。

muduo 异步日志使用一个全局锁,虽然临界区很小,但是如果线程数目较多,锁争用也会有一定的影响性能。一种解决方法像 java 的 ConcurrentHashMap 那样用多个 bucket,前端写日志的时候,再按照线程 id 哈希到不同的 bucket 中,减少 contention

Linux 默认会把 core dump 写到当前目录,而且文件名时固定的 core,为了不让新的 core 冲调旧的, 可以通过 sysctl 设置 kernel.core_pattern 参数 也可以修改 /proc/sys/kernel/core_pattern,让每次 core dump 文件产生不同的文件。例如:%e.%t.%p.%u.core 参数含义见 man 5 core。也可以使用 Apport 来收集专用的诊断信息,见 https://wiki.ubuntu.com/Apport.

Reference

http://en.wikipedia.org/wiki/Write-ahead_logging 不同数据库称呼不同,如 binary log、redo log等。

http://en.wikipedia.org/wiki/Journaling_file_system

http://en.wikipedia.org/wiki/Traceability

http://highscalability.com/log-everything-all-time

http://www.pantheios.org

http://www.drdobbs.com/cpp/201804215

http://logging.apache.org/log4j/1.2/manual.html

http://logback.qos.ch/manual/index.html

http://lwn.net/Articles/446528

http://en.wikipedia.org/wiki/Multiple_buffering

https://www.cs.cornell.edu/~ragarwal/pubs/network-stack.pdf

https://github.com/chenshuo/muduo/discussions/579

山重水复疑无路,柳暗花明又一村
使用 Hugo 构建
主题 StackJimmy 设计