快捷搜索:  汽车  科技

平台出现问题怎么解决(线上问题排查)

平台出现问题怎么解决(线上问题排查)首先看一下 loadavg.log 的内容,如下图:二、 loadavg.log而定位问题的步骤无外乎几步:上面几步是常用定位问题的步骤,有的公司(比如我们公司)自己写了监控脚本,在出现问题的时候,会自动dump线程堆栈、内存使用情况、cpu负载情况、垃圾回收情况等。下面就以我遇到的一个线上问题举例讲解:上面的截图就是当时出问题时脚本自动输出的日志,其中 30669_* 是以当时的线程ID为前缀,下面就针对各个日志(从下到上)内容展开学习。

一、前言

这篇文章是19年在上家公司解决线上问题后做的一个总结性的文章,当时发表在了自己搭建的通过github托管的个人网站上,现把当时的总结再在头条上分享给大家。另外吐槽一句,因为之前在个人网站上发表文章都是用的markdown语法,而头条不支持markdown语法还真难受。。。。最后会附上原文的截图,看起来效果会好一点。

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

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

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

  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负载情况、垃圾回收情况等。下面就以我遇到的一个线上问题举例讲解:

平台出现问题怎么解决(线上问题排查)(1)

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

二、 loadavg.log

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

平台出现问题怎么解决(线上问题排查)(2)

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

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

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

以上图为例,假设系统有8个CPU,则每个CPU在1分钟内的进程数为:1.16/8=0.145

如果我们想查看系统平均负载,可通过如下命令:

cat /proc/loadavg uptime tload

三、top.log

下面看下 30669_top.log 和 30669_top10_thread.log 的内容,如下图:

平台出现问题怎么解决(线上问题排查)(3)

30669_top.log 的内容是资源占用最高的进程情况。

30669_top10_thread.log 的内容是资源占用前10的进程情况。

3.1、内容解读

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 进程使用的虚拟内存。进程使用的虚拟内存总量,单位 kb 。 VIRT = SWAP RES

RES 驻留内存大小。驻留内存是任务使用的非交换物理内存大小。进程使用的、未被换出的物理内存大小,单位 kb 。 RES = 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 任务标志

3.2、top学习

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

3.2.1、语法

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

3.2.2、参数解析

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

3.2.3、常用交互命令

  • 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 改变颜色配置

3.2.4、使用示例

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 //监控网络客户连接数

平台出现问题怎么解决(线上问题排查)(4)

平台出现问题怎么解决(线上问题排查)(5)

平台出现问题怎么解决(线上问题排查)(6)

四、threadcount.log

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

平台出现问题怎么解决(线上问题排查)(7)

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

4.1、统计一个进程中的线程数

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

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

cat/proc/<pid>/status

或者

ls /proc/<pid>/task|wc

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

示例如下:

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

平台出现问题怎么解决(线上问题排查)(8)

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

平台出现问题怎么解决(线上问题排查)(9)

五、 tcp.log

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

平台出现问题怎么解决(线上问题排查)(10)

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

  • 方法一

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

平台出现问题怎么解决(线上问题排查)(11)

  • 方法二

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

平台出现问题怎么解决(线上问题排查)(12)

  • 方法三

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

平台出现问题怎么解决(线上问题排查)(13)

  • 方法四

cat /proc/net/snmp

平台出现问题怎么解决(线上问题排查)(14)

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

六、lsof.log

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

平台出现问题怎么解决(线上问题排查)(15)

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

6.1、lsof简介

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

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

6.2、输出信息解析

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

平台出现问题怎么解决(线上问题排查)(16)

每行显示一个打开的文件,若不指定条件默认将显示所有进程打开的所有文件。 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) 套接字。

6.3、语法格式

lsof [options] filename

七、histolive.log

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

平台出现问题怎么解决(线上问题排查)(17)

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

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

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 的内容,因内容过长,截取主要内容,如下图:

平台出现问题怎么解决(线上问题排查)(18)

上面的内容也可以直接使用命令 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 的内容,如下图:

平台出现问题怎么解决(线上问题排查)(19)

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

jstat -gcutil <pid>

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

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

30669_gccapacity.log 的内容如下图:

平台出现问题怎么解决(线上问题排查)(20)

输出各项含义如下:

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

---------------------------------------------------------------------------------------

9.1、jstat

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

9.1.1、语法格式

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

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

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

