线上问题排查总结(持续更新)

前言

在线上,我们可能经常会碰到程序卡死或者执行很慢等情况,这时我们迫切希望知道是代码哪里的问题,代码运行到了哪里,是哪一步很慢,是否进入了死循环,是否有代码出现了线程不安全的情况,是否有某些连接数或者打开的文件数太多等等问题。此时就需要通过分析案发时的线程堆栈信息,快速定位问题。

要想快速分析、定位问题,通常我们需要借助一点其他工具,比如:jstatjstackjmapjhatjconsolejprofile等等。

而定位问题的步骤无外乎几步:

  1. ps -ef | grep java 获取java进程pid。

  2. top pid 查看指定进程CPU消耗等情况。

  3. top -Hp pid 或者 ps -mp pid -o THREAD,tid,time 查看该进程所有线程的运行情况,找到占用 CPU 过高的线程 pid。

  4. printf "%x\n" pid 打印出 pid 的 16 进制值(jstack 命令结果中的线程 ID 为 nid,且用 16 进制表示)。

  5. jstack -l pid | grep nid 命令查看线程快照,根据上一步得到的 16 进制值找到具体的线程,就能知道这个进程在执行什么代码了。

上面几步是常用定位问题的步骤,有的公司(比如我们公司)自己写了监控脚本,在出现问题的时候,会自动dump线程堆栈、内存使用情况、cpu负载情况、垃圾回收情况等。下面就以我遇到的一个线上问题举例讲解:

线上问题排查相关日志

上面的截图就是当时出问题时脚本自动输出的日志,其中30669_*是以当时的线程ID为前缀,下面就针对各个日志(从下到上)内容展开学习。

loadavg.log

首先看一下loadavg.log的内容,如下图:
loadavg.log

loadavg是系统平均负载,即在特定时间间隔内运行队列中的平均进程数。

前三个是1、5、15分钟内的平均进程数。
第四个的分子是正在运行的进程数,分母是进程总数。
最后一个是最近运行的进程ID号。

一般来说每个CPU的当前活动进程数不大于3那么系统的性能就是良好的。如果每个CPU的任务数大于5,那么就表明机器的性能有严重问题。

以上图为例,假设系统有8个CPU,则每个CPU在1分钟内的进程数为:1.16/8=0.145
如果我们想查看系统平均负载,可通过如下命令:

  1. cat /proc/loadavg
  2. uptime
  3. tload

top.log

下面看下30669_top.log30669_top10_thread.log的内容,如下图:
top日志内容

30669_top.log资源占用最高的进程情况。
30669_top10_thread.log是资源占用前10的进程情况。

内容解读

