微信终端跨平台组件 Mars 系列 1 高性能日志模块 xlog

前言

mars 是微信官方的终端基础组件，是一个使用 C++ 编写的业务性无关，平台性无关的基础组件。目前已接入微信 Android、iOS、Mac、Windows、WP 等客户端。现正在筹备开源中，它主要包括以下几个部分：

1. comm：可以独立使用的公共库，包括 socket、线程、消息队列等
2. xlog：可以独立使用的日志模块
3. sdt：可以独立使用的网络诊断模块
4. stn：可以独立使用的信令分发网路模块

本文章是 mars 系列的第一篇：高性能跨平台日志模块。

正文

对于移动开发者来说，最大的尴尬莫过于用户反馈程序出现问题，但因为不能重现且没有日志无法定位具体原因。这样看来客户端日志颇有点“养兵千日，用兵一时”的感觉，只有当出现问题且不容易重现时才能体现它的重要作用。为了保证关键时刻有日志可用，就需要保证程序整个生命周期内都要打日志，所以日志方案的选择至关重要。

常规方案

方案描述: 对每一行日志加密写文件

例如 Android 平台使用 java 实现日志模块，每有一句日志就加密写进文件。这样在使用过程中不仅存在大量的 GC，更致命的是因为有大量的 IO 需要写入，影响程序性能很容易导致程序卡顿。选择这种方案，在 release 版本只能选择把日志关掉。当有用户反馈时，就需要给用户重新编一个打开日志的安装包，用户重新安装重现后再通过日志来定位问题。不仅定位问题的效率低下，而且并不能保证每个需要定位的问题都能重现。这个方案可以说主要是为程序发布前服务的。

来看一下直接写文件为什么会导致程序卡顿

当写文件的时候，并不是把数据直接写入了磁盘，而是先把数据写入到系统的缓存(dirty page)中，系统一般会在下面几种情况把 dirty page 写入到磁盘：

• 定时回写，相关变量在/proc/sys/vm/dirty_writeback_centisecs和/proc/sys/vm/dirty_expire_centisecs中定义。
• 调用 write 的时候，发现 dirty page 占用内存超过系统内存一定比例，相关变量在/proc/sys/vm/dirty_background_ratio（ 后台运行不阻塞 write）和/proc/sys/vm/dirty_ratio（阻塞 write）中定义。
• 内存不足。

数据从程序写入到磁盘的过程中，其实牵涉到两次数据拷贝：一次是用户空间内存拷贝到内核空间的缓存，一次是回写时内核空间的缓存到硬盘的拷贝。当发生回写时也涉及到了内核空间和用户空间频繁切换。 dirty page 回写的时机对应用层来说又是不可控的，所以性能瓶颈就出现了。

这个方案存在的最主要的问题：因为性能影响了程序的流畅性。对于一个 App 来说，流畅性尤为重要，因为流畅性直接影响用户体验，最基本的流畅性的保证是使用了日志不会导致卡顿，但是流畅性不仅包括了系统没有卡顿，还要尽量保证没有 CPU 峰值。所以一个优秀的日志模块必须保证流畅性：

• 不能影响程序的性能。最基本的保证是使用了日志不会导致程序卡顿

我觉得绝大部分人不会选择这一个方案。

进一步思考

在上个方案中，因为要写入大量的 IO 导致程序卡顿，那是否可以先把日志缓存到内存中，当到一定大小时再加密写进文件，为了进一步减少需要加密和写入的数据，在加密之前可以先进行压缩。至于 Android 下存在频繁 GC 的问题，可以使用 C++ 来实现进行避免，而且通过 C++ 可以实现一个平台性无关的日志模块。

方案描述:把日志写入到作为 log 中间 buffer 的内存中，达到一定条件后压缩加密写进文件。

这个方案的整体的流程图：

这个方案基本可以解决 release 版本因为流畅性不敢打日志的问题，并且对于流畅性解决了最主要的部分：由于写日志导致的程序卡顿的问题。但是因为压缩不是 realtime compress，所以仍然存在 CPU 峰值。但这个方案却存在一个致命的问题：丢日志。

理想中的情况：当程序 crash 时， crash 捕捉模块捕捉到 crash， 然后调用日志接口把内存中的日志刷到文件中。但是实际使用中会发现程序被系统杀死不会有事件通知，而且很多异常退出，crash 捕捉模块并不一定能捕捉到。而这两种情况恰恰是平时跟进的重点，因为没有 crash 堆栈辅助定位问题，所以丢日志的问题这个时候显得尤为凸显。

