简介
Spring cloud微服务广泛应用后,服务的监控和运维压力也与日俱增,经常有服务出现CPU或者内存使用率过高的告警,那么遇到这样的问题我们该如何排查呢?我们可以借助哪些工具来定位问题呢?本文将介绍一下遇到此类问题的解决思路和方法。
一.常见的性能问题优化的经验分享
1.通过应用日志定位思路
对于业务体量不大,QPS不高的服务来说,一般出现性能问题还是很好定位的,比如通过Prometheus等监控平台出现CPU或内存使用率过高的时间点,看一下这个时间点附近的应用日志,一般就可以看出其内存溢出的地方了,偶尔报错的地方也并非就是引发性能问题的地方,因为报错的地方只是压垮骆驼的最后一根稻草,在此报错点之前的地方有出现耗费性能的操作导致的。有时候监控趋势图显示CPU彪生,但其实是因为OOM引发的,要清晰的定位这些问题,这就得再借助下其他工具了,后文再介绍。
2.常见的性能问题
我们发现了日志报错点后,第一点就要去思考有没有往内存中加载大量数据的操作,比如Excel导出一次性加载大量数据而不采用分页的、一次加载大量Redis缓存的、一次Select查询大量Mysql数据的地方。
这些都是及其容易引发内存溢出的地方,也是很多刚工作的同学经常犯的错误,他们在开发环境数据量少时不会暴露此类问题,但是一旦发布生产环境,单表数据量到百万数量级,此类问题就会出现,所以自己或问问同事有没有写过类似的操作或接口,从而快速定位。
以上都是凭借经验判断,如果开发者资历尚浅或者问题隐藏较深,我们就需要借助一些工具来定位问题了。
二.CPU利用率过高问题定位
如果发现CPU利用率过高,比如达到了90%-100%时,我们可以直接登陆应用服务器,通过以下步骤定位问题:
1.查看占用CPU高的线程
命令:top
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND\
4380 root 20 0 9415956 2.350g 26772 S 90.3 41.4 426:14.30 java\
2083 root 20 0 1141656 9460 7044 S 0.7 0.2 130:19.20 Asiainfocwexam\
2038 root 20 0 495668 5880 4776 S 0.3 0.1 524:46.15 Asiainfocwmonit\
2093 root 20 0 1377548 10244 8324 S 0.3 0.2 514:56.84 Asiainfocwsvrd\
6708 root 20 0 27520 3236 2460 S 0.3 0.1 0:00.15 sshd\
21114 root 20 0 729064 18340 6856 S 0.3 0.3 39:46.81 bkmonitorbeat\
1 root 20 0 41284 2860 1940 S 0.0 0.0 0:15.97 systemd
我们可以看出第一个进程PID:4380的CPU占用率过高,他就是我们的java服务,这里PID指的是进程,我们需要根据进程号,找到其占用CPU的线程。
命令:top -Hp 4380
注:
-
命令中H大写,p小写
-
top
:在终端实时显示系统性能数据的命令。 -
-H
:该选项用于显示所有线程的信息而不是仅显示总体的信息。 -
-p 4380
:该选项指定要监视的进程的PID。在这里,4380是一个占位符,你可能会替换为实际的进程PID。PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
4558 root 20 0 9415956 2.333g 26772 S 92.9 41.1 160:56.84 java
4389 root 20 0 9415956 2.333g 26772 S 0.7 41.1 11:17.82 VM Thread
4473 root 20 0 9415956 2.333g 26772 S 0.7 41.1 4:38.15 redisson-netty-
4480 root 20 0 9415956 2.333g 26772 S 0.7 41.1 3:19.37 redisson-netty-
我们可以看到PID:4558的线程CPU使用率较高。
打印出问题线程的堆栈信息
命令:printf '%x\n' 4558
将线程号转为16进制显示,用于在堆栈中定位线程。
注:
-
printf
:是一个格式化输出命令。 -
'%x\n'
:是格式控制字符串,表示将后面的参数按十六进制格式输出,并在末尾添加换行符。 -
4558
:是要格式化输出的整数。[root]# printf ‘%x\n’ 4558
11ce
命令 :jstack 4380|grep -A 100 11ce
通过jstack打印进程4380的堆栈信息,并只过滤出线程11ce
的堆栈信息
命令含义:使用 jstack
来打印指定 Java 进程(PID为4380)的线程堆栈信息,然后使用 grep
过滤输出,查找包含特定字符串 “11ce” 的行,并打印该行及其后续100行的内容。
注:
jstack 4380
:使用jstack
命令获取 Java 进程 4380 的线程堆栈信息。|
:管道符,将jstack
的输出传递给下一个命令。grep -A 200 11ce
:使用grep
过滤包含字符串 “11ce” 的行,同时打印每个匹配行的后续100行内容(包括匹配行本身)。
"org.springframework.kafka.KafkaListenerEndpointContainer#0-0-C-1" #130 prio=5 os_prio=0 tid=0x00007f922eccd800 nid=0x11ce runnable [0x00007f91c80be000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x0000000088383dc0> (a sun.nio.ch.Util$3)
- locked <0x0000000088383db0> (a java.util.Collections$UnmodifiableSet)
- locked <0x0000000088383d68> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at org.apache.kafka.common.network.Selector.select(Selector.java:869)
at org.apache.kafka.common.network.Selector.poll(Selector.java:465)
at org.apache.kafka.clients.NetworkClient.poll(NetworkClient.java:563)
at org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient.poll(ConsumerNetworkClient.java:265)
at org.apache.kafka.clients.consumer.internals.ConsumerNetworkClient.poll(ConsumerNetworkClient.java:236)
at org.apache.kafka.clients.consumer.KafkaConsumer.pollForFetches(KafkaConsumer.java:1292)
at org.apache.kafka.clients.consumer.KafkaConsumer.poll(KafkaConsumer.java:1233)
at org.apache.kafka.clients.consumer.KafkaConsumer.poll(KafkaConsumer.java:1206)
其中第一行中 nid=0x11ce
,此处就是我们上面16进制线程号:11ce。所以此条堆栈对应的代码行数,即为耗费CPU比较高的线程对应的代码(上面堆栈仅为示例)。
三.内存利用率过高问题定位
1.内存过高代码定位
内存过高和CPU过高一样,都可以用上述方法定位,在下方%MEM列,即表示内存占用率,找出对应的PID,重复上面操作即可定位。
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND\
4380 root 20 0 9415956 2.350g 26772 S 10.2 91.4 426:14.30 java\
2.设置java启动参数出现OOM自动打印堆栈
在服务器上建立好路径,比如:/usr/local/app/logs,然后当服务发生OutOfMemoryError(OOM)内存溢出时,会自动打印堆栈信息到dump.hprof文件中,那时我们只需要分析此文件即可定位问题。
nohup java -XX:HeapDumpPath=/usr/local/app/logs/dump.hprof -XX:+HeapDumpOnOutOfMemoryError-jar /usr/local/app/test-web.jar --spring.profiles.active=pro >/dev/null 2>&1 &
3.分析堆文件
在jdk安装目录下,jdk1.8.0_60\bin下,有jvisualvm.exe工具,打开这个工具,点击文件->装入->文件类型选择hprof->选择dump.hprof。如下图:
如果有OOM会显示在概览中,并且堆栈信息也打印了。
特别提醒:
OutOfMemoryError(OOM)的堆栈信息通常只显示了导致内存不足的最终操作,而不一定反映了问题的根本原因。OOM 堆栈信息中的最上层可能只是触发了 Java 虚拟机报告内存不足的点,而不一定是导致内存不足的真正原因。即此工具分析结果只是压死骆驼的最后一根稻草,并不一定是导致内存溢出的原因,所以有时你还需要找到压死骆驼的那块大石头,而不要只盯着这跟稻草优化,比如有时候会显示垃圾回收GC线程占用内存过高,但GC可不是导致OOM的根因。大多数情况下,jvisualvm定位到的问题就是OOM的原因,但不全是,所以你要明白原因。
四.使用阿里巴巴Arthas诊断工具
1.Arthas能做什么?
Arthas有很多强大功能,本文只针对CPU和内存使用率过高的性能问题进行讲解,其他用法参考《官方文档》拓展阅读吧。
2.下载Arthas
如果服务器可以连接互联网,可以直接使用下面的命令下载,如果不能联网,可以下载jar包后上传到服务器。
curl -O https://arthas.aliyun.com/arthas-boot.jar
3.启动Arthas
java -jar arthas-boot.jar
启动时,需要手动选择要监控的java程序,如果只有一个,就输入“1”,如果多个,输入对应的序号数字即可,如图:
4.定位占用资源多的线程堆栈
使用命令打印出占用CPU的线程堆栈,即可定位问题,然后就具体情况具体分析了,每个人遇到的问题都是不一样的,这里只教学下排除问题的方法。以下是几个常用的命令:
①.查询最忙的3个线程,采样5000毫秒内的堆栈信息:
thread -n 3 -i 5000
5000毫秒为采样时间,如果不加-i 5000
,那么默认是采样200毫秒,采样时间过短的话往往不太准确,因为采样本身也会占用CPU性能,所以可以适当延长一下
②.查询当前阻塞其他线程的线程:
thread -b
如果有堵塞的线程会打印出来,如果没有则不会打印出结果。比如一些kafka消费类的线程,会一直处于堵塞状态,这种其实也是正常的,并不是有堵塞的线程,就要去解决优化。我们要看看那些不应该长时间堵塞的线程,为啥出现了堵塞。
注:thread命令使用参考《官方文档-thread命令》
③.查看JVM信息,下面三个命令都可以:
jvm
sysprop
sysenv
如果忙碌线程中,长时间出现GC,那就开启GC日志,
XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/path/to/gc.log
看看是否出现了Full GC,Full GC日志示例:
2024-01-04T12:34:56.789-0500: [Full GC (System.gc()) [PSYoungGen: 0K->0K(5120K)] [ParOldGen: 4096K->4096K(10240K)] 4096K->4096K(15360K), [Metaspace: 1234K->1234K(8192K)], 0.0123456 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
如果出现了Full GC,那就用上文提到的jvisualvm.exe分析堆文件,找出占用内存大的对象,并优化。
总结
本文介绍了通过系统日志、java JDK工具、JVM参数、linux系统命令、Arthas诊断工具等方法,定位和解决线上CPU使用率过高、内存使用率过高的方法,大家可以根据自己的环境灵活搭配使用上述方法,解决性能问题。排查性能问题需要不断的积累经验的过程,新手可能感到无从下手,解除本文提到的工具,多尝试、多总结,遇到性能问题不要侥幸,敬畏墨菲定律,不要想着重启下就能解决,重启大法好,但不能提升你解决问题的能力。所以出现偶发的性能问题一定要及时去定位,不然就像定时炸弹一样,在你下班时间引爆。工作学习上要积极主动些,上工治未病。