JBoss 线程在随机监视器上等待答案

【问题标题】：JBoss threads waiting on random monitorJBoss 线程在随机监视器上等待
【发布时间】：2011-03-09 10:04:52
【问题描述】：

我正在对部署在 JBoss 中的 Web 应用程序进行一些负载测试。它启动良好，但随着测试的增加和更多模拟用户开始使用 JBoss，性能严重下降：

将VisualVM连接到它，我可以看到线程都很好，然后突然开始花费大部分时间等待监视器（绿色正在运行，红色是监视器，黄色是等待）：

运行jstack，我看到线程都在同一个地方等待：

"http-0.0.0.0-8080-172" 守护进程prio=6 tid=0x000000005da90000 nid=0xd2c 等待监视器条目[0x000000006cb4e000]
   java.lang.Thread.State: BLOCKED (在对象监视器上)
    在 org.apache.log4j.Category.callAppenders(Category.java:185)
    - 等待锁定（org.apache.log4j.spi.RootCategory）
    在 org.apache.log4j.Category.forcedLog(Category.java:372)
    在 org.apache.log4j.Category.debug（Category.java:241）
    [我的代码]

大约 200 个 HTTP 处理器线程中的大多数都在等待同一个监视器。查看 WAR 的 log4j.xml，它有一个用于 CONSOLE 的附加程序设置。我删除了 appender 并再次尝试我的测试。相同的行为，除了 jstack 显示所有线程在不同的地方等待：

“http-0.0.0.0-8080-251”守护进程prio=6 tid=0x0000000059811800 nid=0x1108 等待监视器条目[0x0000000073ebe000]
   java.lang.Thread.State: BLOCKED (在对象监视器上)
    在 java.util.Hashtable.get(Hashtable.java:333)
    - 等待锁定（org.jboss.util.property.PropertyMap）
    在 java.util.Properties.getProperty(Properties.java:932)
    在 org.jboss.util.property.PropertyMap.getProperty(PropertyMap.java:626)
    在 java.lang.System.getProperty(System.java:653)
    在 org.jaxen.saxpath.helpers.XPathReaderFactory.createReader(XPathReaderFactory.java:109)
    在 org.jaxen.BaseXPath.(BaseXPath.java:124)
    在 org.jaxen.BaseXPath.(BaseXPath.java:153)
    在 nu.xom.JaxenConnector.(JaxenConnector.java:49)
    在 nu.xom.Node.query(Node.java:424)
    [我的代码]

什么都没有改变，我重新启动 JBoss，运行测试，然后运行 jstack，一旦它变慢了。所有线程都在另一个地方等待：

“http-0.0.0.0-8080-171”守护进程prio=6 tid=0x000000005d0d1000 nid=0x15d4 等待监视器条目[0x000000006cb4e000]
   java.lang.Thread.State: BLOCKED (在对象监视器上)
    在 sun.nio.cs.FastCharsetProvider.charsetForName(FastCharsetProvider.java:118)
    - 等待锁定（sun.nio.cs.StandardCharsets）
    在 java.nio.charset.Charset.lookup2(Charset.java:449)
    在 java.nio.charset.Charset.lookup(Charset.java:437)
    在 java.nio.charset.Charset.isSupported(Charset.java:479)
    在 sun.nio.cs.StreamDecoder.forInputStreamReader(StreamDecoder.java:49)
    在 java.io.InputStreamReader.(InputStreamReader.java:57)
    在 java.io.FileReader.(FileReader.java:41)
    [我的代码]

到底发生了什么？我过去使用过 jstack，当一切运行良好并获得预期结果时，我尝试运行它。我认为 jstack 很好。有什么想法会导致这种奇怪的行为吗？关于从这里去哪里的任何想法？

【问题讨论】：

