一、常見性能工具
1、top 工具
參考：top命令使用詳解
如何查看 CPU 使用率？說到查看 CPU 使用率的工具，我猜你第一反應(yīng)肯定是 top 和 ps。top 顯示了系統(tǒng)總體的 CPU 和內(nèi)存使用情況，以及各個(gè)進(jìn)程的資源使用情況。ps 則只顯示了每個(gè)進(jìn)程的資源使用情況。
top命令詳解：
# 默認(rèn)每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 當(dāng)前時(shí)間為11點(diǎn)58分59秒，系統(tǒng)持續(xù)運(yùn)行了9天22小時(shí)47分鐘
1 users 當(dāng)前登錄用戶數(shù)
load average: 0.03, 0.02, 0.00 系統(tǒng)負(fù)載, 即任務(wù)隊(duì)列的平均長度, 三個(gè)數(shù)值分別為 1 分鐘, 5 分鐘, 15分鐘前到現(xiàn)在的平均值，數(shù)字越大，表名負(fù)載越大
*/
#詳解 第二行
/*
123 total 當(dāng)前系統(tǒng)正在運(yùn)行的進(jìn)程總數(shù)
1 running 正在運(yùn)行的進(jìn)程數(shù)
72 sleeping 睡眠的進(jìn)程數(shù)
0 stopped 停止的進(jìn)程數(shù)
0 zombie 僵尸的進(jìn)程數(shù)
*/
#詳解 第三行
/*
0.3 us 用戶空間占用 CPU 百分比
0.3 sy 內(nèi)核空間占用 CPU 百分比
0.0 ni 用戶進(jìn)程空間內(nèi)改變過優(yōu)先級(jí)的進(jìn)程占用 CPU 百分比
99.3 id 空閑 CPU 百分比
0.0 wa 等待輸入輸出的 CPU 時(shí)間百分比
0.0 hi 硬中斷 (Hardware IRQ) 占用 CPU 的百分比
0.0 si, 0.0 st 軟中斷 (Software Interrupts) 占用 CPU 百分比
*/
#詳解 第四行
/*
8169348 total 物理內(nèi)存總量
5606884 free 空閑內(nèi)存總量
334640 used 使用的內(nèi)存物理總量
2227824 buff/cache 作為內(nèi)核緩存的內(nèi)存量
*/
#詳解 第五行
/*
0 total 交換區(qū)總量
0 free 空閑的交換區(qū)總量
0 used 使用的交換區(qū)總量
7497908 avail Mem 代表可用于進(jìn)程下一次分配的物理內(nèi)存數(shù)量
*/
#詳解 第七行
/*
PID 進(jìn)程 id
PPID 父進(jìn)程 id
RUSER real user name
UID 進(jìn)程所有者的用戶id
USER 進(jìn)程所有者的用戶名
GROUP 進(jìn)程所有者的組名
PR 優(yōu)先級(jí)
NI nice 值, 負(fù)值表示最高優(yōu)先級(jí), 正值表示低優(yōu)先級(jí)
P 最后使用的CPU, 僅在多 CPU 環(huán)境下有意義
%CPU 上次更新到現(xiàn)在的 CPU 時(shí)間占用百分比
TIME+ 進(jìn)程使用的 CPU 時(shí)間總計(jì), 單位 1/100秒
%MEM 進(jìn)程使用的物理內(nèi)存百分比
VIRT 進(jìn)程使用的虛擬內(nèi)存總量, 單位 kb, VIRT = SWAP + RES
SWAP 進(jìn)程使用的虛擬內(nèi)存中, 被換出的大小 單位 kb
RES 進(jìn)程使用的, 未被換出物理內(nèi)存的的大小, 單位 kb. RES = CODE + DATA
S 進(jìn)程狀態(tài). D = 不可中斷的睡眠狀態(tài), R = 運(yùn)行, S = 睡眠, T = 跟蹤/停止, Z = 僵尸進(jìn)程
...
*/
2、vmstat、pidstat、perf、strace、ps工具
參考：
1、vmstat 命令詳解
2、pidstat 命令詳解
3、perf 命令詳解
4、strace 命令詳解
5、ps 命令詳解
3、工具總結(jié)
b0c67a7196f5ca4cc58f14f959a364ca.jpg
二、CPU性能分析套路
如下圖所示，top、vmstat 和 pidstat 分別提供的重要的 CPU 指標(biāo)，并用虛線表示關(guān)聯(lián)關(guān)系，對(duì)應(yīng)出了性能分析下一步的方向。
這三個(gè)命令，幾乎包含了所有重要的 CPU 性能指標(biāo)，比如：
- 從 top 的輸出可以得到各種 CPU 使用率以及僵尸進(jìn)程和平均負(fù)載等信息
- 從 vmstat 的輸出可以得到上下文切換次數(shù)、中斷次數(shù)、運(yùn)行狀態(tài)和不可中斷狀態(tài)的進(jìn)程數(shù)
- 從 pidstat 的輸出可以得到進(jìn)程的用戶 CPU 使用率、系統(tǒng) CPU 使用率、以及自愿上下文切換和非自愿上下文切換情況。
7a445960a4bc0a58a02e1bc75648aa17.png
例子1
問題現(xiàn)象：當(dāng)發(fā)現(xiàn)top輸出的用戶 CPU 使用率有問題時(shí)，可以跟pidstat的輸出做對(duì)比，觀察是否是某個(gè)進(jìn)程導(dǎo)致的問題
定位思路：找出導(dǎo)致性能問題的進(jìn)程后，就要用進(jìn)程分析工具來分析進(jìn)程的行為，比如使用strace分析系統(tǒng)調(diào)用情況，以及使用perf分析調(diào)用鏈中各級(jí)函數(shù)的執(zhí)行情況例子2
問題現(xiàn)象：top輸出的平均負(fù)載升高，可以跟vmstat輸出的運(yùn)行狀態(tài)和不可中斷狀態(tài)的進(jìn)程數(shù)做對(duì)比，觀察是哪種進(jìn)程導(dǎo)致的負(fù)載升高
定位思路：如果是不可中斷進(jìn)程數(shù)增多了，那么就需要做 I/O 的分析，也就是用dstat或sar等工具，進(jìn)一步分析 I/O 的情況
如果是運(yùn)行狀態(tài)進(jìn)程數(shù)增多了，那就需要回到top和pidstat，找出這些處于運(yùn)行狀態(tài)的到底是什么進(jìn)程，然后再用perf、strace、ps等進(jìn)程分析工具做進(jìn)一步分析例子3
問題現(xiàn)象：當(dāng)發(fā)現(xiàn)top輸出的軟中斷 CPU 使用率升高時(shí)，可以查看/proc/softirqs文件中各種類型軟中斷的變化情況，確定到底是哪種軟中斷出的問題
定位思路：例如，發(fā)現(xiàn)是網(wǎng)絡(luò)接收中斷導(dǎo)致的問題，那就可以繼續(xù)用網(wǎng)絡(luò)分析工具sar和tcpdump來分析
三、CPU性能分析案例
問題現(xiàn)象1：Java自研微服務(wù)重構(gòu)后容器掛了
Java自研微服務(wù)新增全量檢索表的緩存
$ 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
# 這兒會(huì)阻塞一會(huì)
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” 的錯(cuò)誤，說明 mytomcat 服務(wù)，并不能正常響應(yīng)客戶端請求
$ 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
# 容器已經(jīng)處于 exited 狀態(tài)，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 的輸出，你就可以看到很詳細(xì)的 OOM 記錄了。你應(yīng)該可以看到下面幾個(gè)關(guān)鍵點(diǎn)。
- 第一，被殺死的是一個(gè) java 進(jìn)程。從內(nèi)核調(diào)用棧上的
mem_cgroup_out_of_memory可以看出，它是因?yàn)槌^ cgroup 的內(nèi)存限制，而被 OOM 殺死的。 - 第二，java 進(jìn)程是在容器內(nèi)運(yùn)行的，而容器內(nèi)存的使用量和限制都是 512M（524288kB）。目前使用量已經(jīng)達(dá)到了限制，所以會(huì)導(dǎo)致 OOM。
- 第三，被殺死的進(jìn)程，PID 為 27281，虛擬內(nèi)存為 4.3G（total-vm:4613208kB），匿名內(nèi)存為 505M（anon-rss:517316kB），頁內(nèi)存為 19M（20168kB）。換句話說，匿名內(nèi)存是主要的內(nèi)存占用。而且，匿名內(nèi)存加上頁內(nèi)存，總共是 524M，已經(jīng)超過了 512M 的限制。
# 重新啟動(dòng)容器
$ docker rm -f mytomcat
$ docker run --name mytomcat --cpus 0.1 -m 512M -p 8080:8080 -itd feisky/tomcat:8
# 查看堆內(nèi)存，注意單位是字節(jié)
$ 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
# 容器內(nèi)部看到的內(nèi)存，仍是主機(jī)內(nèi)存，因此需要JVM 內(nèi)存限制為 512M 就可以
# 刪除問題容器
$ docker rm -f mytomcat
# 運(yùn)行新的容器
$ docker run --name mytomcat --cpus 0.1 -m 512M -e JAVA_OPTS='-Xmx512m -Xms512m' -p 8080:8080 -itd feisky/tomcat:8
問題現(xiàn)象2：Java自研微服務(wù)重構(gòu)后容器啟動(dòng)變得很慢
Java自研微服務(wù)新增線程池并且初始線程數(shù)設(shè)置8，容器啟動(dòng)時(shí)間從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
# 從系統(tǒng)整體來看，兩個(gè) CPU 的使用率分別是 3% 和 5.7% ，都不算高，大部分還是空閑的；可用內(nèi)存還有 7GB（7353652 avail Mem），也非常充足.。具體到進(jìn)程上，java 進(jìn)程的 CPU 使用率為 10%，內(nèi)存使用 0.9%，其他進(jìn)程就都很低了
# -t表示顯示線程，-p指定進(jìn)程號(hào)
$ 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
# 這時(shí)候容器啟動(dòng)已經(jīng)結(jié)束了，在沒有客戶端請求的情況下，Tomcat 本身啥也不用做，CPU 使用率當(dāng)然是 0，為了分析啟動(dòng)過程中的問題，我們需要再次重啟容器
# 刪除舊容器
$ docker rm -f mytomcat
# 運(yùn)行新容器
$ docker run --name mytomcat --cpus 0.1 -m 512M -e JAVA_OPTS='-Xmx512m -Xms512m' -p 8080:8080 -itd feisky/tomcat:8
# 查詢新容器中進(jìn)程的Pid
$ PID=$(docker inspect tomcat -f '{{.State.Pid}}')
# 執(zhí)行 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）很低，但等待運(yùn)行的使用率（%wait）卻非常高，最高甚至已經(jīng)達(dá)到了 97%。這說明，這些線程大部分時(shí)間都在等待調(diào)度，而不是真正的運(yùn)行
# 2、用 --cpus 0.1 ，為容器設(shè)置了 0.1 個(gè) CPU 的限制，也就是 10% 的 CPU。這里也就可以解釋，為什么 java 進(jìn)程只有 10% 的 CPU 使用率，也會(huì)大部分時(shí)間都在等待了，因此解決方案是增加CPU到1
# 刪除舊容器
$ docker rm -f mytomcat
# 運(yùn)行新容器
$ 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 的啟動(dòng)過程只需要 10 秒就完成了，果然快了20 秒
