一、常見性能工具

1、top 工具

參考：top命令使用詳解

如何查看 CPU 使用率？說到查看 CPU 使用率的工具，我猜你第一反應(yīng)肯定是 top 和 ps。top 顯示了系統(tǒng)總體的 CPU 和內(nèi)存使用情況，以及各個進程的資源使用情況。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秒，系統(tǒng)持續(xù)運行了9天22小時47分鐘
1 users 當前登錄用戶數(shù)
load average: 0.03, 0.02, 0.00  系統(tǒng)負載, 即任務(wù)隊列的平均長度, 三個數(shù)值分別為 1 分鐘, 5 分鐘, 15分鐘前到現(xiàn)在的平均值，數(shù)字越大，表名負載越大
*/

#詳解 第二行
/*
123 total   當前系統(tǒng)正在運行的進程總數(shù)
1 running   正在運行的進程數(shù)
72 sleeping 睡眠的進程數(shù)
0 stopped   停止的進程數(shù)
0 zombie    僵尸的進程數(shù)
*/

#詳解 第三行
/*
0.3 us  用戶空間占用 CPU 百分比
0.3 sy  內(nèi)核空間占用 CPU 百分比
0.0 ni  用戶進程空間內(nèi)改變過優(yōu)先級的進程占用 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   物理內(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   代表可用于進程下一次分配的物理內(nèi)存數(shù)量
*/

#詳解 第七行
/*
PID 進程 id
PPID    父進程 id
RUSER   real user name
UID 進程所有者的用戶id
USER    進程所有者的用戶名
GROUP   進程所有者的組名
PR  優(yōu)先級
NI  nice 值, 負值表示最高優(yōu)先級, 正值表示低優(yōu)先級
P   最后使用的CPU, 僅在多 CPU 環(huán)境下有意義
%CPU    上次更新到現(xiàn)在的 CPU 時間占用百分比
TIME+   進程使用的 CPU 時間總計, 單位 1/100秒
%MEM    進程使用的物理內(nèi)存百分比
VIRT    進程使用的虛擬內(nèi)存總量, 單位 kb, VIRT = SWAP + RES
SWAP    進程使用的虛擬內(nèi)存中, 被換出的大小 單位 kb
RES 進程使用的, 未被換出物理內(nèi)存的的大小, 單位 kb. RES = CODE + DATA
S   進程狀態(tài). D = 不可中斷的睡眠狀態(tài), R = 運行, S = 睡眠, T = 跟蹤/停止, Z = 僵尸進程
...
*/

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 指標，并用虛線表示關(guān)聯(lián)關(guān)系，對應(yīng)出了性能分析下一步的方向。
這三個命令，幾乎包含了所有重要的 CPU 性能指標，比如：

• 從 top 的輸出可以得到各種 CPU 使用率以及僵尸進程和平均負載等信息
• 從 vmstat 的輸出可以得到上下文切換次數(shù)、中斷次數(shù)、運行狀態(tài)和不可中斷狀態(tài)的進程數(shù)
• 從 pidstat 的輸出可以得到進程的用戶 CPU 使用率、系統(tǒng) CPU 使用率、以及自愿上下文切換和非自愿上下文切換情況。

7a445960a4bc0a58a02e1bc75648aa17.png

• 例子1
  問題現(xiàn)象：當發(fā)現(xiàn) top 輸出的用戶 CPU 使用率有問題時，可以跟 pidstat 的輸出做對比，觀察是否是某個進程導致的問題
  定位思路：找出導致性能問題的進程后，就要用進程分析工具來分析進程的行為，比如使用 strace 分析系統(tǒng)調(diào)用情況，以及使用 perf 分析調(diào)用鏈中各級函數(shù)的執(zhí)行情況

• 例子2
  問題現(xiàn)象：top 輸出的平均負載升高，可以跟 vmstat 輸出的運行狀態(tài)和不可中斷狀態(tài)的進程數(shù)做對比，觀察是哪種進程導致的負載升高
  定位思路：如果是不可中斷進程數(shù)增多了，那么就需要做 I/O 的分析，也就是用 dstat 或 sar 等工具，進一步分析 I/O 的情況
  如果是運行狀態(tài)進程數(shù)增多了，那就需要回到 top 和 pidstat，找出這些處于運行狀態(tài)的到底是什么進程，然后再用perf、strace、ps等進程分析工具做進一步分析

• 例子3
  問題現(xiàn)象：當發(fā)現(xiàn) top 輸出的軟中斷 CPU 使用率升高時，可以查看 /proc/softirqs 文件中各種類型軟中斷的變化情況，確定到底是哪種軟中斷出的問題
  定位思路：例如，發(fā)現(xiàn)是網(wǎng)絡(luò)接收中斷導致的問題，那就可以繼續(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
# 這兒會阻塞一會
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 服務(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 的輸出，你就可以看到很詳細的 OOM 記錄了。你應(yīng)該可以看到下面幾個關(guān)鍵點。

• 第一，被殺死的是一個 java 進程。從內(nèi)核調(diào)用棧上的 mem_cgroup_out_of_memory 可以看出，它是因為超過 cgroup 的內(nèi)存限制，而被 OOM 殺死的。
• 第二，java 進程是在容器內(nèi)運行的，而容器內(nèi)存的使用量和限制都是 512M（524288kB）。目前使用量已經(jīng)達到了限制，所以會導致 OOM。
• 第三，被殺死的進程，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 的限制。

# 重新啟動容器
$ 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)存，仍是主機內(nèi)存，因此需要JVM 內(nèi)存限制為 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

問題現(xiàn)象2：Java自研微服務(wù)重構(gòu)后容器啟動變得很慢

Java自研微服務(wù)新增線程池并且初始線程數(shù)設(shè)置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
# 從系統(tǒng)整體來看，兩個 CPU 的使用率分別是 3% 和 5.7% ，都不算高，大部分還是空閑的；可用內(nèi)存還有 7GB（7353652 avail Mem），也非常充足.。具體到進程上，java 進程的 CPU 使用率為 10%，內(nèi)存使用 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
# 這時候容器啟動已經(jīng)結(jié)束了，在沒有客戶端請求的情況下，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}}')
# 執(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）很低，但等待運行的使用率（%wait）卻非常高，最高甚至已經(jīng)達到了 97%。這說明，這些線程大部分時間都在等待調(diào)度，而不是真正的運行
# 2、用 --cpus 0.1 ，為容器設(shè)置了 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 秒