1
2
3
4
5
6
7
8
9
top - 15:48:34 up 60 days, 18:06,  1 user,  load average: 1.45, 0.47, 0.20
Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombie
%Cpu(s): 96.7 us, 0.0 sy, 0.0 ni, 3.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 4046212 total, 127012 free, 1575164 used, 2344036 buff/cache
KiB Swap: 4194300 total, 4171260 free, 23040 used. 1984224 avail Mem

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
30669 www 20 0 3769288 1.4g 14732 S 193.3 37.0 9:55.30 java
180.0 146.7 200.0
  1. 第一行top是系统运行时间和平均负载,同uptime命令的执行结果

    • 15:48:34 👉 当前时间

    • up 60 days, 18:06 👉 系统运行时间

    • 1 user 👉 当前登录用户数

    • load average: 1.45, 0.47, 0.20 👉 系统负载,三个数值分别为 1分钟、5分钟、15分钟前到现在的平均值。

  2. 第二行Tasks是任务信息

    • 1 total 👉 进程总数

    • 0 running 👉 正在运行的进程数

    • 1 sleeping 👉 睡眠的进程数

    • 0 stopped 👉 停止的进程数

    • 0 zombie 👉 僵尸进程数

  3. 第三行%Cpu(s)是CPU信息

    • 96.7 us 👉 用户空间占用CPU百分比

    • 0.0 sy 👉 内核空间占用CPU百分比

    • 0.0 ni 👉 用户进程空间内改变过优先级的进程占用CPU百分比

    • 3.3 id 👉 空闲CPU百分比

    • 0.0 wa 👉 等待输入输出的CPU时间百分比

    • 0.0 hi 👉 硬件CPU中断占用百分比

    • 0.0 si 👉 软中断占用百分比

    • 0.0 st 👉 虚拟机(虚拟化技术)占用百分比

  4. 第四行KiB Mem是物理内存信息

    • 4046212 total 👉 物理内存总量

    • 127012 free 👉 空闲物理内存总量

    • 1575164 used 👉 已使用物理内存总量

    • 2344036 buff/cache 👉 用户内核缓存的内存总量

  5. 第五行KiB Swap是交换区内存信息

    • 4194300 total 👉 交换区总量

    • 4171260 free 👉 空闲交换区总量

    • 23040 used 👉 已使用交换区总量

    • 1984224 avail Mem 👉 缓冲的交换区总量,内存中的内容被换出到交换区,而后又被换入到内存,但使用过的交换区尚未被覆盖,该数值即为这些内容已存在于内存中的交换区的大小,相应的内存再次被换出时可不必再对交换区写入。

  6. 第六行是空行

  7. 第七行以后的内容是各进程(任务)的状态信息

    • PID 👉 进程ID,进程的唯一标识符

    • USER 👉 进程所有者的实际用户名

    • PR 👉 进程的调度优先级。这个字段的一些值是rt,意味着进程在实时运行中。

    • NI 👉 进程的nice值(优先级)。越小的值意味着越高的优先级。负值表示高优先级,正值表示低优先级。

    • VIRT 👉 进程使用的虚拟内存。进程使用的虚拟内存总量,单位kbVIRT = SWAP + RES

    • RES 👉 驻留内存大小。驻留内存是任务使用的非交换物理内存大小。进程使用的、未被换出的物理内存大小,单位kbRES = CODE + DATA

    • SHR 👉 SHR 是进程使用的共享内存大小,单位kb

    • S 👉 是进程的状态,有以下几个值:

      • D 👉 不可中断的睡眠态。
      • R 👉 运行态
      • S 👉 睡眠态
      • T 👉 被跟踪或已停止
      • Z 👉 僵尸态
    • %CPU 👉 自从上一次更新时到现在任务所使用的CPU时间百分比。

    • %MEM 👉 进程使用的可用物理内存百分比。

    • TIME+ 👉 任务启动后到现在所使用的全部CPU时间,精确到百分之一秒。

    • COMMAND 👉 运行进程所使用的命令。进程名称(命令名/命令行)

    • 其他非重要列

      • PPID 👉 父进程ID
      • RUSER 👉 真实用户名
      • UID 👉 进程所有者的用户ID
      • GROUP 👉 进程所有者的组名
      • TTY 👉 启动进程的终端名。不是从终端启动的进程则显示为?
      • P 👉 最后使用的CPU,仅在多CPU环境下有意义
      • TIME 👉 进程使用的CPU时间总计,单位秒
      • SWAP 👉 进程使用的虚拟内存中,被换出的大小,单位kb
      • CODE 👉 可执行代码占用的物理内存大小,单位kb
      • DATA 👉 可执行代码以外的部分(数据段+栈)占用的物理内存大小,单位kb
      • nFLT 👉 页面错误次数
      • nDRT 👉 最后一次写入到现在,被修改过的页面数
      • WCHAN 👉 若该进程在睡眠,则显示睡眠中的系统函数名
      • Flags 👉 任务标志

top学习

top命令是用来监控Linux系统状况,比如cpu内存的使用。

语法

1
top [-] [d] [p] [q] [c] [C] [S] [s]  [n]

参数解析

  • d 👉 指定每两次屏幕信息刷新之间的时间间隔。当然用户可以使用s交互命令来改变。
  • p 👉 通过指定监控进程ID来仅仅监控某个进程的状态。
  • q 👉 该选项将使top没有任何延迟的进行刷新。如果调用程序有超级用户权限,那么top将以尽可能高的优先级运行。
  • S 👉 指定累计模式。
  • s 👉 使top命令在安全模式中运行。这将去除交互命令所带来的潜在危险。
  • i 👉 使top不显示任何闲置或者僵死进程。
  • c 👉 显示整个命令行而不只是显示命令名。

