CPU升高的排查步骤和分析思路
CPU升高通常会引起系统运行缓慢甚至不可用，线上报警等。 可能的原因主要有两种：
- 系统内存耗尽，从而导致Full GC次数过多，系统缓慢
- 代码中有比较耗CPU的操作，导致CPU过高，系统运行缓慢
1.1 核心排查步骤
1.1.1 查看所有进程占系统CPU的排序
top
1.1.2 查看进程的cpu
top -p pid
1.1.2 定位使用 CPU 最高的线程
top -Hp pid
使用 CPU 最高的线程的tid是 12817
1.1.3 线程 tid 转化 16 进制
线程堆栈的线程nid是十六进制
> printf '%x\n' 12817 # printf '%x\n' tid
> 3211
1.1.4 找到线程堆栈
# jstack pid | grep nid
jstack 12817 | grep 3211 -A 30
1.2 分析
通过核心排查步骤，找出有问题的代码，观察到线程栈之后。我们就要根据具体问题来具体分析。
- 情况一：发现使用CPU最高的是业务线程
- 情况二：发现使用CPU最高的都是GC 线程
- 情况三：排查是否是上下文切换引起的
1.2.1 业务线程引起的CPU升高
代码中有大量消耗CPU的操作，导致CPU过高，系统运行缓慢。
例如某些复杂算法，甚至算法BUG，无限循环递归等等。通过jstack的堆栈信息，可直接定位到代码行。
此外，搜索关键字deadlock ，堆栈信息会打印出业务死锁的位置。
1.2.2 GC线程引起的CPU升高
当定位到的线程是GC task thread 或者 VM Thread，指的就是垃圾回收的线程。
GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fd99001f800 nid=0x779 runnable
GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fd990021800 nid=0x77a runnable
GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007fd990023000 nid=0x77b runnable
GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007fd990025000 nid=0x77c runnabl
说明当前系统的原因主要问题是垃圾回收过于频繁。
我们通过如下命令进一步排查：
（1）用jmap 命令查看当前堆的使用情况
jmap -heap pid
（2）用jstat 命令查看GC情况
jstat -gcutil pid 1000 10
输出的FGC指的是Full GC数量，如果FGC比较高，而且还在不断增长，可能是内存溢出或者内存泄漏等问题。
（3）用jmap 命令 dump出内存日志
jmap -dump:format=b,file=fileName.dump pid
通过eclipse的mat工具可以分析堆内存。经过mat工具分析之后，基本上就能确定内存中主要是哪个对象比较消耗内存，然后找到该对象的创建位置，进行处理即可。
注意
内存占用不高，但是Full GC次数还是比较多，此时可能是显示的 System.gc()调用导致GC次数过多，这可以通过添加 -XX:+DisableExplicitGC来禁用JVM对显示GC的响应。
1.2.3 上下文切换引起的CPU升高
上下文切换相关的基础知识，请见linux基础知识-CPU-上下文切换
可以用 vmstat 和 pidstat*两个工具监控
vmstat查看系统总体的上下文切换情况 vmstat是一个常用的系统性能分析工具，主要用来分析系统的内存使用情况，也常用来分析CPU上下文切换和中断的次数。
# vmstat 5
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
1 0 90720 3960176 1036 3014980 0 0 35 85 0 1 1 0 98 0 0
0 0 90720 3959928 1036 3015004 0 0 0 24 240 358 0 0 99 0 0
0 1 90720 3959356 1036 3015068 0 0 0 34 260 390 1 0 99 0 0
0 0 90720 3959204 1036 3015088 0 0 0 23 234 340 0 0 99 0 0
0 0 90720 3960708 1036 3015088 0 0 0 609 297 429 0 0 99 0 0
0 0 90720 3960772 1036 3015112 0 0 0 140 295 410 0 0 99 0 0
0 0 90720 3960688 1036 3015164 0 0 0 36 269 406 0 0 99 0 0
- r 是就绪队列的长度，也就是正在运行和等待 CPU 的进程数
- b 处于不可中断睡眠状态的进程数
- swpd 交换分区大小，一般在内存不足的情况会使用swap进行扩展
- free 空闲的物理内存的大小
- si 每秒从磁盘读入虚拟内存的大小，如果这个值大于0，表示物理内存不够用或者内存泄露了，要查找耗内存进程解决掉。
- so 每秒虚拟内存写入磁盘的大小，如果这个值大于0，同上
- bi 块设备每秒接收的块数量，这里的块设备是指系统上所有的磁盘和其他块设备，在处理拷贝大量数据(2-3T)的机器上看过可以达到140000/s，磁盘写入速度差不多140M每秒
- bo 块设备每秒发送的块数量，读取文件，bo就要大于0。bi和bo一般都要接近0，不然就是IO过于频繁，需要调整
- in 每秒CPU的中断次数，包括时间中断
- cs 每秒上下文切换次数
pidstat查看每个进程的详细情况
# pidstat -w 5
05:30:32 PM UID PID cswch/s nvcswch/s Command
05:30:37 PM 0 8 18.16 0.00 rcu_sched
05:30:37 PM 0 11 0.20 0.00 watchdog/0
05:30:37 PM 0 183 4.59 0.00 kworker/3:1H
05:30:37 PM 0 388 2.40 0.00 kworker/0:1H
05:30:37 PM 0 546 0.20 0.00 irqbalance
05:30:37 PM 0 621 9.98 0.00 qemu-ga
05:30:37 PM 109 663 0.40 0.00 uml_switch
05:30:37 PM 0 1275 0.40 0.00 master
05:30:37 PM 110 1277 0.20 0.00 qmgr
05:30:37 PM 0 5896 7.39 0.00 kworker/0:0
05:30:37 PM 0 13579 8.18 0.00 sshd
05:30:37 PM 0 13766 0.20 0.00 vmstat
05:30:37 PM 0 26398 5.19 0.00 kworker/u8:1
05:30:37 PM 0 28341 6.19 0.00 kworker/u8:2
05:30:37 PM 0 28898 5.99 1.40 bash
这个结果中有两列内容是重点关注对象:
- cswch自愿上下文切换: 是指进程无法获取所需资源，导致的上下文切换。比如说， I/O、内存等系统资源不足时，就会发生自愿上下文切换
- nvcswch非自愿上下文切换: 则是指进程由于时间片已到等原因，被系统强制调度，进而发生的上下文切换。比如说，大量进程都在争抢CPU时，就容易发生非自愿上下文切换
cswch切换变多了，说明进程都在等待资源，有可能发生了I/O等其他问题；
nvcswch切换变多了，说明进程都在被强制调度，也就是都在争抢 CPU，说明CPU的确成了瓶颈；
1.3 频繁切换线程上下文的案列
注意： 处于waiting和blocked状态的线程都不会消耗CPU 线程频繁地挂起和唤醒需要消耗CPU, 而且代价颇大
高并发竞争锁引起的cpu升高
生成2000个线程， 利用jdk提供的LockSupport.park()不断挂起这些线程，再使用LockSupport.unpark(t)不断地唤醒这些线程， 唤醒之后又立马挂起，以此达到不断切换线程的目的。
jstack命令获取到线程栈信息
"test-1-thread-6" #1522 prio=5 os_prio=0 tid=0x00007f4b7006f800 nid=0x1b67c waiting on condition [0x00007f4ac8c4a000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006c10828c8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)
at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.info(Logger.java:579)
...
ReentrantLock的底层是使用AQS框架实现的。大概描述一下AQS:
- AQS有个临界变量state,当一个线程获取到state==0时, 表示这个线程进入了临界代码(获取到锁), 并原子地把这个变量值+1
- 没能进入临界区(获取锁失败)的线程, 会利用CAS的方式添加到到CLH队列尾去, 并被LockSupport.park挂起.
- 当线程释放锁的时候, 会唤醒head节点的下一个需要唤醒的线程(有些线程cancel了就不需要唤醒了)
- 被唤醒的线程检查一下自己的前置节点是不是head节点(CLH队列的head节点就是之前拿到锁的线程节点)的下一个节点,如果不是则继续挂起, 如果是的话, 与其他线程重新争夺临界变量,即重复第1步
在AQS的第2步中，如果竞争锁失败的话， 是会使用CAS乐观锁的方式添加到队列尾的, 在并发量非常高的情况下，别线程会在这段代码自旋过久而长期占用CPU, 最终导致CPU告警。
AQS中线程上下文切换
在实际的环境中, 如果临界区的代码执行时间比较短的话，上面AQS的第3、第4步也是会导致CLH队列的线程被频繁唤醒，而又由于抢占锁失败频繁地被挂起. 因此也会带来大量的上下文切换，消耗系统的cpu资源.
