七叶笔记 » golang编程 » 漫画:应用程序被拖慢?罪魁祸首是 Log4j

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

作者 | 漫话编程

来源 | 漫话编程(ID:mhcoding)

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

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

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

故障排除

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

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

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

从图中可以看到 100 多个线程被“http-nio-8080-exec-121”线程阻塞。当我们点击图中的“http-nio-8080-exec-121”超链接时,它会打印出线程的堆栈轨迹:

仔细观察图中被框出来的部分,你可以看到该线程已经获取到 org.apache.log4j.Logger 的锁,正在进行其他的操作。

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

看一下上面堆栈跟踪中被框出来的部分。我们可以看到“http-nio-8080-exec-56”当前正处于阻塞(BLOCKED)状态,而阻塞的原因是它正在等待获取 org.apache.log4j.Logger 的锁。

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

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

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

我们在 Apache Log4j bug 数据库中偶然发现了这个有趣的 Bug,而且这个Bug早在2015年就被发现了。( )。

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

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

结论

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

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

相关文章