小小的日志，大大的坑

作者：京东零售 王军

1. 背景

压测过程中优化线程池以后单机qps存在性能瓶颈，优化过程中发现默认线程池及日志对性能存在严重的影响所以引发了一系列对日志优化的整理

2.哪些场景可能导致性能问题

在任何系统中，日志都是非常重要的组成部分，它是反映系统运行情况的重要依据，也是排查问题时的必要线索。绝大多数人都认可日志的重要性，但是又有哪些场景可能导致性能问题？今天就让我们来聊聊Java日志性能那些事。

2.1 不合理的书写方法

 

如上3种写法，我相信大家或多或少都在项目代码中看到过，那么他们之前有区别呢，会对性能造成什么影响？ 如果此时关闭 DEBUG 日志级别，差异就出现了

格式1 依然还是要执行字符串拼接，即使它不输出日志，属于浪费。

格式2 的缺点就是参数会提前做JSON序列化也产生性能损耗。

所以推荐格式3，新增日志开关，只有在执行时才会动态的拼接，关闭相应日志级别后，不会有性能损耗。

 

2.2 不合理的日志

尽量多的日志，能够把用户的请求串起来，更容易断定出问题的代码位置。由于当前分布式系统，且业务庞杂，任何日志的缺失对于程序员定位问题都是极大的障碍。所以要合理的打印日志，设置合理的日志级别

 

 

 

2.3 日志输出格式

位置信息 官网称作 Location Information，含义是当前这行日志是哪个类的哪个方法哪一行打印的。

可配置的模式有很多，具体见官网 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 倍。

 

3. 如何尽量避免日志对性能产生影响

3.1 日志级别动态调整

用好DEBUG级别！项目代码需要打印大量 INFO级别日志，以支持问题定位及测试排查等。但这些大量的 INFO日志对生产环境是无效的，大量的日志会吃掉 CPU 性能，此时需要能动态调整日志级别，既满足可随时查看 INFO日志，又能满足不需要时可动态关闭，不影响服务性能需要。

3.2 不打无用日志

日志内容，能少就少，不在循环中打，大 list 简化，不打无用内容。

明显知道的异常栈不要打印（比如自定义异常捕获后直接打印异常信息即可）

3.3 避免字符串拼接

避免使用字符串连接：在日志记录中，字符串连接是一项较为昂贵的操作，特别是在循环中使用。每次进行字符串连接都会产生一个新的字符串对象，浪费了内存和时间。应优先考虑使用占位符的形式，如使用slf4j库中的"{}"，然后传入参数，并避免使用字符串连接。

3.4 新增日志开关

按需新增日志开关减少不必要的性能损耗，例如JSON序列化及字符串拼接等等。（若无相关操作则不需要新增日志开关，反而存在一堆废代码）

3.5 调整日志输出格式

影响性能的位置信息按需选择减少性能损耗

3.6 日志异步打印（谨慎选择）

同步打印日志磁盘 I/O 成为瓶颈，导致大量线程 Block，异步缺可能产生日志丢失。

 

4. 优化成果

4.1优化前（单机80qps..性能已经不可用 耗时高达1500+ms）：

 

 

 

4.2优化后（单机200qps tp999稳定在575ms）：