【線上故障】通過系統(tǒng)日志分析和定位
你好，我是雨樂!
在之前的文章中，我們有講到如何定位內(nèi)存泄漏和GDB調(diào)試-從入門實踐到原理。今天，借助本文，來分享另外一種更為棘手的線上問題解決方案-如何在沒有coredump文件的情況下，定位程序崩潰原因。
前言
一個優(yōu)秀的程序員，編碼能力和解決問題的能力必不可少。編碼能力體現(xiàn)的是邏輯思維能力，而解決問題的能力不僅僅依靠自己經(jīng)驗的積累，更需要一定的敏銳嗅覺和使用其他方式解決問題的能力。管他黑貓白貓，抓住老鼠就是好貓。
在日常的項目開發(fā)中，根據(jù)Bug產(chǎn)生的時機和環(huán)境，我們可以將Bug細(xì)分為以下幾種：
- 線下缺陷：此階段發(fā)生在上線前。主要在測試階段，由開發(fā)人員在自測過程中或者有測試人員發(fā)現(xiàn)
- 線上問題：此階段發(fā)生在上線后，也就是在正式環(huán)境或者生產(chǎn)環(huán)境。主要是不符合產(chǎn)品的需求邏輯，可能會影響用戶體驗
- 線上故障：這個階段是最嚴(yán)重的，對公司的收益、用戶體驗都會造成影響，主要為服務(wù)不可用等
在本文的示例中，我們針對的第三個階段，即線上故障進行定位和分析的一種方式，希望借助本文，能夠?qū)δ愕墓收隙ㄎ荒芰τ幸欢ǖ膸椭?/p>
背景
早上到了公司，正在愉快地摸魚，突然企業(yè)微信來了條報警，某個核心服務(wù)重新啟動了。
于是，快速打開iterm，通過跳板機登錄線上服務(wù)器，第一時間，查看有沒有coredump文件生成:
ll /www/coredump/
total 0
竟然沒有coredump文件，當(dāng)時心情是這樣的：
當(dāng)時第一反應(yīng)是有人手動重啟了，于是在組內(nèi)群里問了下，沒人動線上，看來問題比較麻煩。
排查
既然沒有coredump文件產(chǎn)生，且沒有人手動重啟服務(wù)，只能分析下系統(tǒng)日志，看看能得到什么線索。
通過在系統(tǒng)日志中，查找進程名來獲取進程發(fā)生錯誤時候的日志信息。
grep xxx /var/log/messages
kernel: xxx[11120]: segfault at 7f855009e49f ip 0000003ab9a75f62 sp 00007fcccd7f74c0 error 4 in libc-2.12.so[3ab9a00000+18b000]
在上面的信息中：
- xxx 為進程名，后面括號中的11120代表當(dāng)時的線程id7f855009e49f為出錯時候的地址
- 0000003ab9a75f62為發(fā)生錯誤時指令的地址
- 00007fcccd7f74c0 為堆棧指針
- 3ab9a00000為libc在此程序中映射的內(nèi)存基址
- segfault at和error 4這兩條信息可以得出是內(nèi)存讀出錯
其中，內(nèi)核對error的定義如下：
/*
* Page fault error code bits:
*
* bit 0 == 0: no page found 1: protection fault
* bit 1 == 0: read access 1: write access
* bit 2 == 0: kernel-mode access 1: user-mode access
* bit 3 == 1: use of reserved bit detected
* bit 4 == 1: fault was an instruction fetch
* bit 5 == 1: protection keys block access
*/
enum x86_pf_error_code {
X86_PF_PROT = 1 << 0,
X86_PF_WRITE = 1 << 1,
X86_PF_USER = 1 << 2,
X86_PF_RSVD = 1 << 3,
X86_PF_INSTR = 1 << 4,
X86_PF_PK = 1 << 5,
};
#endif /* _ASM_X86_TRAPS_H */
error 4代表用戶態(tài)程序內(nèi)存訪問越界。
好了，通過上述內(nèi)核日志，我們基本可以得出如下結(jié)論：
名為xxx的進程中，線程id為11120發(fā)生了用戶態(tài)程序內(nèi)存訪問越界，且最終core在了libc-2.12.so中。原因基本確定，現(xiàn)在我們開始定位問題。
初步定位
使用ldd命令，查看可執(zhí)行程序的依賴：
ldd xxx
linux-vdso.so.1 => (0x00007ffedb331000)
librt.so.1 => /lib64/librt.so.1 (0x0000003aba200000)
libdl.so.2 => /lib64/libdl.so.2 (0x0000003ab9600000)
libstdc++.so.6 => /usr/lib64/libstdc++.so.6 (0x0000003abce00000)
libm.so.6 => /lib64/libm.so.6 (0x0000003aba600000)
libc.so.6 => /lib64/libc.so.6 (0x0000003ab9a00000)
/lib64/ld-linux-x86-64.so.2 (0x0000562e90634000)
libpthread.so.0 => /lib64/libpthread.so.0 (0x0000003ab9e00000)
libgcc_s.so.1 => /lib64/libgcc_s.so.1 (0x0000003abc200000)
在上一節(jié)中，我們得到了程序發(fā)生錯誤時指令的地址(0000003ab9a75f62)以及l(fā)ibc-2.12.so在進程中的基址(3ab9a00000)，下面我通過objdump命令來進行分析。
反匯編
通過下述命令，得到libc-2.12.so匯編結(jié)果(因為內(nèi)容較多，我們將其重定向輸出到一個臨時文件)
objdump -tT /lib64/libc-2.12.so > ~/info
查找匯編語句
Libc-2.21.so是個基礎(chǔ)庫，其內(nèi)容多達(dá)58m，很難直接從中獲取有用信息。
ll info
-rw-r--r-- 1 root root 58369282 Jan 28 10:14 info
為了快速定位錯誤點，我們抓取跟錯誤點地址3ab9a75f62相關(guān)的命令(為了獲取上下文，所以grep了部分)
objdump -tT /lib64/libc-2.12.so | grep 3ab9a75
輸出如下：
0000003ab9a75100 l F .text 0000000000000176 enlarge_userbuf
0000003ab9a756b0 l F .text 000000000000011b ptmalloc_lock_all
0000003ab9a757d0 l F .text 00000000000000b6 ptmalloc_unlock_all
0000003ab9a75890 l F .text 00000000000000c1 ptmalloc_unlock_all2
0000003ab9a75960 l F .text 0000000000000003 __failing_morecore
0000003ab9a75a20 l F .text 00000000000000da sYSTRIm
0000003ab9a75b00 l F .text 000000000000029d mem2chunk_check
0000003ab9a75da0 l F .text 00000000000000e0 malloc_printerr
0000003ab9a75e80 l F .text 0000000000000541 malloc_consolidate
0000003ab9a75280 l F .text 0000000000000187 _IO_str_seekoff_internal
0000003ab9a75970 l F .text 000000000000006b __malloc_check_init
0000003ab9a75410 l F .text 00000000000001aa _IO_str_overflow_internal
0000003ab9a759e0 l F .text 0000000000000031 __malloc_usable_size
0000003ab9a75020 l F .text 0000000000000062 _IO_str_underflow_internal
0000003ab9a750b0 l F .text 000000000000002b _IO_str_finish
0000003ab9a75090 l F .text 0000000000000012 _IO_str_count
0000003ab9a755c0 l F .text 00000000000000ae _IO_str_init_static_internal
0000003ab9a750e0 l F .text 0000000000000015 _IO_str_pbackfail_internal
0000003ab9a759e0 w F .text 0000000000000031 malloc_usable_size
0000003ab9a75020 g F .text 0000000000000062 _IO_str_underflow
0000003ab9a750e0 g F .text 0000000000000015 _IO_str_pbackfail
0000003ab9a75410 g F .text 00000000000001aa _IO_str_overflow
0000003ab9a75670 g F .text 000000000000001d _IO_str_init_readonly
0000003ab9a75690 g F .text 0000000000000012 _IO_str_init_static
0000003ab9a75280 g F .text 0000000000000187 _IO_str_seekoff
0000003ab9a750e0 g DF .text 0000000000000015 GLIBC_2.2.5 _IO_str_pbackfail
0000003ab9a75690 g DF .text 0000000000000012 GLIBC_2.2.5 _IO_str_init_static
0000003ab9a759e0 w DF .text 0000000000000031 GLIBC_2.2.5 malloc_usable_size
0000003ab9a75020 g DF .text 0000000000000062 GLIBC_2.2.5 _IO_str_underflow
0000003ab9a75280 g DF .text 0000000000000187 GLIBC_2.2.5 _IO_str_seekoff
0000003ab9a75410 g DF .text 00000000000001aa GLIBC_2.2.5 _IO_str_overflow
0000003ab9a75670 g DF .text 000000000000001d GLIBC_2.2.5 _IO_str_init_readonly
為了進一步定位問題點，我們使用objdump命令并指定起始點
objdump -d /lib64/libc-2.12.so --start-address=0x3ab9a75000 | head -n2000 | grep 75f62
輸出如下：
3ab9a75ec8: 0f 85 94 00 00 00 jne 3ab9a75f62 <malloc_consolidate+0xe2>
3ab9a75f62: 48 8b 43 08 mov 0x8(%rbx),%rax
基本能夠確定在進行malloc的時候，出現(xiàn)了問題。
精準(zhǔn)定位在上節(jié)中，我們定位到原因是malloc導(dǎo)致，但是代碼量太大，任何一個對象底層都有可能調(diào)用了malloc(new也會調(diào)用malloc)，所以一時半會，不知道從哪下手。
為了定位原因，采用最近定位法，分析最近一次上線的代碼改動，這次改動，將之前的redis Sentinel改為了redis cluster，而redis 官方?jīng)]有提供cluster的client，所以自己手?jǐn)]了個client，而在這個client中調(diào)用malloc順序如下：
-> Init
--> redisClusterInit
----> calloc
------> malloc
好了，到此，進程崩潰的代碼點基本定位了，下面我進行原因分析。
原因分析
程序?qū)edisClusterClient進行初始化的地方有兩個：
- 程序啟動的時候
- 當(dāng)連接斷開的時候
因為程序已經(jīng)運行了一段時間，所以第一條基本不成立，那么我們看下本次改動使用的命令之一ZRangeByScore的實現(xiàn)：
void RedisClusterClient::ZRangeByScore(std::string& key, std::string min, std::string max,
std::vector<std::string> *vals,
bool withscores,
std::string *msg) {
// ....
redisReply *reply = static_cast<redisReply*>(
redisClusterCommandArgv(cc_, argv.size(), &(argv[0]), &(argvlen[0])));
if (!reply || reply->type != REDIS_REPLY_ARRAY) {
// ...
redisClusterFree(cc_);
cc_ = nullptr;
Init(host_, password_, &connect_timeout_, &op_timeout_, msg);
}
return;
}
// ...
}
單純這塊代碼，是不會有問題的，所以需要把使用這塊代碼的都考慮進來。我們重新理下請求的調(diào)用鏈：
-> Load
--> GetHandler
----> GetSession
------> GetRedisClient
重新進行代碼分析，發(fā)現(xiàn)在特定條件下，GetRedisClient可能會被多個線程同時調(diào)用，如果不進行Init的話，一切正常，而當(dāng)一個線程Init的時候，恰好另外一個線程進行讀，因此引起了訪問一個已經(jīng)釋放的內(nèi)存地址，所以導(dǎo)致了進程崩潰。
這種情況發(fā)生的概率很低，很難重現(xiàn)。畢竟連接突然斷開的同時，又有一個線程在同時訪問，在線上還是很難出現(xiàn)(當(dāng)然可以在線下通過tcpkill進行模擬，這就是另外一回事了)，總體來說，還是比較幸運，能夠迅速定位。
問題解決
在整個bug的分析和解決過程中，定位segfault是最困難的地方，如果知道了segfault的地方，分析原因，就相對來說簡單多了。當(dāng)然，知道了崩潰原因，解決就更不在話下了??。
程序崩潰，基本上都跟內(nèi)存有關(guān)，無非是越界、訪問無效地址等。在本例中，就是因為訪問一個已經(jīng)釋放的內(nèi)存地址而導(dǎo)致的，根據(jù)代碼的實際使用場景，在對應(yīng)的地方，加鎖，線上灰度，然后全量上線。
結(jié)語
遇到線上問題，一定不能慌，如果是頻繁的coredump或者重啟，那么就先回滾到上個版本，然后再分析和解決問題。
如果有生成coredump，那么可以使用gdb進行調(diào)試，查看coredump產(chǎn)生位置，然后根據(jù)上下文分析產(chǎn)生coredump的原因，進而解決問題。
如果沒有生成coredump，這個時候，就需要借助其他方式，比如先查看是否因為OOM導(dǎo)致的進程消失，這個時候需要查看部署本服務(wù)的其他進程的內(nèi)存占用情況;如果排除了OOM原因，那么可能就是其他原因了，這個時候，可以借助系統(tǒng)日志來初步定為進程消失的原因，比如本例中的segfault，然后采用對應(yīng)的方式來解決問題。
好了，本期的文章就到這，我們下期見!
