嵌入式ARM Linux應(yīng)用程序項(xiàng)目問(wèn)題定位

一、現(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)寫(xiě)有所不同)，各指標(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í)行用戶(hù)代碼消耗的CPU時(shí)間比例，這個(gè)比例越高，說(shuō)明CPU的利用率越好，因?yàn)槲覀兊哪康木褪菫榱俗孋PU將更多的時(shí)間用在執(zhí)行用戶(hù)代碼上，如果這個(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í)行用戶(hù)態(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從磁盤(pán)讀取文件內(nèi)容，由于磁盤(pán)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)橹袛嗟奶幚砗芸?，即使有大量的硬件中斷，也不?huì)消耗很多的CPU時(shí)間。
si	CPU消耗在軟中斷里的時(shí)間，系統(tǒng)中常見(jiàn)的軟中斷有網(wǎng)絡(luò)收發(fā)包軟中斷、寫(xiě)文件落盤(pán)產(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 理解為是一類(lèi)特殊的 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)存開(kāi)銷(xiāo)最大的那個(gè)進(jìn)程。

用 sysrq 來(lái)分析問(wèn)題，首先需要使能 sysyrq,使能sysrq后沒(méi)有任何開(kāi)銷(xiāo)，使能方式如下：

$ 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è)展開(kāi)。換句話(huà)說(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

使用瀏覽器打開(kāi)hsys.svg如下。

從下往上看，沿著調(diào)用棧中最寬的函數(shù)來(lái)分析執(zhí)行次數(shù)最多的函數(shù)?？吹降慕Y(jié)果跟的?perf report?類(lèi)似，但直觀了很多，這幾團(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è)線程O(píng)S_timer進(jìn)行timer處理，線程O(píng)S_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