org.apache.log4j.Category.callAppenders 上的线程被阻塞，但不等待任何锁定

Question

我的Web应用程序（在weblogic上部署）崩溃了，当我检查jstack信息时，我发现大多数线程在org.apache.log4j.spi.RootLogger上被阻止。拥有这个锁的线程也被阻塞并卡住至少 20 分钟，直到我杀死该进程，但它没有等待任何其他锁，这是怎么发生的？

这是 jstack 信息：

BLOCKED 线程拥有锁 <783b8910>，但不等待其他锁：

"[STUCK] ExecuteThread: '58' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=7 tid=02e45400 nid=86 lwp_id=7959740 waiting for monitor entry [61cff000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:201)
- locked <783b8910> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.error(Category.java:302)

其他线程等待锁定<783b8910>:

"[STUCK] ExecuteThread: '36' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=7 tid=02e0ea00 nid=64 lwp_id=7959717 waiting for monitor entry [62d7f000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:201)
- waiting to lock <783b8910> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.error(Category.java:319)

和

"[STUCK] ExecuteThread: '34' for queue: 'weblogic.kernel.Default (self-tuning)'" daemon prio=7 tid=02e0a200 nid=62 lwp_id=7959715 waiting for monitor entry [62eff000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:201)
- waiting to lock <783b8910> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.info(Category.java:663)

以此类推，总共有64个线程正在等待锁定<783b8910>

这种情况每月大约发生1-3次，我找不到解决方案，因为我不知道为什么拥有锁的线程在不等待其他锁的情况下被阻塞。

log4j版本是1.2.13

Answer 1

在 Java Command Windows 上，如果您单击停止打印日志，则在打印日志时会发生该线程阻塞，因此线程在打印日志时处于阻塞状态。

因此，如果这是问题，您可以使用 AsyncAppender。

Answer 2

...总共 64 个线程正在等待锁定 <783b8910>

线程都在尝试在

Category.callAppenders(LoggingEvent event)

中写入 log4j 消息。您应该下载 log4j 源代码，然后专门查看与线程堆栈跟踪行相对应的代码行。在我的 log4j 1.2.17 版本中，第 201 行接近以下代码，该代码将在日志消息上调用：

for(Category c = this; c != null; c=c.parent) {
  // Protected against simultaneous call to addAppender, removeAppender,...
  synchronized(c) {
  ...

其中一个线程实际上持有锁。我怀疑，如果您仔细查看所有线程堆栈跟踪，会发现其他一些线程的堆栈位于

org.apache.log4j.Category

中，但没有锁定在第 201 行。也许它正在调用

org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(LoggingEvent)

，它由于某种原因而阻塞。

看看有问题的实际附加程序。它是否有可能写入离线的网络驱动器或其他什么？

警告：以防您错过了备忘录，log4j 版本 1 存在重大安全漏洞。您应该在代码中找到并修复问题，但之后您应该考虑升级到 log4j v2。