前言
在线上,我们可能经常会碰到程序卡死或者执行很慢等情况,这时我们迫切希望知道是代码哪里的问题,代码运行到了哪里,是哪一步很慢,是否进入了死循环,是否有代码出现了线程不安全的情况,是否有某些连接数或者打开的文件数太多等等问题。此时就需要通过分析案发时的线程堆栈信息,快速定位问题。
要想快速分析、定位问题,通常我们需要借助一点其他工具,比如:jstat、jstack、jmap、jhat、jconsole、jprofile等等。
而定位问题的步骤无外乎几步:
上面几步是常用定位问题的步骤,有的公司(比如我们公司)自己写了监控脚本,在出现问题的时候,会自动dump线程堆栈、内存使用情况、cpu负载情况、垃圾回收情况等。下面就以我遇到的一个线上问题举例讲解:
上面的截图就是当时出问题时脚本自动输出的日志,其中30669_*是以当时的线程ID为前缀,下面就针对各个日志(从下到上)内容展开学习。
loadavg.log
首先看一下loadavg.log的内容,如下图:
loadavg是系统平均负载,即在特定时间间隔内运行队列中的平均进程数。
一般来说每个CPU的当前活动进程数不大于3那么系统的性能就是良好的。如果每个CPU的任务数大于5,那么就表明机器的性能有严重问题。
以上图为例,假设系统有8个CPU,则每个CPU在1分钟内的进程数为:1.16/8=0.145
如果我们想查看系统平均负载,可通过如下命令:
cat /proc/loadavguptimetload
top.log
下面看下30669_top.log和30669_top10_thread.log的内容,如下图:
30669_top.log资源占用最高的进程情况。30669_top10_thread.log是资源占用前10的进程情况。
内容解读
1  | top - 15:48:34 up 60 days, 18:06, 1 user, load average: 1.45, 0.47, 0.20  | 
top学习
top命令是用来监控Linux系统状况,比如cpu、内存的使用。
语法
1  | top [-] [d] [p] [q] [c] [C] [S] [s] [n]  | 
参数解析
常用交互命令
使用示例
1  | top //每隔5秒显式所有进程的资源占用情况  | 
threadcount.log
接着看下30669_threadcount.log的内容,如下图:
该日志的内容是30669进程下的线程数量。
统计一个进程中的线程数
下面学习下如何统计一个进程中的线程数。
proc 伪文件系统,它驻留在 /proc 目录,这是最简单的方法来查看任何活动进程的线程数。 /proc 目录以可读文本文件形式输出,提供现有进程和系统硬件相关的信息如 CPU、中断、内存、磁盘等等。
1  | cat/proc/<pid>/status  | 
上面的命令将显示进程 <pid> 的详细信息,包括过程状态(例如, sleeping, running),父进程 PID,UID,GID,使用的文件描述符的数量,以及上下文切换的数量。输出也包括进程创建的总线程数。
示例如下;
首先使用top命令查一下当前占用资源最多的进程,如下图:
从图中可以看出,当前13985是占用资源最多,接下来就看一下13985进程下的线程数,如下图:
tcp.log
接着再看下30669_tcp.log的内容,如下图:
该日志内容是统计案发时TCP的连接数,下面学习下如何获取TCP连接数。
方法一
1  | ss -ant | awk 'NR>1 {a[$1]++} END {for (b in a) print b,a[b]}'  | 
方法二
1  | netstat -an | awk '/^tcp/ {a[$NF]++} END {for (b in a) print b,a[b]}'  | 
方法三
1  | netstat -nat|awk '{print $6}'|sort|uniq -c|sort -rn  | 
方法四
1  | cat /proc/net/snmp  | 
输出内容中的各项参数的意义,请参考 http://perthcharles.github.io/2015/11/10/wiki-netstat-proc/
lsof.log
接着再看下30669_lsof.log的内容,如下图:
这个文件的内容究竟是什么含义,其实我也不知道😂,推测可能是统计的打开的文件数或者打开的文件大小。
lsof 命令详解
简介
lsof(list open files)是一个列出当前系统打开文件的工具。
在linux环境下,任何事物都以文件的形式存在,通过文件不仅仅可以访问常规数据,还可以访问网络连接和硬件。所以如传输控制协议 (TCP) 和用户数据报协议 (UDP) 套接字等,系统在后台都为该应用程序分配了一个文件描述符,无论这个文件的本质如何,该文件描述符为应用程序与基础操作系统之间的交互提供了通用接口。因为应用程序打开文件的描述符列表提供了大量关于这个应用程序本身的信息,因此通过lsof工具能够查看这个列表对系统监测以及排错将是很有帮助的。
输出信息解析
在终端下输入lsof即可显示系统打开的文件,因为 lsof 需要访问核心内存和各种文件,所以必须以 root 用户的身份运行它才能够充分地发挥其功能。
每行显示一个打开的文件,若不指定条件默认将显示所有进程打开的所有文件。lsof输出各列信息的意义如下: 
语法格式
1  | lsof [options] filename  | 
histolive.log
接着再来看30669_histolive.log的内容,如下图:
该日志记录了案发时heap中的所有对象情况,包括对象的数量、所占空间大小、类名。
我们也可以通过如下命令查看:
1  | jmap -histo[:live] pid  | 
输出说明:
heap.log
接着再来看30669_heap.log的内容,因内容过长,截取主要内容,如下图:
 