平台出现问题怎么解决(线上问题排查)(21)

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

9.1.2、类加载统计

平台出现问题怎么解决(线上问题排查)(22)

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

9.1.3、编译统计

平台出现问题怎么解决(线上问题排查)(23)

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

9.1.4、垃圾回收统计

平台出现问题怎么解决(线上问题排查)(24)

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

9.1.5、堆内存统计

平台出现问题怎么解决(线上问题排查)(25)

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

9.1.6、新生代垃圾回收统计

平台出现问题怎么解决(线上问题排查)(26)

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

9.1.7、新生代内存统计

平台出现问题怎么解决(线上问题排查)(27)

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

9.1.8、老年代垃圾回收统计

平台出现问题怎么解决(线上问题排查)(28)

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

9.1.9、老年代内存统计

平台出现问题怎么解决(线上问题排查)(29)

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

9.1.10、堆内存占比

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

9.1.11、jvm编译方法统计

平台出现问题怎么解决(线上问题排查)(30)

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

十、stack.log

最后来看下 30669_1_stack.log 、 30669_2_stack.log 和 30669_3_stack.log 的文件内容,因内容过长,暂先截取部分内容展示,如下图:

平台出现问题怎么解决(线上问题排查)(31)

平台出现问题怎么解决(线上问题排查)(32)

平台出现问题怎么解决(线上问题排查)(33)

10.1、Thread Dump

10.1.1、简介

Thread Dump 是非常有用的诊断Java应用问题的工具。每一个Java虚拟机都有及时生成所有线程在某一点状态的 thread-dump 的能力,虽然各个 Java虚拟机打印的 thread dump 略有不同,但是大多都提供了当前活动线程的快照,及JVM中所有Java线程的堆栈跟踪信息,堆栈信息一般包含完整的类名及所执行的方法,如果可能的话还有源代码的行数。

在实际运行中,往往一次 dump 的信息,还不足以确认问题。建议产生三次 dump 信息(所以就像这次的案例会dump三次stack 每次间隔3秒),如果每次 dump都指向同一个问题,我们才确定问题的典型性。也就是多进行几次线程快照,观察变化,查看问题所在。

10.1.2、特点

  • 能在各种操作系统下使用
  • 能在各种Java应用服务器下使用
  • 可以在生产环境下使用而不影响系统的性能
  • 可以将问题直接定位到应用程序的代码行上

10.1.3、能诊断的问题

  • 查找内存泄露,常见的是程序里load大量的数据到缓存;
  • 发现死锁线程;

10.1.4、如何抓取Thread Dump

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

jps 或 ps –ef|grepjava (获取PID)

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

10.1.5、Thread Dump结构

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

平台出现问题怎么解决(线上问题排查)(34)

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

10.1.5.1、第一部分:Full thread dump identifier

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

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

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

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

"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 系统线程状态,这里是系统的线程状态,具体的含义见下面 [系统线程状态](#jumpOne) 部分;
  • 0x00007f1ff1bfa000 起始栈地址,线程堆栈调用的其实内存地址;
  • java.lang.Thread.State: WAITING (parking) JVM线程状态,这里标明了线程在代码级别的状态,详细的内容见下面的 [JVM线程运行状态](#jumpTwo) 部分。

10.1.5.3、第三部分:HotSpot VM Thread

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

10.1.5.3.1、Attach Listener

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

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

10.1.5.3.2、DestroyJavaVM

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

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

10.1.5.3.3、Service Thread

用于启动服务的线程。

"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)

10.1.5.3.4、CompilerThread

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

"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

10.1.5.3.5、Signal Dispatcher

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

signal dispather 线程也是在第一次接收外部jvm命令时,进行初始化工作。

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f203c139000 nid=0x77d6 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE

10.1.5.3.6、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线程来说是一种灾难。

"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)

10.1.5.3.7、Reference Handler

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

"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)

10.1.5.3.8、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 ….. 有兴趣的同学,可以自己去查看源文件。

"VM Thread" os_prio=0 tid=0x00007f203c0fa000 nid=0x77d3 runnable

10.1.5.4、第四部分:HotSpot GC Thread

VM中用于进行资源回收的线程,包括以下几种类型的线程:

10.1.5.4.1、VM Periodic Task Thread

该线程是JVM周期性任务调度的线程,它由 WatcherThread 创建,是一个单例对象。该线程在JVM内使用得比较频繁,比如:定期的内存监控、JVM运行状况监控。

"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库或者第三方的一些监控工具的内存泄漏有非常大的帮助。

10.1.5.4.2、GC task thread#0 (ParallelGC)

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

"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

10.1.5.4.3、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 )的线程。

