记一次线上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给线上操作了一次，学习了。
