关于java:性能调优小小的log大大的坑

引言

“只有被线上服务问题毒打过的人才明确日志有多重要！”
我先说论断，谁赞成，谁拥护？如果你深有同感，那祝贺你是个社会人了：）

日志对程序的重要性显而易见，笨重、简略、无需费脑，程序代码中随处可见，帮忙咱们排查定位一个有一个问题问题。但看似不起眼的日志，却暗藏着各式各样的“坑”，如果使用不当，不仅不能帮忙咱们，反而会成为服务“杀手”。
本文次要介绍生产环境日志使用不当导致的“坑”及避坑指北，高并发零碎下尤为显著。同时提供一套实现计划能让程序与日志“谐和共处”。

避坑指北

本章节我将介绍过往线上遇到的日志问题，并一一分析问题根因。

不标准的日志书写格局

场景

// 格局 1
log.debug("get user" + uid + "from DB is Empty!");

// 格局 2
if (log.isdebugEnable()) {log.debug("get user" + uid + "from DB is Empty!");
}

// 格局 3
log.debug("get user {} from DB is Empty!", uid);

如上三种写法，我置信大家或多或少都在我的项目代码中看到过，那么他们之前有区别呢，会对性能造成什么影响？
如果此时敞开 DEBUG 日志级别，差别就呈现了，格局 1 仍然还是要执行字符串拼接，即便它不输入日志，属于节约。

格局 2 的毛病就是就在于须要退出额定的判断逻辑，减少了废代码，一点都不优雅。
所以举荐格局 3，只有在执行时才会动静的拼接，敞开相应日志级别后，不会有任何性能损耗。

生产打印大量日志耗费性能

尽量多的日志，可能把用户的申请串起来，更容易判定出问题的代码地位。因为以后分布式系统，且业务庞杂，任何日志的缺失对于程序员定位问题都是极大的阻碍。所以，吃过生产问题苦的程序员，在开发代码过程中，必定是尽量多打日志。
为了当前线上呈现问题能尽快定位问题并修复，程序员在编程实现阶段，就会尽量多打要害日志。那上线后是能疾速定位问题了，然而紧接着又会有新的挑战：随着业务的疾速倒退，用户拜访一直增多，零碎压力越来越大，此时线上大量的 INFO 日志，尤其在高峰期，大量的日志磁盘写入，极具耗费服务性能。
那这就变成了博弈论，日志多了好排查问题，然而服务性能被“吃了”，日志少了服务稳定性没啥影响了，然而排查问题难了，程序员“苦”啊。

发问：为何 INFO 日志打多了，性能会受损（此时 CPU 使用率很高）？

根因一：同步打印日志磁盘 I/O 成为瓶颈，导致大量线程 Block

能够设想，如果日志都输入到同一个日志文件时，此时有多个线程都往文件外面写，是不是就乱了套了。那解决的方法就是加锁，保障日志文件输入不会错乱，如果是在高峰期，锁的争抢无疑是最耗性能的。当有一个线程抢到锁后，其余的线程只能 Block 期待，重大拖垮用户线程，体现就是上游调用超时，用户感觉卡顿。

如下是线程卡在写文件时的堆栈

Stack Trace is:
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.logging.log4j.core.appender.OutputStreamManager.writeBytes(OutputStreamManager.java:352)
- waiting to lock <0x000000063d668298> (a org.apache.logging.log4j.core.appender.rolling.RollingFileManager)
at org.apache.logging.log4j.core.layout.TextEncoderHelper.writeEncodedText(TextEncoderHelper.java:96)
at org.apache.logging.log4j.core.layout.TextEncoderHelper.encodeText(TextEncoderHelper.java:65)
at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:68)
at org.apache.logging.log4j.core.layout.StringBuilderEncoder.encode(StringBuilderEncoder.java:32)
at org.apache.logging.log4j.core.layout.PatternLayout.encode(PatternLayout.java:228)
.....

那么是否线上缩小 INFO 日志就没问题了呢？同样的，ERROR 日志量也不容小觑，假如线上呈现大量异样数据，或者上游大量超时，刹时会产生大量 ERROR 日志，此时还是会把磁盘 I/O 压满，导致用户线程 Block 住。