上面的内容也可以直接使用命令jmap -heap pid 打印jvm内存整体使用情况,可以观察到New Generation(Eden Space,From Space,To Space),tenured generation,Perm Generation的内存使用情况。
从图中内容可以看出新生区和老年区的内存使用率几乎达到了100%,由此可以推断造成这次事故的原因是创建的对象过多,再结合上面了解过的30669_histolive.log,就能找到是哪些对象创建过多。再结合后面要讲的线程堆栈信息定位到具体调用的代码段。
gc.log、gccapacity.log
接着再来看30669_gc.log的内容,如下图: 
上图内容是显示堆内存的各个占比,可通过如下命令查看:
1  | jstat -gcutil <pid>  | 
现在解释下输出内容每个项的含义:
30669_gccapacity.log的内容如下图:
输出各项含义如下:
jstat
jstat是JDK自带的一个轻量级小工具。全称 Java Virtual Machine statistics monitoring tool,它位于java的bin目录下,主要利用JVM内建的指令对Java应用程序的资源和性能进行实时的命令行的监控,包括了对Heap size和垃圾回收状况的监控。
语法格式
1  | jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]  | 
语法格式中的option是「命令选项」,interval是「间隔时间/毫秒」,count 是「查询次数」。
jstat支持的option通过jstat -option进行查看,如下图:
下面以jdk1.8为例了解下jstat命令查看jvm的GC情况。
类加载统计
编译统计
垃圾回收统计
堆内存统计
输出各项意义参考30669_gccapacity.log。
新生代垃圾回收统计
新生代内存统计
老年代垃圾回收统计
老年代内存统计
堆内存占比
参考30669_gc.log内容及解析。
jvm编译方法统计
stack.log
最后来看下30669_1_stack.log、30669_2_stack.log和30669_3_stack.log的文件内容,因内容过长,暂先截取部分内容展示,如下图:
Thread Dump
简介
Thread Dump是非常有用的诊断Java应用问题的工具。每一个Java虚拟机都有及时生成所有线程在某一点状态的thread-dump的能力,虽然各个 Java虚拟机打印的thread dump略有不同,但是大多都提供了当前活动线程的快照,及JVM中所有Java线程的堆栈跟踪信息,堆栈信息一般包含完整的类名及所执行的方法,如果可能的话还有源代码的行数。
在实际运行中,往往一次 dump的信息,还不足以确认问题。建议产生三次 dump信息(所以就像这次的案例会dump三次stack,每次间隔3秒),如果每次 dump都指向同一个问题,我们才确定问题的典型性。也就是多进行几次线程快照,观察变化,查看问题所在。
特点
能在各种操作系统下使用
能在各种Java应用服务器下使用
可以在生产环境下使用而不影响系统的性能
可以将问题直接定位到应用程序的代码行上
能诊断的问题
查找内存泄露,常见的是程序里load大量的数据到缓存;
发现死锁线程;
如何抓取Thread Dump
JDK自带命令行工具获取PID,再获取ThreadDump:
jps或ps –ef|grepjava(获取PID)jstack [-l ]<pid> | tee -a jstack.log(获取ThreadDump)
Thread Dump结构
一个典型的thread dump文件主要由一下几个部分组成:
上图将JVM上的线程堆栈信息和线程信息做了详细的拆解。
1  | printf "%x\n" 20696  | 
第一部分:Full thread dump identifier
这一部分是内容最开始的部分,展示了快照文件的生成时间和JVM的版本信息。
1  | 2019-09-28 15:48:28  | 
第二部分:Java EE middleware, third party & custom application Threads
这是整个文件的核心部分,里面展示了JavaEE容器(如tomcat、resin等)、自己的程序中所使用的线程信息。这一部分详细的含义后面再介绍。
1  | "Thread-3" #26 daemon prio=9 os_prio=0 tid=0x00007f1ff40ae000 nid=0x77f5 waiting on condition [0x00007f1ff1bfa000]  | 
第三部分:HotSpot VM Thread
这一部分展示了JVM内部线程的信息,用于执行内部的原生操作。下面常见的几种内置线程:
Attach Listener
该线程负责接收外部命令,执行该命令并把结果返回给调用者,此种类型的线程通常在桌面程序中出现。
1  | "Attach Listener" #62 daemon prio=9 os_prio=0 tid=0x00007f2014008800 nid=0x7868 waiting on condition [0x0000000000000000]  | 
DestroyJavaVM
执行main()的线程在执行完之后调用JNI中的 jni_DestroyJavaVM() 方法会唤起DestroyJavaVM 线程。在JBoss启动之后,也会唤起DestroyJavaVM线程,处于等待状态,等待其它线程(java线程和native线程)退出时通知它卸载JVM。
1  | "DestroyJavaVM" #83 prio=5 os_prio=0 tid=0x00007f203c009000 nid=0x77cf waiting on condition [0x0000000000000000]  | 
Service Thread
用于启动服务的线程。
1  | "Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007f203c152800 nid=0x77d9 runnable [0x00007f2025ffd000]  | 
CompilerThread
用来调用JITing,实时编译装卸CLASS。通常JVM会启动多个线程来处理这部分工作,线程名称后面的数字也会累加,比如CompilerThread1。
1  | "C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f203c13d800 nid=0x77d8 waiting on condition [0x0000000000000000]  | 
Signal Dispatcher
Attach Listener线程的职责是接收外部jvm命令,当命令接收成功后,会交给signal dispather 线程去进行分发到各个不同的模块处理命令,并且返回处理结果。signal dispather线程也是在第一次接收外部jvm命令时,进行初始化工作。
1  | "Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f203c139000 nid=0x77d6 runnable [0x0000000000000000]  | 
Finalizer
这个线程也是在main线程之后创建的,其优先级为10,主要用于在垃圾收集前,调用对象的finalize()方法;
关于Finalizer线程的几点:
(1)只有当开始一轮垃圾收集时,才会开始调用finalize()方法;因此并不是所有对象的finalize()方法都会被执行;
(2)该线程也是daemon线程,因此如果虚拟机中没有其他非daemon线程,不管该线程有没有执行完finalize()方法,JVM也会退出;
(3)JVM在垃圾收集时会将失去引用的对象包装成Finalizer对象(Reference的实现),并放入ReferenceQueue,由Finalizer线程来处理;最后将该Finalizer对象的引用置为null,由垃圾收集器来回收;
(4)JVM为什么要单独用一个线程来执行finalize()方法呢?
     如果JVM的垃圾收集线程自己来做,很有可能由于在finalize()方法中误操作导致GC线程停止或不可控,这对GC线程来说是一种灾难。