常用交互命令

  • Ctrl+L 👉 擦除并且重写屏幕。
  • h或者? 👉 显示帮助画面,给出一些简短的命令总结说明。
  • k 👉 终止一个进程。系统将提示用户输入需要终止的进程PID,以及需要发送给该进程什么样的信号。一般的终止进程可以使用15信号;如果不能正常结束那就使用信号9强制结束该进程。默认值是信号15。在安全模式中此命令被屏蔽。
  • i 👉 忽略闲置和僵死进程。这是一个开关式命令。
  • q 👉 退出程序。
  • r 👉 重新安排一个进程的优先级别。系统提示用户输入需要改变的进程PID以及需要设置的进程优先级值。输入一个正值将使优先级降低,反之则可以使该进程拥有更高的优先权。默认值是10。
  • s 👉 改变两次刷新之间的延迟时间。系统将提示用户输入新的时间,单位为s。如果有小数,就换算成m s。输入0值则系统将不断刷新,默认值是5 s。需要注意的是如果设置太小的时间,很可能会引起不断刷新,从而根本来不及看清显示的情况,而且系统负载也会大大增加。
  • f或者F 👉 从当前显示中添加或者删除项目。
  • o或者O 👉 改变显示项目的顺序。
  • l 👉 切换显示平均负载和启动时间信息。
  • m 👉 切换显示内存信息。
  • t 👉 切换显示进程和CPU状态信息。
  • c 👉 切换显示命令名称和完整命令行。
  • M 👉 根据驻留内存大小进行排序。
  • P 👉 根据CPU使用百分比大小进行排序。
  • T 👉 根据时间/累计时间进行排序。
  • W 👉 将当前设置写入~/.toprc文件中。这是写top配置文件的推荐方法。
  • Shift+M 👉 可按内存占用情况进行排序。
  • Enter/space 👉 刷新视图
  • A 👉 在全屏模式和多窗口选择模式之间切换
  • d 👉 设置刷新的时间间隔
  • E 👉 切换内存和交换区单位
  • H 👉 开启/关闭线程模式,以线程的方式展示
  • Z 👉 改变颜色配置

使用示例

1
2
3
4
5
6
7
top     //每隔5秒显式所有进程的资源占用情况
top -d 2 //每隔2秒显式所有进程的资源占用情况
top -c //每隔5秒显式进程的资源占用情况,并显示进程的命令行参数(默认只有进程名)
top -p 12345 -p 6789 //每隔5秒显示pid是12345和pid是6789的两个进程的资源占用情况
top -d 2 -c -p 12345 //每隔2秒显示pid是12345的进程的资源使用情况,并显式该进程启动的命令行参数
ps -eLf | grep java | wc -l //监控java线程数
netstat -n | grep tcp | grep 侦听端口 | wc -l //监控网络客户连接数

top -c

top -bn1 -H -p <pid>

ps -mp <pid> -o THREAD,tid,time | sort -k2r

threadcount.log

接着看下30669_threadcount.log的内容,如下图:
threadcount.log

该日志的内容是30669进程下的线程数量。

统计一个进程中的线程数

下面学习下如何统计一个进程中的线程数。

proc 伪文件系统,它驻留在 /proc 目录,这是最简单的方法来查看任何活动进程的线程数。 /proc 目录以可读文本文件形式输出,提供现有进程和系统硬件相关的信息如 CPU、中断、内存、磁盘等等。

1
2
3
4
5
cat/proc/<pid>/status

或者

ls /proc/<pid>/task|wc

上面的命令将显示进程 <pid> 的详细信息,包括过程状态(例如, sleeping, running),父进程 PIDUIDGID,使用的文件描述符的数量,以及上下文切换的数量。输出也包括进程创建的总线程数。

示例如下;

首先使用top命令查一下当前占用资源最多的进程,如下图:
top获取当前占用资源最多的进程

从图中可以看出,当前13985是占用资源最多,接下来就看一下13985进程下的线程数,如下图:
proc获取线程数

tcp.log

接着再看下30669_tcp.log的内容,如下图:
tcp.log

该日志内容是统计案发时TCP的连接数,下面学习下如何获取TCP连接数。

方法一

1
ss -ant | awk 'NR>1 {a[$1]++} END {for (b in a) print b,a[b]}'

获取TCP连接数方法一

方法二

1
netstat -an | awk '/^tcp/ {a[$NF]++} END {for (b in a) print b,a[b]}'

获取TCP连接数方法二

方法三

1
netstat -nat|awk  '{print $6}'|sort|uniq -c|sort -rn

获取TCP连接数方法三

方法四

1
cat /proc/net/snmp

获取TCP连接数方法四

输出内容中的各项参数的意义,请参考 http://perthcharles.github.io/2015/11/10/wiki-netstat-proc/

lsof.log

接着再看下30669_lsof.log的内容,如下图:
lsof.log

这个文件的内容究竟是什么含义,其实我也不知道😂,推测可能是统计的打开的文件数或者打开的文件大小。

lsof 命令详解

简介

lsof(list open files)是一个列出当前系统打开文件的工具。

linux环境下,任何事物都以文件的形式存在,通过文件不仅仅可以访问常规数据,还可以访问网络连接和硬件。所以如传输控制协议 (TCP) 和用户数据报协议 (UDP) 套接字等,系统在后台都为该应用程序分配了一个文件描述符,无论这个文件的本质如何,该文件描述符为应用程序与基础操作系统之间的交互提供了通用接口。因为应用程序打开文件的描述符列表提供了大量关于这个应用程序本身的信息,因此通过lsof工具能够查看这个列表对系统监测以及排错将是很有帮助的。

输出信息解析