"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

10.1.5.4.4、Concurrent Mark-Sweep GC Thread

并发标记清除垃圾回收器(就是通常所说的 CMS GC )线程, 该线程主要针对于年老代垃圾回收。

"Concurrent Mark-Sweep GC Thread" prio=10 tid=0x00007fbea8073800 nid=0x5e8 runnable

10.1.5.4.5、Surrogate Locker Thread (Concurrent GC)

此线程主要配合 CMS 垃圾回收器来使用,是一个守护线程,主要负责处理 GC 过程中 Java 层的 Reference (指软引用、弱引用等等)与 jvm 内部层面的对象状态同步。

"Surrogate Locker Thread (Concurrent GC)" daemon prio=10 tid=0x00007fbea8158800 nid=0x5ee waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE

这里以 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 对象剔除掉。

10.1.5.5、第五部分:JNI global references count

这一部分主要回收那些在native代码上被引用,但在java代码中却没有存活必要的引用,对于防止因为应用代码中直接使用native库或第三方的一些监控工具的内存泄漏有非常大的帮助。

JNI global references: 1652

10.2、系统线程状态

系统线程有如下状态:

10.2.1、deadlock(重点关注)

死锁线程,一般指多个线程调用期间进入了相互资源占用,导致一直等待无法释放的情况。

10.2.2、runnable

一般指该线程正在执行状态中,该线程占用了资源,正在处理某个操作,如通过SQL语句查询数据库、对某个文件进行写入等。

10.2.3、blocked(重点关注)

线程正处于阻塞状态,指当前线程执行过程中,所需要的资源长时间等待却一直未能获取到,被容器的线程管理器标识为阻塞状态,可以理解为等待资源超时的线程。

10.2.4、waiting on condition(重点关注)

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

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

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

网络非常繁忙,几乎消耗了所有的带宽,仍然有大量数据等待网络读写;

网络可能是空闲的,但由于路由或防火墙等原因,导致包无法正常到达;

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

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

10.2.5、waiting for monitor entry 或 in Object.wait()

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

平台出现问题怎么解决(线上问题排查)(35)

图片来源于网络,如有侵权,请联系删除!!!

调用修饰:

  • 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() 。

10.2.5.1、Entry Set 里面的线程。

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

synchronized(obj) { }

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

  • 该 Monitor 不被其他线程拥有, Entry Set 里面也没有其他等待的线程。本线程即成为相应类或者对象的 Monitor 的 Owner ,执行临界区里面的代码;此时在 Thread Dump 中显示线程处于 Runnable 状态。
  • 该 Monitor 被其他线程拥有,本线程在 Entry Set 队列中等待。此时在 Thread Dump 中显示线程处于 waiting for monity entry 状态。

临界区的设置是为了保证其内部的代码执行的原子性和完整性,但因为临界区在任何时间只允许线程串行通过,这和我们使用多线程的初衷是相反的。如果在多线程程序中大量使用synchronized,或者不适当的使用它,会造成大量线程在临界区的入口等待,造成系统的性能大幅下降。如果在Thread Dump中发现这个情况,应该审视源码并对其进行改进。

10.2.5.2、Wait Set 里面的线程

当线程获得了 Monitor ,进入了临界区之后,如果发现线程继续运行的条件没有满足,它则调用对象(通常是被 synchronized 的对象)的 wait() 方法,放弃 Monitor ,进入 Wait Set 队列。只有当别的线程在该对象上调用了 notify() 或者 notifyAll() 方法, Wait Set 队列中的线程才得到机会去竞争,但是只有一个线程获得对象的 Monitor ,恢复到运行态。 Wait Set 中的线程在 Thread Dump 中显示的状态为 in Object.wait() 。

10.2.5.3、总结

通常来说,当CPU很忙的时候关注 Runnable 状态的线程,反之则关注 waiting for monitor entry 状态的线程。

10.3、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()方法,该线程结束生命周期。

平台出现问题怎么解决(线上问题排查)(36)

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

处于 WAITING BLOCKED TIMED_WAITING 的是 不消耗CPU 的。

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

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

十一、原文图片

平台出现问题怎么解决(线上问题排查)(37)

猜您喜欢: