gdb 提示 coredump 文件 truncated 問題排查

本文選自“字節跳動基礎架構實踐”系列文章。

“字節跳動基礎架構實踐”系列文章是由字節跳動基礎架構部門各技術團隊及專家傾力打造的技術乾貨內容，和大家分享團隊在基礎架構發展和演進過程中的實踐經驗與教訓，與各位技術同學一起交流成長。

coredump 我們日常開發中經常會遇到，能夠幫助我們輔助定位問題，但如果 coredump 出現 truncate 會給排查問題帶來不便。本文以線上問題為例，藉助這個Case我們深入瞭解一下這類問題的排查思路，以及如何使用一些調試工具、閱讀內核源代碼，更清晰地瞭解coredump的處理過程。希望能為大家在排查這類問題的時候，提供一個清晰的脈絡。

問題背景

在 c/cpp 類的程序開發中進程遇到 coredump，偶爾會遇到 coredump truncate 問題，影響 core 後的問題排查。coredump truncate 大部分是由於 core limits 和剩餘磁盤空間引發的。這種比較好排查和解決。今天我們要分析的一種特殊的 case。

藉助這個 Case 我們深入瞭解一下這類問題的排查思路，使用一些調試工具和閱讀內核源代碼能更清晰的瞭解 coredump 的處理過程。能夠在排查這類問題的時候有個清晰的脈絡。

業務同學反饋在容器內的服務出 core 後 gdb 調試報錯。業務的服務運行在 K8S+Docker 的環境下，服務在容器內最終由 system 託管。 在部分機器上的 coredump 文件在 gdb 的時候出現如下警告，導致排查問題受影響。報錯信息如下：

<code>BFD: Warning: /tmp/coredump.1582242674.3907019.dp-b9870a84ea-867bccccdd-5hb7h 
is truncated: expected core file size >= 89036038144, found: 31395205120./<code>

導致的結果是 gdb 無法繼續調試。我們登錄機器後排查不是磁盤空間和 core ulimit 的問題。需要進一步排查。

名詞約定：

GDB：UNIX 及 UNIX-like 下的二進制調試工具，

Coredump： 核心轉儲，是操作系統在進程收到某些信號而終止運行時，將此時進程地址空間的內容以及有關進程狀態的其他信息寫出的一個磁盤文件。這種信息往往用於調試。

ELF： 可執行與可鏈接格式（Executable and Linkable Format），用於可執行文件、目標文件、共享庫和核心轉儲的標準文件格式。x86 架構上的類 Unix 操作系統的二進制文件格式標準。

BFD：

二進制文件描述庫(Binary File Descriptor library)是 GNU 項目用於解決不同格式的目標文件的可移植性的主要機制。

VMA： 虛擬內存區域（Virtual Memory Area），VMA 是用戶進程裡的一段 virtual address space 區塊，內核使用 VMA 來跟蹤進程的內存映射。

排查過程

用戶態排查

開始懷疑是自研的 coredump handler 程序有問題。於是還原系統原本的 coredump。

手動觸發一次 Coredump。結果問題依然存在。 現在排除 coredump handler 的問題。說明問題可能發生在 kernel 層或 gdb 的問題。

需要確定是 gdb 問題還是 kernel 吐 core 的問題。 先從 gdb 開始查起，下載 gdb 的源代碼找到報錯的位置（為了方便閱讀，源代碼的縮進進行了調整）。

目前看不是 gdb 的問題。coredump 文件寫入不完整。coredump 的寫入是由內核完成的。需要從內核側排查。

在排查之前觀察這個 coredump 的程序使用的內存使用非常大，幾十 G 規模。懷疑是否和其過大有關，於是做一個實驗。寫一個 50G 內存的程序模擬，並對其 coredump。

<code>#include 
#include 
#include 

