log4j致使的性能问题

问题背景

　　双十一零点时，有一个服务A（后文该服务都用A来代替）的tp99由日常的50ms左右忽然彪到60000ms，致使调用端积累了几十W的数据，同时，也影响到了同一个docker上的其余服务。那为何会出现这种问题呢，且看下面排查过程。

问题分析

　　一、将一台docker上其余服务都进行下线，同时将其余docker上的A服务进行下线，也就是说调用方只能调用到该docker上的A服务。这个时候发现除了A服务性能比较差，其余服务基本恢复正常。

　　二、将A服务的每一步认为耗时的地方都加上日志打印，包括内部方法调用的地方。这时候发现一个奇怪，在方法methodA()的内部耗时打印日志是10ms，在this.methodA()调用的地方耗时打印日志是1000ms；并且查看依赖的两个外部服务的性能都比较正常，因此加上日志打印后也看不出来究竟是什么地方耗时。

　　三、再次梳理代码，能考虑到的地方都考虑到了，依然没有任何解决方案。

　　四、早上8点时，经一个同事的指点，是不是日志打印太多致使了该问题，由于log4j在多线程状况下，会竞争Logger的锁。下载线程快照文件后（执行jstatck -l pid），文件部份内容以下图所示，看了一下，差很少大概有200个线程都是blocked状态，都在等待这把锁：

　　五、将A服务内全部打印日志的地方都注释掉，而后重启，此时性能恢复。

　　六、查看监控得知，当时A服务由平时200/m的调用量忽然彪到了5000/m的调用量。且A服务内部有不少不合理的日志打印，因此致使了此次线上问题。

　　那回到最开始，为何会影响docker上的其余服务呢。由于A服务和其余服务共用了一个线程池（200个），当大量A请求过来，且不少线程都阻塞的状况下，致使了其余服务没有线程可用，因此影响了到其余服务。那这时的解决方案就是在设计初期要作线程隔离的规划（关于高并发系统的各类隔离策略能够参见http://jinnianshilongnian.iteye.com/blog/2324025）

Log4j分析

　　咱们来看一下log4j的内部实现，查看以下源代码。能够简单理解为当写入同一个日志文件时（如调用log.info(xxx)，会写入info.log文件），为了保证写入文件的顺序不错乱，会对该资源加锁。

 1     public void callAppenders(LoggingEvent event) {
 2         int writes = 0;
 3 
 4         for(Category c = this; c != null; c = c.parent) {
 5             synchronized(c) {
 6                 if(c.aai != null) {
 7                     writes += c.aai.appendLoopOnAppenders(event);
 8                 }
 9 
10                 if(!c.additive) {
11                     break;
12                 }
13             }
14         }
15 
16         if(writes == 0) {
17             this.repository.emitNoAppenderWarning(this);
18         }
19 
20     }

 

Log4j配置分析

　　待补充

总结

　　一、日志打印要有针对性，不应打的日志不打，该打的日志必定要打，且要有必定的打印规范。

　　二、线上日志级别调到最高，通常开启的info级别

　　三、若是碰到以下状况，如 LOG.info("params = {}", JSON.toJSONString(user));以下打印需求，能够修改成以下打印方式，由于你不加的话，其实JSON序列化也执行了，因此为了避免必要的性能损耗，前面能够加上判断。

　　　　if(LOG.isInfoEnable) {

　　　　　　LOG.info("params = {}", JSON.toJSONString(user));

　　　　}

 　　四、能够采用logback、log4j2来替换log4j。