《JVM故障诊断指南》之7 —— 线程转储分析

---

原文是免费电子书，链接：http://www.javacodegeeks.com/whitepaper/jvm-troubleshooting-guide
以下为本人翻译，仅用于交流学习，版权归原作者所有，转载注明出处，请不要用于商业用途 。

---

线程转储分析

线程转储分析介绍

这小节我们会教你如何分析一个JVM线程转储以及如何查找问题的根源。我们的观点是，对于任何一个涉及Java EE的线上支持，线程转储分析都是需要掌握的最重要的技能。你从线程转储快照能拿到的信息常常比你想象的多。

在我们深入到线程转储分析问题之前掌握基础知识是非常重要的。

Java 虚拟机概览

Java虚拟机是任何一个Java EE平台的基础。它是中间件和应用发布以及运行的地方。

JVM提供给中间件软件和Java /Java EE 程序：

• 给Java程序一个运行环境 (二进制格式)。
• 一些程序的特性和功能设备(IO设备，数据结构，线程管理，安全，监控等)
• 通过垃圾收集来进行动态内存分配和管理。

JVM可以装在很多操作系统上 (Solaris, AIX, Windows 等.)，基于你硬件服务器的参数指标，你可以为每个物理/虚拟机安装多个JVM进程。

JVM 和中间件软件的交互

下面这张图展示了JVM，中间件和应用的概览。

这里给你展示了一个JVM，中间件和应用的典型的简易交互图，你可以看到，一个标准的Java EE应用的线程分配主要在中间件内核和JVM之间完成（应用本身或者一些APIs直接创建了线程属于例外情况，不过这种情况很少见并且要非常小心）。

另外请记住，某些线程是JVM自己内部管理的比如GC(垃圾收集)线程，它用于处理并发垃圾收集。

在Java EE容器完成了大部分的线程分配之后，对你来说理解和认识线程栈踪迹以及从线程转储数据里正确识别它是很重要的。这里会让你快速了解Java EE容器执行的请求类型。

从线程转储分析里，你可以学到如何去区分JVM里不同的线程池以及鉴别请求类型。

JVM 线程转储- 它是什么?

一个JVM线程转储是一个快照，它在给定的时间提供给你一个完整的已被创建的Java线程列表。

每个Java线程给你提供如下信息：

• 线程名字; 经常被中间件使用，用于识别线程的ID，它伴随着相关的线程池的名字和状态 (运行，阻塞等)

• Thread 类型 &优先级 ex: daemon prio=3 * 中间件软件通常创建它们的线程作为守护线程，这意味着这些线程会在后台运行，为它们的用户提供服务。比如你的Java EE应用。*

• Java 线程ID ex: tid=0x000000011e52a800 * 这是Java线程的ID，通过java.lang.Thread.getId()获取，并且常常以自增的long型来实现。*

• Native 线程ID ex: nid=0x251c** 这是一种Native 线程ID，能允许你将操作系统层面上的并且在多个CPU上使用的线程和你的JVM关联起来的关键信息。**

• Java 线程状态和详情 ex: waiting for monitor entry [0xfffffffea5afb000] java.lang.Thread.State: BLOCKED (on object monitor)
  * 可以快速了解关于线程状态和它潜在的当前阻塞条件。*

• Java 线程栈踪迹; 这是你到目前为止能从线程转储里获得的最重要的信息。这也是你在分析上花时间最多的地方，为了找出许多问题类型的根源，你需要很多的信息，而Java栈踪迹为你提供了90%的信息，你可以从之后的训练部分学到更多。

• Java 堆简略分析： 我们用HotSpot VM 1.6作为开始,你可以在线程转储快照的底部找到HotSpot内存区的简略分析，比如Java堆(年轻代，年老代)和持久代。这对于当频繁GC被认为是主要原因的时候非常有用，因为它和线程数据/模式有很大关系。

  Heap
  PSYoungGen total 466944K, used 178734K [0xffffffff45c00000, 0xffffffff70800000, 
  0xffffffff70800000)
  eden space 233472K, 76% used 
  [0xffffffff45c00000,0xffffffff50ab7c50,0xffffffff54000000)  from space 233472K, 0% used 
  [0xffffffff62400000,0xffffffff62400000,0xffffffff70800000)  to space 233472K, 0% used 
  [0xffffffff54000000,0xffffffff54000000,0xffffffff62400000)
  PSOldGen    total 1400832K, used 1400831K [0xfffffffef0400000, 
  0xffffffff45c00000, 0xffffffff45c00000)  object space 1400832K, 99% used 
  [0xfffffffef0400000,0xffffffff45bfffb8,0xffffffff45c00000)
  PSPermGen    total 262144K, used 248475K [0xfffffffed0400000, 
  0xfffffffee0400000, 0xfffffffef0400000)  object space 262144K, 94% used 
  [0xfffffffed0400000,0xfffffffedf6a6f08,0xfffffffee0400000)
  

