记一次线上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]