发问：假如不关怀 INFO 排查问题，是不是生产只打印 ERROR 日志就没性能问题了？

根因二：高并发下日志打印异样堆栈造成线程 Block

有次线上下游呈现大量超时，异样都被咱们的服务捕捉了，庆幸的是容灾设计时预计到会有这种问题产生，做了兜底值逻辑，原本庆幸没啥影响是，服务器开始“教做人”了。线上监控开始报警，CPU 使用率增长过快，CPU 一路间接增到 90%+，此时紧急扩容止损，并找一台拉下流量，拉取堆栈。
Dump 下来的线程堆栈查看后，联合火焰退剖析，大部分现成都卡在如下堆栈地位：

Stack Trace is:
java.lang.Thread.State: BLOCKED (on object monitor)
at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
- waiting to lock <0x000000064c514c88> (a java.lang.Object)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:349)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.loadClass(ThrowableProxyHelper.java:205)
at org.apache.logging.log4j.core.impl.ThrowableProxyHelper.toExtendedStackTrace(ThrowableProxyHelper.java:112)
at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:112)
at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:96)
at org.apache.logging.log4j.core.impl.Log4jLogEvent.getThrownProxy(Log4jLogEvent.java:629)
...

此处堆栈较长，大部分现场全副 Block 在 java.lang.ClassLoader.loadClass，而且往下盘堆栈发现都是因为这行代码触发的

at org.apache.logging.slf4j.Log4jLogger.error(Log4jLogger.java:319)

// 对应的业务代码为
log.error("ds fetcher get error", e);

啊这。。。就很离谱，你打个日志为何会加载类呢？加载类为何会 Block 这么多线程呢？
一番查阅剖析后，得出如下论断：

• 应用 Log4j 的 Logger.error 去打印异样堆栈的时候，为了打印出堆栈中类的地位信息，须要应用 Classloader 进行类加载；
• Classloader 加载是线程平安的，尽管并行加载能够进步加载不同类的效率，然而多线程加载雷同的类时，还是须要相互同步期待，尤其当不同的线程打印的异样堆栈完全相同时，就会减少线程 Block 的危险，而 Classloader 去加载一个无奈加载的类时，效率会急剧下降，使线程 Block 的状况进一步好转；
• 因为反射调用效率问题，JDK 对反射调用进行了优化，动静生成 Java 类进行办法调用，替换原来的 native 调用，而生成的动静类是由 DelegatingClassLoader 进行加载的，不能被其余的 Classloader 加载，异样堆栈中有反射优化的动静类，在高并发的条件下，就非常容易产生线程 Block 的状况。

联合上文堆栈，卡在此处就很明清晰了：

• 大量的线程涌进，导致上游的服务超时，使得超时异样堆栈频繁打印，堆栈的每一层，须要通过反射去拿对应的类、版本、行数等信息，loadClass 是须要同步期待的，一个线程加锁，导致大部分线程 block 住期待类加载胜利，影响性能。

