一、現(xiàn)象
業(yè)務(wù)線反饋,單板只要一跑我們的通訊軟件appA,CPU就變得很高,即使沒有任何通訊,空跑時CPU利用率同樣的高,難得業(yè)務(wù)會關(guān)注CPU性能,好久沒更新博客了,小記一下(又是debug一兩天,最后改一行代碼解決的問題o(╯□╰)o)。
啟動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)用啟動后,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)含義
簡單介紹下top各指標(biāo)含義。top 命令顯示了 us、sy、nic、idle 、io、hi、si 和 st 這幾個指標(biāo)(不同版本的top顯示簡寫有所不同),各指標(biāo)含義如下,這幾個指標(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時間比例,這個比例越高,說明CPU的利用率越好,因為我們的目的就是為了讓CPU將更多的時間用在執(zhí)行用戶代碼上,如果這個指標(biāo)過高影響了你的業(yè)務(wù),那就需要去分析業(yè)務(wù)代碼了。 |
sy | CPU執(zhí)行內(nèi)核代碼消耗的CPU時間比例,這個比例要越低越好,因為CPU不應(yīng)該把時間浪費在執(zhí)行內(nèi)核函數(shù)上,如內(nèi)核函數(shù)浪費了很多時間,那說明內(nèi)核可能需要優(yōu)化了。 |
ni |
Nice值被調(diào)大的線程執(zhí)行用戶態(tài)代碼消耗的CPU百分比。對于非實時任務(wù),通過調(diào)整線程的Nice值可以控制它的CPU時間,當(dāng)我們增大一個線程的Nice值時,我們期望它可以少占用一些CPU時間,CPU利用率里的ni這個值就給我們一個參考指標(biāo)來觀察我們的調(diào)整效果。 運行一個進程后,它的默認Nice值為0,通過renice來增加該進程的Nice值(正數(shù)),該進程的CPU利用率就會在ni中顯示,而減少進程的Nice值(負數(shù))則不會在這里面顯示。 |
id | CPU空閑時間,我們通常說的整體CPU利用率就是(100-idl)這個值,也是其他幾項的和。為了提升系統(tǒng)的資源利用率,目標(biāo)就是盡量降低idl。 |
wa | CPU阻塞在I/O上的時間,比如CPU從磁盤讀取文件內(nèi)容,由于磁盤I/O太慢,導(dǎo)致CPU不得不等待數(shù)據(jù)就緒,然后才能繼續(xù)執(zhí)行下一步操作,這就wai時間,這個值越高,說明I/O處理能力出現(xiàn)了問題。 |
hi | CPU消耗在硬中斷里的時間,正常情況下這個值都很低,因為中斷的處理很快,即使有大量的硬件中斷,也不會消耗很多的CPU時間。 |
si | CPU消耗在軟中斷里的時間,系統(tǒng)中常見的軟中斷有網(wǎng)絡(luò)收發(fā)包軟中斷、寫文件落盤產(chǎn)生的軟中斷、高精度定時器軟中斷等。所以網(wǎng)絡(luò)吞吐量較高的系統(tǒng)中,這個值也會高一些。 |
在上面這幾項中,idle 和 wait 是 CPU 不工作的時間,其余的項都是 CPU 工作的時間。idle 和 wait 的主要區(qū)別是,idle 是 CPU 無事可做,而 wait 則是 CPU 想做事卻做不了。你也可以將 wait 理解為是一類特殊的 idle,即該 CPU 上有至少一個線程阻塞在 I/O 時的 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)致的,也就是說 sys 利用率會忽然飆高一下,比如在 usr 低于 15% 的情況下,sys 會高于 40%,同時sirq會高于10%,持續(xù)不到一秒后又恢復(fù)正常。
CPU 的 sys 利用率高,說明內(nèi)核函數(shù)執(zhí)行花費了太多的時間,同樣,CPU 的 sirq利用率高,說明內(nèi)核處理軟中斷執(zhí)行花費了太多的時間,先對比應(yīng)用啟動前后系統(tǒng)各部分信息,看看能否推斷出CPU執(zhí)行哪部分的的內(nèi)核函數(shù)花費的時間長。
啟動應(yīng)用前
我們先通過pidstat看看appA啟動前,系統(tǒng)中每個進程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
?
可以看到,各進程正常,CPU使用率低,接下來通過mpstat查看內(nèi)核各部分詳細。
?
]# 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四個參數(shù),SUM表示每個處理器的中斷總數(shù),CPU表示每個核的每秒中斷數(shù)量, SCPU表示每個核每秒的軟中斷數(shù)量。
-P: 統(tǒng)計的CPU編號,一般用ALL
-u: 輸出列的信息
-V: 查看版本號
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
?
對應(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
?
每個硬中斷產(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
?
對應(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 ......
?
啟動appA應(yīng)用前,可以看出irq為84的中斷gp_timer中斷比較高, 3155次/S左右。
啟動應(yī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
?
對比啟動應(yīng)用前3000/s,每秒中斷產(chǎn)生次數(shù)增長了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)用啟動前變?yōu)?倍,?3155.00次/S左右。相應(yīng)的高精度定時器軟中斷HRTIMER從之前的200/S上升到2100/S,到此基本可以確定應(yīng)用瘋狂定時操作引起的,進一步看內(nèi)核執(zhí)行的函數(shù)來確認。
采集內(nèi)核函數(shù)的方法
目前基本清楚因為定時器中斷變高導(dǎo)致的內(nèi)核函數(shù)執(zhí)行時間變長,接下來采集 CPU 在 sys 飆高的瞬間所執(zhí)行的內(nèi)核函數(shù),同時看看應(yīng)用執(zhí)行什么引起的定時器中斷,再做相應(yīng)的優(yōu)化。采集內(nèi)核函數(shù)的方法有很多,比如:
通過 perf( perf 是內(nèi)核自帶的性能剖析工具) 可以采集 CPU 的熱點,看看 sys 利用率高時,哪些內(nèi)核耗時的 CPU 利用率高;
通過 perf 的?call-graph?功能可以查看具體的調(diào)用棧信息,也就是線程是從什么路徑上執(zhí)行下來的;
通過 perf 的?annotate?功能可以追蹤到線程是在內(nèi)核函數(shù)的哪些語句上比較耗時;
通過 ftrace 的?function-graph?功能可以查看這些內(nèi)核函數(shù)的具體耗時,以及在哪個路徑上耗時最大。
針對一些瞬時sys 利用率高問題,還可以通過系統(tǒng)快照sysrq,把當(dāng)前 CPU 正在做的工作記錄下來,然后結(jié)合內(nèi)核源碼分析為什么 sys 利用率會高。
sysrq常用來分析內(nèi)核問題的工具,用它可以觀察當(dāng)前的內(nèi)存快照、任務(wù)快照,可以構(gòu)造 vmcore 把系統(tǒng)的所有信息都保存下來,甚至還可以在內(nèi)存緊張的時候用它殺掉內(nèi)存開銷最大的那個進程。
用 sysrq 來分析問題,首先需要使能 sysyrq,使能sysrq后沒有任何開銷,使能方式如下:
?
$ sysctl -w kernel.sysrq=1
?
sysrq 的功能被使能后,使用它的 -t 選項來把當(dāng)前的任務(wù)快照保存下來,看看系統(tǒng)中都有哪些任務(wù),以及這些任務(wù)都在干什么。使用方式如下:
?
$ echo t > /proc/sysrq-trigger
?
執(zhí)行后,任務(wù)快照會被打印到內(nèi)核緩沖區(qū),這些任務(wù)快照信息通過?dmesg?命令來查看:
?
$ dmesg
?
內(nèi)核采集分析
這里使用perf?對appA進程進行采樣,輸出內(nèi)核整個調(diào)用鏈上的匯總信息。
?
# 采樣10s后退出 $ perf record -a -g -p `pidof appA` -- sleep 10
?
采樣完成后,繼續(xù)執(zhí)行?perf report命令,得到 perf 的匯總報告。
額。。。屏幕太小、ARM 串口來打印,這打印很難看。
火焰圖分析
針對 perf 匯總數(shù)據(jù)的展示問題,Brendan Gragg 發(fā)明了火焰圖,通過矢量圖的形式,更直觀展示匯總結(jié)果。
(圖片來自 Brendan Gregg?博客)
橫軸表示采樣數(shù)和采樣比例。一個函數(shù)占用的橫軸越寬,就代表它的執(zhí)行時間越長。同一層的多個函數(shù),則是按照字母來排序。
縱軸表示調(diào)用棧,由下往上根據(jù)調(diào)用關(guān)系逐個展開。換句話說,上下相鄰的兩個函數(shù)中,下面的函數(shù),是上面函數(shù)的父函數(shù)。這樣,調(diào)用棧越深,縱軸就越高。
另外,要注意圖中的顏色,并沒有特殊含義,只是用來區(qū)分不同的函數(shù)。
火焰圖是動態(tài)的矢量圖格式,所以它還支持一些動態(tài)特性。比如,鼠標(biāo)懸停到某個函數(shù)上時,就會自動顯示這個函數(shù)的采樣數(shù)和采樣比例。而當(dāng)你用鼠標(biāo)點擊函數(shù)時,火焰圖就會把該層及其上的各層放大,方便你觀察這些處于火焰圖頂部的調(diào)用棧的細節(jié)。
如果我們根據(jù)性能分析的目標(biāo)來劃分,火焰圖可以分為下面這幾種。
on-CPU 火焰圖:表示 CPU 的繁忙情況,用在 CPU 使用率比較高的場景中。
off-CPU 火焰圖:表示 CPU 等待 I/O、鎖等各種資源的阻塞情況。
內(nèi)存火焰圖:表示內(nèi)存的分配和釋放情況。
熱 / 冷火焰圖:表示將 on-CPU 和 off-CPU 結(jié)合在一起綜合展示。
差分火焰圖:表示兩個火焰圖的差分情況,紅色表示增長,藍色表示衰減。差分火焰圖常用來比較不同場景和不同時期的火焰圖,以便分析系統(tǒng)變化前后對性能的影響情況。
如何生成火焰圖?首先,下載幾個能從?perf record記錄生成火焰圖的工具,這些工具都放在 https://github.com/brendangregg/FlameGraph 。
?
$ git clone https://github.com/brendangregg/FlameGraph $ cd FlameGraph
?
安裝好工具后,要生成火焰圖,其實主要需要三個步驟:
執(zhí)行?perf script?,將?perf record?的記錄轉(zhuǎn)換成可讀的采樣記錄;
執(zhí)行?stackcollapse-perf.pl?腳本,合并調(diào)用棧信息;
執(zhí)行?flamegraph.pl?腳本,生成火焰圖。
如果你的機器安裝了完整的系統(tǒng),通過管道簡化這三個步驟的執(zhí)行如下:
?
$ perf script -i /root/perf.data | ./stackcollapse-perf.pl --all | ./flamegraph.pl > hsys.svg
?
因為我的目標(biāo)系統(tǒng)是在ARM busybos上,先在目標(biāo)機器上執(zhí)行步驟1,在將中間文件上傳到X86系上完成步驟2和3。
?
$ perf script -i perf.data > perf-temp $ tftp -p 192.168.1.55 -l perf-temp
?
X86機器上完成步驟2和3.
?
$ cat perf-temp| ./stackcollapse-perf.pl --all | ./flamegraph.pl > hsys.svg
?
使用瀏覽器打開hsys.svg如下。
從下往上看,沿著調(diào)用棧中最寬的函數(shù)來分析執(zhí)行次數(shù)最多的函數(shù)??吹降慕Y(jié)果跟的?perf report?類似,但直觀了很多,這幾團系統(tǒng)調(diào)用的火焰,就是我們關(guān)注的地方。
可以看到,應(yīng)用發(fā)起的幾個系統(tǒng)調(diào)用后,內(nèi)核sys_rt_sigtimedwait、sys_mq_timedsend、sys_mq_timedreceive分別占總執(zhí)行時間的22.69%、(13.71%+6.15%)、(8.53%+8.89%)。
到這里,找出了內(nèi)核執(zhí)行最頻繁的函數(shù)調(diào)用堆棧,而這個堆棧中的各層級函數(shù),就是潛在的性能瓶頸來源。對比同一cpu高版本內(nèi)核,該問題并不明顯,如果想深入了解linux時間子系統(tǒng),請移步時間子系統(tǒng)-蝸窩科技??磥韮?nèi)核是動不了,不好下手,那回到應(yīng)用看看。
三、解決
既然已經(jīng)清楚原因是應(yīng)用定時相關(guān)操作引起的,回到應(yīng)用排查相關(guān)代碼。
這個應(yīng)用是一個協(xié)議棧,整個協(xié)議棧有多個不同優(yōu)先級的實時線程,每個線程負責(zé)各部分通訊處理,其中兩個線程為整個協(xié)議棧提供timers處理機制,線程Thread_start向操作系統(tǒng)注冊一個周期timer,該周期timer的間隔就是協(xié)議棧軟件timer的基準(zhǔn)時間,線程A周期等待操作系統(tǒng)timer超時信號。
當(dāng)超時信號到達時,線程Thread_start遍歷所有上層應(yīng)用注冊的timer,判斷時間是否到期,如果該timer到期,通過消息隊列mq將該timer發(fā)送給另一個線程OS_timer進行timer處理,線程OS_timer接收到該timer后,執(zhí)行該timer注冊的超時回調(diào)函數(shù)callbalk_timeout。
排查后發(fā)現(xiàn),問題出在線程Thread_start向操作系統(tǒng)注冊的這個周期timer,它的觸發(fā)間隔為500us,由于觸發(fā)頻率太高,導(dǎo)致操作系統(tǒng)處理定時器軟硬中斷消耗大部分CPU,表現(xiàn)就是系統(tǒng)cpu飆高,但是檢索整個協(xié)議棧,并沒有發(fā)現(xiàn)上層應(yīng)用注冊小于1ms的timer,協(xié)議棧根本用不到這么小基準(zhǔn)的timer。
所以,解決的辦法很簡單,就修改一行代碼,將線程Thread_start向操作系統(tǒng)注冊的周期timer間隔500us調(diào)整為1ms,問題解決。
優(yōu)化后,時鐘軟硬中斷降低。系統(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)整體詳細指標(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一兩天,最后改一行代碼解決問題o(╯□╰)o)。。。
審核編輯:湯梓紅
評論