前两天测试找到我说风控系统压测时CPU飙高到了95%，询问一下我是可能什么原因。这个风控系统是我之前参与搭建和开发的，现在系统在进行上线前的压测。由于项目已经交接给另一个团队了，本着学习的精神，于是我去查了一下日志，但是日志太多了，并没有看出什么问题。于是便用上了jdk自带的监控工具，在此记录一下过程
找到导致CPU飙升的线程
首先需要定位到是服务里的那些线程导致CPU飙升的，我们的服务是Java服务，只关注Java进程即可，命令如下
1 执行top命令
在服务器上通过命令行输入 top 命令可以查到服务的进程号。一般CPU占用高的会排在最前面，由于公司的项目运行在内网，没有实际的cpu飙高信息，下面举个例子
[root@VM_0_3_centos ~]# top
top - 22:56:02 up 228 days, 3:51, 1 user, load average: 0.08, 0.14, 0.12
Tasks: 75 total, 1 running, 74 sleeping, 0 stopped, 0 zombie
%Cpu(s): 1.0 us, 1.3 sy, 0.0 ni, 97.3 id, 0.3 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 1015024 total, 69356 free, 513292 used, 432376 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 334880 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
11115 root 20 0 2299632 145836 3304 S 0.3 14.4 313:38.63 java
2 root 20 0 0 0 0 S 0.0 0.0 0:01.45 kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 8:38.85 ksoftirqd/0
5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
7 root rt 0 0 0 0 S 0.0 0.0 0:00.00 migration/0
8 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh 2 执行 top -H -p $pid 命令
通过此命令可以看到具体是哪个线程占用了CPU，如上面的是11115线程占用cpu最高，便执行top -H -p 11115，然后记下该占用cpu最高的线程的id，如下是 11116 占用了较高的cpu资源
[root@VM_0_3_centos ~]# top -H -p 11115
top - 23:01:21 up 228 days, 3:56, 1 user, load average: 0.01, 0.07, 0.11
Threads: 26 total, 0 running, 26 sleeping, 0 stopped, 0 zombie
%Cpu(s): 1.0 us, 0.3 sy, 0.0 ni, 98.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 1015024 total, 70288 free, 510980 used, 433756 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 337152 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
11116 root 20 0 2299632 145836 3304 S 0.2 14.4 0:03.08 java
11117 root 20 0 2299632 145836 3304 S 0.0 14.4 9:41.75 java
11118 root 20 0 2299632 145836 3304 S 0.0 14.4 0:00.01 java
11119 root 20 0 2299632 145836 3304 S 0.0 14.4 0:00.00 java
11120 root 20 0 2299632 145836 3304 S 0.0 14.4 0:00.00 java
11121 root 20 0 2299632 145836 3304 S 0.0 14.4 1:37.22 java
11122 root 20 0 2299632 145836 3304 S 0.0 14.4 1:37.17 java
11123 root 20 0 2299632 145836 3304 S 0.0 14.4 0:00.00 java
11124 root 20 0 2299632 145836 3304 S 0.0 14.4 257:43.10 java
11150 root 20 0 2299632 145836 3304 S 0.0 14.4 11:57.31 java
11152 root 20 0 2299632 145836 3304 S 0.0 14.4 12:32.29 java 查看对应线程的堆栈信息
找到了cpu飙高的线程后，最终要的是要查看线程的堆栈信息，不然你也不知道这个线程为什么飙高了，这个线程在干什么。需要要到jdk的监控工具
执行 jstack pid > /tmp/log.txt 命令
如刚刚的例子中，执行 jstack 11115 > /tmp/log.txt ，注意这里11115是进程的pid，而不是线程的。这个命令会把该进程的所有堆栈信息输出到文件
[root@VM_0_3_centos ~]# jstack 11115 > /tmp/log.txt
[root@VM_0_3_centos ~]# 根据线程id 查看堆栈信息
由于堆栈日志 线程id是16进制的，所以需要先将10进制的线程id转为16进制，如刚刚11116线程id要转为16进制数，再去生成的log.txt文件中根据16进制数搜索。我们来看一下输出的日志文件内容
[root@VM_0_3_centos ~]# tail -f /tmp/log.txt
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x00000000f5b93448> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
"VM Thread" os_prio=0 tid=0x00007f0b20095000 nid=0x2b6d runnable
"VM Periodic Task Thread" os_prio=0 tid=0x00007f0b200de000 nid=0x2b74 waiting on condition
JNI global references: 948
其中nid就是线程id
CPU飙高的原因总结
cpu飙高的可能原因无非是线程一直在占用cpu的资源。一般java服务有以下情况会出现cpu飙高的情况，在此总结一下
内存问题
导致JVM频繁GC，此时服务占用CPU资源的主要是GC线程，而不是业务线程。多个线程的CPU都超过了100%，通过jstack命令可以看到这些线程主要是垃圾回收线程。通过jstat命令监控GC情况，可以看到Full GC次数非常多，并且次数在不断增加。
死锁问题
多线程场景下出现死锁也会导致cpu飙高，直接在输入的堆栈日志文件中搜索关键字：deadlock.。会打印出业务死锁的位置。至于出现死锁的原因就不多说了，可以去查一下，然后把死锁解决
代码问题
这个说的有点笼统，如某些复杂算法，算法BUG，导致无限循环递归等等。这个是比较好定位的，日志文件中同一个线程的日志信息会反复出现，稍加排查基本就能定位到具体的代码位置了
阻塞性操作
代码某个位置有阻塞性的操作，导致该功能调用整体比较耗时，但出现是比较随机的；平时消耗的CPU不多，而且占用的内存也不高。但在压测场景下出现CPU飙高。可通过压测工具不断加大访问力度，首先找到该代码位置，由于压测大量线程将阻塞于该阻塞点，例如出现
"http-nio-8080-exec-4" #31 daemon prio=5 os_prio=31 tid=0x00007fd08d0fa000 nid=0x6403 waiting on condition [0x00007000033db000]
java.lang.Thread.State: TIMED_WAITING (sleeping) //期限等待
at java.lang.Thread.sleep(Native Method)
at java.lang.Thread.sleep(Thread.java:340)
at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
at com.*.user.controller.UserController.detail(UserController.java:18) //业务代码阻塞点找到业务代码阻塞点，这里业务代码使用了TimeUnit.sleep()方法，使线程进入了TIMED_WAITING(期限等待)状态。
