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

你好，我是雨樂(lè)！

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

前言

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

在日常的項(xiàng)目開(kāi)發(fā)中，根據(jù)Bug產(chǎn)生的時(shí)機(jī)和環(huán)境，我們可以將Bug細(xì)分為以下幾種：

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

在本文的示例中，我們針對(duì)的第三個(gè)階段，即線上故障進(jìn)行定位和分析的一種方式，希望借助本文，能夠?qū)δ愕墓收隙ㄎ荒芰τ幸欢ǖ膸椭?/p>

背景

早上到了公司，正在愉快地摸魚(yú)，突然企業(yè)微信來(lái)了條報(bào)警，某個(gè)核心服務(wù)重新啟動(dòng)了。

于是，快速打開(kāi)iterm，通過(guò)跳板機(jī)登錄線上服務(wù)器，第一時(shí)間，查看有沒(méi)有coredump文件生成:

ll?/www/coredump/
total?0

竟然沒(méi)有coredump文件，當(dāng)時(shí)心情是這樣的：

當(dāng)時(shí)第一反應(yīng)是有人手動(dòng)重啟了，于是在組內(nèi)群里問(wèn)了下，沒(méi)人動(dòng)線上，看來(lái)問(wèn)題比較麻煩。

排查

既然沒(méi)有coredump文件產(chǎn)生，且沒(méi)有人手動(dòng)重啟服務(wù)，只能分析下系統(tǒng)日志，看看能得到什么線索。

通過(guò)在系統(tǒng)日志中，查找進(jìn)程名來(lái)獲取進(jìn)程發(fā)生錯(cuò)誤時(shí)候的日志信息。

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 為進(jìn)程名，后面括號(hào)中的11120代表當(dāng)時(shí)的線程id
• 7f855009e49f為出錯(cuò)時(shí)候的地址
• 0000003ab9a75f62為發(fā)生錯(cuò)誤時(shí)指令的地址
• 00007fcccd7f74c0 為堆棧指針
• 3ab9a00000為libc在此程序中映射的內(nèi)存基址
• segfault at和error 4這兩條信息可以得出是內(nèi)存讀出錯(cuò)

其中，內(nèi)核對(duì)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)存訪問(wèn)越界。

好了，通過(guò)上述內(nèi)核日志，我們基本可以得出如下結(jié)論：

名為xxx的進(jìn)程中，線程id為11120發(fā)生了用戶態(tài)程序內(nèi)存訪問(wèn)越界，且最終core在了libc-2.12.so中。原因基本確定，現(xiàn)在我們開(kāi)始定位問(wè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ā)生錯(cuò)誤時(shí)指令的地址(0000003ab9a75f62)以及l(fā)ibc-2.12.so在進(jìn)程中的基址(3ab9a00000)，下面我通過(guò)objdump命令來(lái)進(jìn)行分析。

反匯編

通過(guò)下述命令，得到libc-2.12.so匯編結(jié)果(因?yàn)閮?nèi)容較多，我們將其重定向輸出到一個(gè)臨時(shí)文件)

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

查找匯編語(yǔ)句

Libc-2.21.so是個(gè)基礎(chǔ)庫(kù)，其內(nèi)容多達(dá)58m，很難直接從中獲取有用信息。

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

為了快速定位錯(cuò)誤點(diǎn)，我們抓取跟錯(cuò)誤點(diǎn)地址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

為了進(jìn)一步定位問(wèn)題點(diǎn)，我們使用objdump命令并指定起始點(diǎn)

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

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

精準(zhǔn)定位

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

為了定位原因，采用最近定位法，分析最近一次上線的代碼改動(dòng)，這次改動(dòng)，將之前的redis Sentinel改為了redis cluster，而redis 官方?jīng)]有提供cluster的client，所以自己手?jǐn)]了個(gè)client，而在這個(gè)client中調(diào)用malloc順序如下：

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

好了，到此，進(jìn)程崩潰的代碼點(diǎn)基本定位了，下面我進(jìn)行原因分析。

原因分析

程序?qū)edisClusterClient進(jìn)行初始化的地方有兩個(gè)：

• 程序啟動(dòng)的時(shí)候
• 當(dāng)連接斷開(kāi)的時(shí)候

因?yàn)槌绦蛞呀?jīng)運(yùn)行了一段時(shí)間，所以第一條基本不成立，那么我們看下本次改動(dòng)使用的命令之一ZRangeByScore的實(shí)現(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;
??}
??//?...
}

單純這塊代碼，是不會(huì)有問(wèn)題的，所以需要把使用這塊代碼的都考慮進(jìn)來(lái)。我們重新理下請(qǐng)求的調(diào)用鏈：

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

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

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

問(wèn)題解決

在整個(gè)bug的分析和解決過(guò)程中，定位segfault是最困難的地方，如果知道了segfault的地方，分析原因，就相對(duì)來(lái)說(shuō)簡(jiǎn)單多了。當(dāng)然，知道了崩潰原因，解決就更不在話下了??。

程序崩潰，基本上都跟內(nèi)存有關(guān)，無(wú)非是越界、訪問(wèn)無(wú)效地址等。在本例中，就是因?yàn)樵L問(wèn)一個(gè)已經(jīng)釋放的內(nèi)存地址而導(dǎo)致的，根據(jù)代碼的實(shí)際使用場(chǎng)景，在對(duì)應(yīng)的地方，加鎖，線上灰度，然后全量上線。

結(jié)語(yǔ)

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

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

如果沒(méi)有生成coredump，這個(gè)時(shí)候，就需要借助其他方式，比如先查看是否因?yàn)镺OM導(dǎo)致的進(jìn)程消失，這個(gè)時(shí)候需要查看部署本服務(wù)的其他進(jìn)程的內(nèi)存占用情況；如果排除了OOM原因，那么可能就是其他原因了，這個(gè)時(shí)候，可以借助系統(tǒng)日志來(lái)初步定為進(jìn)程消失的原因，比如本例中的segfault，然后采用對(duì)應(yīng)的方式來(lái)解決問(wèn)題。