开篇
近期由于业务需要进行业务迁移, 期间因为误设置 log4j 的日志级别, 导致系统性能整体下降, 具体表现在 QPS 下降明显, 系统 RT 上升. 迁移期间由于各类系统环境较原来有较大差别, 因为在排查过程中也走了一些弯路, 总结起来避免他人再次踩坑.
问题背景
问题的背景其实很简单, 线上系统的 log4j 的日志级别由 warn 调整为 info, 导致大量的调用 log4j 的日志接口, 导致系统的 rt 上升伴随着 qps 下降, 具体的影响效果可以看下图.
需要额外解释的就是 log4j 的这个问题需要在 qps 较大的情况下才会复现, 按照我遇到的情况基本上需要在 2k/s 以上会比较明显 (数据不一定非常准确), 只是为了说明需要在大量请求的情况才会触发 synchronized 的问题.
当然问题的本质在于大量调用 log4j 的日志接口, 导致竞争 synchronized 影响性能, 影响的时间应该也是在 ms 级别, 这其实在另外一个方面说明了只求非常极致追求性能问题才会细致的去分析这些问题.
优化效果
优化后 qps 的提升效果图, 这边是以分钟进行统计的.
优化后系统的响应时间效果图.
现象分析
整个分析过程其实并不是那么具有条理性, 只是现在总结起来看上去像那么回事.
对比两套系统的差异点, 发现系统的 log4j 的日志级别不一致, 尝试修改日志级别观察效果.
发现日志级别调高后系统性能明显提升, 开始怀疑 log4j 的问题并网上查阅资料.
jstack 打印对应的日志, 发现在不同日志级别情况下下面的 BLOCKED 的日志数量不一样.
发现竞争锁的日志 waiting to lock <0x00007f3a04020830>.
观察 jstack 日志并找到 log4j 的源码发现代码当中有同步锁关键字 synchronized.
- #514 daemon prio=5 os_prio=0 tid=0x00007f369002f800 nid=0x561a waiting for monitor entry [0x00007f348fb96000]
- java.lang.Thread.State: BLOCKED (on object monitor)
- at org.apache.log4j.Category.callAppenders(Category.java:204)
- - waiting to lock <0x00007f3a04020830> (a org.apache.log4j.spi.RootLogger)
- at org.apache.log4j.Category.forcedLog(Category.java:391)
- at org.apache.log4j.Category.log(Category.java:856)
- #521 daemon prio=5 os_prio=0 tid=0x00007f367c042800 nid=0x5617 waiting for monitor entry [0x00007f348fe99000]
- java.lang.Thread.State: BLOCKED (on object monitor)
- at org.apache.log4j.Category.callAppenders(Category.java:204)
- - waiting to lock <0x00007f3a04020830> (a org.apache.log4j.spi.RootLogger)
- at org.apache.log4j.Category.forcedLog(Category.java:391)
- at org.apache.log4j.Category.log(Category.java:856)
原因分析
直接定位 log4j 的源码位置, 发现 synchronized 的关键字, 基本上这时候其实是验证之前的猜想而已.
关于 synchronized 的性能问题, 可以网上去参考 java 几种锁的性能对比, 只记得一个简单的结论 synchronized 在大量竞争的情况下劣势比较明显各种同步方法性能比较 (synchronized,ReentrantLock,Atomic).
- void callAppenders(LoggingEvent event) {
- int writes = 0;
- for(Category c = this; c != null; c=c.parent) {
- // Protected against simultaneous call to addAppender, removeAppender,...
- synchronized(c) {
- if(c.aai != null) {
- writes += c.aai.appendLoopOnAppenders(event);
- }
- if(!c.additive) {
- break;
- }
- }
- }
- if(writes == 0) {
- repository.emitNoAppenderWarning(this);
- }
- }
心得
老大曾说过, 凡事做个有心人, 会发现更多的东西.
来源: https://yq.aliyun.com/articles/688523