没有更多上下文/信息，很难具体说明发生了什么。一般来说，看起来有很多对各种资源的争用和/或可能的死锁情况。作为您的第一步，听起来您删除了一些对 log4j 的争用。是否可以通过缓存查询结果或同步访问可能导致死锁的数据结构的某种组合对其他两种资源做同样的事情？
我很乐意提供更多信息，但我不知道该提供什么。奇怪的是，虽然有很多争用，但线程并没有死锁。他们在监视器上等待 2 到 10+ 秒，然后继续执行，然后不久再次在监视器上等待。这些调用非常基本（例如 System.getProperties），无法避免。 JBoss 和其他第三方代码进行这些调用。因为我很确定 System.getProperties 和 HashTable 是可靠的，所以我的下一个最佳猜测是当争用发生时 jstack 具有误导性。如果是这样，我还能如何确定争用发生的位置？

标签： java performance debugging concurrency jboss

【解决方案1】：

这种行为是意料之中的。当您扩大负载测试时，您总是会发现瓶颈，而在复杂的系统中，这些瓶颈会转移。

您的工作是找出这些瓶颈并尝试解决它们，一次一个。每次你这样做，你总会找到另一个，但希望系统每次都能更好地扩展。这并不容易，但是扩展负载并不容易。

举第一个例子。您对 log4j 的 Logger.debug() 方法有很多调用。 Log4j 在负载下登录时表现不佳，因此您需要采取一些预防措施。即使您的 log4j 配置说“不记录调试消息”，log4j 仍然需要做一些工作才能意识到这一点。推荐的处理方法是将每个 Logger.debug() 调用包装在 if Logger.isDebugEnabled() { Logger.debug(); }` 块。这应该会改变这个特定的瓶颈。
在您的第二个示例中，您正在调用 XOM 的 Node.query() 方法。此方法必须在每次调用时重新编译 XPath 表达式，这似乎是一个瓶颈。找到一个 API，您可以在其中预编译 XPath 表达式并重新使用它。
在第三个示例中，您正在阅读File。这在高负载系统中不是一个好主意，当您执行大量小型操作时，file-io 很慢。如果可以的话，考虑重新实现它以以不同的方式工作。

所有这些都是不相关的，但都存在您在扩展负载时会看到的性能瓶颈。你永远无法摆脱它们，但希望你能把它带到一个足够好的地步。

【讨论】：

我没有看到瓶颈。 Log4j 调用（甚至串行写入文件）、调用 System.getProperty 和调用 Charset.isSupported 是快速操作，而不是通常需要避免的调用。我只运行 250 个线程。这些锁通常会很快松开。 System.getProperty 上等待的 100 多个线程意味着锁定 HashTable 的线程需要很长时间。锁定线程只是调用 Hashtable.get。需要很长时间的原因很少。也许 jstack 具有误导性？似乎不太可能，因为当 Web 应用程序平稳运行时，它不会显示阻塞线程。
@NateS：它们可能是快速操作，但它们是单线程的，这使它们成为瓶颈。不管它们有多快，它们都不是并发的。您自己的堆栈转储证明了这一点。
我不敢相信有 250 个线程都调用 System.getProperties 的简单测试程序会显示出与我的应用程序相同的争用问题。
@NateS：不管你信不信，证据就在那里。无论如何，你有我的建议，如果你想采取行动当然取决于你。
非常感谢您的帮助。我的观点是，证据并不能证明你的结论。问题不是 XOM，而是 System.getProperty。这在整个代码中都被调用，这不是我的并且无法避免。例如，JBoss 调用它根本不涉及我的代码。我无法避免使用 Jboss。此外，问题不是读取文件，而是 Charset.isSupported。这是由字符串构造函数、URLEncoder 等调用的。我无法避免创建字符串！对这些资源的轻微争用很好，但我很困惑为什么这些锁被持有这么长时间以产生只有 250 个线程的问题。

【解决方案2】：

我在通过 Eclipse 运行的 Tomcat 中设置了应用程序，但没有发现问题。最终我发现我们使用 32 位 Windows 服务包装器启动 JBoss，尽管我们使用的是 64 位 JDK。这台机器是 64 位的。我不确定这甚至会如何工作？无论如何，改用 32 位 JDK 让这个疯狂的问题消失了，我得以继续我的生活。

【讨论】：