導航

昨天搞定了一個十萬火急的issue，客戶抱怨產(chǎn)品升級后系統(tǒng)會變慢和CPU使用率相當高，客戶脾氣很大，聲稱不盡快解決這個問題就退貨，弄得我們 R&D壓力很大，解決這個issue的任務分給了我，客戶是南非的一個公司，由于時差問題，我只好在家遠程解決問題，晚上8點半用 gotomeeting遠程到客戶電腦查看我們的系統(tǒng)，折騰了四個多小時，終于在凌晨時reproduce了這個high CPU，趕緊抓Log，用wireshark抓包，用gcore,gstack,strace和top保存了系統(tǒng)的相關輸出。在第2天分析了這些文件后， 找到了產(chǎn)品的bug，代碼的作者分配了10K的緩沖區(qū)，并想當然認為10K足以夠用，當然99%的情況下是夠用的，但是在這1%的情況下出現(xiàn)了問題，緩沖 區(qū)不幸被寫滿了，然后程序進入了死循環(huán)，導致high CPU。找到了問題了，fix就很容易了，客戶的脾氣也緩和了，fix很快就可以deliver給客戶。反思解決問題的過程，覺得這個分析過程具有可復用 性，值得總結(jié)一下。

1.用top命令查看哪個進程占用CPU高
gateway網(wǎng)關進程14094占用CPU高達891%，這個數(shù)值是進程內(nèi)各個線程占用CPU的累加值。

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
14094 root 15 0 315m 10m 7308 S 891% 2.2 1:49.01 gateway
20642 root 17 0 17784 4148 2220 S 0.5 0.8 2:39.96 microdasys
1679 root 18 0 10984 1856 1556 R 0.3 0.4 0:22.21 sshd
22563 root 18 0 2424 1060 800 R 0.3 0.2 0:00.03 top
1 root 18 0 2156 492 460 S 0.0 0.1 0:01.59 init

2.用top -H -p pid命令查看進程內(nèi)各個線程占用的CPU百分比

#top -H -p 14094
top中可以看到有107個線程，但是下面9個線程占用CPU很高，下面以線程14086為主，分析其為何high CPU

PID USER PR NI VIRT RES SHR S %CPU MEM TIME+ COMMAND
14086 root 25 0 922m 914m 538m R 101 10.0 21:35.46 gateway
14087 root 25 0 922m 914m 538m R 101 10.0 10:50.22 gateway
14081 root 25 0 922m 914m 538m S 99 10.0 8:57.36 gateway
14082 root 25 0 922m 914m 538m R 99 10.0 11:51.92 gateway
14089 root 25 0 922m 914m 538m R 99 10.0 21:21.77 gateway
14092 root 25 0 922m 914m 538m R 99 10.0 19:55.47 gateway
14094 root 25 0 922m 914m 538m R 99 10.0 21:02.21 gateway
14083 root 25 0 922m 914m 538m R 97 10.0 21:32.39 gateway
14088 root 25 0 922m 914m 538m R 97 10.0 11:23.12 gateway

3.使用gstack命令查看進程中各線程的函數(shù)調(diào)用棧
#gstack 14094 > gstack.log
在gstack.log中查找線程ID14086，由于函數(shù)棧會暴露函數(shù)細節(jié)，因此只顯示了兩個函數(shù)楨，線程ID14086對應線程號是37

Thread 37 (Thread 0x4696ab90 (LWP 14086)):
#0 0x40000410 in __kernel_vsyscall ()
#1 0x40241f33 in poll () from /lib/i686/nosegneg/libc.so.6

4.使用gcore命令轉(zhuǎn)存進程映像及內(nèi)存上下文

#gcore 14094
該命令生成core文件core.14094

5。用strace命令查看系統(tǒng)調(diào)用和花費的時間
#strace -T -r -c -p 14094

-c參數(shù)顯示統(tǒng)計信息，去掉此參數(shù)可以查看每個系統(tǒng)調(diào)用話費的時間及返回值。

% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------------------
99.99 22.683879 3385 6702 poll
0.00 0.001132 0 6702 gettimeofday
0.00 0.000127 1 208 208 accept
0.00 0.000022 22 1 read
0.00 0.000000 0 1 write
0.00 0.000000 0 1 close
0.00 0.000000 0 14 time
0.00 0.000000 0 2 stat64
0.00 0.000000 0 4 clock_gettime
0.00 0.000000 0 7 send
0.00 0.000000 0 10 10 recvfrom
------ ----------- ----------- --------- --------- ------------------------------
100.00 22.685160 13652 218 total

6.用gdb調(diào)試core文件，并線程切換到37號線程
gcore和實際的core dump時產(chǎn)生的core文件幾乎一樣，只是不能用gdb進行某些動態(tài)調(diào)試

(gdb) gdb gateway core.14094
(gdb) thread 37
[Switching to thread 37 (Thread 0x4696ab90 (LWP 14086))]#0 0x40000410 in __kernel_vsyscall ()
(gdb) where
#0 0x40000410 in __kernel_vsyscall ()
#1 0x40241f33 in poll () from /lib/i686/nosegneg/libc.so.6

可以根據(jù)詳細的函數(shù)棧進行gdb調(diào)試，打印一些變量值，并結(jié)合源代碼分析為何會poll調(diào)用占用很高的CPU。
因為代碼涉及到公司產(chǎn)權(quán)，顧不在此做詳細分析，需要明白的是分析的流程和使用的命令。

流程為：進程ID->線程ID->線程函數(shù)調(diào)用棧->函數(shù)耗時和調(diào)用統(tǒng)計->源代碼分析