并发编程系列:线上问题定位

2021-03-11 14:15:08 浏览数 (1)

系列文章:

并发编程系列:关于线程中断

并发编程系列:阻塞队列的实现原理

一 背景

大家都知道,在服务/应用发布到预览或者线上环境时,经常会出现一些测试中没有出现的问题。并且由于环境所限,我们也不可能在线上调试代码,所以只能通过日志、系统信息和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利用率飙高

0 人点赞