系列文章:
一 背景
大家都知道,在服务/应用发布到预览或者线上环境时,经常会出现一些测试中没有出现的问题。并且由于环境所限,我们也不可能在线上调试代码,所以只能通过日志、系统信息和dump等手段来在线上定位问题。
通常需要借助一些工具,例如jdk本身提供的一些jmap,jstack等等,或者是阿里提供的比较强大的Arthus,另外就是最基础的一些命令。根据经验,系统上发生的主要问题是在cpu、内存、磁盘几个方面,因此会优先针对这类问题进行定位。由于绝大部分服务都是部署在Linux环境下,所以一下以Linux命令为例进行说明。
二 top命令
top命令可以用于查询每个进程的情况,显示信息如下:
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的性能信息:
top - 22:39:16 up 180 days, 7:30, 1 user, load average: 0.08, 0.06, 0.05 Tasks: 106 total, 1 running, 105 sleeping, 0 stopped, 0 zombie %Cpu0 : 1.7 us, 1.3 sy, 0.0 ni, 97.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu1 : 1.3 us, 1.0 sy, 0.0 ni, 97.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 16266504 total, 324240 free, 6100720 used, 9841544 buff/cache KiB Swap: 0 total, 0 free, 0 used. 9826652 avail Mem
以上是我们某台机器上的实时数据,因为当前运行正常,所以没有异常数据。但看一下下面的数据:
命令行显示了5个CPU,说明是一个5核的机器,平均每个CPU利用率在60%以上。有时可能存在CPU利用率达到100%,如果出现这种情况,那么很有可能是代码中写了死循环,继续看代码定位问题原因。
CPU参数的含义如下:
交互命令H,可以查看每个线程的性能信息:
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):
jstat -gcutil 81443 1000 5
信息:
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利用率飙高。使用命令可以参考如下:
jstack 81443 > ./dump01
dump文件内容:
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 "%x\n" 0x5503即可):
192:dubbo-proxy-tools xxxx$ printf "%x\n" 0x5503 5503
2、某个线程一直在top 10的位置,那么说明该线程可能有性能问题
3、CPU利用率高的线程不断变化,说明不是某一个线程导致的CPU利用率飙高