C++ 日志库大体上有两种 API 风格:
Stream 风格使用起来更自然,不必费心保持格式字符串与参数类型的一致性。而且当输出日志级别高于日志级别时,打印日志是个空操作,运行时开销接近零。
5.1 功能需求
日志需要有多种 level:TRACE、DEBUG、INFO、WARN、ERROR、FATAL等。
日志输出级别应该在运行时可调整,不应重新编译,也不需要重启进程,只要调用setLogLevel()
就能即时生效。
对于分布式系统中的服务进程,日志的目的地——本地文件。不能往网络写日志消息,因为诊断日志的功能之一就是诊断网络故障。
如果日志输出到本地文件,那么必须要滚动,这样可以简化日志归档的实现。滚动条件如下:
- 文件大小(达到阈值就换下一个文件)
- 时间(每天固定时间新建一个日志文件,不论前一个文件有没有写满)
日志命名规范
一个典型日志文件名如下:
- 第一部分
logfile_test
是进程名,通常是main()
函数参数中argv[0]
的 basename,必要时可以加入程序 version。(basename 得到特定路径中的最后一个’/‘后面的内容) - 第二部分:文件创建时间(GMT 时区),可以通过文件名来选择某一时间范围内的日志。
- 第三部分:机器名称,这样即便日志文件发生机器间拷贝,也可以溯源。
- 第四部分:进程 id,如果一个程序一秒之内反复启动,那么每次都会生成不同的日志文件。
- 第五部分:统一后缀名
.log
。
程序 crash 时日志相关问题
如果程序发生崩溃,那么最后若干条日志往往会丢失,因为日志库不能每条消息都刷盘,更不能每条消息都 open/close 文件,性能开销过大。
muduo 采用两种办法:
- 定期(默认 3 秒)将缓冲区的日志消息 flush 到硬盘。
- 每条内存中的日志消息都带有 cookie(或者叫哨兵/sentry),其值为某个函数的地址,这样可以在 core dump 文件中查找 cookie,定位到尚未来得及写入磁盘的消息。
日志消息格式 HINTS
- 每条日志占一行。方便用
awk``sed``grep
等命令行工具定位。 - 时间戳精确到微秒。每条消息都通过
gettimeofday()
获得当前时间,因为不是系统调用所以没有性能损失。 - 始终使用 GMT 时区。
- 打印线程 id。便于缝隙多线程程序的时序,也可以检测死锁。(此处指调用 LOG_INFO<< 的线程)
- 打印日志级别。
- 打印源文件名和行号。
5.2 性能需求
muduo 中使用了几个优化措施,以达到性能指标:
- 时间戳字符串中的日期和时间两部分是缓存的,一秒之内的多条日志只需重新格式化微秒部分。
- 日志消息的前 4 个字段是定长的,可以避免在运行期求字符串长度(避免反复调用
strlen()
)。因为编译期认识memcpy()
函数,对于定长的内存复制,会在编译期把它 inline 展开为高效的目标代码。 - 线程 id 是预格式化为字符串,在输出日志消息时只发生拷贝,而不产生调用。
源文件名采用编译期计算获得 basename,避免运行期
strrchr()
开销。5.3 多线程异步日志
多线程日志追求线程安全,简单的做法和其后果是:
用一个全局
mutex
保护 IO——造成全部线程抢一个锁;- 每个线程单独写一个日志文件——让业务线程阻塞在写磁盘操作上。
异步日志(非阻塞日志):用一个背景线程负责收集日志消息,并写入日志文件,其他业务线程只往这个背景线程发送日志消息。
因为网络 IO 线程或业务线程,直接进行写磁盘的话,可能偶尔会发生阻塞。这可能导致请求方超时、耽误发送心跳消息等。
需要一个“队列”将各个线程待写的日志消息传送到日志线程。不必每次产生一条消息都通知背景线程。
muduo 日志库采用双缓冲技术:
准备两块 buffer:A & B。业务线程负责往 buffer A 填充日志消息,背景线程负责将 buffer B 的数据写入文件。当 buffer A 写满之后,交换 A & B,让背景线程将 buffer A 的数据写入文件,业务线程往 buffer B 中填充日志消息。如此往复。此外,为了及时刷盘,即便 buffer 未满也会定期(预设值 == 3 秒)执行上述 swap-write 操作。
使用两个 buffer 的好处:产生新的日志消息时不必等待磁盘文件操作,也避免每条新日志消息都 wake-up 背景线程。减少了 wake-up 频度、降低开销。
muduo 部分源码内容和解读可以看原书 § 5.3最后。