Log4j Bug –减慢您的应用程序

最近，我们正在对流行的SaaS应用程序进行故障排除。该应用程序间歇性地减慢了速度。要从问题中恢复，必须重新启动应用程序。在高流量期间，此应用有时会变慢；有时在交通繁忙时也是如此。没有凝聚力模式。

这种应用程序变慢并重新启动它持续了一段时间。然后，我们开始解决问题。我们发现了一些有趣的东西，以为您也可以从我们的发现中受益，因此撰写了本文。

技术栈

这个流行的SaaS应用程序在Azure云上运行。下面是它的技术堆栈：

+ Spring框架

+ GlassFish应用服务器

+ Java 8

+ Azure云

故障排除

得知此问题后，我们就在发生减速时从该应用程序捕获了线程转储。有多种捕获线程转储的选项；我们选择了“ jstack”工具来捕获线程转储。

注意：发生问题时，正确获取线程转储非常重要。在问题持续时间窗口之外捕获的线程转储将无用。

现在，我们将捕获的线程转储上传到fastThread.io –在线线程转储分析工具。该工具立即生成了此精美报告。（我们建议您单击超链接以查看生成的报告，以便获得第一手的经验）。

该报告立即缩小了问题的根本原因。 fastThread.io工具突出显示“ http-nio-8080-exec-121”线程正在阻止134个应用程序线程。下面是传递依赖关系图，显示了已阻塞的线程：

图：fastThread.io显示了已阻塞线程的传递依赖关系

从该图可以看到134个应用程序线程被“ http-nio-8080-exec-121”线程阻塞（第一个从左侧开始）。当我们单击图中的“ http-nio-8080-exec-121”超链接时，它会打印线程的堆栈跟踪：

图：http-nio-8080-exec-121获得的org.apache.log4j.Logger锁

我要求您仔细查看堆栈跟踪中突出显示的部分。您可以看到线程获得org.apache.log4j.Logger锁，然后继续前进以将日志记录写入Azure云存储。

现在，让我们看一下“ http-nio-8080-exec-56”线程（134个被阻塞的线程之一）的堆栈跟踪：

图：http-nio-8080-exec-56等待获得org.apache.log4j.Logger锁

看一下上面堆栈跟踪中突出显示的部分。它正在等待获取org.apache.log4j.Logger锁。您可以看到'http-nio-8080-exec-56'线程处于BLOCKED状态，因为'http-nio-8080-exec-114'获得了org.apache.log4j.Logger锁并且没有释放它。

其余的134个线程也被卡住，等待'org.apache.log4j.Logger'锁。因此，每当任何应用程序线程尝试登录时，它都会进入此BLOCKED状态。因此134个应用程序线程结束进入此BLOCKED状态。

然后，我们用google搜索org.apache.log4j.Logger BLOCKED线程。我们偶然发现了Apache Log4j错误数据库中报告的这个有趣的缺陷。

事实证明，这是Log4J框架中的已知错误之一，也是开发新Log4j2框架的主要原因之一。以下是该缺陷描述的有趣摘录：

没有针对此问题的临时修复程序，这是Log4j 2出现的原因之一。唯一的解决方法是升级到Log4j 2。

是的，我是说Log4j 2中的代码有很大不同，并且锁定的处理方式也有很大不同。根记录器或附加器循环上没有锁。

由于该错误，任何试图登录的线程都进入了“阻塞”状态。这导致整个应用程序停止运行。将应用程序从Log4j迁移到Log4j2框架后，问题得到解决。