记一次线上logback日志打印导致应用响应慢的分析报告

记一次线上logback日志打印导致应用响应慢的分析报告

• 一、现象描述

微信小程序页面中点击某个按钮，加载页面响应很慢，不是偶发性，很多用户反馈使用响应很慢。

• 二、问题排查

2.1 查看应用监控

在监控平台查看应用的cpu、内存、数据库慢查询、线程数、接口耗时。除了接口耗时久以外，其他都正常，cpu偶尔飙高。

在日志平台elk中，通过搜索某个耗时高（找了一个耗时60s左右）的接口，并通过此接口的traceId将整个接口的调用链日志搜索出来，发现整个traceId的日志打印超过了500行，也会发现某几行日志打印时间间隔会超过4s。

2.2 应用分析

在2.1中，找到了间隔打印的代码，这些代码也就是做了一些数据库查询。如果说耗时在数据库查询中，那么在监控平台也会看到sql的慢查询，但在监控平台并没有发现sql慢查询，也联系dba帮忙监控一下数据库的链接数、慢查询语句等，但最终结果也是反馈数据库都正常。

2.3 应用所在机器排查

登录应用所在机器查看一下机器情况。

①top 一下，cpu会在60%~100%多之间变换，不存在cpu一直彪高情况

②jstat -gc pid 5000 20

young gc出现频率稍高，但能接受，full gc次数不算多。

③top -Hp pid  

找出cpu最高的线程nid，大概80%左右。printf %x nid 将十进制的nid转化为16进制

④jstack -l pid | grep 十六进制nid

发现有好多等待锁的线程

"http-nio-8091-exec-20" #40 daemon prio=5 os_prio=0 tid=0x0000fffef4011000 nid=0x384b3b waiting on condition [0x0000fffeef9fd000]

目前能确认的是有一把锁，但锁是什么呢？

2.4 arthas分析调用链耗时

我在本地大概进行复现了这种情况，现在按照生产当时排查问题的思路在本地进行大概模拟复现一次。

前置条件：

①无访问量时，执行一次接口，查看耗时，基本在55ms左右

②对某个接口进行ab 压测：ab -n 1000 -c 100  http://127.0.0.1:8091/getTest/1000

总共1000个访问，100并发

③再次访问接口，查看耗时，达到8s~9s

④来吧，arthas查看一下getTest接口

trace org.example.controller.TestController getTest

trace org.example.service.TestService9 getA "#cost>500"

trace org.example.service.LogService logPrint "#cost>500"

奇怪，怎么都是org.slf4j.Logger:info() 耗时这么高，继续进去看看

trace  org.slf4j.Logger info "#cost>500"

再进一下ch.qos.logback.classic.Logger:filterAndLog_0_Or3Plus

trace ch.qos.logback.classic.Logger filterAndLog_0_Or3Plus "#cost>100"

trace ch.qos.logback.classic.Logger buildLoggingEventAndAppend "#cost>50"

 trace ch.qos.logback.classic.Logger callAppenders "#cost>50"

 trace ch.qos.logback.classic.Logger appendLoopOnAppenders "#cost>50"

 trace ch.qos.logback.core.spi.AppenderAttachableImpl appendLoopOnAppenders "#cost>50

Appender的实现类

trace ch.qos.logback.core.Appender doAppend -n 5

trace ch.qos.logback.core.  tab键补全

 trace ch.qos.logback.core.OutputStreamAppender append

再查看具体代码写法，居然上了一把锁，终于找到这把锁了，这把锁是公平锁

ReentrantLock lock = new ReentrantLock(true);

关于公平锁和非公平锁

可以参考一下这个文章 

http://www.manongjc.com/detail/25-bieszlxfzlztwai.html 

• 三、解决问题

3.1升级logback版本

原先logback版本是1.1.7，升级到1.2.3后，查看了OutputStreamAppender.java的实现。

①将公平锁改为非公锁了。可以减少cpu唤醒线程的开销

 ②subAppend方法改了，大概意思应该是拿锁不成功就不等待了

3.2 再次实验一把

之前logback为1.1.7在开启压测后，接口耗时达到8s~9s

现在升级logback为1.2.3，再开启压测，看看效果。接口耗时3s，时间减半！！！

------------------------------------------------------------------------------------------------

最后，感谢公司的大神使用arthas给线上操作了一次，学习了。