一、常见性能工具
1、top 工具
参考：top命令使用详解
如何查看 CPU 使用率？说到查看 CPU 使用率的工具，我猜你第一反应肯定是 top 和 ps。top 显示了系统总体的 CPU 和内存使用情况，以及各个进程的资源使用情况。ps 则只显示了每个进程的资源使用情况。
top命令详解：
# 默认每3秒刷新一次
$ top
top - 11:58:59 up 9 days, 22:47, 1 user, load average: 0.03, 0.02, 0.00 #第一行
Tasks: 123 total, 1 running, 72 sleeping, 0 stopped, 0 zombie #第二行
%Cpu(s): 0.3 us, 0.3 sy, 0.0 ni, 99.3 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st #第三行
KiB Mem : 8169348 total, 5606884 free, 334640 used, 2227824 buff/cache #第四行
KiB Swap: 0 total, 0 free, 0 used. 7497908 avail Mem #第五行
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND #第七行
1 root 20 0 78088 9288 6696 S 0.0 0.1 0:16.83 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.05 kthreadd
4 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/0:0H
#详解 第一行
/*
11:58:59 up 9 days, 22:47 当前时间为11点58分59秒，系统持续运行了9天22小时47分钟
1 users 当前登录用户数
load average: 0.03, 0.02, 0.00 系统负载, 即任务队列的平均长度, 三个数值分别为 1 分钟, 5 分钟, 15分钟前到现在的平均值，数字越大，表名负载越大
*/
#详解 第二行
/*
123 total 当前系统正在运行的进程总数
1 running 正在运行的进程数
72 sleeping 睡眠的进程数
0 stopped 停止的进程数
0 zombie 僵尸的进程数
*/
#详解 第三行
/*
0.3 us 用户空间占用 CPU 百分比
0.3 sy 内核空间占用 CPU 百分比
0.0 ni 用户进程空间内改变过优先级的进程占用 CPU 百分比
99.3 id 空闲 CPU 百分比
0.0 wa 等待输入输出的 CPU 时间百分比
0.0 hi 硬中断 (Hardware IRQ) 占用 CPU 的百分比
0.0 si, 0.0 st 软中断 (Software Interrupts) 占用 CPU 百分比
*/
#详解 第四行
/*
8169348 total 物理内存总量
5606884 free 空闲内存总量
334640 used 使用的内存物理总量
2227824 buff/cache 作为内核缓存的内存量
*/
#详解 第五行
/*
0 total 交换区总量
0 free 空闲的交换区总量
0 used 使用的交换区总量
7497908 avail Mem 代表可用于进程下一次分配的物理内存数量
*/
#详解 第七行
/*
PID 进程 id
PPID 父进程 id
RUSER real user name
UID 进程所有者的用户id
USER 进程所有者的用户名
GROUP 进程所有者的组名
PR 优先级
NI nice 值, 负值表示最高优先级, 正值表示低优先级
P 最后使用的CPU, 仅在多 CPU 环境下有意义
%CPU 上次更新到现在的 CPU 时间占用百分比
TIME+ 进程使用的 CPU 时间总计, 单位 1/100秒
%MEM 进程使用的物理内存百分比
VIRT 进程使用的虚拟内存总量, 单位 kb, VIRT = SWAP + RES
SWAP 进程使用的虚拟内存中, 被换出的大小 单位 kb
RES 进程使用的, 未被换出物理内存的的大小, 单位 kb. RES = CODE + DATA
S 进程状态. D = 不可中断的睡眠状态, R = 运行, S = 睡眠, T = 跟踪/停止, Z = 僵尸进程
...
*/
2、vmstat、pidstat、perf、strace、ps工具
参考：
1、vmstat 命令详解
2、pidstat 命令详解
3、perf 命令详解
4、strace 命令详解
5、ps 命令详解
3、工具总结
b0c67a7196f5ca4cc58f14f959a364ca.jpg
二、CPU性能分析套路
如下图所示，top、vmstat 和 pidstat 分别提供的重要的 CPU 指标，并用虚线表示关联关系，对应出了性能分析下一步的方向。
这三个命令，几乎包含了所有重要的 CPU 性能指标，比如：
- 从 top 的输出可以得到各种 CPU 使用率以及僵尸进程和平均负载等信息
- 从 vmstat 的输出可以得到上下文切换次数、中断次数、运行状态和不可中断状态的进程数
- 从 pidstat 的输出可以得到进程的用户 CPU 使用率、系统 CPU 使用率、以及自愿上下文切换和非自愿上下文切换情况。
7a445960a4bc0a58a02e1bc75648aa17.png
例子1
问题现象：当发现top输出的用户 CPU 使用率有问题时，可以跟pidstat的输出做对比，观察是否是某个进程导致的问题
定位思路：找出导致性能问题的进程后，就要用进程分析工具来分析进程的行为，比如使用strace分析系统调用情况，以及使用perf分析调用链中各级函数的执行情况例子2
问题现象：top输出的平均负载升高，可以跟vmstat输出的运行状态和不可中断状态的进程数做对比，观察是哪种进程导致的负载升高
定位思路：如果是不可中断进程数增多了，那么就需要做 I/O 的分析，也就是用dstat或sar等工具，进一步分析 I/O 的情况
如果是运行状态进程数增多了，那就需要回到top和pidstat，找出这些处于运行状态的到底是什么进程，然后再用perf、strace、ps等进程分析工具做进一步分析例子3
问题现象：当发现top输出的软中断 CPU 使用率升高时，可以查看/proc/softirqs文件中各种类型软中断的变化情况，确定到底是哪种软中断出的问题
定位思路：例如，发现是网络接收中断导致的问题，那就可以继续用网络分析工具sar和tcpdump来分析
三、CPU性能分析案例
问题现象1：Java自研微服务重构后容器挂了
Java自研微服务新增全量检索表的缓存
$ docker run --name mytomcat --cpus 0.1 -m 512M -p 8080:8080 -itd feisky/tomcat:8
Unable to find image 'feisky/tomcat:8' locally
8: Pulling from feisky/tomcat
741437d97401: Pull complete
...
22cd96a25579: Pull complete
Digest: sha256:71871cff17b9043842c2ec99f370cc9f1de7bc121cd2c02d8e2092c6e268f7e2
Status: Downloaded newer image for feisky/tomcat:8
WARNING: Your kernel does not support swap limit capabilities or the cgroup is not mounted. Memory limited without swap.
2df259b752db334d96da26f19166d662a82283057411f6332f3cbdbcab452249
$ curl localhost:8080
curl: (56) Recv failure: Connection reset by peer
# 这儿会阻塞一会
Hello, wolrd!
curl: (52) Empty reply from server
curl: (7) Failed to connect to localhost port 8080: Connection refused
curl: (7) Failed to connect to localhost port 8080: Connection refused
#curl 返回了 “Connection reset by peer” 的错误，说明 mytomcat 服务，并不能正常响应客户端请求
$ docker logs -f tomcat
Using CATALINA_BASE: /usr/local/tomcat
Using CATALINA_HOME: /usr/local/tomcat
Using CATALINA_TMPDIR: /usr/local/tomcat/temp
Using JRE_HOME: /docker-java-home/jre
Using CLASSPATH: /usr/local/tomcat/bin/bootstrap.jar:/usr/local/tomcat/bin/tomcat-juli.jar
18-Feb-2019 12:43:32.719 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/docs]
18-Feb-2019 12:43:33.725 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/docs] has finished in [1,006] ms
18-Feb-2019 12:43:33.726 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [/usr/local/tomcat/webapps/manager]
18-Feb-2019 12:43:34.521 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory [/usr/local/tomcat/webapps/manager] has finished in [795] ms
18-Feb-2019 12:43:34.722 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
18-Feb-2019 12:43:35.319 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
18-Feb-2019 12:43:35.821 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 24096 ms
$ docker ps -a
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
0f2b3fcdd257 feisky/tomcat:8 "catalina.sh run" 2 minutes ago Exited (137) About a minute ago mytomcat
# 容器已经处于 exited 状态，OOMKilled 是 true，ExitCode 是 137
$ dmesg
[193038.106393] java invoked oom-killer: gfp_mask=0x14000c0(GFP_KERNEL), nodemask=(null), order=0, oom_score_adj=0
[193038.106396] java cpuset=0f2b3fcdd2578165ea77266cdc7b1ad43e75877b0ac1889ecda30a78cb78bd53 mems_allowed=0
[193038.106402] CPU: 0 PID: 27424 Comm: java Tainted: G OE 4.15.0-1037 #39-Ubuntu
[193038.106404] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS 090007 06/02/2017
[193038.106405] Call Trace:
[193038.106414] dump_stack+0x63/0x89
[193038.106419] dump_header+0x71/0x285
[193038.106422] oom_kill_process+0x220/0x440
[193038.106424] out_of_memory+0x2d1/0x4f0
[193038.106429] mem_cgroup_out_of_memory+0x4b/0x80
[193038.106432] mem_cgroup_oom_synchronize+0x2e8/0x320
[193038.106435] ? mem_cgroup_css_online+0x40/0x40
[193038.106437] pagefault_out_of_memory+0x36/0x7b
[193038.106443] mm_fault_error+0x90/0x180
[193038.106445] __do_page_fault+0x4a5/0x4d0
[193038.106448] do_page_fault+0x2e/0xe0
[193038.106454] ? page_fault+0x2f/0x50
[193038.106456] page_fault+0x45/0x50
[193038.106459] RIP: 0033:0x7fa053e5a20d
[193038.106460] RSP: 002b:00007fa0060159e8 EFLAGS: 00010206
[193038.106462] RAX: 0000000000000000 RBX: 00007fa04c4b3000 RCX: 0000000009187440
[193038.106463] RDX: 00000000943aa440 RSI: 0000000000000000 RDI: 000000009b223000
[193038.106464] RBP: 00007fa006015a60 R08: 0000000002000002 R09: 00007fa053d0a8a1
[193038.106465] R10: 00007fa04c018b80 R11: 0000000000000206 R12: 0000000100000768
[193038.106466] R13: 00007fa04c4b3000 R14: 0000000100000768 R15: 0000000010000000
[193038.106468] Task in /docker/0f2b3fcdd2578165ea77266cdc7b1ad43e75877b0ac1889ecda30a78cb78bd53 killed as a result of limit of /docker/0f2b3fcdd2578165ea77266cdc7b1ad43e75877b0ac1889ecda30a78cb78bd53
[193038.106478] memory: usage 524288kB, limit 524288kB, failcnt 77
[193038.106480] memory+swap: usage 0kB, limit 9007199254740988kB, failcnt 0
[193038.106481] kmem: usage 3708kB, limit 9007199254740988kB, failcnt 0
[193038.106481] Memory cgroup stats for /docker/0f2b3fcdd2578165ea77266cdc7b1ad43e75877b0ac1889ecda30a78cb78bd53: cache:0KB rss:520580KB rss_huge:450560KB shmem:0KB mapped_file:0KB dirty:0KB writeback:0KB inactive_anon:0KB active_anon:520580KB inactive_file:0KB active_file:0KB unevictable:0KB
[193038.106494] [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name
[193038.106571] [27281] 0 27281 1153302 134371 1466368 0 0 java
[193038.106574] Memory cgroup out of memory: Kill process 27281 (java) score 1027 or sacrifice child
[193038.148334] Killed process 27281 (java) total-vm:4613208kB, anon-rss:517316kB, file-rss:20168kB, shmem-rss:0kB
[193039.607503] oom_reaper: reaped process 27281 (java), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
从 dmesg 的输出，你就可以看到很详细的 OOM 记录了。你应该可以看到下面几个关键点。
- 第一，被杀死的是一个 java 进程。从内核调用栈上的
mem_cgroup_out_of_memory可以看出，它是因为超过 cgroup 的内存限制，而被 OOM 杀死的。 - 第二，java 进程是在容器内运行的，而容器内存的使用量和限制都是 512M（524288kB）。目前使用量已经达到了限制，所以会导致 OOM。
- 第三，被杀死的进程，PID 为 27281，虚拟内存为 4.3G（total-vm:4613208kB），匿名内存为 505M（anon-rss:517316kB），页内存为 19M（20168kB）。换句话说，匿名内存是主要的内存占用。而且，匿名内存加上页内存，总共是 524M，已经超过了 512M 的限制。
# 重新启动容器
$ docker rm -f mytomcat
$ docker run --name mytomcat --cpus 0.1 -m 512M -p 8080:8080 -itd feisky/tomcat:8
# 查看堆内存，注意单位是字节
$ docker exec mytomcat java -XX:+PrintFlagsFinal -version | grep HeapSize
uintx ErgoHeapSizeLimit = 0 {product}
uintx HeapSizePerGCThread = 87241520 {product}
uintx InitialHeapSize := 132120576 {product}
uintx LargePageHeapSizeThreshold = 134217728 {product}
uintx MaxHeapSize := 2092957696 {product}
$ docker exec mytomcat free -m
total used free shared buff/cache available
Mem: 7977 521 1941 0 5514 7148
Swap: 0 0 0
# 容器内部看到的内存，仍是主机内存，因此需要JVM 内存限制为 512M 就可以
# 删除问题容器
$ docker rm -f mytomcat
# 运行新的容器
$ docker run --name mytomcat --cpus 0.1 -m 512M -e JAVA_OPTS='-Xmx512m -Xms512m' -p 8080:8080 -itd feisky/tomcat:8
问题现象2：Java自研微服务重构后容器启动变得很慢
Java自研微服务新增线程池并且初始线程数设置8，容器启动时间从10秒增加到30秒
$ top
top - 12:57:18 up 2 days, 5:50, 2 users, load average: 0.00, 0.02, 0.00
Tasks: 131 total, 1 running, 74 sleeping, 0 stopped, 0 zombie
%Cpu0 : 3.0 us, 0.3 sy, 0.0 ni, 96.6 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu1 : 5.7 us, 0.3 sy, 0.0 ni, 94.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 8169304 total, 2465984 free, 500812 used, 5202508 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 7353652 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
29457 root 20 0 2791736 73704 19164 S 10.0 0.9 0:01.61 java 27349 root 20 0 1121372 96760 39340 S 0.3 1.2 4:20.82 dockerd
27376 root 20 0 1031760 43768 21680 S 0.3 0.5 2:44.47 docker-containe 29430 root 20 0 7376 3604 3128 S 0.3 0.0 0:00.01 docker-containe
1 root 20 0 78132 9332 6744 S 0.0 0.1 0:16.12 systemd
# 从系统整体来看，两个 CPU 的使用率分别是 3% 和 5.7% ，都不算高，大部分还是空闲的；可用内存还有 7GB（7353652 avail Mem），也非常充足.。具体到进程上，java 进程的 CPU 使用率为 10%，内存使用 0.9%，其他进程就都很低了
# -t表示显示线程，-p指定进程号
$ pidstat -t -p 29457 1
12:59:59 UID TGID TID %usr %system %guest %wait %CPU CPU Command
13:00:00 0 29457 - 0.00 0.00 0.00 0.00 0.00 0 java
13:00:00 0 - 29457 0.00 0.00 0.00 0.00 0.00 0 |__java
13:00:00 0 - 29458 0.00 0.00 0.00 0.00 0.00 1 |__java
...
13:00:00 0 - 29491 0.00 0.00 0.00 0.00 0.00 0 |__java
# 这时候容器启动已经结束了，在没有客户端请求的情况下，Tomcat 本身啥也不用做，CPU 使用率当然是 0，为了分析启动过程中的问题，我们需要再次重启容器
# 删除旧容器
$ docker rm -f mytomcat
# 运行新容器
$ docker run --name mytomcat --cpus 0.1 -m 512M -e JAVA_OPTS='-Xmx512m -Xms512m' -p 8080:8080 -itd feisky/tomcat:8
# 查询新容器中进程的Pid
$ PID=$(docker inspect tomcat -f '{{.State.Pid}}')
# 执行 pidstat
$ pidstat -t -p $PID 1
12:59:28 UID TGID TID %usr %system %guest %wait %CPU CPU Command
12:59:29 0 29850 - 10.00 0.00 0.00 0.00 10.00 0 java
12:59:29 0 - 29850 0.00 0.00 0.00 0.00 0.00 0 |__java
12:59:29 0 - 29897 5.00 1.00 0.00 86.00 6.00 1 |__java
...
12:59:29 0 - 29905 3.00 0.00 0.00 97.00 3.00 0 |__java
12:59:29 0 - 29906 2.00 0.00 0.00 49.00 2.00 1 |__java
12:59:29 0 - 29908 0.00 0.00 0.00 45.00 0.00 0 |__java
# 问题分析：
# 1、虽然 CPU 使用率（%CPU）很低，但等待运行的使用率（%wait）却非常高，最高甚至已经达到了 97%。这说明，这些线程大部分时间都在等待调度，而不是真正的运行
# 2、用 --cpus 0.1 ，为容器设置了 0.1 个 CPU 的限制，也就是 10% 的 CPU。这里也就可以解释，为什么 java 进程只有 10% 的 CPU 使用率，也会大部分时间都在等待了，因此解决方案是增加CPU到1
# 删除旧容器
$ docker rm -f mytomcat
# 运行新容器
$ docker run --name mytomcat--cpus 1 -m 512M -e JAVA_OPTS='-Xmx512m -Xms512m' -p 8080:8080 -itd feisky/tomcat:8
# 查看容器日志
$ docker logs -f mytomcat
...
18-Feb-2019 12:54:02.139 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 10001 ms
#Tomcat 的启动过程只需要 10 秒就完成了，果然快了20 秒