在实际实践中，Android 可以使用共享内存做中间 buffer 防止丢日志，但其他平台并没有太好的办法，而且 Android 4.0 以后，大部分手机不再有权限使用共享内存，即使在 Android 4.0 之前，共享内存也不是一个公有接口，使用时只能通过系统调用的方式来使用。所以这个方案仍然存在不足：

• 如果损坏一部分数据虽然不会累及整个日志文件但会影响整个压缩块

• 个别情况下仍然会丢日志，而且集中压缩会导致 CPU 短时间飙高

通过这个方案，可以看出日志不仅要保证程序的流畅性，还要保证日志内容的完整性和容错性：

• 不能因为程序被系统杀掉，或者发生了 crash， crash 捕捉模块没有捕捉到导致部分时间点没有日志， 要保证程序整个生命周期内都有日志。
• 不能因为部分数据损坏就影响了整个日志文件，应该最小化数据损坏对日志文件的影响。

mars 的日志模块 xlog

前面提到了使用内存做中间 buffer 做日志可能会丢日志，直接写文件虽然不会丢日志但又会影响性能。所以亟需一个既有直接写内存的性能，又有直接写文件的可靠性的方案，也就是 mars 在用的方案。

mmap

mmap 是使用逻辑内存对磁盘文件进行映射，中间只是进行映射没有任何拷贝操作，避免了写文件的数据拷贝。操作内存就相当于在操作文件，避免了内核空间和用户空间的频繁切换。

为了验证 mmap 是否真的有直接写内存的效率，我们写了一个简单的测试用例：把512 Byte的数据分别写入150 kb大小的内存和 mmap，以及磁盘文件100w次并统计耗时

从上图看出mmap几乎和直接写内存一样的性能，而且 mmap 既不会丢日志，回写时机对我们来说又基本可控。 mmap 的回写时机：

• 内存不足

• 进程 crash

• 调用 msync 或者 munmap

• 不设置 MAP_NOSYNC 情况下 30s-60s(仅限FreeBSD)

如果可以通过引入 mmap 既能保证高性能又能保证高可靠性，那么还存在的其他问题呢？比如集中压缩导致 CPU 短时间飙高，这个问题从上个方案就一直存在。而且使用 mmap 后又引入了新的问题，可以看一下使用 mmap 之后的流程：

前面已经介绍了，当程序被系统杀掉会把逻辑内存中的数据写入到 mmap 文件中，这时候数据是明文的，很容易被窥探，可能会有人觉得那在写进 mmap 之前先加密不就行了，但是这里又需要考虑，是压缩后再加密还是加密后再压缩的问题，很明显先压缩再加密效率比较高，这个顺序不能改变。而且在写入 mmap 之前先进行压缩，也会减少所占用的 mmap 的大小，进而减少 mmap 所占用内存的大小。所以最终只能考虑：是否能在写进逻辑内存之前就把日志先进行压缩，再进行加密，最后再写入到逻辑内存中。问题明确了：就是怎么对单行日志进行压缩，也就是其他模块每写一行日志日志模块就必须进行压缩。

压缩

现在是研究压缩的时候了。比较通用的压缩方案是先进行短语式压缩， 短语式压缩过程中有两个滑动窗口，历史滑动窗口和前向缓存窗口，在前向缓存窗口中通过和历史滑动窗口中的内容进行匹配从而进行编码。

比如这句绕口令：吃葡萄不吐葡萄皮，不吃葡萄倒吐葡萄皮。中间是有两块重复的内容“吃葡萄”和“吐葡萄皮”这两块。第二个“吃葡萄”的长度是 3 和上个“吃葡萄”的距离是 10 ，所以可以用 (10,3) 的值对来表示，同样的道理“吐葡萄皮”可以替换为 (10,4 )

这些没压缩的字符通过 ascci 编码其实也是 0-255 的整数，所以通过短语式压缩得到的结果实质上是一堆整数。对整数的压缩最常见的就是 huffman 编码。通用的压缩方案也是这么做的，当然中间还掺杂了游程编码，code length 的转换。但其实这个不是关注的重点。我们只需要明白整个压缩过程中，短语式压缩也就是 LZ77 编码完成最大的压缩部分也是最重要的部分就行了，其他模块的压缩其实是对这个压缩结果的进一步压缩，进一步压缩的方式主要使用 huffman 压缩，所以这里就需要基于数字出现的频率进行统计编码，也就是说如果滑动窗口大小没上限的前提下，越多的数据集中压缩，压缩的效果就越好。日志模块使用这个方案时压缩效果可以达到 86.3%。

既然 LZ77 编码已经完成了大部分压缩，那么是否可以弱化 huffman 压缩部分，比如使用静态 huffman 表，自定义字典等。于是我们测试了四种方案：

这里可以看出来后两种方案明显优于前两种，压缩率都可以达到 83.7%。第三种是把整个 app 生命周期作为一个压缩单位进行压缩，如果这个压缩单位中有数据损坏，那么后面的日志也都解压不出来。但其实在短语式压缩过程中，滑动窗口并不是无限大的，一般是 32kb ，所以只需要把一定大小作为一个压缩单位就可以了。这也就是第四个方案， 这样的话即使压缩单位中有部分数据损坏，因为是流式压缩，并不影响这个单位中损坏数据之前的日志的解压，只会影响这个单位中这个损坏数据之后的日志。

对于使用流式压缩后，我们采用了三台安卓手机进行了耗时统计，和之前使用通用压缩的的日志方案进行了对比(耗时为单行日志的平均耗时):

通过横向对比，可以看出虽然使用流式压缩的耗时是使用多条日志同时压缩的 2.5 倍左右，但是这个耗时本身就很小，是微秒级别的，几乎不会对性能造成影响。最关键的，多条日志同时压缩会导致 CPU 曲线短时间内极速升高，进而可能会导致程序卡顿，而流式压缩是把时间分散在整个生命周期内，CPU 的曲线更平滑，相当于把压缩过程中使用的资源均分在整个 app 生命周期内。

xlog 方案总结

该方案的简单描述：

使用流式压缩方式对单行日志进行压缩，压缩加密后写进作为 log 中间 buffer的 mmap 中，当 mmap 中的数据到达一定大小后再写进磁盘文件中。

虽然使用流式压缩并没有达到最理想的压缩率，但和 mmap 一起使用能兼顾流畅性 完整性 容错性 的前提下，83.7%的压缩率也是能接受的。使用这个方案，除非 IO 损坏或者磁盘没有可用空间，基本可以保证不会丢失任何一行日志。

在实现过程中，各个平台上也踩了不少坑，比如：

• iOS 锁屏后，因为文件保护属性的问题导致文件不可写，需要把文件属性改为 NSFileProtectionNone。

• boost 使用 ftruncate 创建的 mmap 是稀疏文件，当设备上无可用存储时，使用 mmap 过程中可能会抛出 SIGBUS 信号。通过对新建的 mmap 文件的内容全写'0'来解决。

• ……

日志模块还存在一些其他策略：

• 每次启动的时候会清理日志，防止占用太多用户磁盘空间

• 为了防止 sdcard 被拔掉导致写不了日志，支持设置缓存目录，当 sdcard 插上时会把缓存目录里的日志写入到 sdcard 上

• ……

在使用的接口方面支持多种匹配方式：

• 类型安全检测方式：%s %d 。例如：xinfo(“%s %d”, “test”, 1)
• 序号匹配的方式：%0 %1 。例如：xinfo(TSF”%0 %1 %0”, “test”, 1)
• 智能匹配的懒人模式：% 。例如：xinfo(TSF”% %_”, “test”, 1)

最后

对于终端设备来说，打日志并不只是把日志信息写到文件里这么简单。除了前文提到的流畅性 完整性 容错性，还有一个最重要的是安全性。基于不怕被破解，但也不能任何人都能破解的原则，对日志的规范比加密算法的选择更为重要，所以本文并没有讨论这一点。

从前面的几个方案中可以看出，一个优秀的日志模块必须做到：

• 不能把用户的隐私信息打印到日志文件里，不能把日志明文打到日志文件里。
• 不能影响程序的性能。最基本的保证是使用了日志不会导致程序卡顿。
• 不能因为程序被系统杀掉，或者发生了 crash，crash 捕捉模块没有捕捉到导致部分时间点没有日志， 要保证程序整个生命周期内都有日志。
• 不能因为部分数据损坏就影响了整个日志文件，应该最小化数据损坏对日志文件的影响。

上面这几点也即安全性 流畅性 完整性 容错性， 它们之间存在着矛盾关系：

• 如果直接写文件会卡顿，但如果使用内存做中间 buffer 又可能丢日志
• 如果不对日志内容进行压缩会导致 IO 卡顿影响性能，但如果压缩，部分损坏可能会影响整个压缩块，而且为了增大压缩率集中压缩又可能导致 CPU 短时间飙高。

mars 的日志模块 xlog 就是在兼顾这四点的前提下做到：高性能高压缩率、不丢失任何一行日志、避免系统卡顿和 CPU 波峰。