1  | "Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f203c106000 nid=0x77d5 in Object.wait() [0x00007f202c41b000]  | 
Reference Handler
JVM在创建main线程后就创建Reference Handler线程,其优先级最高,为10,它主要用于处理引用对象本身(软引用、弱引用、虚引用)的垃圾回收问题 。
1  | "Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f203c101800 nid=0x77d4 in Object.wait() [0x00007f202c51c000]  | 
VM Thread
JVM中线程的母体,根据HotSpot源码中关于vmThread.hpp里面的注释,它是一个单例的对象(最原始的线程)会产生或触发所有其他的线程,这个单例的VM线程是会被其他线程所使用来做一些VM操作(如清扫垃圾等)。
在 VM Thread 的结构体里有一个VMOperationQueue队列,所有的VM线程操作(vm_operation)都会被保存到这个列队当中,VMThread 本身就是一个线程,它的线程负责执行一个自轮询的loop函数(具体可以参考:VMThread.cpp里面的void VMThread::loop()) ,该loop函数从VMOperationQueue列队中按照优先级取出当前需要执行的操作对象(VM_Operation),并且调用VM_Operation->evaluate函数去执行该操作类型本身的业务逻辑。VM操作类型被定义在vm_operations.hpp文件内,列举几个:ThreadStop、ThreadDump、PrintThreads、GenCollectFull、GenCollectFullConcurrent、CMS_Initial_Mark、CMS_Final_Remark….. 有兴趣的同学,可以自己去查看源文件。
1  | "VM Thread" os_prio=0 tid=0x00007f203c0fa000 nid=0x77d3 runnable  | 
第四部分:HotSpot GC Thread
VM中用于进行资源回收的线程,包括以下几种类型的线程:
VM Periodic Task Thread
该线程是JVM周期性任务调度的线程,它由WatcherThread创建,是一个单例对象。该线程在JVM内使用得比较频繁,比如:定期的内存监控、JVM运行状况监控。
1  | "VM Periodic Task Thread" os_prio=0 tid=0x00007f203c155800 nid=0x77da waiting on condition  | 
可以使用jstat 命令查看GC的情况,比如查看某个进程没有存活必要的引用可以使用命令 jstat -gcutil <pid> 250 7 参数中pid是进程id,后面的250和7表示每250毫秒打印一次,总共打印7次。
这对于防止因为应用代码中直接使用native库或者第三方的一些监控工具的内存泄漏有非常大的帮助。
GC task thread#0 (ParallelGC)
垃圾回收线程,该线程会负责进行垃圾回收。通常JVM会启动多个线程来处理这个工作,线程名称中#后面的数字也会累加。
1  | "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f203c01e000 nid=0x77d1 runnable  | 
Gang worker#0 (Parallel GC Threads)
如果在JVM中增加了 -XX:+UseConcMarkSweepGC 参数将会启用CMS (Concurrent Mark-Sweep)GC Thread方式,原来垃圾回收线程GC task thread#0 (ParallelGC) 被替换为 Gang worker#0 (Parallel GC Threads)。Gang worker 是JVM用于年轻代垃圾回收(minor gc)的线程。
1  | "Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x00007fbea801b800 nid=0x5e4 runnable  | 
Concurrent Mark-Sweep GC Thread
并发标记清除垃圾回收器(就是通常所说的CMS GC)线程, 该线程主要针对于年老代垃圾回收。
1  | "Concurrent Mark-Sweep GC Thread" prio=10 tid=0x00007fbea8073800 nid=0x5e8 runnable  | 
Surrogate Locker Thread (Concurrent GC)
此线程主要配合CMS垃圾回收器来使用,是一个守护线程,主要负责处理GC过程中Java层的Reference(指软引用、弱引用等等)与jvm 内部层面的对象状态同步。
1  | "Surrogate Locker Thread (Concurrent GC)" daemon prio=10 tid=0x00007fbea8158800 nid=0x5ee waiting on condition [0x0000000000000000]  | 
这里以 WeakHashMap 为例进行说明,首先是一个关键点:
WeakHashMap和HashMap一样,内部有一个Entry[]数组;WeakHashMap的Entry比较特殊,它的继承体系结构为Entry->WeakReference->Reference;Reference里面有一个全局锁对象:Lock,它也被称为pending_lock,注意:它是静态对象;Reference里面有一个静态变量:pending;Reference里面有一个静态内部类:ReferenceHandler的线程,它在static块里面被初始化并且启动,启动完成后处于wait状态,它在一个Lock同步锁模块中等待;WeakHashMap里面还实例化了一个ReferenceQueue队列;
假设,WeakHashMap对象里面已经保存了很多对象的引用,JVM 在进行CMS GC的时候会创建一个ConcurrentMarkSweepThread(简称CMST)线程去进行GC。ConcurrentMarkSweepThread线程被创建的同时会创建一个SurrogateLockerThread(简称SLT)线程并且启动它,SLT启动之后,处于等待阶段。CMST开始GC时,会发一个消息给SLT让它去获取Java层Reference对象的全局锁:Lock。直到CMS GC完毕之后,JVM 会将WeakHashMap中所有被回收的对象所属的WeakReference容器对象放入到Reference 的pending属性当中(每次GC完毕之后,pending属性基本上都不会为null了),然后通知SLT释放并且notify全局锁:Lock。此时激活了ReferenceHandler线程的run方法,使其脱离wait状态,开始工作了。ReferenceHandler这个线程会将pending中的所有WeakReference对象都移动到它们各自的列队当中,比如当前这个WeakReference属于某个WeakHashMap对象,那么它就会被放入相应的ReferenceQueue列队里面(该列队是链表结构)。 当我们下次从WeakHashMap对象里面get、put数据或者调用size方法的时候,WeakHashMap就会将ReferenceQueue列队中的WeakReference依依poll出来去和Entry[]数据做比较,如果发现相同的,则说明这个Entry所保存的对象已经被GC掉了,那么将Entry[]内的Entry对象剔除掉。
第五部分:JNI global references count
这一部分主要回收那些在native代码上被引用,但在java代码中却没有存活必要的引用,对于防止因为应用代码中直接使用native库或第三方的一些监控工具的内存泄漏有非常大的帮助。
1  | JNI global references: 1652  | 
系统线程状态
系统线程有如下状态:
deadlock(重点关注)
死锁线程,一般指多个线程调用期间进入了相互资源占用,导致一直等待无法释放的情况。
runnable
一般指该线程正在执行状态中,该线程占用了资源,正在处理某个操作,如通过SQL语句查询数据库、对某个文件进行写入等。
blocked(重点关注)
线程正处于阻塞状态,指当前线程执行过程中,所需要的资源长时间等待却一直未能获取到,被容器的线程管理器标识为阻塞状态,可以理解为等待资源超时的线程。
waiting on condition(重点关注)
线程正处于等待资源或等待某个条件的发生,具体的原因需要结合堆栈信息进行分析。
如果堆栈信息明确是应用代码,则证明该线程正在等待资源,一般是大量读取某种资源且该资源采用了资源锁的情况下,线程进入等待状态,等待资源的读取,或者正在等待其他线程的执行等。
如果发现有大量的线程都正处于这种状态,并且堆栈信息中得知正等待网络读写,这是因为网络阻塞导致线程无法执行,很有可能是一个网络瓶颈的征兆:
- 网络非常繁忙,几乎消耗了所有的带宽,仍然有大量数据等待网络读写;
 - 网络可能是空闲的,但由于路由或防火墙等原因,导致包无法正常到达;
 