• 讲道理，即便大部分线程期待一个线程 loadClass，也只是一瞬间的卡顿，为何这个报错这会始终 loadClass 类呢？联合上述论断剖析程序代码，得出：此处线程内的申请上游服务逻辑蕴含 Groovy 脚本执行逻辑，属于动静类生成，上文论断三表明，动静类在高并发状况下，无奈被 log4j 正确反射加载到，那么堆栈反射又要用，进入了死循环，越来越多的线程只能退出期待，block 住。

  最佳实际

  1. 去掉不必要的异样堆栈打印

  显著晓得的异样，就不要打印堆栈，省点性能吧，任何事 + 高并发，意义就不一样了：）

  try {System.out.println(Integer.parseInt(number) + 100);
  } catch (Exception e) {
    // 改良前
    log.error("parse int error :" + number, e);
    // 改良后
    log.error("parse int error :" + number);
  }

  如果 Integer.parseInt 产生异样，导致异样起因必定是出入的 number 不非法，在这种状况下，打印异样堆栈齐全没有必要，能够去掉堆栈的打印。

  2. 将堆栈信息转换为字符串再打印

  public static String stacktraceToString(Throwable throwable) {StringWriter stringWriter = new StringWriter();
    throwable.printStackTrace(new PrintWriter(stringWriter));
    return stringWriter.toString();}

  log.error 得出的堆栈信息会更加欠缺，JDK 的版本，Class 的门路信息，jar 包中的类还会打印 jar 的名称和版本信息，这些都是去加载类反射得来的信息，极大的损耗性能。
  调用 stacktraceToString 将异样堆栈转换为字符串，相对来说，的确了一些版本和 jar 的元数据信息，此时须要你本人决策取舍，到底是否有必要打印出这些信息（比方类抵触排查基于版本还是很有用的）。

  3. 禁用反射优化

  应用 Log4j 打印堆栈信息，如果堆栈中有反射优化生成的动静代理类，这个代理类不能被其它的 Classloader 加载，这个时候打印堆栈，会重大影响执行效率。然而禁用反射优化也会有副作用，导致反射执行的效率升高。

  4. 异步打印日志

  生产环境，尤其是 QPS 高的服务，肯定要开启异步打印，当然开启异步打印，有肯定失落日志的可能，比方服务器强行“杀死”，这也是一个取舍的过程。

  5. 日志的输入格局

  咱们看戏日志输入格局区别

  // 格局 1
  [%d{yyyy/MM/dd HH:mm:ss.SSS}[%X{traceId}] %t [%p] %C{1} (%F:%M:%L) %msg%n
  
  // 格局 2
  [%d{yy-MM-dd.HH:mm:ss.SSS}] [%thread]  [%-5p %-22c{0} -] %m%n

官网也有明确的性能比照提醒，如果应用了如下字段输入，将极大的损耗性能

 %C or $class, %F or %file, %l or %location, %L or %line, %M or %method

log4j 为了拿到函数名称和行号信息，利用了异样机制，首先抛出一个异样，之后捕捉异样并打印出异样信息的堆栈内容，再从堆栈内容中解析出行号。而实现源码中减少了锁的获取及解析过程，高并发下，性能损耗可想而知。

如下是比拟影响性能的参数配置，请大家酌情配置：

%C - 调用者的类名 (速度慢, 不举荐应用)
%F - 调用者的文件名 (速度极慢, 不举荐应用)
%l - 调用者的函数名、文件名、行号 (极度不举荐，十分耗性能)
%L - 调用者的行号 (速度极慢, 不举荐应用)
%M - 调用者的函数名 (速度极慢, 不举荐应用)

解决方案——日志级别动静调整

我的项目代码须要打印大量 INFO 级别日志，以反对问题定位及测试排查等。但这些大量的 INFO 日志对生产环境是有效的，大量的日志会吃掉 CPU 性能，此时须要能动静调整日志级别，既满足可随时查看 INFO 日志，又能满足不须要时可动静敞开，不影响服务性能须要。

计划：联合 Apollo 及 log4j2 个性，从 api 层面，动静且细粒度的管制全局或单个 Class 文件内的日志级别。劣势是随时失效，生产排查问题，可指定关上单个 class 文件日志级别，排查完后可随时敞开。

限于本篇篇幅，具体实现代码就不贴出了，其实实现很简略，就是奇妙的使用 Apollo 的动静告诉机制去重置日志级别，如果大家感兴趣的话，能够私信或者留言我，我开一篇文章专门来具体解说如何实现。

总结与瞻望

本篇带你理解了日志在日常软件服务中常见的问题，以及对应的解决办法。切记，简略的货色 + 高并发 = 不简略！要对生产放弃敬畏之心！

能读到结尾阐明你真是铁粉了，有任何问题请私信或者评论，我看到了肯定会第一工夫回复。如果你感觉自己分享的内容够“干”，麻烦点赞、关注、转发，这是对我最大激励，感激反对！
心愿我分享的文章可能给每一位读者带来帮忙！集体技术博客：https://jifuwei.github.io/