嵌入式ARM Linux應用程序項目問題定位

一、現象

業務線反饋，單板只要一跑我們的通訊軟件appA，CPU就變得很高，即使沒有任何通訊，空跑時CPU利用率同樣的高，難得業務會關注CPU性能，好久沒更新博客了，小記一下（又是debug一兩天，最后改一行代碼解決的問題o(╯□╰)o）。

啟動appA?前，top看一下CPU使用情況，如下，9%還算正常（有其他業務應用）。

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
  ...

我們的應用啟動后，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各指標含義

簡單介紹下top各指標含義。top 命令顯示了 us、sy、nic、idle 、io、hi、si 和 st 這幾個指標(不同版本的top顯示簡寫有所不同)，各指標含義如下，這幾個指標之和為 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指標	含義
us	CPU執行用戶代碼消耗的CPU時間比例，這個比例越高，說明CPU的利用率越好，因為我們的目的就是為了讓CPU將更多的時間用在執行用戶代碼上，如果這個指標過高影響了你的業務，那就需要去分析業務代碼了。
sy	CPU執行內核代碼消耗的CPU時間比例，這個比例要越低越好，因為CPU不應該把時間浪費在執行內核函數上，如內核函數浪費了很多時間，那說明內核可能需要優化了。
ni	Nice值被調大的線程執行用戶態代碼消耗的CPU百分比。對于非實時任務，通過調整線程的Nice值可以控制它的CPU時間，當我們增大一個線程的Nice值時，我們期望它可以少占用一些CPU時間，CPU利用率里的ni這個值就給我們一個參考指標來觀察我們的調整效果。運行一個進程后，它的默認Nice值為0，通過renice來增加該進程的Nice值（正數），該進程的CPU利用率就會在ni中顯示，而減少進程的Nice值（負數）則不會在這里面顯示。
id	CPU空閑時間，我們通常說的整體CPU利用率就是（100-idl）這個值，也是其他幾項的和。為了提升系統的資源利用率，目標就是盡量降低idl。
wa	CPU阻塞在I/O上的時間，比如CPU從磁盤讀取文件內容，由于磁盤I/O太慢，導致CPU不得不等待數據就緒，然后才能繼續執行下一步操作，這就wai時間，這個值越高，說明I/O處理能力出現了問題。
hi	CPU消耗在硬中斷里的時間，正常情況下這個值都很低，因為中斷的處理很快，即使有大量的硬件中斷，也不會消耗很多的CPU時間。
si	CPU消耗在軟中斷里的時間，系統中常見的軟中斷有網絡收發包軟中斷、寫文件落盤產生的軟中斷、高精度定時器軟中斷等。所以網絡吞吐量較高的系統中，這個值也會高一些。

在上面這幾項中，idle 和 wait 是 CPU 不工作的時間，其余的項都是 CPU 工作的時間。idle 和 wait 的主要區別是，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利用率變高導致的，也就是說 sys 利用率會忽然飆高一下，比如在 usr 低于 15% 的情況下，sys 會高于 40%，同時sirq會高于10%，持續不到一秒后又恢復正常。

CPU 的 sys 利用率高，說明內核函數執行花費了太多的時間，同樣，CPU 的 sirq利用率高，說明內核處理軟中斷執行花費了太多的時間，先對比應用啟動前后系統各部分信息，看看能否推斷出CPU執行哪部分的的內核函數花費的時間長。

啟動應用前

我們先通過pidstat看看appA啟動前,系統中每個進程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查看內核各部分詳細。

]# 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四個參數,SUM表示每個處理器的中斷總數，CPU表示每個核的每秒中斷數量， SCPU表示每個核每秒的軟中斷數量。

-P: 統計的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

對應的軟中斷信息：

# 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

硬中斷

處理器硬中斷總數：

# 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

每個硬中斷產生速率：

# 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

對應的中斷信息：

# 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應用前，可以看出irq為84的中斷gp_timer中斷比較高， 3155次/S左右。

啟動應用后

先啟動應用，然后再看一下這些指標的變化。

# 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有所升高，什么導致的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

對比啟動應用前3000/s，每秒中斷產生次數增長了120%。繼續查看哪些中斷變高了？

# 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中斷相比應用啟動前變為2倍，?3155.00次/S左右。相應的高精度定時器軟中斷HRTIMER從之前的200/S上升到2100/S，到此基本可以確定應用瘋狂定時操作引起的，進一步看內核執行的函數來確認。

采集內核函數的方法

目前基本清楚因為定時器中斷變高導致的內核函數執行時間變長，接下來采集 CPU 在 sys 飆高的瞬間所執行的內核函數，同時看看應用執行什么引起的定時器中斷，再做相應的優化。采集內核函數的方法有很多，比如：

通過 perf（ perf 是內核自帶的性能剖析工具）可以采集 CPU 的熱點，看看 sys 利用率高時，哪些內核耗時的 CPU 利用率高；

通過 perf 的?call-graph?功能可以查看具體的調用棧信息，也就是線程是從什么路徑上執行下來的；

通過 perf 的?annotate?功能可以追蹤到線程是在內核函數的哪些語句上比較耗時；

通過 ftrace 的?function-graph?功能可以查看這些內核函數的具體耗時，以及在哪個路徑上耗時最大。

針對一些瞬時sys 利用率高問題，還可以通過系統快照sysrq，把當前 CPU 正在做的工作記錄下來，然后結合內核源碼分析為什么 sys 利用率會高。

sysrq常用來分析內核問題的工具，用它可以觀察當前的內存快照、任務快照，可以構造 vmcore 把系統的所有信息都保存下來，甚至還可以在內存緊張的時候用它殺掉內存開銷最大的那個進程。