线程转储分析概览

为了让你更好的理解，下面的图展示了一个可视化的HotSpot虚拟机线程转储分析，它是从普通的线程池里找到的： 

这儿有一些你可以从虚拟机线程转储里找到的信息。有一些信息比其他信息更有用，这取决于不同的问题。

现在，对于每个线程转储部分，我们都在下面列出来了详细的分析：

Full thread dump 标识符

这是基本的唯一标识符，一旦产生了线程转储(比如: via kill -3 for UNIX).，你就可以从Java标准输出日志里看到它。这也是线程转储快照数据的开始。

Full thread dump Java HotSpot(TM) 64-Bit Server VM (20.0-b11 mixed mode):

Java EE 中间件,第三方和定制化的应用线程

这部分是线程转储的核心，通常会花更多时间来分析。能找到的线程数和你的中间件，第三方库(或许有自己的线程)以及应用(如果创建自定义的线程，通常不是做好的实践)有关。

在我们的例子中，使用的是Weblogic中间件。用Weblogic 9.2作为开始，它用了可以自动调节的线程池，并带有“‘weblogic.kernel.Default (self-tuning)”唯一标识符。

"[STANDBY] ExecuteThread: '414' for queue: 'weblogic.kernel.Default (selftuning)'" daemon prio=3 tid=0x000000010916a800 nid=0x2613 in Object.wait() 
[0xfffffffe9edff000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
-   waiting on <0xffffffff27d44de0> (a weblogic.work.ExecuteThread)         at java.lang.Object.wait(Object.java:485)
        at weblogic.work.ExecuteThread.waitForRequest(ExecuteThread.java:160)
-   locked <0xffffffff27d44de0> (a weblogic.work.ExecuteThread)         at weblogic.work.ExecuteThread.run(ExecuteThread.java:181)

HotSpot VM 线程

这是HotSpot自己管理的内部线程，用于服务内部的Native操作。通常你不用担心这个，除非你的CPU占用率很高(通过线程转储和prstat/native线程ID关联)。

"VM Periodic Task Thread" prio=3 tid=0x0000000101238800 nid=0x19 waiting on condition

HotSpot GC 线程

当使用HotSpot的parallel GC(当使用物理多核的硬件时很常见)的时候，JVM默认会自动创建，或者根据JVM自动调整到某种GC线程。这些GC线程允许虚拟机用并行的方式去实现周期性的GC清理，用CPU利用率作为代价，这样可以使GC时间整体减少。

"GC task thread#0 (ParallelGC)" prio=3 tid=0x0000000100120000 nid=0x3 runnable 
"GC task thread#1 (ParallelGC)" prio=3 tid=0x0000000100131000 nid=0x4 runnable

当发生GC相关的问题比如频繁GC，内存溢出等，这些数据非常关键，你可以使用native id值将任何一个CPU占用高的问题和这些线程关联起来。

JNI 全局引用计数

JNI (Java Native Interface) 全局引用是一种从native 代码到Java对象的基本的对象引用，由Java垃圾收集管理。它的作用是为了阻止一个对象被回收，而这个对象仍然被native代码使用，但是在Java代码里却没有活的引用。

同样重要的是为了检测JNI相关的泄露，要时刻注意JNI引用。如果你的代码直接使用了JNI或者用了第三方工具比如监控工具，就会很容易导致native内存泄露。

JNI global references: 1925

Java 堆利用概览

这部分数据从JDK1.6开始便加入了，它可以给你一个简短快速的关于堆的预览。这对于解决这种伴随着高使用率CPU的GC相关问题非常有用。一旦你在一个快照里得到了线程转储和堆转储，你就可以在同一个时间某个Java堆内存空间来确定(或排除)任何一个问题。在我们的例子线程转储里，你可以看到老年代已经达到最大了！

Heap
 PSYoungGen      total 466944K, used 178734K [0xffffffff45c00000, 
0xffffffff70800000, 0xffffffff70800000)   eden space 233472K, 76% used 
[0xffffffff45c00000,0xffffffff50ab7c50,0xffffffff54000000)   from space 233472K, 0% used 
[0xffffffff62400000,0xffffffff62400000,0xffffffff70800000)   to   space 233472K, 0% used 
[0xffffffff54000000,0xffffffff54000000,0xffffffff62400000)
 PSOldGen        total 1400832K, used 1400831K [0xfffffffef0400000, 
0xffffffff45c00000, 0xffffffff45c00000)   object space 1400832K, 99% used 
[0xfffffffef0400000,0xffffffff45bfffb8,0xffffffff45c00000)
 PSPermGen       total 262144K, used 248475K [0xfffffffed0400000, 
0xfffffffee0400000, 0xfffffffef0400000)   object space 262144K, 94% used 
[0xfffffffed0400000,0xfffffffedf6a6f08,0xfffffffee0400000)

为了让你能够快速的从线程转储里找到问题，你第一个要做的是理解如何去阅读一个线程栈踪迹以及如何拿到正确的信息。意思就是说，如果我让你告诉我线程#38在做什么，你应该能知道正确答案，包括这个线程栈踪迹是在一个正常环境下还是在一个阻塞环境下。

Java 栈踪迹回顾

大多数人对Java栈踪迹很熟悉。当发生Java异常的时候，从服务端或者应用的日志文件里能找到这种典型的数据。在这里，Java栈踪迹给我们提供了线程代码的执行路径，这个线程触发了Java异常比如java.lang.NoClassDefFoundError, java.lang.NullPpointerException 等。这种代码执行路径允许我们看到最终导致Java异常的代码的不同层级。

Java栈踪迹必须从下往上读:

• 最下面的行显示了请求的最原始位置，比如一个Java/Java EE 容器线程。
• 栈踪迹顶部第一行展示了最后一个触发的异常Java类

让我们通过一个简单例子来深入这个过程。我们创建一个例子程序，简单的执行了一些类方法并抛出了一个异常。这个程序产生的输出如下：

JavaStrackTraceSimulator
Author: Pierre-Hugues Charbonneau http://javaeesupportpatterns.blogspot.com
Exception in thread "main" java.lang.IllegalArgumentException: 
     at org.ph.javaee.training.td.Class2.call(Class2.java:12)      at org.ph.javaee.training.td.Class1.call(Class1.java:14)
     at org.ph.javaee.training.td.JavaSTSimulator.main(JavaSTSimulator.java:20)

• 程序JavaSTSimulator被调用 (通过”main”线程)
• 从Class1里调用方法call()
• Class1的方法call()调用Class2的方法call()
• Class2 方法 call() 抛出了一个异常java.lang.IllegalArgumentException
• 这个异常此时出现在了日志或者标准输出中。

你可以看到，指向了异常的代码执行路径总是从下往上显示的。

线程转储：线程栈踪迹分析

从JVM产生的线程转储可以为你提供整个JVM进程中所有已创建线程的代码级别的执行快照。已创建的线程不是说所有的线程都在工作。产生的线程转储快照一般来自于Java EE的容器 JVM：

• 一些线程可以执行原始计算任务比如XML解析，IO/磁盘访问等。
• 一些线程可以等待某些阻塞的IO调用比如远程Web Service调用，数据库查询等。
• 一些线程可以在垃圾回收的时候被调用，比如GC线程。S
• 一些线程可能会等待任务(线程在进入wait()状态时候通常不做任何工作)
• 一些线程会等待其他线程的工作然后一起完成，比如，线程在某些对象上等待获取一个锁(synchronized block{})。

线程栈踪迹给你提供了当前执行的快照。通常第一行包括了线程的native信息比如名字，地址等。当前执行栈踪迹要从下往上读。请跟着下面的分析过程一步步来。你从线程转储分析里学到的经验越多，你就越能更快的阅读和定位出每个线程所做的工作：

• 从底部开始阅读线程栈踪迹。
• 首先，找出起始地方(Java EE容器线程，定制的线程，GC线程，JVM内部线程，单独的Java“main”线程)。
• 下一步是找出这个线程正在执行的请求的类型 (WebApp, Web Service, JMS, Remote EJB (RMI), 内部Java EE容器等)。
• 下一步是从执行栈踪迹里找出你应用模块涉及的并且由这个线程执行的实际核心任务。分析的复杂性取决于中间件环境和应用的抽象层次。
• 下一步是看第一行后面10-20行。找出这个线程有关的协议或者任务，比如HTTP调用，Socket通信，JDBC或者原始数据计算任务如磁盘访问，类加载等。
• 下一步是看第一行。第一行通常会告知你拿到的快照里当前代码块执行时的线程状态的LOT。
• 最后2个步骤的组合会给你提供重要的总结信息，即当前线程有关的工作状态或者阻塞状态。

下面这张可视化分析图包括了上面的所有步骤，它用了一个真实的从JBoss 5的生成环境捕获的线程转储例子。在这个例子中，许多线程显示了一个同样的问题，当创建新的JAX-WS Service实例的时候有频繁的IO操作。

你可以看到，第一行后面的10行告诉了我们和线程有关的阻塞或者慢状态，后面的行告诉了我们初始线程的详细信息和请求类型。