【線上故障】通過系統(tǒng)日志分析和定位

你好，我是雨樂！

在之前的文章中，我們有講到如何定位內存泄漏和GDB調試-從入門實踐到原理。今天，借助本文，來分享另外一種更為棘手的線上問題解決方案-如何在沒有coredump文件的情況下，定位程序崩潰原因。

前言

一個優(yōu)秀的程序員，編碼能力和解決問題的能力必不可少。編碼能力體現(xiàn)的是邏輯思維能力，而解決問題的能力不僅僅依靠自己經驗的積累，更需要一定的敏銳嗅覺和使用其他方式解決問題的能力。管他黑貓白貓，抓住老鼠就是好貓。

在日常的項目開發(fā)中，根據(jù)Bug產生的時機和環(huán)境，我們可以將Bug細分為以下幾種：

• 線下缺陷：此階段發(fā)生在上線前。主要在測試階段，由開發(fā)人員在自測過程中或者有測試人員發(fā)現(xiàn)
• 線上問題：此階段發(fā)生在上線后，也就是在正式環(huán)境或者生產環(huán)境。主要是不符合產品的需求邏輯，可能會影響用戶體驗
• 線上故障：這個階段是最嚴重的，對公司的收益、用戶體驗都會造成影響，主要為服務不可用等

在本文的示例中，我們針對的第三個階段，即線上故障進行定位和分析的一種方式，希望借助本文，能夠對你的故障定位能力有一定的幫助。

背景

早上到了公司，正在愉快地摸魚，突然企業(yè)微信來了條報警，某個核心服務重新啟動了。

于是，快速打開iterm，通過跳板機登錄線上服務器，第一時間，查看有沒有coredump文件生成:

ll?/www/coredump/
total?0

竟然沒有coredump文件，當時心情是這樣的：

當時第一反應是有人手動重啟了，于是在組內群里問了下，沒人動線上，看來問題比較麻煩。

排查

既然沒有coredump文件產生，且沒有人手動重啟服務，只能分析下系統(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代表當時的線程id
• 7f855009e49f為出錯時候的地址
• 0000003ab9a75f62為發(fā)生錯誤時指令的地址
• 00007fcccd7f74c0 為堆棧指針
• 3ab9a00000為libc在此程序中映射的內存基址
• segfault at和error 4這兩條信息可以得出是內存讀出錯

其中，內核對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)程序內存訪問越界。

好了，通過上述內核日志，我們基本可以得出如下結論：

名為xxx的進程中，線程id為11120發(fā)生了用戶態(tà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匯編結果(因為內容較多，我們將其重定向輸出到一個臨時文件)

objdump?-tT?/lib64/libc-2.12.so?>?~/info

查找匯編語句

Libc-2.21.so是個基礎庫，其內容多達58m，很難直接從中獲取有用信息。

ll?info
-rw-r--r--?1?root?root?58369282?Jan?28?10:14?info

為了快速定位錯誤點，我們抓取跟錯誤點地址3ab9a75f62相關的命令(為了獲取上下文，所以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?
??3ab9a75f62:?48?8b?43?08???????????mov????0x8(%rbx),%rax

基本能夠確定在進行malloc的時候，出現(xiàn)了問題。

精準定位

在上節(jié)中，我們定位到原因是malloc導致，但是代碼量太大，任何一個對象底層都有可能調用了malloc(new也會調用malloc)，所以一時半會，不知道從哪下手。

為了定位原因，采用最近定位法，分析最近一次上線的代碼改動，這次改動，將之前的redis Sentinel改為了redis cluster，而redis 官方沒有提供cluster的client，所以自己手擼了個client，而在這個client中調用malloc順序如下：

->?Init
-->?redisClusterInit
---->?calloc
------>?malloc

好了，到此，進程崩潰的代碼點基本定位了，下面我進行原因分析。

原因分析

程序對RedisClusterClient進行初始化的地方有兩個：

• 程序啟動的時候
• 當連接斷開的時候

因為程序已經運行了一段時間，所以第一條基本不成立，那么我們看下本次改動使用的命令之一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(
????????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;
??}
??//?...
}

單純這塊代碼，是不會有問題的，所以需要把使用這塊代碼的都考慮進來。我們重新理下請求的調用鏈：

->?Load
-->?GetHandler
---->?GetSession
------>?GetRedisClient

重新進行代碼分析，發(fā)現(xiàn)在特定條件下，GetRedisClient可能會被多個線程同時調用，如果不進行Init的話，一切正常，而當一個線程Init的時候，恰好另外一個線程進行讀，因此引起了訪問一個已經釋放的內存地址，所以導致了進程崩潰。

這種情況發(fā)生的概率很低，很難重現(xiàn)。畢竟連接突然斷開的同時，又有一個線程在同時訪問，在線上還是很難出現(xiàn)(當然可以在線下通過tcpkill進行模擬，這就是另外一回事了)，總體來說，還是比較幸運，能夠迅速定位。

問題解決

在整個bug的分析和解決過程中，定位segfault是最困難的地方，如果知道了segfault的地方，分析原因，就相對來說簡單多了。當然，知道了崩潰原因，解決就更不在話下了??。

程序崩潰，基本上都跟內存有關，無非是越界、訪問無效地址等。在本例中，就是因為訪問一個已經釋放的內存地址而導致的，根據(jù)代碼的實際使用場景，在對應的地方，加鎖，線上灰度，然后全量上線。

結語

遇到線上問題，一定不能慌，如果是頻繁的coredump或者重啟，那么就先回滾到上個版本，然后再分析和解決問題。

如果有生成coredump，那么可以使用gdb進行調試，查看coredump產生位置，然后根據(jù)上下文分析產生coredump的原因，進而解決問題。

如果沒有生成coredump，這個時候，就需要借助其他方式，比如先查看是否因為OOM導致的進程消失，這個時候需要查看部署本服務的其他進程的內存占用情況；如果排除了OOM原因，那么可能就是其他原因了，這個時候，可以借助系統(tǒng)日志來初步定為進程消失的原因，比如本例中的segfault，然后采用對應的方式來解決問題。