主机配置
- CPU：8核
- 内存： 4G
测试目标过程和配置
- 一个业务处理接口
- 分层的各个函数进行切面监控执行时间并进行日志打印输出
- log4j appender 采用 RollingFileAppdendar
测试工具：
LoadRunner
压测过程：
采用200个并发请求进行压测，压测的结果显示TPS只有18（即每秒处理18个请求）。然后被这个结果深深的震惊了。
查看主机性能情况，负载、IO、内存使用都很低，同时并没有存在频繁的full gc的情况。
监控线程执行情况
thread_monitor_1.png
真是红透半天天了呀，这货。
打印并查看线程一看，发现大量的处理线程blocked在等待同一个log4j的rootLogger对象锁。
http-bio-8080-exec-76" daemon prio=10 tid=0x00007f4b6428b800 nid=0x2ce2 waiting for monitor entry [0x00007f4c19d66000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:204)
- waiting to lock <0x00000005bd1bfe58> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:391)
at org.apache.log4j.Category.log(Category.java:856)
at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:304)
at com.best.ti.util.log.MethodTimeAdvice.invoke(MethodTimeAdvice.java:44)
查看log4j源码
public
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) { //------- here is a LOCK
if(c.aai != null) {
writes += c.aai.appendLoopOnAppenders(event);
}
if(!c.additive) {
break;
}
}
}
if(writes == 0) {
repository.emitNoAppenderWarning(this);
}
}
日志并发输出的时候，所有的logger对象关联的parent category链路路引用的是同一个rootLogger对象，所以会锁等待，在高并发且日志输出频繁的情况下， 这个锁等待的情况会很严重，进而影响了应用的性能表现。
关闭执行时间监控的日志打印
关闭后， QPS上升到了200左右。
升级为log4j 2
不修改代码，采用bridge的方式升级为log4j2日志实现。
压测结果显示：
- 用 同步输出，TPS 为58
- 采用异步AsyncAppender输出，TPS 达到了 116
