从应用到内核查接口超时(上) (2)

考虑到的问题点有 HttpClient、Hystrix、Log4j2。使用固定数据替换了三方接口的返回值,删去了 Hystrix,甚至将逻辑代码都删掉,只要使用 Log4j2 输出大量日志,问题就可以复现,终于定位到了 Log4j2,原来是监守自盗啊。。

虽然定位到 Log4j2,但日志也不能不记啊,还是要查问题到底出在哪里。

使用 btrace 排查 log4j2 内的锁性能。

首先考虑 Log4j2 代码里的锁,怀疑是由于锁冲突,导致输出 log 时被 block 住了。

查看源码,统计存在锁的地方有三处:

rollover() 方法,在检测到日志文件需要切换时会锁住进行日志文件的切分。

encodeText() 方法,日志输出需要将各种字符集的日志都转换为 byte 数组,在进行大日志输出时,需要分块进行。为了避免多线程块之间的乱序,使用synchronized 关键字对方法加锁。

flush() 方法,同样是为了避免不同日志之间的穿插乱序,需要对此方法加锁。

具体是哪一处代码出现了问题呢,我使用 btrace 这一 Java 性能排查利器进行了排查。

使用 btrace 分别在这三个方法前后都注入代码,将方法每次的执行时间输出,然后进行压测,等待问题发生,最终找到了执行慢的方法: encodeText()。

排查代码并未发现 encodeText 方法的异常(千锤百炼的代码,当然看不出什么问题)。

使用 jmc 分析问题

这时,组内大神建议我使用 jmc 来捕捉异常事件。 给 docker-compose 添加以下参数来启用环境的 JFR。

environment: - JFR=true - JMX_PORT=port - JMX_HOST=ip - JMX_LOGIN=user:pwd

内容版权声明:除非注明,否则皆为本站原创文章。

转载注明出处:https://www.heiqu.com/wppdxg.html