在终端下输入lsof即可显示系统打开的文件,因为 lsof 需要访问核心内存和各种文件,所以必须以 root 用户的身份运行它才能够充分地发挥其功能。

lsof命令输出

每行显示一个打开的文件,若不指定条件默认将显示所有进程打开的所有文件。lsof输出各列信息的意义如下:

  • COMMAND:进程的名称

  • PID:进程标识符

  • USER:进程所有者

  • FD:文件描述符,应用程序通过文件描述符识别该文件。如cwd、txt等 TYPE:文件类型,如DIR、REG等

  • DEVICE:指定磁盘的名称

  • SIZE:文件的大小

  • NODE:索引节点(文件在磁盘上的标识)

  • NAME:打开文件的确切名称


FD 列中的文件描述符cwd 值表示应用程序的当前工作目录,这是该应用程序启动的目录,除非它本身对这个目录进行更改,txt 类型的文件是程序代码,如应用程序二进制文件本身或共享库,如上列表中显示的 /sbin/init 程序。

其次数值表示应用程序的文件描述符,这是打开该文件时返回的一个整数。如上的最后一行文件/dev/initctl,其文件描述符为 10。u 表示该文件被打开并处于读取/写入模式,而不是只读 ® 或只写 (w) 模式。同时还有大写 的W 表示该应用程序具有对整个文件的写锁。该文件描述符用于确保每次只能打开一个应用程序实例。初始打开每个应用程序时,都具有三个文件描述符,从 0 到 2,分别表示标准输入、输出和错误流。所以大多数应用程序所打开的文件的 FD 都是从 3 开始。

与 FD 列相比,Type 列则比较直观。文件和目录分别称为 REG 和 DIR。而CHR 和 BLK,分别表示字符和块设备;或者 UNIX、FIFO 和 IPv4,分别表示 UNIX 域套接字、先进先出 (FIFO) 队列和网际协议 (IP) 套接字。

语法格式

1
lsof [options] filename

histolive.log

接着再来看30669_histolive.log的内容,如下图:
histolive.log

该日志记录了案发时heap中的所有对象情况,包括对象的数量、所占空间大小、类名。

我们也可以通过如下命令查看:

1
jmap -histo[:live] pid

