Cpu消耗过高原因分析

背景

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

现象

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原因，修改问题代码，解决问题