开篇

近期由于业务需要进行业务迁移，期间因为误设置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);

}

}

心得

老大曾说过，凡事做个有心人，会发现更多的东西。