写日志的那些事儿

写日志简介

一般提到写日志，主要有下面几种不同的场景：

• 诊断日志：应用打印异常信息，排查问题用，一般是给人看的，输出格式会比较随意，里面可能会有异常堆栈，或者排查问题用的一些文本信息；

• 数据日志：一般是用来做监控和数据分析的，可以人肉临时分析，也可以给机器分析，要求格式比较固定；

• 交易日志：一般在日志式文件系统、NoSQL、DB 中使用，一般有 journaling，WAL（write-ahead logging），binlog。这种日志通常都不是给人看的。

EagleEye 写的日志，是数据日志，记录的是中间件的网络调用埋点，或者是应用的业务埋点，它们都通过调用 eagleeye-core 的 EagleEye API 输出。
EagleEye 在写日志方面，有下面几个目标：

• 写日志性能要足够好，应避免影响应用主流程；

• 写日志对系统影响尽量小，在系统压力很大的时候，甚至可以选择放弃输出日志。

在最老的实现里，EagleEye 使用了常见的 log4j 去写日志，在 1.1.3 版的大幅重构之后，就自己直接实现了写日志。
当时想法就是要简化写日志的逻辑，因为 EagleEye 并不是通用的写日志组件，而是写自己的埋点日志。不使用通用的日志框架，主要考虑有几点：

• 自己写，可控性强，可以做专门定制化，有利于提升性能

• 避免日志组件的依赖冲突问题，不用再担心 Classloader 隔离、类加载等

• 可以把很多 EagleEye 不需要的通用逻辑砍掉，例如配置化、日志级别（LogLevel）、日志格式（Layout）、层次结构（Category）、多种输出实现（Appender）

从写日志这个功能上面讲，可以细分成三步：

• 写日志到 logger：指调用 log(...) 方法，把字符串和相关参数传到日志框架。对于框架来说，这是一个追加日志的事件（LogEvent）。

• 把日志编码成字符串或字节：指把日志事件格式化，编码成字符串或字节数组的过程，例如每行日志按照指定格式追加时间戳、日志级别、代码位置等信息，就是在这一步完成。

• 日志输出到目的地：通用日志框架可以指定多个输出目的地（Appender），目的地不仅可以是写本地文件，甚至可以是走网络、存数据库、发消息等。

下面就这三步，结合 EagleEye 关注的目标，说说在这些方面遇到了什么问题，以及如何实现的。

写日志到 logger

同步写的问题

多线程环境并发写日志，首先需要保证线程安全，就是说，多个线程一起写日志时，内容不能出现交织。
要做到这一点，最最简单的办法，就是每条线程单独写一个文件，这个方案在淘宝是不现实的，因为应用的线程非常多（仅 HSF 线程池就已经有 600 个线程），如果采用这个方案，会产生很多日志文件。
再简单一点的办法是把写日志作为临界区，进入临界区时用锁来保证每一时刻只有一个线程在写日志，例如 BufferedOutputStream 就是一个写时同步的实现。
应用用 log4j、logback 打日志，如果没特殊配置过，一般就是同步写的。

EagleEye 的 1.1.x 版自己实现写日志，用的就是同步写的方案。使用同步写一般是很快的，但是极偶尔会出现写日志写 hang 住的情况，这时候会把当前正在写日志的线程卡住，其它要写日志的线程就会堵塞在临界区外面等待。
EagleEye 1.1.x 版上线后，遇到过好几次应用的 HSF 线程池里几乎全部线程都卡在写 EagleEye 日志上的情况，导致这台服务器的服务有一段时间基本不可用。出现写硬盘 hang 住的情况虽然不多见，但是起因很难排查，对于 EagleEye 这种网络调用埋点，一旦卡住，就会导致这次调用超时。如果是业务线程写日志 hang 住，就会导致业务请求处理超时。（所以应用使用同步去写日志，都会有因为写日志导致响应超时的风险。）

异步写，基于 BlockingQueue

在 1.2.x 之后，改用了异步写的方案：任何线程要写日志，只需要把日志事件对象加入日志队列就行了，后台会专门起一个线程从队列取日志、写文件。
这是一个典型的多生产者对单消费者的问题，关键就在于这个队列的实现，因为这里面涉及消费者等待队列不空，生产者等待队列空的逻辑，当时就选择了比较直观的 BlockingQueue。
j.u.c 里比较常见的 BlockingQueue 实现，有 ArrayBlockingQueue、LinkedBlockingQueue、LinkedTransferQueue、SynchronousQueue 这几个：

• SynchronousQueue 常用于生产者消费者一对一交换的场景，不适合。

• LinkedTransferQueue 是 Java7 里新加的队列实现，在 NIO 框架、线程池框架里常亮相，性能应该不错，不过提交日志到队列，完全不需要等待消费者做 transfer 动作，因此用不上。

• LinkedBlockingQueue 是基于链表实现的队列，一头一尾各有一把锁，缺点就是入队有内存分配开销。

• ArrayBlockingQueue 是一个定长的环形数组，队列创建之后，就没有内存开销了，但缺点是这个队列共用一把锁，竞争比 LinkedBlockingQueue 激烈。

实测发现用 LinkedBlockingQueue 做队列，吞吐量比 ArrayBlockingQueue 高，但考虑到 ArrayBlockingQueue 本身的定长特性，在写日志 qps 很高时内存波动更稳定，而且队列定长也正好可以作为写日志的“节流阀”（队列满时，新增的日志无法放入，会直接被丢弃，从而起到控制日志写入速度的作用），因此最终选择了 ArrayBlockingQueue。
log4j、logback 等日志框架，有对应的 AsyncAppender 实现异步队列，都选择了 ArrayBlockingQueue。

使用 BlockingQueue 入队有一个细节，就是用 add、put、offer 中的哪一个。add 会抛异常是不合适的，关键还是看 put 还是 offer。put 是一直等，直到入队为止，offer 是不等，或者只尝试等一段时间。相比之下，offer 的实现更合适，对于调用埋点日志，如果队列满，可以直接把日志丢掉不用等；对于更重要一些的业务日志，尽量不丢弃，可以尝试等几百毫秒。如果使用了等的策略，日志队列又经常满的话，会拖慢业务的响应时间，logback 用了 put 来保证重要日志不丢失，在高 qps 时，吞吐量是比用 offer 要差的。

改造之后，20 线程 4w qps 记一条 EagleEye 日志平均耗时是 2500ns 左右。

异步写，基于无锁队列

1.2.0、1.2.1 上线以后，发现写日志 qps 在 2000 以上时，系统的上下文切换也会相应增高 3000-4000 次。ArrayBlockingQueue 本身锁争用比较高，而且生产者每把一条日志加入队列后，都会唤醒消费者去消费，这是 BlockingQueue 的实现要求。在日志队列这个场景，消费者的速度一般高于生产者速度，因此队列经常处于空状态，消费者每次起来只处理一条或几条日志之后队列又空了只好重新挂起等待，而生产者每放入一条日志，都会唤醒消费者，结果就会导致系统 cs 偏高。

如果把 BlockingQueue 的功能拆开来看，一个功能是在维护队列在并发场景的出队、入队，另一个功能是做生产者、消费者之间的同步策略。
前一个功能可以另外用无锁队列来实现，降低锁争用开销，后一个功能可以针对记日志的场景做专门优化。

j.u.c 里面的 ConcurrentLinkedQueue 就是默认的无锁队列。另外，这篇论文也提出了一个对无锁队列的改进。不过，这些实现都是在无界队列上实施的算法，更适合的数据结构应该是对 ArrayBlockingQueue 的定长环形数组进行改造，把它变为无锁。看到这里，相信有不少同学能想到最近比较火的 Disruptor，这个库的核心就是使用环形数组（RingBuffer）实现无锁队列，性能号称比 ArrayBlockingQueue 要好不少。

EagleEye 记日志的场景对异步队列的需求可以简化成多生产者对单消费者的需求，因此专门写一个无锁队列去做这件事比较合适。在写这个无锁队列时，主要参考了 Disruptor 的 RingBuffer 实现，另外，这篇博客提出了不少对环形数组实现的无锁队列的优化方法也很有参考价值（需要翻墙）。

