标签:执行 param repo log img str bre void pos
双十一零点时,有一个服务A(后文该服务都用A来代替)的tp99由平常的50ms左右突然彪到60000ms,导致调用端积累了几十W的数据,同时,也影响到了同一个docker上的其他服务。那为什么会出现这种问题呢,且看下面排查过程。
1、将一台docker上其他服务都进行下线,同时将其他docker上的A服务进行下线,也就是说调用方只能调用到该docker上的A服务。这个时候发现除了A服务性能比较差,其他服务基本恢复正常。
2、将A服务的每一步认为耗时的地方都加上日志打印,包括内部方法调用的地方。这时候发现一个奇怪,在方法methodA()的内部耗时打印日志是10ms,在this.methodA()调用的地方耗时打印日志是1000ms;而且查看依赖的两个外部服务的性能都比较正常,所以加上日志打印后也看不出来到底是什么地方耗时。
3、再次梳理代码,能考虑到的地方都考虑到了,依然没有任何解决方案。
4、早上8点时,经一个同事的指点,是否是日志打印太多导致了该问题,因为log4j在多线程情况下,会竞争Logger的锁。下载线程快照文件后(执行jstatck -l pid),文件部分内容如下图所示,看了一下,差不多大概有200个线程都是blocked状态,都在等待这把锁:
5、将A服务内所有打印日志的地方都注释掉,然后重启,此时性能恢复。
6、查看监控得知,当时A服务由平时200/m的调用量突然彪到了5000/m的调用量。且A服务内部有很多不合理的日志打印,所以导致了这次线上问题。
那回到最开始,为什么会影响docker上的其他服务呢。因为A服务和其他服务共用了一个线程池(200个),当大量A请求过来,且很多线程都阻塞的情况下,导致了其他服务没有线程可用,所以影响了到其他服务。那这时的解决方案就是在设计初期要做线程隔离的规划(关于高并发系统的各种隔离策略可以参见http://jinnianshilongnian.iteye.com/blog/2324025)
我们来看一下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 }
待补充
1、日志打印要有针对性,不该打的日志不打,该打的日志一定要打,且要有一定的打印规范。
2、线上日志级别调到最高,一般开启的info级别
3、如果碰到如下情况,如 LOG.info("params = {}", JSON.toJSONString(user));如下打印需求,可以修改为如下打印方式,因为你不加的话,其实JSON序列化也执行了,所以为了不必要的性能损耗,前面可以加上判断。
if(LOG.isInfoEnable) {
LOG.info("params = {}", JSON.toJSONString(user));
}
4、可以采用logback、log4j2来替换log4j。
标签:执行 param repo log img str bre void pos
原文地址:http://www.cnblogs.com/coder-yoyo/p/6224600.html