输出说明:

  • instances列:表示当前类有多少个实例。

  • bytes列:说明当前类的实例总共占用了多少个字节

  • class name列:表示的就是当前类的名称,class name 解读:

    • B代表byte

    • C代表char

    • D代表double

    • F代表float

    • I代表int

    • J代表long

    • Z代表boolean

    • 前边有[代表数组,[I 就相当于int[]

    • 对象用[L+类名表示

heap.log

接着再来看30669_heap.log的内容,因内容过长,截取主要内容,如下图:

heap.log

上面的内容也可以直接使用命令jmap -heap pid 打印jvm内存整体使用情况,可以观察到New GenerationEden SpaceFrom SpaceTo Space),tenured generation,Perm Generation的内存使用情况。

从图中内容可以看出新生区和老年区的内存使用率几乎达到了100%,由此可以推断造成这次事故的原因是创建的对象过多,再结合上面了解过的30669_histolive.log,就能找到是哪些对象创建过多。再结合后面要讲的线程堆栈信息定位到具体调用的代码段。

gc.log、gccapacity.log

接着再来看30669_gc.log的内容,如下图:

gc.log

上图内容是显示堆内存的各个占比,可通过如下命令查看:

1
jstat -gcutil <pid>

现在解释下输出内容每个项的含义:

  • S0 👉 幸存1区当前使用比例
  • S1 👉 幸存2区当前使用比例
  • E 👉 伊甸园区使用比例
  • O 👉 老年代使用比例
  • M 👉 元数据区使用比例
  • CCS 👉 压缩使用比例
  • YGC 👉 年轻代垃圾回收次数
  • YGCT 👉 年轻代垃圾回收消耗时间
  • FGC 👉 老年代垃圾回收次数
  • FGCT 👉 老年代垃圾回收消耗时间
  • GCT 👉 垃圾回收消耗总时间

30669_gccapacity.log的内容如下图:

gccapacity.log

输出各项含义如下:

  • NGCMN 👉 新生代最小容量
  • NGCMX 👉 新生代最大容量
  • NGC 👉 当前新生代容量
  • S0C 👉 第一个幸存区大小
  • S1C 👉 第二个幸存区的大小
  • EC 👉 伊甸园区的大小
  • OGCMN 👉 老年代最小容量
  • OGCMX 👉 老年代最大容量
  • OGC 👉 当前老年代大小
  • OC 👉 当前老年代大小
  • MCMN 👉 最小元数据容量
  • MCMX 👉 最大元数据容量
  • MC 👉 当前元数据空间大小
  • CCSMN 👉 最小压缩类空间大小
  • CCSMX 👉 最大压缩类空间大小
  • CCSC 👉 当前压缩类空间大小
  • YGC 👉 年轻代gc次数
  • FGC 👉 老年代GC次数

jstat

jstatJDK自带的一个轻量级小工具。全称 Java Virtual Machine statistics monitoring tool,它位于javabin目录下,主要利用JVM内建的指令对Java应用程序的资源和性能进行实时的命令行的监控,包括了对Heap size和垃圾回收状况的监控。

语法格式

1
jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]

语法格式中的option是「命令选项」,interval是「间隔时间/毫秒」,count 是「查询次数」。

jstat支持的option通过jstat -option进行查看,如下图:

jstat支持的option

下面以jdk1.8为例了解下jstat命令查看jvm的GC情况

类加载统计

jstat-类加载统计

  • Loaded 👉 加载class的数量
  • Bytes 👉 所占用空间大小
  • Unloaded 👉 未加载数量
  • Bytes 👉 未加载占用空间
  • Time 👉 时间

编译统计

jstat-编译统计

  • Compiled 👉 编译数量。
  • Failed 👉 失败数量
  • Invalid 👉 不可用数量
  • Time 👉 时间
  • FailedType 👉 失败类型
  • FailedMethod 👉 失败的方法

垃圾回收统计

jstat-垃圾回收统计

  • S0C 👉 第一个幸存区的大小
  • S1C 👉 第二个幸存区的大小
  • S0U 👉 第一个幸存区的使用大小
  • S1U 👉 第二个幸存区的使用大小
  • EC 👉 伊甸园区的大小
  • EU 👉 伊甸园区的使用大小
  • OC 👉 老年代大小
  • OU 👉 老年代使用大小
  • MC 👉 方法区大小
  • MU 👉 方法区使用大小
  • CCSC 👉 压缩类空间大小
  • CCSU 👉 压缩类空间使用大小
  • YGC 👉 年轻代垃圾回收次数
  • YGCT 👉 年轻代垃圾回收消耗时间
  • FGC 👉 老年代垃圾回收次数
  • FGCT 👉 老年代垃圾回收消耗时间
  • GCT 👉 垃圾回收消耗总时间

堆内存统计

jstat-堆内存统计

输出各项意义参考30669_gccapacity.log

新生代垃圾回收统计

jstat-新生代垃圾回收统计

  • S0C 👉 第一个幸存区大小
  • S1C 👉 第二个幸存区的大小
  • S0U 👉 第一个幸存区的使用大小
  • S1U 👉 第二个幸存区的使用大小
  • TT 👉 对象在新生代存活的次数
  • MTT 👉 对象在新生代存活的最大次数
  • DSS 👉 期望的幸存区大小
  • EC 👉 伊甸园区的大小
  • EU 👉 伊甸园区的使用大小
  • YGC 👉 年轻代垃圾回收次数
  • YGCT 👉 年轻代垃圾回收消耗时间

新生代内存统计

jstat-新生代内存统计

  • NGCMN 👉 新生代最小容量
  • NGCMX 👉 新生代最大容量
  • NGC 👉 当前新生代容量
  • S0CMX 👉 最大幸存1区大小
  • S0C 👉 当前幸存1区大小
  • S1CMX 👉 最大幸存2区大小
  • S1C 👉 当前幸存2区大小
  • ECMX 👉 最大伊甸园区大小
  • EC 👉 当前伊甸园区大小
  • YGC 👉 年轻代垃圾回收次数
  • FGC 👉 老年代回收次数

老年代垃圾回收统计

jstat-老年代垃圾回收统计

  • MC 👉 方法区大小
  • MU 👉 方法区使用大小
  • CCSC 👉 压缩类空间大小
  • CCSU 👉 压缩类空间使用大小
  • OC 👉 老年代大小
  • OU 👉 老年代使用大小
  • YGC 👉 年轻代垃圾回收次数
  • FGC 👉 老年代垃圾回收次数
  • FGCT 👉 老年代垃圾回收消耗时间
  • GCT 👉 垃圾回收消耗总时间

老年代内存统计

jstat-老年代内存统计

  • OGCMN 👉 老年代最小容量
  • OGCMX 👉 老年代最大容量
  • OGC 👉 当前老年代大小
  • OC 👉 老年代大小
  • YGC 👉 年轻代垃圾回收次数
  • FGC 👉 老年代垃圾回收次数
  • FGCT 👉 老年代垃圾回收消耗时间
  • GCT 👉 垃圾回收消耗总时间

堆内存占比

参考30669_gc.log内容及解析。

jvm编译方法统计

jstat-jvm编译方法统计

  • Compiled 👉 最近编译方法的数量
  • Size 👉 最近编译方法的字节码数量
  • Type 👉 最近编译方法的编译类型。
  • Method 👉 方法名标识。

stack.log

最后来看下30669_1_stack.log30669_2_stack.log30669_3_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都指向同一个问题,我们才确定问题的典型性。也就是多进行几次线程快照,观察变化,查看问题所在。

特点

  1. 能在各种操作系统下使用

  2. 能在各种Java应用服务器下使用

  3. 可以在生产环境下使用而不影响系统的性能

  4. 可以将问题直接定位到应用程序的代码行上

能诊断的问题

  1. 查找内存泄露,常见的是程序里load大量的数据到缓存;

  2. 发现死锁线程;

如何抓取Thread Dump

JDK自带命令行工具获取PID,再获取ThreadDump:

  1. jpsps –ef|grepjava (获取PID)

  2. jstack [-l ]<pid> | tee -a jstack.log (获取ThreadDump)

Thread Dump结构

一个典型的thread dump文件主要由一下几个部分组成:

Thread Dump结构

上图将JVM上的线程堆栈信息和线程信息做了详细的拆解。

1
printf "%x\n" 20696

第一部分:Full thread dump identifier

这一部分是内容最开始的部分,展示了快照文件的生成时间和JVM的版本信息。

1
2
2019-09-28 15:48:28
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.131-b11 mixed mode):

