考虑到的问题点有 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