Java虚拟机在所有线程都忙于字符串操作时变慢

Question

我遇到了一个非常奇怪的问题。我的Tomcat每天都能以大约25%的CPU稳定运行24/7，但有些日子CPU却飙升到了60%，系统崩溃并无法恢复。

当我在减速期间拍摄线程转储时，几乎所有的线程都忙于某种字符串或相关操作。

没有OutOfMemory错误或任何异常被抛出，所有请求仍然得到处理，但响应时间恶化到极致，即使是一个次秒的请求也会变慢，需要60秒甚至更长时间。

我的服务器配置如下:

    Ubuntu 12.04.2 LTS
    Linux 3.2.0-38-virtual #60-Ubuntu SMP x86_64 x86_64 x86_64 GNU/Linux

    java version "1.7.0_13"
    Java(TM) SE Runtime Environment (build 1.7.0_13-b20)
    Java HotSpot(TM) 64-Bit Server VM (build 23.7-b01, mixed mode)

    export JAVA_OPTS='-server
    -Xms18g -Xmx18g
    -XX:MaxPermSize=512m
    -XX:ThreadStackSize=512
    -XX:NewRatio=1
    -XX:SurvivorRatio=4
    -XX:+UseConcMarkSweepGC
    -XX:+UseParNewGC
    -XX:+CMSClassUnloadingEnabled
    -Xloggc:/usr/tomcat/logs/gc.log
    -XX:+PrintGCDetails
    -XX:+PrintGCDateStamps
    -XX:+PrintTenuringDistribution
    -Dcom.sun.management.jmxremote
    -Dcom.sun.management.jmxremote.port=9999
    -Dcom.sun.management.jmxremote.authenticate=false
    -Dcom.sun.management.jmxremote.ssl=false
    -Djava.awt.headless=true'

点击此处下载线程转储。我已经移除了大部分线程及其堆栈跟踪信息。

点击此处下载vmstat日志

点击此处下载gc日志

你有任何导致此问题的想法吗？ 谢谢

- Rudi Strydom

---

这是不是停止世界的垃圾回收机制？你记录垃圾回收事件吗？ - mindas

大多数线程正在执行String.toUpperCase()。不幸的是，堆栈跟踪没有显示调用此方法的代码。您是否截断了堆栈跟踪？ - gogognome

mindas: 绝对不是垃圾回收（GC）。在STW集合中，JVM将使用所有CPU达到100％，除非被阻止（例如通过固定）。它不会停留在60％的CPU利用率。 - kittylyst

通常的线程转储是否不同？字符串操作较少吗？ - flup

关于“我已经删除了大量线程及其堆栈跟踪”，请将所有内容都提供给我们。否则，您可能会删掉重要的细节。如果您希望隐藏某些信息，则可以缩写包或重命名Class.method()。 - jtoberon

Answer 1

尝试使用以下JVM选项增加代码缓存的最大大小：

-XX:ReservedCodeCacheSize=256m

请查看我对另一个问题的回答，了解此建议的背景。

- Jonas Meller

---

嗨，乔纳斯，感谢你的建议。如果JIT编译器被禁用，那么突然出现性能下降的原因就可以解释了。我已经在我的Web服务器上实施了它，并会让你知道结果。 - Rudi Strydom

嗨，Rudi，有什么消息吗？我很好奇知道它是否对你有帮助。 - Jonas Meller

到目前为止一切都很好，已经将近一个月没有出现任何问题。我在开放这个问题668天后进行了奖励分配。 - Rudi Strydom

Answer 2

为了尝试确定有问题的请求，您可以在Tomcat中配置“Stuck Thread Detection Valve”（卡住线程检测阀门）。

该阀门允许检测处理时间较长的请求，这可能表明正在处理它的线程已经卡住了。

当检测到这样的请求时，其线程的当前堆栈跟踪将以WARN级别写入Tomcat日志中。

被卡住的线程的ID和名称可以通过JMX在stuckThreadIds和stuckThreadNames属性中获得。这些ID可与标准的Threading JVM MBean（java.lang:type=Threading）一起使用，以检索有关每个被卡住的线程的其他信息。

- fglez

Answer 3

如果CPU利用率低于100％，但应用程序已经停止运行，这意味着有些因素阻止了CPU的完全利用。

I/O或过多的上下文切换（例如由于锁定而引起）通常是导致此问题的罪魁祸首。

你能在其中一个事件期间发布vmsstat 1的输出吗？ - 诊断的下一步是消除在这里是否存在上下文切换问题。

- kittylyst

---

嗨，谢谢回复。我已经上传了vmstat和gc日志。 - Rudi Strydom

Answer 4

这不是内存问题，因为在您的转储中，GC甚至没有忙碌，并且有足够的可用内存。此外，CPU被卡在60％，但是如果应用程序正在繁忙地计算（GC或其他操作），则会卡在100％，如果这是网络攻击也是同样情况。因此，此问题的根源必须包括一些磁盘IO操作。

众所周知，Tomcat存在漏洞并且存在严重问题之一是我遇到的，即出于无特定原因，Tomcat突然用无意义的条目淹没了自己的日志文件。这不仅导致磁盘填充到100％，而且还大大减慢了传入请求的速度。您可以通过查看tomcat日志及其大小来检查此内容。

如果这不是来源，则应使用可用工具检查Tomcat的任何奇怪的磁盘IO 并从那里进行处理。

- TwoThe

Answer 5