int main(void){
        for( int i=0; i<1024>

經過測試正常吐 core。gdb 正常，暫時排除 core 大體積問題。

所以初步判斷是 kernel 在吐的 core 文件自身的問題。需要在進一步跟進。

查看內核代碼發現一處可疑點:

<code>/*
 * Ensures that file size is big enough to contain the current file
 * postion. This prevents gdb from complaining about a truncated file
 * if the last "write" to the file was dump_skip.
 */
void dump_truncate(struct coredump_params *cprm){
    struct file *file = cprm->file;
    loff_t offset;

    if (file->f_op->llseek && file->f_op->llseek != no_llseek) {
        offset = file->f_op->llseek(file, 0, SEEK_CUR);
        if (i_size_read(file->f_mapping->host) f_path.dentry, offset, 0, file);
    }
}/<code>

這段代碼的註釋引起了我們的注意。

現在懷疑在出現這個 case 的時候沒有執行到這個 dump_truncate 函數。於是嘗試把 dump_truncate 移到第二個位置處。重新編譯內核嘗試。 重新打了測試內核測試後問題依然存在。

於是繼續看代碼:

這段代引起了注意。懷疑某個時刻執行 get_dump_page 的時候返回了 NULL。然後走到了 dump_skip 函數，dump_skip 返回 0，導致 goto end_coredump。於是 stap 抓下。

不出所料，dump_skip 返回 0 後 coredump 停止。

也就是說第二階段只 dump 了一部分 vma 就停止了。 導致 coredump 寫入不完整。

VMA 部分 dump 分析

再看下 dump_skip 函數:

<code>int dump_skip(struct coredump_params *cprm, size_t nr){
    static char zeroes[PAGE_SIZE];
    struct file *file = cprm->file;
    if (file->f_op->llseek && file->f_op->llseek != no_llseek) {
        if (dump_interrupted() ||
            file->f_op->llseek(file, nr, SEEK_CUR) pos += nr;
        return 1;
    } else {
        while (nr > PAGE_SIZE) {
            if (!dump_emit(cprm, zeroes, PAGE_SIZE))
                return 0;
            nr -= PAGE_SIZE;
        }
        return dump_emit(cprm, zeroes, nr);
    }
}/<code>

因為 coredump 是 pipe 的，所以是沒有 llseek 操作的，因此會走到 else 分支裡。也就是 dump_emit 返回 0 導致的。於是 stap 抓下 dump_emit 函數:

<code>function func:string(task:long)
%{
    snprintf(STAP_RETVALUE, MAXSTRINGLEN, "%s", signal_pending(current) ? "true" : "false");
%}

probe kernel.function("dump_emit").return
{
    printf("return: %d, cprm->limit:%d, cprm->written: %d, signal: %s\n", $return, @entry($cprm->limit), @entry($cprm->written), func($return));
}/<code>

結果如下：

<code>return: 1, cprm->limit:-1, cprm->written: 0, signal: false
return: 1, cprm->limit:-1, cprm->written: 64, signal: false
return: 1, cprm->limit:-1, cprm->written: 120, signal: false
... 省略9221238行 ...
return: 1, cprm->limit:-1, cprm->written: 37623402496, signal: false
return: 1, cprm->limit:-1, cprm->written: 37623406592, signal: false
return: 1, cprm->limit:-1, cprm->written: 37623410688, signal: false
return: 0, cprm->limit:-1, cprm->written: 37623414784, signal: true/<code>

不出意外和懷疑的一致，dump_emit 返回 0 了，此時寫入到 core 文件的有 37623414784 字節。主要因為 dump_interrupted 檢測條件為真。(cprm->limit = -1 不會進入 if 邏輯，kernrel_wirte 寫 pipe 也沒有出錯)。

下面我們看 dump_interrupted 函數。為了方便閱讀，整理出相關的函數：

<code>static bool dump_interrupted(void){
    /*
     * SIGKILL or freezing() interrupt the coredumping. Perhaps we
     * can do try_to_freeze() and check __fatal_signal_pending(),
     * but then we need to teach dump_write() to restart and clear
     * TIF_SIGPENDING.
     */
    return signal_pending(current);
}

static inline int signal_pending(struct task_struct *p){
    return unlikely(test_tsk_thread_flag(p,TIF_SIGPENDING));
}
static inline int test_tsk_thread_flag(struct task_struct *tsk, int flag){
    return test_ti_thread_flag(task_thread_info(tsk), flag);
}
static inline int test_ti_thread_flag(struct thread_info *ti, int flag){
    return test_bit(flag, (unsigned long *)&ti->flags);
}

/**
 * test_bit - Determine whether a bit is set
 * @nr: bit number to test
 * @addr: Address to start counting from
 */
static inline int test_bit(int nr, const volatile unsigned long *addr){
    return 1UL & (addr[BIT_WORD(nr)] >> (nr & (BITS_PER_LONG-1)));
}/<code>

相關的宏：

<code>#ifdef CONFIG_64BIT
#define BITS_PER_LONG 64
#else
#define BITS_PER_LONG 32
#endif /* CONFIG_64BIT */
#define TIF_SIGPENDING      2   /* signal pending */ 平臺相關。以X64架構為例。
/<code>

有上面的代碼就很清楚 dump_interrupted 函數就是檢測 task 的 thread_info->flags 是否 TIF_SIGPENDING 置位。

目前懷疑還是和用戶的內存 vma 有關。但什麼場景會觸發 TIF_SIGPENDING 置位是個問題。dump_interrupted 函數的註釋中已經說明了，一個是接收到了 KILL 信號，一個是 freezing()。 freezing()一般和 cgroup 有關，一般是 docker 在使用。KILL 有可能是 systemd 發出的。 於是做了 2 個實驗：

實驗一：

<code>systemd啟動實例，bash裸起服務，不接流量。
測試結果gdb正常...
然後再用systemd起來，不接流量。測試結果也是正常的。
這就奇怪了。但是不能排除systemd。
回想接流量和不接流量的區別是coredump的壓縮後的體積大小不同，不接流
量vma大都是空，空洞比較多，因此coredump非常快，有流量vma不是空
的，coredump比較慢。因此懷疑和coredump時間有關係，超過某個時間就
有TIF_SIGPENDING被置位。
/<code> 

實驗二：

<code>是產生一個50G的內存。代碼如最上方。
在容器內依然使用systemd啟動一個測試程序
（直接在問題容器內替換這個bin。然後systemctl重啟服務）
然後發送SEGV信號。stap抓一下。
coredump很漫長。等待結果
結果很意外。core正常，gdb也正常。/<code>

這個 TIF_SIGPENDING 信號源是個問題。

還有個排查方向就是 get_dump_page 為啥會返回 NULL。 所以現在有 2 個排查方向：

1. 需要確定 TIF_SIGPENDING 信號源。
2. get_dump_page 返回 NULL 的原因。

get_dump_page 返回 NULL 分析

首先看 get_dump_page 這個返回 NULL 的 case：

<code>* Returns NULL on any kind of failure - a hole must then be inserted into
 * the corefile, to preserve alignment with its headers; and also returns
 * NULL wherever the ZERO_PAGE, or an anonymous pte_none, has been found -
 * allowing a hole to be left in the corefile to save diskspace./<code>

看註釋返回 NULL，一個是 page 是 ZERO_PAGE，一個是 pte_none 問題。

首先看 ZREO 問題，於是構造一個 ZERO_PAGE 的程序來測試：

<code>#include 
#include 
#include 

const int BUFFER_SIZE = 4096 * 1000;
int main(void){
    int i = 0;
    unsigned char* buffer;
    for( int n=0; n<10240>

測試結果是 coredump 正常，同時 trace 一下 get_dump_page 的返回值。 結果和預想的有些不同，返回了很多個 NULL。 說明和 get_dump_page 函數的因素不大。

於是轉向到 TIF_SIGPENDING 信號發生源。

TIF_SIGPENDING 信號來源分析

bpftrace 抓一下看看：

<code>#!/usr/bin/env bpftrace
#include 

kprobe:__send_signal
{
        $t = (struct task_struct *)arg2;
        if ($t->pid == $1) {
                printf("comm:%s(pid: %d) send sig: %d to %s\n", comm, pid, arg0, $t->comm);
        }
}/<code>

結果如下：

結果比較有趣。kill 和 systemd 打斷了 coredump 進程。信號 2(SIGINT)和信號 9(SIGKILL)都足以打斷進程。 現在問題變為 kill 和 systemd 為什麼會發送這 2 個信號。一個懷疑是超時。coredump 進程為 not running 太久會不會觸發 systemd 什麼機制呢。

於是查看了 systemd service 的 doc 發現這樣一段話：

TimeoutAbortSec=
This option configures the time to wait for the service to terminate when it was aborted due to a watchdog timeout (see WatchdogSec=). If the service has a short TimeoutStopSec= this option can be used to give the system more time to write a core dump of the service. Upon expiration the service will be forcibly terminated by SIGKILL (see KillMode= in systemd.kill(5)). The core file will be truncated in this case. Use TimeoutAbortSec= to set a sensible timeout for the core dumping per service that is large enough to write all expected data while also being short enough to handle the service failure in due time.
Takes a unit-less value in seconds, or a time span value such as "5min 20s". Pass an empty value to skip the dedicated watchdog abort timeout handling and fall back TimeoutStopSec=. Pass "infinity" to disable the timeout logic. Defaults to DefaultTimeoutAbortSec= from the manager configuration file (see systemd-system.conf(5)).
If a service of Type=notify handles SIGABRT itself (instead of relying on the kernel to write a core dump) it can send "EXTEND_TIMEOUT_USEC=…" to extended the abort time beyond TimeoutAbortSec=. The first receipt of this message must occur before TimeoutAbortSec= is exceeded, and once the abort time has exended beyond TimeoutAbortSec=, the service manager will allow the service to continue to abort, provided the service repeats "EXTEND_TIMEOUT_USEC=…" within the interval specified, or terminates itself (see sd_notify(3)).

標紅的字引起了注意，於是調大一下(TimeoutAbortSec="10min")再試。無效...

無效後就很奇怪，難道 system 都不是信號的發起者，是信號的"傳遞者"? 現在有 2 個懷疑，一個是 systemd 是信號的發起者，一個是 systemd 不是信號的發起者，是信號的“傳遞者”。於是這次同時抓業務進程和 systemd 進程看看。 結果如下：

其中 3533840 是容器的 init 進程 systemd。3533916 是業務進程。和預想的一樣，systemd 並不是信號的第一個發起者。systemd 是接收到 runc 的信號 15（SIGTERM）而停止的，停止前會對子進程發起 kill 行為。也就是最後的 systemd send sig。

有個疑問就來了，之前用程序 1 測試了 system+docker 的場景，沒有復現，回想一下 coredump 的過程應該是這樣的，程序 1 沒有對每個 page 都寫，只寫了一個 malloc 之後的第一個 page 的第一個一個字節。coredump 在遍歷每個 vma 的時候耗時要比都寫了 page 要快很多（因為沒有那麼多空洞，VMA 不會那麼零碎）。coredump 體積雖然大，但時間短，因此沒有觸發這個問題，對於排查這個問題帶來一定的曲折。

於是排查方向轉到 kill 命令和 runc。 經過排查發現 K8S 的一個 lifecycle 中的 prestop 腳本有 kill 行為。 把這個腳本停到後再次抓一下：

這次沒有 kill 行為，但是 systemd 還是被 runc 殺死了，發送了 2 個信號，一個是 SIGTERM，一個是 SIGKILL。 現在解釋通了 kill 信號的來源，這也就解釋了 kill 的信號來源。其實 kill 和 systemd 的信號根源間接或直接都是 runc。runc 的銷燬指令來自 k8s。

於是根據 K8S 的日誌繼續排查。經過排查發現最終的觸發邏輯是來自字節內部實現的 Load 驅逐。該機制當容器的 Load 過高時則會把這個實例驅逐掉，避免影響其他實例。 因為 coredump 的時候 CPU 會長期陷入到內核態，導致 load 升高。所以 I 引發了 Pod 驅逐。

coredump 期間實例的負載很高，導致 k8s 的組件 kubelet 的觸發了 load 高驅逐實例的行為。刪除 pod。停止 systemd。殺死正在 coredump 的進程，最終導致 coredump 第二階段寫 vma 數據未完成。

驗證問題

在做一個簡單的驗證，停止 K8S 組件 kubelet，然後對服務發起 core。最後 gdb。 驗證正常，gdb 正常讀取數據。 至此這個問題就排查完畢了。 最後修改內部實現 cgroup 級的 Load（和整機 load 近似的採集數據的方案）採集功能，過濾 D 狀態的進程（coredump 進程在用戶態表現為 D 狀態）後，這個問題徹底解決。

總結

本次 coredump 文件 truncate 是因為 coredump 的進程被殺死（SIGKILL 信號）導致 VMA 沒有寫入完全（只寫入了一部分）導致，。 解決這個問題通過閱讀內核源代碼加以使用 bpftrace、systemtap 工具追蹤 coredump 的過程。打印出關心的數據，藉助源代碼最終分析出問題的原因。同時我們對內核的 coredump 過程有了一定的瞭解。

最後，歡迎加入字節跳動基礎架構團隊，一起探討、解決問題，一起變強！

附：coredump 文件簡單分析

在排查這個問題期間也閱讀了內核處理 coredump 的相關源代碼，簡單總結一下:

coredump 文件其實是一個精簡版的 ELF 文件。coredump 過程並不複雜。 coredump 的過程分為 2 個階段，一個階段是寫 program header（第一個 program header 是 Note Program Header）,每個 program header 包含了 VMA 的大小和在文件的偏移量。gdb 也是依此來確定每個 VMA 的位置的。另一個階段是寫 vma 的數據，遍歷進程的所有 vma。然後寫入文件。 一個 coredump 文件的結構可以簡單的用如下圖的結構表示。

參考文獻

1. Binary_File_Descriptor_library
2. systemd.service — Service unit configuration
3. Kubernets Pod Lifecycle

更多分享

字節跳動在 RocksDB 存儲引擎上的改進實踐

字節跳動自研萬億級圖數據庫&圖計算實踐

深入理解 Linux 內核--jemalloc 引起的 TLB shootdown 及優化

字節跳動基礎架構團隊

字節跳動基礎架構團隊是支撐字節跳動旗下包括抖音、今日頭條、西瓜視頻、火山小視頻在內的多款億級規模用戶產品平穩運行的重要團隊，為字節跳動及旗下業務的快速穩定發展提供了保證和推動力。

公司內，基礎架構團隊主要負責字節跳動私有云建設，管理數以萬計服務器規模的集群，負責數萬臺計算/存儲混合部署和在線/離線混合部署，支持若干 EB 海量數據的穩定存儲。

文化上，團隊積極擁抱開源和創新的軟硬件架構。我們長期招聘基礎架構方向的同學，具體可參見 job.bytedance.com （文末“閱讀原文”），感興趣可以聯繫郵箱 [email protected]。

歡迎關注字節跳動技術團隊