系列文章:
并发编程系列:关于线程中断
并发编程系列:阻塞队列的实现原理
一 背景
大家都知道,在服务/应用发布到预览或者线上环境时,经常会出现一些测试中没有出现的问题。并且由于环境所限,我们也不可能在线上调试代码,所以只能通过日志、系统信息和dump等手段来在线上定位问题。
通常需要借助一些工具,例如jdk本身提供的一些jmap,jstack等等,或者是阿里提供的比较强大的Arthus,另外就是最基础的一些命令。根据经验,系统上发生的主要问题是在cpu、内存、磁盘几个方面,因此会优先针对这类问题进行定位。由于绝大部分服务都是部署在Linux环境下,所以一下以Linux命令为例进行说明。
二 top命令
top命令可以用于查询每个进程的情况,显示信息如下:
代码语言:javascript复制top - 22:32:03 up 180 days, 7:23, 1 user, load average: 0.07, 0.06, 0.05
Tasks: 106 total, 1 running, 105 sleeping, 0 stopped, 0 zombie
%Cpu(s): 1.5 us, 1.0 sy, 0.0 ni, 97.5 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 16266504 total, 324836 free, 6100252 used, 9841416 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 9827120 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME COMMAND
1466 root 20 0 3243684 665836 14684 S 0.7 4.1 82:18.89 java
660 root 20 0 835120 25288 8036 S 0.3 0.2 718:10.90 exe
4835 root 20 0 6715536 129904 13368 S 0.3 0.8 400:01.40 java
8287 root 20 0 1003108 118464 18812 S 0.3 0.7 731:56.27 node /opt/my-ya
8299 root 20 0 1002164 107792 18816 S 0.3 0.7 730:11.28 node /opt/my-ya
8395 root 20 0 611552 35476 14504 S 0.3 0.2 14:17.25 node /opt/qkd-n
10184 root 20 0 3089652 673520 15880 S 0.3 4.1 83:32.81 java
12882 root 20 0 917540 64556 16156 S 0.3 0.4 543:55.74 PM2 v4.4.0: God
13556 root 20 0 2998424 556848 14548 S 0.3 3.4 496:48.18 java
14293 root 10 -10 151296 26920 6880 S 0.3 0.2 1868:03 AliYunDun
14755 root 20 0 3030352 676388 14720 S 0.3 4.2 49:16.41 java
22908 root 20 0 623456 38892 14536 S 0.3 0.2 98:50.65 node /opt/qkd-n
22936 root 20 0 622680 39712 14532 S 0.3 0.2 98:27.12 node /opt/qkd-n
24142 root 20 0 3303328 659496 14716 S 0.3 4.1 23:20.38 java
25566 root 20 0 706964 52660 16308 S 0.3 0.3 19:17.11 node /opt/qkd-n
25597 root 20 0 708020 53112 16308 S 0.3 0.3 19:06.83 node /opt/qkd-
如上面内容所示,需要注意一下各列的含义,这里再重复一遍,如下表所示:
由于限定我们的应用是Java应用,所以只需要关注COMMOND列是java的进程信息。
有时候%CPU这列的数字可能会超过100%,这不一定是出了问题,因为是机器所有核加在一起的CPU利用率,所以我们需要计算一下,平均每个核上的利用比例,再来确定是否是CPU使用过高,进而再去分析是否发生了死循环、内存回收等问题的可能。
在top命令出来的界面下,输入1(top的交互命令数字),可以查看每个CPU的性能信息:
代码语言:javascript复制 PID USER PR NI VIRT RES SHR S %CPU %MEM TIME COMMAND
5875 qkadmin 20 0 163144 3324 1612 R 1.0 0.0 0:00.24 top
1498 root 20 0 3243684 665836 14684 S 0.3 4.1 39:27.18 java
27412 root 20 0 3243684 665836 14684 S 0.3 4.1 15:14.25 java
4982 root 20 0 6715536 129904 13368 S 0.3 0.8 198:59.46 java
8287 root 20 0 1003108 118728 18812 S 0.3 0.7 688:11.51 node /opt/my-ya
10289 root 20 0 3089652 673520 15880 S 0.3 4.1 30:15.15 java
12261 root 20 0 803192 10800 4592 S 0.3 0.1 10:05.35 aliyun-service
12263 root 20 0 803192 10800 4592 S 0.3 0.1 5:45.73 aliyun-service
14351 root 20 0 2998424 556848 14548 S 0.3 3.4 1:14.78 java
以上是我们某台机器上的实时数据,因为当前运行正常,所以没有异常数据。但看一下下面的数据:
命令行显示了5个CPU,说明是一个5核的机器,平均每个CPU利用率在60%以上。有时可能存在CPU利用率达到100%,如果出现这种情况,那么很有可能是代码中写了死循环,继续看代码定位问题原因。
CPU参数的含义如下:
交互命令H,可以查看每个线程的性能信息:
代码语言:javascript复制 PID USER PR NI VIRT RES SHR S %CPU %MEM TIME COMMAND
5875 qkadmin 20 0 163144 3324 1612 R 1.0 0.0 0:00.24 top
1498 root 20 0 3243684 665836 14684 S 0.3 4.1 39:27.18 java
27412 root 20 0 3243684 665836 14684 S 0.3 4.1 15:14.25 java
4982 root 20 0 6715536 129904 13368 S 0.3 0.8 198:59.46 java
8287 root 20 0 1003108 118728 18812 S 0.3 0.7 688:11.51 node /opt/my-ya
10289 root 20 0 3089652 673520 15880 S 0.3 4.1 30:15.15 java
12261 root 20 0 803192 10800 4592 S 0.3 0.1 10:05.35 aliyun-service
12263 root 20 0 803192 10800 4592 S 0.3 0.1 5:45.73 aliyun-service
14351 root 20 0 2998424 556848 14548 S 0.3 3.4 1:14.78 java
可能发生的几个问题和对应的现象有:
1、某个线程,CPU利用率一直在100%左右,那么说明这个线程很有可能出现死循环,记住这个PID,并进一步定位具体应用;另外也可能是出现内存泄漏,触发频繁GC导致。这种情况,可以使用jstat命令查看GC情况,以分析是否持久代或老年代内存区域满导致触发Full GC,进而使CPU利用率飙高,命令和显示信息如下(81443是当前机器上观察的进程id):
代码语言:javascript复制jstat -gcutil 81443 1000 5
信息:
代码语言:javascript复制 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 53.94 78.77 0.05 97.26 93.39 1 0.006 0 0.000 0.006
0.00 53.94 78.77 0.05 97.26 93.39 1 0.006 0 0.000 0.006
0.00 53.94 78.77 0.05 97.26 93.39 1 0.006 0 0.000 0.006
0.00 53.94 78.77 0.05 97.26 93.39 1 0.006 0 0.000 0.006
0.00 53.94 78.77 0.05 97.26 93.39 1 0.006 0 0.000 0.006
三 dump
下一步,可以把线程dump下来,然后再继续分析是哪个线程、执行到那段代码导致CPU利用率飙高。使用命令可以参考如下:
代码语言:javascript复制jstack 81443 > ./dump01
dump文件内容:
代码语言:javascript复制192:dubbo-proxy-tools xxx$ cat dump01
2021-02-13 22:51:08
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.212-b10 mixed mode):
"Attach Listener" #14 daemon prio=9 os_prio=31 tid=0x00007f8cef903000 nid=0x1527 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"DestroyJavaVM" #12 prio=5 os_prio=31 tid=0x00007f8cef91d000 nid=0x2803 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"JPS event loop" #10 prio=5 os_prio=31 tid=0x00007f8cf1153800 nid=0xa703 runnable [0x0000700003656000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method)
at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:198)
at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:117)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x00000007b5700798> (a io.netty.channel.nio.SelectedSelectionKeySet)
- locked <0x00000007b57007b0> (a java.util.Collections$UnmodifiableSet)
- locked <0x00000007b5700748> (a sun.nio.ch.KQueueSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:753)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:408)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
at java.lang.Thread.run(Thread.java:748)
"Service Thread" #9 daemon prio=9 os_prio=31 tid=0x00007f8cf3822800 nid=0x5503 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C1 CompilerThread3" #8 daemon prio=9 os_prio=31 tid=0x00007f8cf1802800 nid=0x3a03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007f8cf480c000 nid=0x3c03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
线程id (nid=0x2803) 是16进制,可与转成10进制,来跟top命令观察的id对应(可以简单地使用 printf "%xn" 0x5503即可):
代码语言:javascript复制192:dubbo-proxy-tools xxxx$ printf "%xn" 0x55035503
2、某个线程一直在top 10的位置,那么说明该线程可能有性能问题
3、CPU利用率高的线程不断变化,说明不是某一个线程导致的CPU利用率飙高