上面的三幅图简单说明了这个最大长度为 qsize 的环形队列实现，即由 put、take 两个游标来标识当前队列的下一次调用 put 和 take 应该返回的位置，put、take 是 64位长的递增的非负数，队列需要时刻保证 put>= take 且 (put - take) <= qsize。队列的长度为：(put - take)，判空方法是 put == take，判满的方法是 (put - take) == qsize。元素入队时，需要判断是否队满，然后 CAS 设置 put 自增即可；出队时，先判断是否队空。具体代码不多，这里也不细说了，有兴趣的同学可以直接看 eagleeye-core 里面的 AsyncAppender 实现。

在这里简单提一下几个注意点：

1. ABA 问题：因为 put、take 是 64位长的递增的非负数，所以每次返回的元素下标唯一，从而避免了 CAS 算法的 ABA 问题。

2. 使用位操作来计算数组下标：要求队列的最大长度是 2 的 n 次方，那么计算 x 在队列中的数组下标可以用 (x & (qsize - 1)) 来取代 (x % qsize)。

3. 消费者批量消费：由于只有一个消费者，那么它在判断队列是否为空时，可以得到队列当前的 size，那么它可以一口气消费 size 个元素。

4. 避免伪共享：把队列用到的 Long、AtomicLong 补齐成 64 个字节，把整个 CacheLine 填满。

5. 降低内存屏障的开销：如果临时读到旧数据不会带来特别大的问题，可以使用 AtomicLong.lazySet(value) 来取代 volatile 的写。另外，可以把读到的 volatile 变量值缓存在一个非 volatile 变量中，判断时先读非 volatile 变量，减少读 volatile 变量的开销。

另外再谈谈生产者和消费者之间的同步策略。Disruptor 把这个抽象为 WaitStrategy，提供了忙等（BusySpin）、阻塞等（Blocking）、睡眠等（Sleeping）、弃权等（Yielding）等等多种实现，比 BlockingQueue 要灵活很多。写日志这里，比较适合的方式应该是阻塞等和睡眠等。睡眠等的策略要求队列容量比较大，否则很容易在生产速度很快的时候，出现因为写满队列了消费者还没醒来，导致丢日志的情况。阻塞等的策略要针对写日志做调整，否则就出现 ArrayBlockingQueue 那种频繁唤醒消费者导致上下文切换频繁的问题了。EagleEye 把生产者唤醒消费者的条件改为：在队列的日志数超过指定阈值（队列快满了），且消费者不在运行状态，且生产者可以获得锁，才唤醒消费者。为了避免写日志 qps 非常低时，要很长时间才到达阈值的问题，消费者的阻塞要设置最大时间为 1 秒，这样，无论如何 1 秒内写的日志肯定会被处理的。

改造之后，20 线程 4w qps 记一条 EagleEye 日志平均耗时是 1500ns 左右。

获取当前时间

EagleEye 埋点每条都有时间戳，对于多阶段的网络调用，还会统计到每个阶段的耗时，每次免不了都要获取一次时间。那么是否需要对 System.currentTimeMillis() 进行优化呢？如果需要优化，可以由后台线程每毫秒更新一次一个本地的时间戳变量，需要读取时间时，直接读取本地的这个时间戳。EagleEye 当前还没做这个处理，因为获取时间的实现是调用 gettimeofday()，在 64 位 Linux 并不是系统调用，开销非常小。

写日志跟时间相关的，还有另一个注意点，就是不同时区的服务器时间应该做调整，调整成统一的时区。例如美国服务器调用在东八区的中国服务器，记录的日志时间会不一样，这对分析是一个麻烦。因此，可以在初始化时先把时区的时间差算好，记录时间时，统一调整到东八区。（这里记录的时间是形如：2013-02-03 12:34:56 这样的，而不是毫秒数，如果记录 System.currentTimeMillis()，已经统一为 UTC 时区了）

把日志编码成字符串 / 字节

写日志的这一步，一般就是把日志对象 Encode 为字符串。有下面几个细节点：

预先分配字符串的输出大 buffer

不建议每输出一行都申请一次 buffer（例如每次都 new StringBuilder()），这样会增加对象分配和 GC 压力。可以在 ThreadLocal 放置一个 4KB 输出缓存，重复使用。因为 EagleEye 使用的异步队列能保证仅有一个线程做 encode，所以可以连 ThreadLocal 都省掉。

减少 append 操作的越界检查

StringBuilder 的性能是挺好了，但是每次 append 都要做字符串越界检查，可以自己实现一个特殊的 StringBuilder，让它的 API 可以接受多个参数，让越界检查少做几次。或者不怕麻烦的话直接用 char[] 也是可以的。

整数转字符串、浮点转字符串的优化

EagleEye 没有用这种优化，这篇博文里提到了写日志可以用这种优化，有需要的同学可以试试。

字符编码转换

由于历史原因，EagleEye 日志用的是 GBK 编码，如果输出用 UTF-8 编码，对于内码使用 Unicode 的 JVM 来说转换会更快（因为 Unicode 转 GBK 要查表，Unicode 转 UTF-8 只要算就行了）。UTF-8 也更加适合国际化。

日志输出到目的地

EagleEye 现在只有输出到本地文件的功能，因此下面仅介绍这方面的一些经验。

使用 buffer 输出

使用 buffer 写文件，对写性能有很大提高，一般可以把 buffer 设置成 8KB 输出。如果不使用 buffer，或者 buffer 比较小，那么写日志到硬盘的次数会增大不少，IOPS 高了对系统有影响。毕玄给的建议是写日志有 500 IOPS 对于虚拟机来说已经有点吃力啦。实测发现 EagleEye 按 4w qps 写日志48KB 缓存每条日志 100 字节，写硬盘的次数基本在 500 左右。因此对日志写入次数做控制是有必要的。

使用 buffer 这块，可以跟上面编码字符串用同一个缓存，这样编码后可以直接就输出了，节省一次拷贝。如果用 StringBuilder.toString()，它会拷贝出一个 String 返回，然后如果你把 String 放入输出 buffer 里面，又会再触发拷贝一次。所以说，buffer 最好自己能控制，JVM 里面的字符串多余拷贝还是比较多的，不知不觉性能就下去了。

写文件的性能

目前 EagleEye 还是用的 FileOutputStream，最近看到 log4j 2 用的是 ByteBuffer + RandomAccessFile 的策略，号称性能提升 20～200%。后面可以看看实现，试一下效果。

文件归档滚动时不要删除文件

Linux 系统删除一个大文件（超过 500MB）会比较慢，日志越大卡住的时间越长。因此，文件归档时应该尽量避免由写日志线程直接去删除文件，可以先把当前文件重命名，然后创建新文件去写。删除过期的归档文件可以让后台维护线程去做，或者用脚本去做清理。

多进程写日志

上面谈的是多线程写日志，那么，多进程如何写日志才能避免日志内容交织呢？EagleEye 1.3.0 以后做了特殊处理，所以如果多进程写日志都写在同一个文件上，不会产生交织情况（log4j 也有这个问题）。多进程写日志的方案有下面几个：

• 每个进程单独写一个文件。这个方案简单可靠，缺点是对日志收集来说有点不方便，但可以接受。

• 写文件时，每个进程都先获取文件锁 FileChannel.lock()，写完之后 release。logback 用的是这个策略（prudent=true）。

• 依赖 write(2) O_APPEND 的原子性：open(2)/write(2) 在设置了 O_APPEND 之后，操作系统可以保证写入是原子操作（一次写出的内容不要超过 PAGE_SIZE=4K），在这里有详细讨论。JVM 里面，如果使用 new FileOutputStream(file, append) 这个 API，第二个参数 append 设置为 true，会带有 O_APPEND 参数。

这是 FileOutputStream 的代码，设置了 append 为 true，就会设置 O_APPEND。

可以看到实际用的是 write(2) 系统调用：
关于 write(2) 在 O_APPEND 的原子性： http://pubs.opengroup.org/onlinepubs/009695399/functions/pwrite.html

运维友好方面的细节