用 sysrq 來分析問題，首先需要使能 sysyrq,使能sysrq后沒有任何開銷，使能方式如下：

$ sysctl -w kernel.sysrq=1

sysrq 的功能被使能后，使用它的 -t 選項來把當前的任務快照保存下來，看看系統中都有哪些任務，以及這些任務都在干什么。使用方式如下：

$ echo t > /proc/sysrq-trigger

執行后，任務快照會被打印到內核緩沖區，這些任務快照信息通過?dmesg?命令來查看：

$ dmesg

內核采集分析

這里使用perf?對appA進程進行采樣，輸出內核整個調用鏈上的匯總信息。

# 采樣10s后退出
$ perf record -a -g -p `pidof appA` -- sleep 10

采樣完成后，繼續執行?perf report命令，得到 perf 的匯總報告。

額。。。屏幕太小、ARM 串口來打印，這打印很難看。

火焰圖分析

針對 perf 匯總數據的展示問題，Brendan Gragg 發明了火焰圖，通過矢量圖的形式，更直觀展示匯總結果。

（圖片來自 Brendan Gregg?博客）

橫軸表示采樣數和采樣比例。一個函數占用的橫軸越寬，就代表它的執行時間越長。同一層的多個函數，則是按照字母來排序。

縱軸表示調用棧，由下往上根據調用關系逐個展開。換句話說，上下相鄰的兩個函數中，下面的函數，是上面函數的父函數。這樣，調用棧越深，縱軸就越高。

另外，要注意圖中的顏色，并沒有特殊含義，只是用來區分不同的函數。

火焰圖是動態的矢量圖格式，所以它還支持一些動態特性。比如，鼠標懸停到某個函數上時，就會自動顯示這個函數的采樣數和采樣比例。而當你用鼠標點擊函數時，火焰圖就會把該層及其上的各層放大，方便你觀察這些處于火焰圖頂部的調用棧的細節。

如果我們根據性能分析的目標來劃分，火焰圖可以分為下面這幾種。

on-CPU 火焰圖：表示 CPU 的繁忙情況，用在 CPU 使用率比較高的場景中。

off-CPU 火焰圖：表示 CPU 等待 I/O、鎖等各種資源的阻塞情況。

內存火焰圖：表示內存的分配和釋放情況。

熱 / 冷火焰圖：表示將 on-CPU 和 off-CPU 結合在一起綜合展示。

差分火焰圖：表示兩個火焰圖的差分情況，紅色表示增長，藍色表示衰減。差分火焰圖常用來比較不同場景和不同時期的火焰圖，以便分析系統變化前后對性能的影響情況。

如何生成火焰圖？首先，下載幾個能從?perf record記錄生成火焰圖的工具，這些工具都放在 https://github.com/brendangregg/FlameGraph 。

$ git clone https://github.com/brendangregg/FlameGraph
$ cd FlameGraph

安裝好工具后，要生成火焰圖，其實主要需要三個步驟：

執行?perf script?，將?perf record?的記錄轉換成可讀的采樣記錄；

執行?stackcollapse-perf.pl?腳本，合并調用棧信息；

執行?flamegraph.pl?腳本，生成火焰圖。

如果你的機器安裝了完整的系統，通過管道簡化這三個步驟的執行如下：

$ perf script -i /root/perf.data | ./stackcollapse-perf.pl --all |  ./flamegraph.pl > hsys.svg

因為我的目標系統是在ARM busybos上，先在目標機器上執行步驟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如下。

從下往上看，沿著調用棧中最寬的函數來分析執行次數最多的函數。看到的結果跟的?perf report?類似，但直觀了很多，這幾團系統調用的火焰，就是我們關注的地方。

可以看到，應用發起的幾個系統調用后，內核sys_rt_sigtimedwait、sys_mq_timedsend、sys_mq_timedreceive分別占總執行時間的22.69%、（13.71%+6.15%）、（8.53%+8.89%）。

到這里，找出了內核執行最頻繁的函數調用堆棧，而這個堆棧中的各層級函數，就是潛在的性能瓶頸來源。對比同一cpu高版本內核，該問題并不明顯，如果想深入了解linux時間子系統，請移步時間子系統-蝸窩科技。看來內核是動不了，不好下手，那回到應用看看。

三、解決

既然已經清楚原因是應用定時相關操作引起的，回到應用排查相關代碼。

這個應用是一個協議棧，整個協議棧有多個不同優先級的實時線程，每個線程負責各部分通訊處理，其中兩個線程為整個協議棧提供timers處理機制，線程Thread_start向操作系統注冊一個周期timer，該周期timer的間隔就是協議棧軟件timer的基準時間，線程A周期等待操作系統timer超時信號。

當超時信號到達時，線程Thread_start遍歷所有上層應用注冊的timer，判斷時間是否到期，如果該timer到期，通過消息隊列mq將該timer發送給另一個線程OS_timer進行timer處理，線程OS_timer接收到該timer后，執行該timer注冊的超時回調函數callbalk_timeout。

排查后發現，問題出在線程Thread_start向操作系統注冊的這個周期timer，它的觸發間隔為500us，由于觸發頻率太高，導致操作系統處理定時器軟硬中斷消耗大部分CPU，表現就是系統cpu飆高，但是檢索整個協議棧，并沒有發現上層應用注冊小于1ms的timer，協議棧根本用不到這么小基準的timer。

所以，解決的辦法很簡單，就修改一行代碼，將線程Thread_start向操作系統注冊的周期timer間隔500us調整為1ms，問題解決。

優化后，時鐘軟硬中斷降低。系統sys CPU利用率下降，如下：

$ pidstat  1 5 -p `pidof appA` #目標應用指標
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 #系統整體詳細指標
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