Cpu消耗过高原因分析

背景现象猜测导致服务器响应变慢的原因排查过程及结果猜测Cpu高消耗的原因Top命令查看进程占用Cpu情况Top -Hp 【pid】查看进程内线程占用Cpu情况发现异常线程占用Cpu情况堆栈分析jmap、jhat使用命令导出jvm线程对应的堆栈信息 jstack 使用导出java进程中单个线程的轨迹在线分析 可使用自动化脚本 结果

背景

记录公司一次技术分享，也是一次生产服务器假死的解决过程。

现象

1.前端页面响应慢，用户无法正常工作。 2.大量接口客户端服务超时报警。

猜测导致服务器响应变慢的原因

1.QPS激增，数据库压力上涨导致请求阻塞 2.网络异常，大面积服务暂时不可用 3.OOM，导致某台服务不可用，影响上层消费者服务 4.服务器存储空间占满 5.CPU超负荷，请求被阻塞

排查过程及结果

通过df命令查看磁盘空间使用情况，排除服务器存储空间问题 通过free -h -s 3命令每隔3秒查看内存内存使用情况，排除问题 通过elk接口访问统计，排除QPS激增和OOM 最终通过top命令查看CUP使用情况，发现CPU使用情况消耗太高

猜测Cpu高消耗的原因

1.请求创建的线程过多，频繁切换上下文 2.大量Full gc 3.死循环 4.计算密集型任务被触发，比如计算圆周率、组合排队、视频编码等

Top命令查看进程占用Cpu情况

Top -Hp 【pid】查看进程内线程占用Cpu情况

发现异常线程占用Cpu情况

堆栈分析

jmap、jhat

使用命令

使用 jmap -heap 【pid】 查看进程堆内存使用情况，包括使用的GC算法、堆配置参数和各代中堆内存使用情况

root@ubuntu:/# jmap -heap 21711 Attaching to process ID 21711, please wait... Debugger attached successfully. Server compiler detected. JVM version is 20.10-b01 using thread-local object allocation. Parallel GC with 4 thread(s) Heap Configuration: MinHeapFreeRatio = 40 MaxHeapFreeRatio = 70 MaxHeapSize = 2067791872 (1972.0MB) NewSize = 1310720 (1.25MB) MaxNewSize = 17592186044415 MB OldSize = 5439488 (5.1875MB) NewRatio = 2 SurvivorRatio = 8 PermSize = 21757952 (20.75MB) MaxPermSize = 85983232 (82.0MB) Heap Usage: PS Young Generation Eden Space: capacity = 6422528 (6.125MB) used = 5445552 (5.1932830810546875MB) free = 976976 (0.9317169189453125MB) 84.78829520089286% used From Space: capacity = 131072 (0.125MB) used = 98304 (0.09375MB) free = 32768 (0.03125MB) 75.0% used To Space: capacity = 131072 (0.125MB) used = 0 (0.0MB) free = 131072 (0.125MB) 0.0% used PS Old Generation capacity = 35258368 (33.625MB) used = 4119544 (3.9287033081054688MB) free = 31138824 (29.69629669189453MB) 11.683876009235595% used PS Perm Generation capacity = 52428800 (50.0MB) used = 26075168 (24.867218017578125MB) free = 26353632 (25.132781982421875MB) 49.73443603515625% used ....

附列性能参数：

使用jmap -histo[:live] pid查看堆内存中的对象数目、大小统计直方图，如果带上live则只统计活对象

root@ubuntu:/# jmap -histo:live 21711 | more num #instances #bytes class name ---------------------------------------------- 1: 38445 5597736 <constMethodKlass> 2: 38445 5237288 <methodKlass> 3: 3500 3749504 <constantPoolKlass> 4: 60858 3242600 <symbolKlass> 5: 3500 2715264 <instanceKlassKlass> 6: 2796 2131424 <constantPoolCacheKlass> 7: 5543 1317400 [I 8: 13714 1010768 [C 9: 4752 1003344 [B 10: 1225 639656 <methodDataKlass> 11: 14194 454208 java.lang.String 12: 3809 396136 java.lang.Class 13: 4979 311952 [S 14: 5598 287064 [[I 15: 3028 266464 java.lang.reflect.Method 16: 280 163520 <objArrayKlassKlass> 17: 4355 139360 java.util.HashMap$Entry 18: 1869 138568 [Ljava.util.HashMap$Entry; 19: 2443 97720 java.util.LinkedHashMap$Entry 20: 2072 82880 java.lang.ref.SoftReference 21: 1807 71528 [Ljava.lang.Object; 22: 2206 70592 java.lang.ref.WeakReference 23: 934 52304 java.util.LinkedHashMap 24: 871 48776 java.beans.MethodDescriptor 25: 1442 46144 java.util.concurrent.ConcurrentHashMap$HashEntry 26: 804 38592 java.util.HashMap 27: 948 37920 java.util.concurrent.ConcurrentHashMap$Segment 28: 1621 35696 [Ljava.lang.Class; 29: 1313 34880 [Ljava.lang.String; 30: 1396 33504 java.util.LinkedList$Entry 31: 462 33264 java.lang.reflect.Field 32: 1024 32768 java.util.Hashtable$Entry 33: 948 31440 [Ljava.util.concurrent.ConcurrentHashMap$HashEntry;

导出jvm线程对应的堆栈信息

1.jmap -dump:live,format=b,file=file.dat 262 备注：file.bin 表示文件名称，262表示jvm线程PID ，-dump:live 表示堆中存活的对象 2.用jhat查看 jhat -port 9998 /tmp/dump.dat

root@ubuntu:/# jhat -port 9998 /tmp/dump.dat Reading from /tmp/dump.dat... Dump file created Tue Jan 28 17:46:14 CST 2014 Snapshot read, resolving... Resolving 132207 objects... Chasing references, expect 26 dots.......................... Eliminating duplicate references.......................... Snapshot resolved. Started HTTP server on port 9998 Server is ready.

登陆服务器即可

jstack 使用

导出java进程中单个线程的轨迹

jstack 262 >test.txt 备注：262 表示PID ,test.txt 表示导出文件

在线分析

1.查看十六进制pid printf “%x\n” 【pid】 2.jstack 【pid】 |grep 【十六进制pid】

可使用自动化脚本

当服务器线程数超过 2500 时自动 dump 线程数最高的 java 进程的内存及线程栈。

#!/usr/bin/env bash # # 服务器线程数达到 2500 以上时 dump 线程数最多的 java 进程的线程及内存 # source ~/.bashrc cur_thread_num=`ps -efL | wc -l` if [ $cur_thread_num -le 2500 ]; then exit 0 fi cur_date=`date +"%Y-%m-%d_%H-%M-%S"` cd ./dumpfile # 服务器当前线程 dump 到文件:按照线程数由大到小排序显示 ps -efL --sort -nlwp > server_thread_dump_$cur_date # dump 线程数最多的 jvm 的线程及内存 most_thread_num_pid=`cat server_thread_dump_$cur_date | sed -n '2p' | awk '{print $2}'` nohup jstack -l $most_thread_num_pid > java_app_thread_dump_${cur_date}_pid_${most_thread_num_pid} & nohup jmap -dump:format=b,file=java_app_mem_dump_${cur_date}_pid_${most_thread_num_pid} $most_thread_num_pid & exit 0

结果

通过分析堆栈，找到大量GC，分析GC原因，修改问题代码，解决问题