本文内容： 1、背景 2、影响性能的日志因素 3、好的日志习惯 |
|| 背景
写这篇文章有 2 个原因，一是前段时间架构组同事的一次性能优化分享，单单日志（log4j2）这一项优化性能就提升了 19 倍，QPS 从1660 升到 32000，被震撼到了。
二是最近接手的一个项目中，日志加了彩色打印，按日志的级别设置了不同的高亮颜色，看得我眼花缭乱，用 less 等一些命令查看时还会展示出来一堆 "ESC[m]"，这让有点强迫症的我看着很不爽。
趁着技术优化，把这块也改一下，自己先爽了再说。顺便也重新认识一下在各种算法、秒杀设计大行其道的当下，这个不太起眼的小家伙。
|| 影响性能的日志因素
| 位置信息
官网称作 Location Information，就是我们配置文件里的这类信息（%c{3}#%M %L），含义是当前这行日志是哪个类的哪个方法哪一行打印的。输出效果如下：
cashpool.task.OrderReceiveTask#run 78可配置的模式有很多，具体见官网 https://logging.apache.org/log4j/2.x/manual/layouts.html#Patterns 。
这里只说和位置相关的 %C or %class, %F or %file, %l or %location, %L or %line, %M or %method。
官网这几个模式的说明中也都反复强调了会影响性能。同时也给出了具体的性能数据，比常用的同步 logger 慢 1.3 ~ 5 倍。如果在异步 logger 中使用位置信息，将会慢 30 ~ 100 倍。
Generating line number information (location information) is an expensive operation and may impact performance. Use with caution.
为什么会这么慢呢？
我们都知道，java 程序执行时，每个线程都会有自己的栈，每个方法都会生成一个 frame，要获取位置信息，就要获取当前线程的栈帧信息，java 9 之前提供了两种获取栈帧的方法
java.lang.Throwable#getStackTrace()
java.lang.Thread#getStackTrace()java 9 提供了 StackWalker 类，有网友说它的性能要好一些，我没找到有力证据，看到的都是介绍跳帧的功能，有兴趣的可以深究一下。
我们就看一下 java 9 之前的 2 种方法：
有网友说 java.lang.Throwable#getStackTrace() 的性能要好一些，我也没有找到直接证据，但从调用底层 native 的方法名字看 Thread 里调用的是 dumpThreads ，看到 dump 字眼，就会联想到 stop the world ，如果真挂起线程，那效率就低了。
而且 log4j 里用的是java.lang.Throwable#getStackTrace()。
不管是哪种方法获取堆栈信息，应该都不会太高效。
想想我们一个请求，从框架层面交给一个线程后，动辄几十层方法才能调到我们的业务代码太正常不过了。
既然这么低效，那我们不打位置信息，有问题怎么定位呢？
我仔细回想了一下过往排查问题时，好像都是通过日志内容，定位到哪一行代码，几乎没有通过类名行号去定位代码，编译后的行号准不准确也另说。
其实我们的主要目的是不通过框架获取堆栈的形式打印位置信息，我们完全可以在日志的内容中带上位置信息，通过一个切面就能搞定的事。
| 不同的 Appender
我们工作中一般都是把日志输出到文件中的，我们就挑 3 个文件相关的 Appender 说明一下，不同的 Appender 性能的差异主要在 I/O 上。
FileAppender 和 RollingFileAppender 内部使用的都是 BufferedOutputStream。
而 RandomAccessFileAppender 内部使用了 ByteBuffer + RandomAccessFile 技术，与 FileAppender 相比，性能提高了20 ~ 200%。
AsyncAppender 它不能独立存在，要依赖其他的 Appenders，配置在它们之后。
它只是新起一个线程中把 LogEvents 交给了它所依赖的 Appenders。默认内部使用的是 ArrayBlockingQueue ，多线程并发打日志时，性能可能会变得更差。这种场景官方推荐使用无锁的 Asynchronous Loggers 。
Asynchronous Loggers，它是 log4j2 新提供的功能，通过新起线程执行 I/O 操作来提升性能，底层使用的是 Disruptor 框架，通过无锁线程通信，代替了 ArrayBlockingQueue 。
它支持所有 Loggers 异步处理，也支持同步、异步 组合使用。可靠性要求高的比如异常信息就可以配成同步的，其他配成异步的。
每个 Appender 的具体用法可以从官网查看，
https://logging.apache.org/log4j/2.x/manual/appenders.html
| 不同的刷盘策略
上面说到的 Appenders 的配置项中，都有一个 “immediateFlush”，默认 = false，日志文件不像数据库那样追求高可靠性，可以忽略此配置，知道配置为 true 性能会变差就行。
貌似所有涉及到刷盘的技术，都会提供这类的配置项，这里就不多说了。
|| 好的日志习惯
| 日志格式统一
这里主要指日志内容中各个元素的顺序，统一的日志格式，不仅查看起来方便、高效，而且如果有通过日志做一些筛选、统计类的需求，可以轻松搞定。
| 日志文件大小
如果访问量不是很大，一天也就几百兆，个人觉得完全没必要按大小或者按小时拆分日志文件。
反倒是决定拆分文件之前，更应该看看日志打的是否合理，是不是打了很多无用日志导致的。
| 不打无用日志
日志内容，能少就少，不在循环中打，大 list 简化，不打无用内容。
比如日志里的时间，[年-月-日] 是不是可以不打，文件名上带年月日就行，这样每行就能省 10 个字符，如果只打时分秒很难受，可以加上[月-日]，年真没必要加。
还有线程名，打出来的都是线程池里的线程名称，没有任何意义，有 traceId 过滤出一次请求的日志就可以了，这个不打又可以省一二十个字符。
单靠这几点小优化后，日志文件就缩小了 20%。
| 关键信息提到最前
很多告警都是通过监控日志关键字触发的，然后发消息给负责人。但消息内容一般都很长，可能包含前后行的信息，如果前行内容长，消息再做省略处理，你收到消息后啥有用的内容也看不到了，只知道收到了报警，具体信息还要去看日志。
我们需要把最关键的信息打在最前面，尤其像失败原因之类的，理想的效果就是看到报警消息就知道问题原因，不用再去查日志了。
| 敏感信息和日期
我们打的日志中难免会包含手机号、银行卡号等敏感信息，这些都要脱敏的。
还有日志里打出来的业务时间，如果不做特殊处理，一般都是一个毫秒串，需要知道具体时间的话还得再通过工具转换一次，很不方便。
我们打日志一般都是 JSON 串，这 2 个问题都可以统一解决，通过 fastjson 的 Filter 就能轻松搞定。
脱敏需要自己写 Filter 和 脱敏规则，日期就用 fastjson 自带的 SerializerFeature#WriteDateUseDateFormat。
| 用好 debug 级别
我发现很多人当然也包括我在内，都不太用 debug 级别的日志，就像大家都不喜欢写单测一样。
其实 debug 日志是一个很好的习惯，不仅在联调测试过程中方便定位问题，也不会造成生成环境过多无用的日志，还有助于代码的阅读，何乐不为。
| 用好切面日志
我们一般加切面日志，都是不加区分的把方法的入参、返回结果统统打印出来，而且有的还控制层、服务层等层层打印，尤其像返回结果是 List 的，就造成很多无用日志。
所以在加切面的时候是不是可以加上日志级别、返回类型的考虑，用不用每层都加切面。
前面最开始提到的位置信息，就可以通过切面解决，即不损失功能，也提高了性能。
参考文献：
https://docs.oracle.com/javase/9/docs/api/java/lang/StackWalker.html
https://stackoverflow.com/questions/2347828/how-expensive-is-thread-getstacktrace
https://zhuanlan.zhihu.com/p/471819212
https://logging.apache.org/log4j/2.x/manual/layouts.html#LocationInformation
https://logging.apache.org/log4j/2.x/manual/layouts.html#Patterns
https://logging.apache.org/log4j/2.x/manual/appenders.html
https://logging.apache.org/log4j/2.x/performance.html#asyncLogging