我认为你的问题在于这个配置决策-XX:PermSize=320m -XX:MaxPermSize=320m不允许你的PermSpace动态改变，当你耗尽它时会导致死锁-请记住，内存中使用PermSpace进行缓存。我建议将-XX:MaxPermSize=320m更改为-XX:MaxPermSize=512m。

- Elliott Frisch

Answer 6

GC日志中是否有异常？看起来你正在使用一个相当大的堆，带有一些不寻常的选项并且执行了大量字符串分配操作。也许随着时间的推移，你会遭受堆碎片化的困扰（CMS不会压缩）。还要确保没有发生交换（如果堆太大而很少被VM访问，则可能会发生）。

我怀疑这与GC有关，因为显然没有线程被阻塞。你尝试过更近期的JDK吗？另外，你可以重试但删除一些不常用的选项-XX:+CMSScavengeBeforeRemark，因为这些选项在每个较小的JDK发布中可能没有太多测试覆盖率。

另一个怀疑是传入请求使用奇怪的字符集（西里尔文或阿拉伯文），导致大量的字符集映射开销。还要检查页面上是否有机器人，是否有任何可疑的请求进来？

你肯定需要更长的堆栈跟踪来找出字符串操作的根源。

- R.Moeller

---

我也得出结论它与GC有关。但我对其是否为字符集问题存在疑虑（尽管使用UTF-8而不是latin1是一个好主意），因为我看到很多线程在“CharacterDataLatin1:222”处…这只是一个简单的赋值：“int mapChar = ch;”。OP从未提供GC时间戳输出。我建议阅读这个回答：关于Solaris。 - brettw

嗨，谢谢回复。我已经上传了vmstat和gc日志。 - Rudi Strydom

Answer 7

您需要使用BTrace来诊断方法调用。

编写一个如下所示的BTrace脚本：

跟踪以com.xx.xx为前缀的类调用String的任何方法，并打印调用次数。

@TLS
private static Map<String, Integer> countMap = BTraceUtils.newHashMap();

private static String prefix = "com.xx.xx";// package like com.xx.xx which you want to trace ()

@OnMethod(clazz = "java.lang.String", method = "/.*/") //all method in String
public static void traceMethodInvoke() {
    String str = BTraceUtils.jstackStr();
    for (String currentClass : str.split("\\n")) {
        if (BTraceUtils.Strings.startsWith(currentClass, prefix)) {
            if (!countMap.containsKey(currentClass)) {
                countMap.put(currentClass, 1);
            } else {
                countMap.put(currentClass, countMap.get(currentClass) + 1);
            }
            break;
        }
    }
}

@OnTimer(5000)
public static void print() {
    BTraceUtils.println("========================================");
    for (Map.Entry<String, Integer> entry : countMap.entrySet()) {
        if (entry.getValue() > 100) {// print if cont > 10
            BTraceUtils.println(entry.getValue() + "\t\t" + entry.getKey());
        }
    }
    BTraceUtils.println("===========================================");

}  

---

输出结果如下：

====================================================
1022                           com.xx.xx.classA#m1
322                            com.xx.xx.classA#m2
2022                           com.xx.xx.classA#m21
422                            com.xx.xx.ccc.classX#m11
522                            com.xx.xx.zz.classS#m44
.........

你可以更改前缀以跟踪另一个包前缀。

根据结果，您可以分析源代码并找出问题。

- lichengwu

Answer 8

浏览了线程转储并查看了RUNNABLE线程后，有一件事情很明显。您的系统似乎正在同时处理/尝试处理大量请求。除非您有多个内核，否则可能会有很多时间分片。另一方面，我没有看到明确的证据表明这与GC有关。（但是您没有包含GC日志...）

我建议您注意两件事。 1. 查看操作系统的虚拟内存统计信息。灾难性系统减速的一个可能原因是虚拟内存抖动。这是总应用程序对虚拟内存页面的需求超过可用物理内存的情况...操作系统花费大量时间在物理内存和交换磁盘/页面文件之间交换页面。 2. 查看您正在接收的请求模式。可能在某些时候，您正在接收的请求数量/类型仅超出了系统的容量。

如果问题是VM抖动，则解决方案是减少应用程序内存需求。简单的方法是减少Java堆大小。

如果问题是负载，则更难以解决：

• 您可以尝试升级硬件（或将更多的虚拟CPU添加到您的虚拟机中）。
• 您可以尝试将负载分散到多个服务器实例上。
• 您可以尝试减少工作线程的数量，以便服务器不会同时处理太多请求。
• 您可以尝试对应用程序进行分析和/或分析请求统计信息，以查看是否存在可调整的热点或可关闭的昂贵功能...

最后，您可以尝试从CMS切换到Parallel Collector，参考Oracle GC Tuning页面：Available Collectors。但我怀疑这是一个GC问题。

- Stephen C

---

嗨，谢谢回复。我已经上传了vmstat和gc日志。 - Rudi Strydom

Answer 9

首先，您应该找出哪些线程实际上正在消耗CPU。可能是执行字符串操作的线程，也可能是执行GC和扫描操作的其他VM线程。 链接说明如何将CPU峰值与线程转储相关联

一旦您可以确定线程，下一步应该更加清晰。

希望这有所帮助。

- Anugoonj

---

我可以肯定地确认这不是由于垃圾回收，以下是虚拟机执行的统计数据： 2500次ParNew操作，收集时间为486,866毫秒 5次ConcurrentMarkSweep操作，收集时间为3,029毫秒。 - Rudi Strydom