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

原创

程序员架构进阶

修改于 2021-03-11 14:15:08

5130

修改于 2021-03-11 14:15:08

文章被收录于专栏：架构进阶架构进阶

系列文章：

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

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

一背景

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

  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，可以查看每个线程的性能信息：

  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" 0x55035503

2、某个线程一直在top 10的位置，那么说明该线程可能有性能问题

3、CPU利用率高的线程不断变化，说明不是某一个线程导致的CPU利用率飙高

原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。

如有侵权，请联系 cloudcommunity@tencent.com 删除。

shell

性能测试

运维

原创声明：本文系作者授权腾讯云开发者社区发表，未经许可，不得转载。

如有侵权，请联系 cloudcommunity@tencent.com 删除。

shell

性能测试

运维

登录后参与评论

0 条评论

热度