第二部分:Java EE middleware, third party & custom application Threads

这是整个文件的核心部分,里面展示了JavaEE容器(如tomcat、resin等)、自己的程序中所使用的线程信息。这一部分详细的含义后面再介绍。

1
2
3
4
5
6
7
8
"Thread-3" #26 daemon prio=9 os_prio=0 tid=0x00007f1ff40ae000 nid=0x77f5 waiting on condition [0x00007f1ff1bfa000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000c14fed38> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at org.LatencyUtils.PauseDetector$PauseDetectorThread.run(PauseDetector.java:85)
  • Thread-3 线程名称,当使用java.lang.Thread类生成一个线程时,将被命名为Thre-(Number),若java.util.concurrent.ThreadFactory类,将会被命名为pool-(Number)-thread-(Number)

  • daemon 线程类型,线程分为守护线程 (daemon) 和非守护线程 (non-daemon) 两种,通常都是守护线程;

  • prio=9 线程优先级,默认为5,数字越大优先级越高;

  • os_prio=0 操作系统线程优先级

  • tid=0x00007f1ff40ae000 JVM线程的id,JVM内部线程的唯一标识,通过 java.lang.Thread.getId()获取,通常用自增的方式实现;

  • nid=0x77f5 系统线程id,对应的系统线程id(Native Thread ID),可以通过 top 命令进行查看,是十六进制的形式;

  • waiting on condition 系统线程状态,这里是系统的线程状态,具体的含义见下面 系统线程状态 部分;

  • 0x00007f1ff1bfa000 起始栈地址,线程堆栈调用的其实内存地址;

  • java.lang.Thread.State: WAITING (parking) JVM线程状态,这里标明了线程在代码级别的状态,详细的内容见下面的 JVM线程运行状态 部分。

第三部分:HotSpot VM Thread

这一部分展示了JVM内部线程的信息,用于执行内部的原生操作。下面常见的几种内置线程:

Attach Listener

该线程负责接收外部命令,执行该命令并把结果返回给调用者,此种类型的线程通常在桌面程序中出现。

1
2
"Attach Listener" #62 daemon prio=9 os_prio=0 tid=0x00007f2014008800 nid=0x7868 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
DestroyJavaVM

执行main()的线程在执行完之后调用JNI中的 jni_DestroyJavaVM() 方法会唤起DestroyJavaVM 线程。在JBoss启动之后,也会唤起DestroyJavaVM线程,处于等待状态,等待其它线程(java线程和native线程)退出时通知它卸载JVM。

1
2
"DestroyJavaVM" #83 prio=5 os_prio=0 tid=0x00007f203c009000 nid=0x77cf waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Service Thread

用于启动服务的线程。

