vlambda博客
学习文章列表

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!
作者 | 漫话编程
来源 | 漫话编程(ID:mhcoding)

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

之前一段时间,因为我们发现的一个 SaaS 应用程序会间歇性地卡顿、变慢,因为很长时间都没有定位到原因,所以解决的办法就只能是重启。

这个现象和之前我们遇到的程序变得卡顿不太一样,因为我们发现这个应用程序不仅在高流量期间时会变慢,有时在低流量时期也会变慢。所以这令大家都很奇怪。

这类应用程序的变慢,重新启动之后就可以维持一段时间,但是过段时间又有可能会再次出现。

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

故障排除

当我们准备排查这个问题的时候,我们在应用程序速度很慢的时候,尝试着捕获了这个应用程序的线程 Dump。有很多种方式来捕获线程转 Dump,我们选择了“jstack”工具来获取。

在问题发生时获得线程 Dump 是非常关键的!

然后我们将捕获的线程Dump上传到一个线上线程Dump分析工具(https://fastthread.io/)。该工具立即帮我们生成了一份报告。

报告立即找出了问题的根本原因。分析工具上显示“http-nio-8080-exec-121”线程阻塞了 100 多个线程。下面是传递依赖图,展示了阻塞线程:

漫画:应用程序被拖慢?罪魁祸首是 Log4j!
从图中可以看到 100 多个线程被“http-nio-8080-exec-121”线程阻塞。当我们点击图中的“http-nio-8080-exec-121”超链接时,它会打印出线程的堆栈轨迹:
漫画:应用程序被拖慢?罪魁祸首是 Log4j!
仔细观察图中被框出来的部分,你可以看到该线程已经获取到 org.apache.log4j.Logger 的锁,正在进行其他的操作。

接下来,我们随便找一个被"http-nio-8080-exec-121"阻塞的线程,看一下他的堆栈信息:

漫画:应用程序被拖慢?罪魁祸首是 Log4j!
看一下上面堆栈跟踪中被框出来的部分。我们可以看到“http-nio-8080-exec-56”当前正处于阻塞(BLOCKED)状态,而阻塞的原因是它正在等待获取 org.apache.log4j.Logger 的锁。

前面我们刚刚分析过,“http-nio-8080-exec-121”获得了 org.apache.log4j.Logger 的锁,正在进行其他操作,而锁并没有被释放,所以其他线程想要获得锁就只能被阻塞。

其余的所有被阻塞的线程也在等待获取 org.apache.log4j.Logger 的锁。因此,每当任何应用程序线程试图记录日志时,它都会因为无法获取到锁而进入阻塞状态。

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

刚开始我们也没有太多的头绪,后来我们尝试借助 Google 的力量,然后我们用谷歌搜索了"org.apache.log4j.Logger 阻塞线程"这样的关键字。

我们在 Apache Log4j bug 数据库中偶然发现了这个有趣的 Bug,而且这个Bug早在2015年就被发现了。(https://bz.apache.org/bugzilla/show_bug.cgi?id=57714 )。

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

这是 Log4J 框架中已知的 bug 之一,也是开发新的 Log4j2 框架的主要原因之一。

由于这个 bug,任何试图打印日志的线程都进入了阻塞状态。它导致整个应用程序戛然而止。一旦应用程序从 Log4j 迁移到 Log4j2 框架,问题就解决了。

结论

Log4j 已经在 2015 年 8 月开始就不再被维护了。如果您的应用程序仍在使用 Log4J 框架,强烈建议升级到 Log4j2 框架。Log4j2 不仅仅是 Log4j 框架的下一个版本,它是一个从零开始编写的新框架,它有很多性能改进。

最后,如果网站遇到程序被拖慢的问题,那么也可以考虑一下这个因素。

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

漫画:应用程序被拖慢?罪魁祸首是 Log4j!

更多精彩推荐

漫画:应用程序被拖慢?罪魁祸首是 Log4j!
点分享
点点赞
点在看