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

简介: 面试时经常会被问到“CPU飙高怎么排查”,“内存泄露怎么定位解决”这类问题。本篇介绍一些常见的分析方法和工具

系列文章:

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

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

一 背景

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

相关文章
|
6月前
|
负载均衡 NoSQL 关系型数据库
性能基础之全链路压测知识整理
【2月更文挑战第16天】性能基础之全链路压测知识整理
302 11
|
存储 NoSQL Redis
记一次线上严重并发bug
记一次线上严重并发bug
|
运维 监控 Java
记一次线上OOM和性能优化,值得借鉴!
记一次线上OOM和性能优化,值得借鉴!
234 0
|
存储 监控 数据可视化
再谈全链路压测
以我现在所在的银行业务系统来说,目前的现状大概有这些:业务逻辑太复杂、系统庞大、子系统较多、系统间解耦程度较低、调用链路较长、核心系统环环相扣。
再谈全链路压测
|
消息中间件 监控 算法
JVM技术之旅-线上分析排查问题
JVM技术之旅-线上分析排查问题
304 0
JVM技术之旅-线上分析排查问题
|
运维 监控 NoSQL
一次线上问题排查所引发的思考
之前或多或少分享过一些内存模型、对象创建之类的内容,其实大部分人看完都是懵懵懂懂,也不知道这些的实际意义。
|
存储 监控 安全
JVM内存管理机制&线上问题排查
本文主要基于“深入java虚拟机”这本书总结JVM的内存管理机制,并总结了常见的线上问题分析思路。文章最后面是我对线上故障思考的ppt总结。 Java内存区域 虚拟机运行时数据区如下图所示: 15291199000153.jpg 方法区:方法区又称为永生代(Permanent Generation)是线程共享的内存区域。
2995 0
|
缓存 IDE Java
在被线上大量日志输出导致性能瓶颈毒打了很多次之后总结出的经验(上)
在被线上大量日志输出导致性能瓶颈毒打了很多次之后总结出的经验(上)
在被线上大量日志输出导致性能瓶颈毒打了很多次之后总结出的经验(上)
|
存储 监控 Java
在被线上大量日志输出导致性能瓶颈毒打了很多次之后总结出的经验(中)
在被线上大量日志输出导致性能瓶颈毒打了很多次之后总结出的经验(中)
在被线上大量日志输出导致性能瓶颈毒打了很多次之后总结出的经验(中)
|
存储 Prometheus 监控
在被线上大量日志输出导致性能瓶颈毒打了很多次之后总结出的经验(下)
在被线上大量日志输出导致性能瓶颈毒打了很多次之后总结出的经验(下)
在被线上大量日志输出导致性能瓶颈毒打了很多次之后总结出的经验(下)