1
2
3
4
5
6
7
8
9
10
11
12
"Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007f203c152800 nid=0x77d9 runnable [0x00007f2025ffd000]
java.lang.Thread.State: RUNNABLE
at java.lang.Class.getDeclaredFields0(Native Method)
at java.lang.Class.privateGetDeclaredFields(Class.java:2583)
at java.lang.Class.getDeclaredField(Class.java:2068)
at sun.management.GarbageCollectionNotifInfoCompositeData$1.run(GarbageCollectionNotifInfoCompositeData.java:69)
at sun.management.GarbageCollectionNotifInfoCompositeData$1.run(GarbageCollectionNotifInfoCompositeData.java:65)
at java.security.AccessController.doPrivileged(Native Method)
at sun.management.GarbageCollectionNotifInfoCompositeData.getCompositeTypeByBuilder(GarbageCollectionNotifInfoCompositeData.java:65)
at sun.management.GarbageCollectionNotifInfoCompositeData.getCompositeData(GarbageCollectionNotifInfoCompositeData.java:116)
at sun.management.GarbageCollectionNotifInfoCompositeData.toCompositeData(GarbageCollectionNotifInfoCompositeData.java:61)
at sun.management.GarbageCollectorImpl.createGCNotification(GarbageCollectorImpl.java:141)
CompilerThread

用来调用JITing,实时编译装卸CLASS。通常JVM会启动多个线程来处理这部分工作,线程名称后面的数字也会累加,比如CompilerThread1

1
2
3
4
5
"C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f203c13d800 nid=0x77d8 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f203c13a800 nid=0x77d7 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Signal Dispatcher

Attach Listener线程的职责是接收外部jvm命令,当命令接收成功后,会交给signal dispather 线程去进行分发到各个不同的模块处理命令,并且返回处理结果。
signal dispather线程也是在第一次接收外部jvm命令时,进行初始化工作。

1
2
"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f203c139000 nid=0x77d6 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
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
2
3
4
5
6
7
"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f203c106000 nid=0x77d5 in Object.wait() [0x00007f202c41b000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
- locked <0x00000000c022a288> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)
Reference Handler

JVM在创建main线程后就创建Reference Handler线程,其优先级最高,为10,它主要用于处理引用对象本身(软引用、弱引用、虚引用)的垃圾回收问题 。

1
2
3
4
5
6
7
"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f203c101800 nid=0x77d4 in Object.wait() [0x00007f202c51c000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x00000000c00e5800> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
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文件内,列举几个:ThreadStopThreadDumpPrintThreadsGenCollectFullGenCollectFullConcurrentCMS_Initial_MarkCMS_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,后面的2507表示每250毫秒打印一次,总共打印7次。
这对于防止因为应用代码中直接使用native库或者第三方的一些监控工具的内存泄漏有非常大的帮助。

GC task thread#0 (ParallelGC)

垃圾回收线程,该线程会负责进行垃圾回收。通常JVM会启动多个线程来处理这个工作,线程名称中#后面的数字也会累加。

1
2
3
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f203c01e000 nid=0x77d1 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f203c020000 nid=0x77d2 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 workerJVM用于年轻代垃圾回收(minor gc)的线程。

1
2
3
"Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x00007fbea801b800 nid=0x5e4 runnable 

"Gang worker#1 (Parallel GC Threads)" prio=10 tid=0x00007fbea801d800 nid=0x5e7 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
2
"Surrogate Locker Thread (Concurrent GC)" daemon prio=10 tid=0x00007fbea8158800 nid=0x5ee waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

这里以 WeakHashMap 为例进行说明,首先是一个关键点:

  • WeakHashMapHashMap一样,内部有一个Entry[]数组;
  • WeakHashMapEntry比较特殊,它的继承体系结构为Entry->WeakReference->Reference;
  • Reference 里面有一个全局锁对象:Lock,它也被称为pending_lock,注意:它是静态对象;
  • Reference 里面有一个静态变量:pending
  • Reference 里面有一个静态内部类:ReferenceHandler的线程,它在static块里面被初始化并且启动,启动完成后处于wait状态,它在一个Lock同步锁模块中等待;
  • WeakHashMap里面还实例化了一个ReferenceQueue队列;

假设,WeakHashMap对象里面已经保存了很多对象的引用,JVM 在进行CMS GC的时候会创建一个ConcurrentMarkSweepThread(简称CMST)线程去进行GCConcurrentMarkSweepThread线程被创建的同时会创建一个SurrogateLockerThread(简称SLT)线程并且启动它,SLT启动之后,处于等待阶段。
CMST开始GC时,会发一个消息给SLT让它去获取Java层Reference对象的全局锁:Lock。直到CMS GC完毕之后,JVM 会将WeakHashMap中所有被回收的对象所属的WeakReference容器对象放入到Referencepending属性当中(每次GC完毕之后,pending属性基本上都不会为null了),然后通知SLT释放并且notify全局锁:Lock。此时激活了ReferenceHandler线程的run方法,使其脱离wait状态,开始工作了。
ReferenceHandler这个线程会将pending中的所有WeakReference对象都移动到它们各自的列队当中,比如当前这个WeakReference属于某个WeakHashMap对象,那么它就会被放入相应的ReferenceQueue列队里面(该列队是链表结构)。 当我们下次从WeakHashMap对象里面getput数据或者调用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(重点关注)

