一、現(xiàn)象
業(yè)務(wù)線反饋,單板只要一跑我們的通訊軟件appA,CPU就變得很高,即使沒(méi)有任何通訊,空跑時(shí)CPU利用率同樣的高,難得業(yè)務(wù)會(huì)關(guān)注CPU性能,好久沒(méi)更新博客了,小記一下(又是debug一兩天,最后改一行代碼解決的問(wèn)題o(╯□╰)o)。
啟動(dòng)appA?前,top看一下CPU使用情況,如下,9%還算正常(有其他業(yè)務(wù)應(yīng)用)。
?
Mem: 49320K used, 202284K free, 0K shrd, 0K buff, 27420K cached CPU: 3.0% usr 6.0% sys 0.0% nic 91.0% idle 0.0% io 0.0% irq 0.0% sirq Load average: 1.79 2.79 2.98 1/86 1721 PID PPID USER STAT VSZ %VSZ CPU %CPU COMMAND 1721 1376 root R 2272 0.9 0 1.6 top -d 1 917 1 root S 38936 15.4 0 1.1 ... 908 1 root S 38936 15.4 0 0.5 ... 915 1 root S 38936 15.4 0 0.5 ... 896 1 root S 38936 15.4 0 0.5 ... 914 1 root S 38936 15.4 0 0.5 ... 857 1 root S 4396 1.7 0 0.5 /usr/sbin/telnetd 3 2 root SW 0 0.0 0 0.5 [ksoftirqd/0] 1376 857 root S 2272 0.9 0 0.0 -sh 929 1 root S 2272 0.9 0 0.0 /sbin/getty -L ttyO2 115200 vt100 1 0 root S 2268 0.9 0 0.0 init ...
?
我們的應(yīng)用啟動(dòng)后,CPU使用率很高,65%左右,是什么讓CPU占用高?
?
$top -d1 Mem: 54604K used, 197000K free, 0K shrd, 0K buff, 27220K cached CPU: 14.6% usr 38.5% sys 0.0% nic 36.2% idle 0.0% io 0.0% irq 10.5% sirq Load average: 3.26 2.22 1.58 1/107 1470 PID PPID USER STAT VSZ %VSZ CPU %CPU COMMAND 1444 1376 root S 28008 11.1 0 5.8 {Thread_start} ./appA 3 2 root SW 0 0.0 0 4.0 [ksoftirqd/0] 1445 1376 root S 28008 11.1 0 2.9 {Task_OS_Timer} ./appA 1470 1376 root R 2272 0.9 0 2.3 top -d 1 917 1 root S 38936 15.4 0 1.7 ... 1450 1376 root S 28008 11.1 0 1.7 ... 896 1 root S 38936 15.4 0 1.1 ... 1449 1376 root S 28008 11.1 0 0.5 {CycleIO} ./appA 857 1 root S 4396 1.7 0 0.5 /usr/sbin/telnetd ......
?
TOP各指標(biāo)含義
簡(jiǎn)單介紹下top各指標(biāo)含義。top 命令顯示了 us、sy、nic、idle 、io、hi、si 和 st 這幾個(gè)指標(biāo)(不同版本的top顯示簡(jiǎn)寫有所不同),各指標(biāo)含義如下,這幾個(gè)指標(biāo)之和為 100。
?
us, user : time running un-niced user processes sy, system : time running kernel processes ni, nice : time running niced user processes id, idle : time spent in the kernel idle handler wa, IO-wait : time waiting for I/O completion hi : time spent servicing hardware interrupts si : time spent servicing software interrupts st : time stolen from this vm by the hypervisor
?
CPU指標(biāo) | 含義 |
---|---|
us | CPU執(zhí)行用戶代碼消耗的CPU時(shí)間比例,這個(gè)比例越高,說(shuō)明CPU的利用率越好,因?yàn)槲覀兊哪康木褪菫榱俗孋PU將更多的時(shí)間用在執(zhí)行用戶代碼上,如果這個(gè)指標(biāo)過(guò)高影響了你的業(yè)務(wù),那就需要去分析業(yè)務(wù)代碼了。 |
sy | CPU執(zhí)行內(nèi)核代碼消耗的CPU時(shí)間比例,這個(gè)比例要越低越好,因?yàn)镃PU不應(yīng)該把時(shí)間浪費(fèi)在執(zhí)行內(nèi)核函數(shù)上,如內(nèi)核函數(shù)浪費(fèi)了很多時(shí)間,那說(shuō)明內(nèi)核可能需要優(yōu)化了。 |
ni |
Nice值被調(diào)大的線程執(zhí)行用戶態(tài)代碼消耗的CPU百分比。對(duì)于非實(shí)時(shí)任務(wù),通過(guò)調(diào)整線程的Nice值可以控制它的CPU時(shí)間,當(dāng)我們?cè)龃笠粋€(gè)線程的Nice值時(shí),我們期望它可以少占用一些CPU時(shí)間,CPU利用率里的ni這個(gè)值就給我們一個(gè)參考指標(biāo)來(lái)觀察我們的調(diào)整效果。 運(yùn)行一個(gè)進(jìn)程后,它的默認(rèn)Nice值為0,通過(guò)renice來(lái)增加該進(jìn)程的Nice值(正數(shù)),該進(jìn)程的CPU利用率就會(huì)在ni中顯示,而減少進(jìn)程的Nice值(負(fù)數(shù))則不會(huì)在這里面顯示。 |
id | CPU空閑時(shí)間,我們通常說(shuō)的整體CPU利用率就是(100-idl)這個(gè)值,也是其他幾項(xiàng)的和。為了提升系統(tǒng)的資源利用率,目標(biāo)就是盡量降低idl。 |
wa | CPU阻塞在I/O上的時(shí)間,比如CPU從磁盤讀取文件內(nèi)容,由于磁盤I/O太慢,導(dǎo)致CPU不得不等待數(shù)據(jù)就緒,然后才能繼續(xù)執(zhí)行下一步操作,這就wai時(shí)間,這個(gè)值越高,說(shuō)明I/O處理能力出現(xiàn)了問(wèn)題。 |
hi | CPU消耗在硬中斷里的時(shí)間,正常情況下這個(gè)值都很低,因?yàn)橹袛嗟奶幚砗芸?,即使有大量?a href="http://www.wenjunhu.com/v/tag/1751/" target="_blank">硬件中斷,也不會(huì)消耗很多的CPU時(shí)間。 |
si | CPU消耗在軟中斷里的時(shí)間,系統(tǒng)中常見的軟中斷有網(wǎng)絡(luò)收發(fā)包軟中斷、寫文件落盤產(chǎn)生的軟中斷、高精度定時(shí)器軟中斷等。所以網(wǎng)絡(luò)吞吐量較高的系統(tǒng)中,這個(gè)值也會(huì)高一些。 |
在上面這幾項(xiàng)中,idle 和 wait 是 CPU 不工作的時(shí)間,其余的項(xiàng)都是 CPU 工作的時(shí)間。idle 和 wait 的主要區(qū)別是,idle 是 CPU 無(wú)事可做,而 wait 則是 CPU 想做事卻做不了。你也可以將 wait 理解為是一類特殊的 idle,即該 CPU 上有至少一個(gè)線程阻塞在 I/O 時(shí)的 idle。
二、分析
由CPU: 14.6% usr 38.5% sys 0.0% nic 36.2% idle 0.0% io 0.0% irq 10.5% sirq可以看出,CPU 利用率飆高是由 sys 利用率和sirq利用率變高導(dǎo)致的,也就是說(shuō) sys 利用率會(huì)忽然飆高一下,比如在 usr 低于 15% 的情況下,sys 會(huì)高于 40%,同時(shí)sirq會(huì)高于10%,持續(xù)不到一秒后又恢復(fù)正常。
CPU 的 sys 利用率高,說(shuō)明內(nèi)核函數(shù)執(zhí)行花費(fèi)了太多的時(shí)間,同樣,CPU 的 sirq利用率高,說(shuō)明內(nèi)核處理軟中斷執(zhí)行花費(fèi)了太多的時(shí)間,先對(duì)比應(yīng)用啟動(dòng)前后系統(tǒng)各部分信息,看看能否推斷出CPU執(zhí)行哪部分的的內(nèi)核函數(shù)花費(fèi)的時(shí)間長(zhǎng)。
啟動(dòng)應(yīng)用前
我們先通過(guò)pidstat看看appA啟動(dòng)前,系統(tǒng)中每個(gè)進(jìn)程usr、system、guest、wait各部分CPU使用情況:
?
$ pidstat 1 3 #每秒打印一次 打印3次 Linux 3.12.10 08/22/22 _armv7l_ (1 CPU) 0944 UID PID %usr %system %guest %wait %CPU CPU Command 0944 0 47 0.00 0.96 0.00 0.00 0.96 0 kworker/0:1 0944 0 894 2.88 3.85 0.00 0.00 6.73 0 cpu_mem_task 0944 0 968 0.00 1.92 0.00 0.00 1.92 0 pidstat 0944 UID PID %usr %system %guest %wait %CPU CPU Command 0945 0 857 0.00 1.00 0.00 0.00 1.00 0 telnetd 0945 0 881 0.00 1.00 0.00 0.00 1.00 0 xxxx 0945 0 894 2.00 5.00 0.00 0.00 7.00 0 xxxx 0945 0 968 1.00 2.00 0.00 0.00 3.00 0 pidstat 0945 UID PID %usr %system %guest %wait %CPU CPU Command 0946 0 3 0.00 1.00 0.00 0.00 1.00 0 ksoftirqd/0 0946 0 894 1.00 6.00 0.00 0.00 7.00 0 xxxx 0946 0 968 1.00 2.00 0.00 0.00 3.00 0 pidstat
?
可以看到,各進(jìn)程正常,CPU使用率低,接下來(lái)通過(guò)mpstat查看內(nèi)核各部分詳細(xì)。
?
]# mpstat --help Usage: mpstat [ options ] [[ ] ] Options are: [ -A ] [ -n ] [ -T ] [ -u ] [ -V ] [ -I { SUM | CPU | SCPU | ALL } ] [ -N { | ALL } ] [ --dec={ 0 | 1 | 2 } ] [ -o JSON ] [ -P { | ALL } ]
?
-A: 等同于-u -I ALL -P ALL
-I:指定SUM CPU SCPU ALL四個(gè)參數(shù),SUM表示每個(gè)處理器的中斷總數(shù),CPU表示每個(gè)核的每秒中斷數(shù)量, SCPU表示每個(gè)核每秒的軟中斷數(shù)量。
-P: 統(tǒng)計(jì)的CPU編號(hào),一般用ALL
-u: 輸出列的信息
-V: 查看版本號(hào)
CPU利用率
每秒輸出1次, 輸出5次:
?
[root@/tmp]# mpstat 1 5 0951 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle 0952 all 1.01 0.00 5.05 0.00 0.00 2.02 0.00 0.00 0.00 91.92 0953 all 2.15 0.00 1.08 0.00 0.00 0.00 0.00 0.00 0.00 96.77 0954 all 0.00 0.00 0.00 0.00 0.00 1.09 0.00 0.00 0.00 98.91 0955 all 2.04 0.00 3.06 0.00 0.00 2.04 0.00 0.00 0.00 92.86 0956 all 0.00 0.00 2.15 0.00 0.00 0.00 0.00 0.00 0.00 97.85 Average: all 1.05 0.00 2.32 0.00 0.00 1.05 0.00 0.00 0.00 95.58
?
軟中斷
軟中斷每秒輸出1次, 輸出6次:
?
# mpstat -I SCPU 1 6 0922 CPU HI/s TIMER/s NET_TX/s NET_RX/s BLOCK/s BLOCK_IOPOLL/s TASKLET/s SCHED/s HRTIMER/s RCU/s 0923 0 0.00 25.00 1.00 3.00 0.00 0.00 0.00 0.00 200.00 0.00 0924 0 0.00 31.00 0.00 4.00 0.00 0.00 0.00 0.00 200.00 0.00 0925 0 0.00 26.00 0.00 4.00 0.00 0.00 0.00 0.00 199.00 0.00 0926 0 0.00 36.00 0.00 4.00 0.00 0.00 0.00 0.00 200.00 0.00 0927 0 0.00 31.00 0.00 3.00 0.00 0.00 0.00 0.00 199.00 0.00 0928 0 0.00 31.00 1.00 3.00 0.00 0.00 0.00 0.00 200.00 0.00 Average: 0 0.00 30.00 0.33 3.50 0.00 0.00 0.00 0.00 199.67 0.00
?
對(duì)應(yīng)的軟中斷信息:
?
# cat /proc/softirqs CPU0 HI: 0 TIMER: 7778445 NET_TX: 7244 NET_RX: 293406 BLOCK: 0 BLOCK_IOPOLL: 0 TASKLET: 1 SCHED: 0 HRTIMER: 522165833 RCU: 0
?
硬中斷
處理器硬中斷總數(shù):
?
# mpstat -I SUM 1 6 Linux 3.12.10 08/22/22 _armv7l_ (1 CPU) 0950 CPU intr/s 0951 all 3000.00 0952 all 3151.00 0953 all 3229.00 0954 all 3129.00 0955 all 3049.00 0956 all 3210.00 Average: all 3127.79
?
每個(gè)硬中斷產(chǎn)生速率:
?
# mpstat -I CPU 1 6 Linux 3.12.10 08/22/22 _armv7l_ (1 CPU) 0946 CPU 20/s 28/s 30/s 33/s 34/s 35/s 68/s 80/s 84/s 86/s 87/s 90/s 94/s 116/s 125/s 127/s 173/s 230/s 233/s 255/s 261/s Err/s 0947 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 3151.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 5.00 0.00 0.00 0.00 0.00 0.00 0948 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 3140.00 0.00 4.00 0.00 0.00 0.00 0.00 0.00 7.00 0.00 0.00 0.00 0.00 0.00 0949 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 3355.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 6.00 0.00 0.00 0.00 0.00 0.00 0950 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 3031.00 0.00 4.00 0.00 0.00 0.00 0.00 0.00 4.00 0.00 0.00 0.00 0.00 0.00 0951 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 3288.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 6.00 0.00 0.00 0.00 0.00 0.00 0952 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 3155.00 0.00 4.00 0.00 0.00 0.00 0.00 0.00 6.00 0.00 0.00 0.00 0.00 0.00 Average: 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 3186.67 0.00 2.00 0.00 0.00 0.00 0.00 0.00 5.67 0.00 0.00 0.00 0.00 0.00
?
對(duì)應(yīng)的中斷信息:
?
# cat /proc/interrupts CPU0 84: 1583852200 INTC 68 gp_timer 86: 108 INTC 70 44e0b000.i2c 87: 483682 INTC 71 4802a000.i2c 90: 59 INTC 74 UART2 173: 701497 GPIO 29 eth0 230: 6 GPIO 22 button_int 233: 0 GPIO 25 fpga_int 255: 0 GPIO 15 mmc0 261: 0 GPIO 21 power_int Err: 0 ......
?
啟動(dòng)appA應(yīng)用前,可以看出irq為84的中斷gp_timer中斷比較高, 3155次/S左右。
啟動(dòng)應(yīng)用后
先啟動(dòng)應(yīng)用,然后再看一下這些指標(biāo)的變化。
?
# mpstat 1 5 Linux 3.12.10 08/22/22 _armv7l_ (1 CPU) 1045 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle 1046 all 7.95 0.00 18.18 0.00 0.00 3.41 0.00 0.00 0.00 70.45 1047 all 6.17 0.00 16.05 0.00 0.00 1.23 0.00 0.00 0.00 76.54 1048 all 4.94 0.00 17.28 0.00 0.00 2.47 0.00 0.00 0.00 75.31 1049 all 8.05 0.00 17.24 0.00 0.00 4.60 0.00 0.00 0.00 70.11 1050 all 11.76 0.00 12.94 0.00 0.00 2.35 0.00 0.00 0.00 72.94 Average: all 7.82 0.00 16.35 0.00 0.00 2.84 0.00 0.00 0.00 72.99
?
usr,sys 升高明顯,soft有所升高,什么導(dǎo)致的sys升高?下面看硬中斷處理信息:
?
# mpstat -I SUM 1 6 Linux 3.12.10 08/22/22 _armv7l_ (1 CPU) 1011 CPU intr/s 1012 all 6571.00 1013 all 6597.00 1014 all 6574.00 1015 all 6566.00 1016 all 6592.00 1017 all 6583.00 Average: all 6580.50
?
對(duì)比啟動(dòng)應(yīng)用前3000/s,每秒中斷產(chǎn)生次數(shù)增長(zhǎng)了120%。繼續(xù)查看哪些中斷變高了?
?
# mpstat -I CPU 1 6 Linux 3.12.10 08/22/22 _armv7l_ (1 CPU) 1004 CPU 20/s 28/s 30/s 33/s 34/s 35/s 68/s 80/s 84/s 86/s 87/s 90/s 94/s 116/s 125/s 127/s 173/s 230/s 233/s 255/s 261/s Err/s 1005 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 6552.00 0.00 3.00 0.00 0.00 0.00 0.00 0.00 28.00 0.00 0.00 0.00 0.00 0.00 1006 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 6552.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 30.00 0.00 0.00 0.00 0.00 0.00 1007 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 6637.00 0.00 4.00 0.00 0.00 0.00 0.00 0.00 27.00 0.00 0.00 0.00 0.00 0.00 1008 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 6543.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 28.00 0.00 0.00 0.00 0.00 0.00 1010 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 6579.00 0.00 4.00 0.00 0.00 0.00 0.00 0.00 30.00 0.00 0.00 0.00 0.00 0.00 1011 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 6561.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 29.00 0.00 0.00 0.00 0.00 0.00 Average: 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 6570.67 0.00 1.83 0.00 0.00 0.00 0.00 0.00 28.67 0.00 0.00 0.00 0.00 0.00
# mpstat -I SCPU 1 6 Linux 3.12.10 08/22/22 _armv7l_ (1 CPU) 1029 CPU HI/s TIMER/s NET_TX/s NET_RX/s BLOCK/s BLOCK_IOPOLL/s TASKLET/s SCHED/s HRTIMER/s RCU/s 1030 0 0.00 41.58 0.00 9.90 0.00 0.00 0.00 0.00 2172.28 0.00 1031 0 0.00 43.00 0.00 12.00 0.00 0.00 0.00 0.00 2187.00 0.00 1032 0 0.00 38.00 0.00 11.00 0.00 0.00 0.00 0.00 2191.00 0.00 1033 0 0.00 34.00 1.00 10.00 0.00 0.00 0.00 0.00 2190.00 0.00 1034 0 0.00 37.00 0.00 11.00 0.00 0.00 0.00 0.00 2190.00 0.00 1035 0 0.00 40.00 0.00 10.00 0.00 0.00 0.00 0.00 2184.00 0.00 Average: 0 0.00 38.94 0.17 10.65 0.00 0.00 0.00 0.00 2185.69 0.00
?
可以看irq為84的中斷gp_timer中斷相比應(yīng)用啟動(dòng)前變?yōu)?倍,?3155.00次/S左右。相應(yīng)的高精度定時(shí)器軟中斷HRTIMER從之前的200/S上升到2100/S,到此基本可以確定應(yīng)用瘋狂定時(shí)操作引起的,進(jìn)一步看內(nèi)核執(zhí)行的函數(shù)來(lái)確認(rèn)。
采集內(nèi)核函數(shù)的方法
目前基本清楚因?yàn)槎〞r(shí)器中斷變高導(dǎo)致的內(nèi)核函數(shù)執(zhí)行時(shí)間變長(zhǎng),接下來(lái)采集 CPU 在 sys 飆高的瞬間所執(zhí)行的內(nèi)核函數(shù),同時(shí)看看應(yīng)用執(zhí)行什么引起的定時(shí)器中斷,再做相應(yīng)的優(yōu)化。采集內(nèi)核函數(shù)的方法有很多,比如:
通過(guò) perf( perf 是內(nèi)核自帶的性能剖析工具) 可以采集 CPU 的熱點(diǎn),看看 sys 利用率高時(shí),哪些內(nèi)核耗時(shí)的 CPU 利用率高;
通過(guò) perf 的?call-graph?功能可以查看具體的調(diào)用棧信息,也就是線程是從什么路徑上執(zhí)行下來(lái)的;
通過(guò) perf 的?annotate?功能可以追蹤到線程是在內(nèi)核函數(shù)的哪些語(yǔ)句上比較耗時(shí);
通過(guò) ftrace 的?function-graph?功能可以查看這些內(nèi)核函數(shù)的具體耗時(shí),以及在哪個(gè)路徑上耗時(shí)最大。
針對(duì)一些瞬時(shí)sys 利用率高問(wèn)題,還可以通過(guò)系統(tǒng)快照sysrq,把當(dāng)前 CPU 正在做的工作記錄下來(lái),然后結(jié)合內(nèi)核源碼分析為什么 sys 利用率會(huì)高。
sysrq常用來(lái)分析內(nèi)核問(wèn)題的工具,用它可以觀察當(dāng)前的內(nèi)存快照、任務(wù)快照,可以構(gòu)造 vmcore 把系統(tǒng)的所有信息都保存下來(lái),甚至還可以在內(nèi)存緊張的時(shí)候用它殺掉內(nèi)存開銷最大的那個(gè)進(jìn)程。
用 sysrq 來(lái)分析問(wèn)題,首先需要使能 sysyrq,使能sysrq后沒(méi)有任何開銷,使能方式如下:
?
$ sysctl -w kernel.sysrq=1
?
sysrq 的功能被使能后,使用它的 -t 選項(xiàng)來(lái)把當(dāng)前的任務(wù)快照保存下來(lái),看看系統(tǒng)中都有哪些任務(wù),以及這些任務(wù)都在干什么。使用方式如下:
?
$ echo t > /proc/sysrq-trigger
?
執(zhí)行后,任務(wù)快照會(huì)被打印到內(nèi)核緩沖區(qū),這些任務(wù)快照信息通過(guò)?dmesg?命令來(lái)查看:
?
$ dmesg
?
內(nèi)核采集分析
這里使用perf?對(duì)appA進(jìn)程進(jìn)行采樣,輸出內(nèi)核整個(gè)調(diào)用鏈上的匯總信息。
?
# 采樣10s后退出 $ perf record -a -g -p `pidof appA` -- sleep 10
?
采樣完成后,繼續(xù)執(zhí)行?perf report命令,得到 perf 的匯總報(bào)告。
額。。。屏幕太小、ARM 串口來(lái)打印,這打印很難看。
火焰圖分析
針對(duì) perf 匯總數(shù)據(jù)的展示問(wèn)題,Brendan Gragg 發(fā)明了火焰圖,通過(guò)矢量圖的形式,更直觀展示匯總結(jié)果。
(圖片來(lái)自 Brendan Gregg?博客)
橫軸表示采樣數(shù)和采樣比例。一個(gè)函數(shù)占用的橫軸越寬,就代表它的執(zhí)行時(shí)間越長(zhǎng)。同一層的多個(gè)函數(shù),則是按照字母來(lái)排序。
縱軸表示調(diào)用棧,由下往上根據(jù)調(diào)用關(guān)系逐個(gè)展開。換句話說(shuō),上下相鄰的兩個(gè)函數(shù)中,下面的函數(shù),是上面函數(shù)的父函數(shù)。這樣,調(diào)用棧越深,縱軸就越高。
另外,要注意圖中的顏色,并沒(méi)有特殊含義,只是用來(lái)區(qū)分不同的函數(shù)。
火焰圖是動(dòng)態(tài)的矢量圖格式,所以它還支持一些動(dòng)態(tài)特性。比如,鼠標(biāo)懸停到某個(gè)函數(shù)上時(shí),就會(huì)自動(dòng)顯示這個(gè)函數(shù)的采樣數(shù)和采樣比例。而當(dāng)你用鼠標(biāo)點(diǎn)擊函數(shù)時(shí),火焰圖就會(huì)把該層及其上的各層放大,方便你觀察這些處于火焰圖頂部的調(diào)用棧的細(xì)節(jié)。
如果我們根據(jù)性能分析的目標(biāo)來(lái)劃分,火焰圖可以分為下面這幾種。
on-CPU 火焰圖:表示 CPU 的繁忙情況,用在 CPU 使用率比較高的場(chǎng)景中。
off-CPU 火焰圖:表示 CPU 等待 I/O、鎖等各種資源的阻塞情況。
內(nèi)存火焰圖:表示內(nèi)存的分配和釋放情況。
熱 / 冷火焰圖:表示將 on-CPU 和 off-CPU 結(jié)合在一起綜合展示。
差分火焰圖:表示兩個(gè)火焰圖的差分情況,紅色表示增長(zhǎng),藍(lán)色表示衰減。差分火焰圖常用來(lái)比較不同場(chǎng)景和不同時(shí)期的火焰圖,以便分析系統(tǒng)變化前后對(duì)性能的影響情況。
如何生成火焰圖?首先,下載幾個(gè)能從?perf record記錄生成火焰圖的工具,這些工具都放在 https://github.com/brendangregg/FlameGraph 。
?
$ git clone https://github.com/brendangregg/FlameGraph $ cd FlameGraph
?
安裝好工具后,要生成火焰圖,其實(shí)主要需要三個(gè)步驟:
執(zhí)行?perf script?,將?perf record?的記錄轉(zhuǎn)換成可讀的采樣記錄;
執(zhí)行?stackcollapse-perf.pl?腳本,合并調(diào)用棧信息;
執(zhí)行?flamegraph.pl?腳本,生成火焰圖。
如果你的機(jī)器安裝了完整的系統(tǒng),通過(guò)管道簡(jiǎn)化這三個(gè)步驟的執(zhí)行如下:
?
$ perf script -i /root/perf.data | ./stackcollapse-perf.pl --all | ./flamegraph.pl > hsys.svg
?
因?yàn)槲业哪繕?biāo)系統(tǒng)是在ARM busybos上,先在目標(biāo)機(jī)器上執(zhí)行步驟1,在將中間文件上傳到X86系上完成步驟2和3。
?
$ perf script -i perf.data > perf-temp $ tftp -p 192.168.1.55 -l perf-temp
?
X86機(jī)器上完成步驟2和3.
?
$ cat perf-temp| ./stackcollapse-perf.pl --all | ./flamegraph.pl > hsys.svg
?
使用瀏覽器打開hsys.svg如下。
從下往上看,沿著調(diào)用棧中最寬的函數(shù)來(lái)分析執(zhí)行次數(shù)最多的函數(shù)??吹降慕Y(jié)果跟的?perf report?類似,但直觀了很多,這幾團(tuán)系統(tǒng)調(diào)用的火焰,就是我們關(guān)注的地方。
可以看到,應(yīng)用發(fā)起的幾個(gè)系統(tǒng)調(diào)用后,內(nèi)核sys_rt_sigtimedwait、sys_mq_timedsend、sys_mq_timedreceive分別占總執(zhí)行時(shí)間的22.69%、(13.71%+6.15%)、(8.53%+8.89%)。
到這里,找出了內(nèi)核執(zhí)行最頻繁的函數(shù)調(diào)用堆棧,而這個(gè)堆棧中的各層級(jí)函數(shù),就是潛在的性能瓶頸來(lái)源。對(duì)比同一cpu高版本內(nèi)核,該問(wèn)題并不明顯,如果想深入了解linux時(shí)間子系統(tǒng),請(qǐng)移步時(shí)間子系統(tǒng)-蝸窩科技??磥?lái)內(nèi)核是動(dòng)不了,不好下手,那回到應(yīng)用看看。
三、解決
既然已經(jīng)清楚原因是應(yīng)用定時(shí)相關(guān)操作引起的,回到應(yīng)用排查相關(guān)代碼。
這個(gè)應(yīng)用是一個(gè)協(xié)議棧,整個(gè)協(xié)議棧有多個(gè)不同優(yōu)先級(jí)的實(shí)時(shí)線程,每個(gè)線程負(fù)責(zé)各部分通訊處理,其中兩個(gè)線程為整個(gè)協(xié)議棧提供timers處理機(jī)制,線程Thread_start向操作系統(tǒng)注冊(cè)一個(gè)周期timer,該周期timer的間隔就是協(xié)議棧軟件timer的基準(zhǔn)時(shí)間,線程A周期等待操作系統(tǒng)timer超時(shí)信號(hào)。
當(dāng)超時(shí)信號(hào)到達(dá)時(shí),線程Thread_start遍歷所有上層應(yīng)用注冊(cè)的timer,判斷時(shí)間是否到期,如果該timer到期,通過(guò)消息隊(duì)列mq將該timer發(fā)送給另一個(gè)線程OS_timer進(jìn)行timer處理,線程OS_timer接收到該timer后,執(zhí)行該timer注冊(cè)的超時(shí)回調(diào)函數(shù)callbalk_timeout。
排查后發(fā)現(xiàn),問(wèn)題出在線程Thread_start向操作系統(tǒng)注冊(cè)的這個(gè)周期timer,它的觸發(fā)間隔為500us,由于觸發(fā)頻率太高,導(dǎo)致操作系統(tǒng)處理定時(shí)器軟硬中斷消耗大部分CPU,表現(xiàn)就是系統(tǒng)cpu飆高,但是檢索整個(gè)協(xié)議棧,并沒(méi)有發(fā)現(xiàn)上層應(yīng)用注冊(cè)小于1ms的timer,協(xié)議棧根本用不到這么小基準(zhǔn)的timer。
所以,解決的辦法很簡(jiǎn)單,就修改一行代碼,將線程Thread_start向操作系統(tǒng)注冊(cè)的周期timer間隔500us調(diào)整為1ms,問(wèn)題解決。
優(yōu)化后,時(shí)鐘軟硬中斷降低。系統(tǒng)sys CPU利用率下降,如下:
?
$ pidstat 1 5 -p `pidof appA` #目標(biāo)應(yīng)用指標(biāo) Linux 3.12.10 08/22/22 _armv7l_ (1 CPU) 1745 UID PID %usr %system %guest %wait %CPU CPU Command 1746 0 1112 8.91 0.99 0.00 0.00 9.90 0 appA 1747 0 1112 3.00 8.00 0.00 0.00 11.00 0 appA 1748 0 1112 8.00 3.00 0.00 0.00 11.00 0 appA 1749 0 1112 10.00 1.00 0.00 0.00 11.00 0 appA $mpstat -A 1 1 #系統(tǒng)整體詳細(xì)指標(biāo) Linux 3.12.10 08/22/22 _armv7l_ (1 CPU) 1724 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %idle 1725 all 1.20 0.00 10.84 0.00 0.00 0.00 0.00 0.00 87.95 1725 0 1.20 0.00 10.84 0.00 0.00 0.00 0.00 0.00 87.95 1724 CPU intr/s 1725 all 6821.69 1725 0 6820.48 1724 CPU 20/s 28/s 30/s 33/s 34/s 35/s 68/s 80/s 84/s 86/s 87/s 90/s 94/s 116/s 125/s 127/s 173/s 230/s 233/s 255/s 261/s Err/s 1725 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 6792.77 0.00 3.61 0.00 0.00 0.00 0.00 0.00 24.10 0.00 0.00 0.00 0.00 0.00 1724 CPU HI/s TIMER/s NET_TX/s NET_RX/s BLOCK/s BLOCK_IOPOLL/s TASKLET/s SCHED/s HRTIMER/s RCU/s 1725 0 0.00 30.12 1.20 13.25 0.00 0.00 0.00 0.00 1443.37 0.00 Average: CPU %usr %nice %sys %iowait %irq %soft %steal %guest %idle Average: all 1.20 0.00 10.84 0.00 0.00 0.00 0.00 0.00 87.95 Average: 0 1.20 0.00 10.84 0.00 0.00 0.00 0.00 0.00 87.95
?
上面的火焰圖,看到?sys_rt_sigtimedwait、sys_mq_timedsend、sys_mq_timedreceive明顯降低.
? | sys_rt_sigtimedwait | sys_mq_timedsend | sys_mq_timedreceive |
---|---|---|---|
前 | 22.69% | 19.86%(13.71%+6.15%) | 17.51%(8.53%+8.89%) |
后 | 14.94% | 9.84%(5.84%+4%) | 11.47%(5.67%+5.8%) |
真是debug一兩天,最后改一行代碼解決問(wèn)題o(╯□╰)o)。。。
審核編輯:湯梓紅
評(píng)論
查看更多