所以一定要结合系统的一些性能观察工具进行综合分析,比如netstat统计单位时间的发送包的数量,看是否很明显超过了所在网络带宽的限制;观察CPU的利用率,看系统态的CPU时间是否明显大于用户态的CPU时间。这些都指向由于网络带宽所限导致的网络瓶颈。
- 还有一种常见的情况是该线程在 sleep,等待 sleep 的时间到了,将被唤醒。
 
waiting for monitor entry 或 in Object.wait()
Monitor 是Java中用以实现线程之间的互斥与协作的主要手段,它可以看成是对象或者class的锁,每个对象都有,也仅有一个 Monitor。
调用修饰:
locked <地址> 目标:注意临界区对象锁可重入,线程状态为RUNNABLE;waitting to lock <地址> 目标:还没有获得锁,进入等待区,线程状态为BLOCKED;waitting on <地址> 目标:获得锁了,等待区等待,线程状态为WAITTING,TIMED_WAITTING;parking to wait for <地址> 目标:线程原语,随current包出现,与synchronized体系不同;
从上图可以看出,每个Monitor在某个时刻只能被一个线程拥有,该线程就是 Active Thread,而其他线程都是 Waiting Thread,分别在两个队列 Entry Set和Wait Set里面等待。
其中在 Entry Set 中等待的线程状态是 waiting for monitor entry,在 Wait Set 中等待的线程状态是 in Object.wait()。
Entry Set里面的线程。
把被 synchronized 保护起来的代码段为临界区,代码如下:
1  | synchronized(obj) {  | 
当一个线程申请进入临界区时,它就进入了 Entry Set 队列中,这时候有两种可能性:
- 该
Monitor不被其他线程拥有,Entry Set里面也没有其他等待的线程。本线程即成为相应类或者对象的Monitor的Owner,执行临界区里面的代码;此时在Thread Dump中显示线程处于Runnable状态。 - 该
Monitor被其他线程拥有,本线程在Entry Set队列中等待。此时在Thread Dump中显示线程处于waiting for monity entry状态。 
临界区的设置是为了保证其内部的代码执行的原子性和完整性,但因为临界区在任何时间只允许线程串行通过,这和我们使用多线程的初衷是相反的。如果在多线程程序中大量使用synchronized,或者不适当的使用它,会造成大量线程在临界区的入口等待,造成系统的性能大幅下降。如果在Thread Dump中发现这个情况,应该审视源码并对其进行改进。
Wait Set里面的线程
当线程获得了Monitor,进入了临界区之后,如果发现线程继续运行的条件没有满足,它则调用对象(通常是被synchronized的对象)的wait()方法,放弃Monitor,进入 Wait Set队列。只有当别的线程在该对象上调用了 notify()或者notifyAll()方法,Wait Set队列中的线程才得到机会去竞争,但是只有一个线程获得对象的Monitor,恢复到运行态。Wait Set中的线程在Thread Dump中显示的状态为 in Object.wait()。
总结
通常来说,当CPU很忙的时候关注 Runnable 状态的线程,反之则关注 waiting for monitor entry 状态的线程。
JVM线程运行状态
线程在一定条件下,状态会发生变化。线程一共有以下几种状态:
新建状态(New):线程刚刚被创建,但是还没有调用start()方法,jstack命令不会列出处于此状态的线程信息。
就绪状态(Runnable):线程对象创建后,其他线程调用了该对象的
start()方法。该状态的线程位于“可运行线程池”中,变得可运行,只等待获取CPU的使用权。即在就绪状态的进程除CPU之外,其它的运行所需资源都已全部获得。运行状态(Running):就绪状态的线程获取了CPU,执行程序代码。
阻塞状态(Blocked):阻塞状态是线程因为某种原因放弃CPU使用权,暂时停止运行。直到线程进入就绪状态,才有机会转到运行状态。
WAITING (on object monitor) 等待阻塞:运行的线程执行wait()方法,该线程会释放占用的所有资源,JVM会把该线程放入“等待池”中。进入这个状态后,是不能自动唤醒的,必须依靠其他线程调用notify()或notifyAll()方法才能被唤醒,
BLOCKED (on object monitor) 同步阻塞:运行的线程在获取对象的同步锁时,若该同步锁被别的线程占用,则JVM会把该线程放入“锁池”中。
TIMED_WAITING(sleeping) 其他阻塞:运行的线程执行sleep()或join()方法,或者发出了I/O请求时,JVM会把该线程置为阻塞状态。当sleep()状态超时、join()等待线程终止或者超时、或者I/O处理完毕时,线程重新转入就绪状态。
死亡状态(Dead):线程执行完了或者因异常退出了run()方法,该线程结束生命周期。
实际上jvm线程栈中,几乎是不会出现NEW,RUNNING,DEAD 这些状态,其中Runnable就算是正在运行了。 
处于WAITING, BLOCKED, TIMED_WAITING的是不消耗CPU的。
处于Runnable状态的线程,是否消耗cpu要看具体的上下文情况: 
- 如果是纯Java运算代码, 则消耗CPU;
 - 如果是网络IO,很少消耗CPU,这点在分布式程序中经常碰到 ;
 - 如果是本地代码,结合本地代码的性质判断(可以通过
pstack/gstack获取本地线程堆栈)- 如果是纯运算代码,则消耗CPU;
 - 如果被挂起,则不消耗CPU;
 - 如果是IO,则不怎么消耗CPU;