线程正处于等待资源或等待某个条件的发生,具体的原因需要结合堆栈信息进行分析。

  1. 如果堆栈信息明确是应用代码,则证明该线程正在等待资源,一般是大量读取某种资源且该资源采用了资源锁的情况下,线程进入等待状态,等待资源的读取,或者正在等待其他线程的执行等。

  2. 如果发现有大量的线程都正处于这种状态,并且堆栈信息中得知正等待网络读写,这是因为网络阻塞导致线程无法执行,很有可能是一个网络瓶颈的征兆:

    • 网络非常繁忙,几乎消耗了所有的带宽,仍然有大量数据等待网络读写;
    • 网络可能是空闲的,但由于路由或防火墙等原因,导致包无法正常到达;

所以一定要结合系统的一些性能观察工具进行综合分析,比如netstat统计单位时间的发送包的数量,看是否很明显超过了所在网络带宽的限制;观察CPU的利用率,看系统态的CPU时间是否明显大于用户态的CPU时间。这些都指向由于网络带宽所限导致的网络瓶颈。

  1. 还有一种常见的情况是该线程在 sleep,等待 sleep 的时间到了,将被唤醒。

waiting for monitor entry 或 in Object.wait()

Monitor 是Java中用以实现线程之间的互斥与协作的主要手段,它可以看成是对象或者class的锁,每个对象都有,也仅有一个 Monitor

monitor

调用修饰:

  • locked <地址> 目标:注意临界区对象锁可重入,线程状态为RUNNABLE;
  • waitting to lock <地址> 目标:还没有获得锁,进入等待区,线程状态为BLOCKED;
  • waitting on <地址> 目标:获得锁了,等待区等待,线程状态为WAITTING,TIMED_WAITTING;
  • parking to wait for <地址> 目标:线程原语,随current包出现,与synchronized体系不同;

从上图可以看出,每个Monitor在某个时刻只能被一个线程拥有,该线程就是 Active Thread,而其他线程都是 Waiting Thread,分别在两个队列 Entry SetWait Set里面等待。

其中在 Entry Set 中等待的线程状态是 waiting for monitor entry,在 Wait Set 中等待的线程状态是 in Object.wait()

Entry Set里面的线程。

把被 synchronized 保护起来的代码段为临界区,代码如下:

1
2
3
synchronized(obj) {

}

当一个线程申请进入临界区时,它就进入了 Entry Set 队列中,这时候有两种可能性:

  • Monitor不被其他线程拥有,Entry Set里面也没有其他等待的线程。本线程即成为相应类或者对象的MonitorOwner,执行临界区里面的代码;此时在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线程运行状态

线程在一定条件下,状态会发生变化。线程一共有以下几种状态:

  1. 新建状态(New):线程刚刚被创建,但是还没有调用start()方法,jstack命令不会列出处于此状态的线程信息。

  2. 就绪状态(Runnable):线程对象创建后,其他线程调用了该对象的start()方法。该状态的线程位于“可运行线程池”中,变得可运行,只等待获取CPU的使用权。即在就绪状态的进程除CPU之外,其它的运行所需资源都已全部获得。

  3. 运行状态(Running):就绪状态的线程获取了CPU,执行程序代码。

  4. 阻塞状态(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处理完毕时,线程重新转入就绪状态。

  5. 死亡状态(Dead):线程执行完了或者因异常退出了run()方法,该线程结束生命周期。

JVM线程状态

实际上jvm线程栈中,几乎是不会出现NEW,RUNNING,DEAD 这些状态,其中Runnable就算是正在运行了。

处于WAITING, BLOCKED, TIMED_WAITING的是不消耗CPU的。
处于Runnable状态的线程,是否消耗cpu要看具体的上下文情况:

  • 如果是纯Java运算代码, 则消耗CPU;
  • 如果是网络IO,很少消耗CPU,这点在分布式程序中经常碰到 ;
  • 如果是本地代码,结合本地代码的性质判断(可以通过pstack/gstack获取本地线程堆栈)
    • 如果是纯运算代码,则消耗CPU;
    • 如果被挂起,则不消耗CPU;
    • 如果是IO,则不怎么消耗CPU;

本文标题:线上问题排查总结(持续更新)

文章作者:王洪博

发布时间:2019年09月29日 - 14:09

最后更新:2020年02月26日 - 03:02

原始链接:http://whb1990.github.io/posts/4a0297a6.html

▄︻┻═┳一如果你喜欢这篇文章,请点击下方"打赏"按钮请我喝杯 ☕
0%