下面是 EagleEye 在实现时遇到的一些很难归入上面三大类的问题，大家可以参考下。

日志写到固定路径

EagleEye 日志都固定写到 ~/logs/eagleeye 目录下面，调用日志是 eagleeye.log，业务日志是 biz_eagleeye.log。使用统一的固定路径有一个好处，就是找起来方便，日志收集也很容易配置。现在淘宝的应用日志路径里面，有的会包含机器名、应用名，定位日志就要费周章了，而且，还要考虑机器名、应用名会改变的问题。如果这些变量追加在日志文件名上面，会相对好一些。

自动删除存档文件

已经不止一次见到由于日志打爆硬盘导致 P1 故障了，所以删除历史存档这个功能尽量给程序自己做，指望部署脚本定时删除相对不靠谱，靠人肉删就更不靠谱了。

文件按大小滚动

EagleEye 的日志是按文件大小滚动的，不采用按时间滚动，是因为 EagleEye 日志随这应用 qps 上升会线性翻倍，有可能会 1 小时就打出了大量日志。如果按大小滚动，那么 EagleEye 日志在硬盘的占用量是固定可控的。前面提到删除的文件越大就越慢，因此 EagleEye 日志一般 300MB 左右会滚动，保证删起来也比较快。

另外注意，获取文件大小本身也是一个系统调用，会比较耗时，因此日志输出的实现应该把文件大小在内存中缓存计数，避免每次都调用系统方法去获取文件大小。

运行时开关

写日志组件应该提供运行时开关，可以方便控制日志级别。EagleEye 提供了文件级别的开关，可以运行时打开、关闭日志输出，调整日志的采样率（采样率是 EagleEye 自身的特性，一般日志框架不需要）。另外，为了大范围批量操作方便，还需要支持通过 diamond 上配置开关，这些功能 EagleEye 是依赖 HSF/Pandora 去完成的。

运行期文件被删除了怎么办

这是一般记日志的框架不会考虑的，但是确实会遇到。例如文件被误删，或者因为长时间没写日志，文件被清理脚本删掉了（Linux 可以删，但是进程还持有文件 fd，文件 inode 在进程 close 的时候才释放，还可以“正常”读写；对于 Windows，一般锁住删不掉，但是如果用 Unlocker 一类软件是可以解锁句柄的）。出现了这种情况，除非把应用重启，否则只能干瞪眼了。因此，EagleEye 在后台线程还会监视日志文件是否被删除，如果删除了就滚动日志，重建文件。

日志的日志

用来记录日志框架本身的一些异常信息，对排查问题有很大帮助。例如 log4j 的 LogLog。实现时需要注意记日志不要导致死循环。

每秒刷新

EagleEye 为了提高性能，使用异步实现日志输出，输出 buffer 还带有 8KB 缓存，写满才会写文件，但是对于日常环境，或者线上排查问题的场景，会期望日志能马上刷出来。日志框架里一般都可以配置是否“immediateFlush”，但是这会比较影响性能。EagleEye 的做法是异步队列的消费者线程每 1 秒至少会醒一次，检查是否需要写日志，写完日志之后，还要触发本批日志刷新。当日志写到缓存 buffer 时，buffer 会检查距离上次写文件是否超过 1s，如果超过 1s，即使不满 4KB 也会触发刷新。

应用退出时不丢日志

这是对每秒刷新的进一步补充，应用退出时把最后一秒还没写到文件的内容刷新出去，可以在 Runtime 上设置 ShutdownHook 实现。

不依赖系统默认的字符编码

EagleEye 的业务日志包含不少中文，如果字符串输出到文件时不指定编码，就会用系统的默认编码（String.getBytes() 或 new Writer() 时），不同编码的系统就产生不同编码的日志，会导致日志收集、后期分析处理出现乱码。因此需要为输出统一设置编码。

该文章来自阿里巴巴技术协会（ATA）精选集

来源：云栖团队博客

原文：https://yq.aliyun.com/articles/2920

转载文章，向原作者致敬！如有侵权或不周之处，敬请劳烦联系若飞（微信：1321113940）马上删除，谢谢！

·END·