摘要：trace_noschedule 只會針對內核態執行時間超過閾值不調度的進程記錄 stack trace。stack_trace 記錄佔用 CPU 時間超過閾值不調度進程的棧。

本文是由字節跳動系統部 STE 團隊出品的“kernel trace tools”系列文章之一，以介紹團隊自研多類延遲問題追蹤工具。

在實際工作中，會遇到由於內核態不調度而引發的高網絡延遲或者卡頓問題。但是，對於該類問題的定位和追蹤缺乏行之有效的方案或客觀依據，需要耗費大量時間和精力用於問題排查，trace-noschedule 工具便是在該背景下誕生的自研工具。

目前，trace-noschedule 已開源，感興趣詳見 Open Source Repo：

（ https://github.com/bytedance/trace-noschedule ）

1. 問題背景

在實際項目實踐中，我們經常會遇到延遲高導致的問題。由於我們服務器的內核默認配成內核態不支持搶佔，因此不搶佔這點也是可能導致問題的原因之一。例如 A 進程陷入內核態執行時間過長，必然影響其他希望在該核運行的進程。此時就會導致調度延遲。針對這種 case，我們開發了一款工具專門跟蹤陷入內核態長時間不調度的進程。這對於我們排查問題可以有一定的指導方向。同時如果是此類原因導致的延遲，也可以快速定位問題原因。

2. 我們想做什麼

當一個進程陷入內核態時，我們應該記錄其時間戳。當離開內核時，再一次記錄時間戳。然後求差值即可得到進程在內核態運行的時間。思路比較清晰。

3. 如何實現

我們知道應用程序陷入內核態的方式主要是系統調用。我們是否可以通過系統調用提供的 tracepoint 完成呢？當系統調用開始，記錄時間戳，系統調用退出，再次記錄時間戳。求差值，就是本次系統調用花費的時間。這種方法是否可靠？很明顯不可靠。因爲進程在內核態很可能由於資源不滿足導致主動 schedule。這種情況下，根本不是一直佔用 CPU 不調度的情況。因此，這種方法不可行。

既然系統調用這條路走不通，我們就換一種方式。我們知道一個線程執行的生命週期，起於 schedule，止於 schedule。所以我們可以知道一個線程從開始執行到主動或被動放棄 CPU 之間的時間差。這部分時間是總時間，即 user+kernel 的時間。我們是否有辦法獲取總時間呢？很幸運我們有 schedule 的 tracepoint 可以獲取。

static void __sched notrace __schedule(bool preempt)
{
    /* ... */
    trace_sched_switch(preempt, prev, next);
    /* ... */
}

我們只需要 enable sched_switch 即可獲取每個線程執行的總時間。是不是激動的心，顫抖的手，是不是馬上想用 bcc 行動了？但是有個新的問題擺在我們面前，如何過濾掉 user 態執行的時間？因爲用戶態支持搶佔，內核態不支持搶佔。所以統計內核態的時間纔是有意義的。

過濾用戶態執行時間可以間接的通過定時器實現。我們知道週期性定時中斷，可以獲取被打斷的上下文是用戶態或者內核態。所以開始時間戳 last 需要不斷的更新。第一次是從 schedule 開始，後面每次更新是在定時器中斷中，如果發現當前中斷是打斷的用戶態，那麼更新 last 時間戳，否則不更新。此刻認爲用戶線程在內核態執行。我們看下示例代碼。

static enum hrtimer_restart trace_nosched_hrtimer_handler(struct hrtimer *hrtimer)
{
        /*
         * Skip the idle task and make sure we are not only the
         * running task on the CPU. If we are interrupted from
         * user mode, it indicate that we are not executing in
         * the kernel space, so we should also skip it.
         */
        if (!is_idle_task(current) && regs && !user_mode(regs) &&
            !single_task_running()) {
                /* The kernel mode */
                /*
                 * If the execution time exceeds the threshold, record
                 * the call trace.
                 */
        } else {
                /* The user mode */
                stack_trace->last_timestamp = now;
        }
}

我們看到不更新時間戳的條件比較苛刻。主要考慮以下幾種情況：

  • 如果中斷時從用戶態發生，則更新 last_timestamp 時間戳。

  • 如果當前 CPU 運行隊列只有一個 task，更新 last_timestamp 時間戳。因爲這種情況下，佔有 CPU 不放沒有任何問題。

  • 如果當前進程是 idle 進程，同樣更新 last_timestamp 時間戳。因爲 idle 進程本身就可能在內核態長時間運行，沒有任何問題。

我們再看下 tracepoint 的 hook 函數實現。

static void probe_sched_switch(void *priv, bool preempt,
                               struct task_struct *prev,
                               struct task_struct *next)
{
        u64 now = local_clock();
        u64 last = cpu_stack_trace->last_timestamp;
        cpu_stack_trace->last_timestamp = now;
        /*
         * Skip the idle task and make sure we are not only the
         * running task on the CPU.
         */
        if (!is_idle_task(prev) && !single_task_running())
                hist_update(cpu_stack_trace, now - last);
}

記錄時間差值，差不多可以認爲是內核態執行的時間。當操作設定閾值，我們更新柱狀圖統計計數。

4. 如何安裝

安裝 trace-noschedule 工具很簡單，git clone 代碼後執行如下命令即可安裝。

make -j8
make install

5. 如何使用

安裝 trace-noschedule 工具成功後。會創建如下 /proc/trace_noschedule 目錄。

root@n18-061-206:/proc/trace_noschedule# ls
distribution  enable  stack_trace  threshold

/proc/trace_noschedule 目錄下存在 4 個文件，分別：distribution, enable, stack_trace 和 threshold。工具安裝後，默認是關閉狀態。

5.1 打開 tracer

執行以下命令打開 tracer。

echo 1 > /proc/trace_noschedule/enable

5.2 關閉 tracer

執行如下命令關閉 tracer。

echo 0 > /proc/trace_noschedule/enable

Note : debug 問題後請記得關閉 tracer。因爲模塊內部實現基於 sched tracepoint，overhead 不能忽略。

5.3 設置閾值

trace_noschedule 只會針對內核態執行時間超過閾值不調度的進程記錄 stack trace。爲了更高效的運作，我們有必要設定一個合理閾值。例如設置 60ms 的閾值(單位：ns)：

echo 60000000 > /proc/trace_noschedule/threshold

5.4 查看內核態長時間未調度進程執行的時間分佈。

root@n18-061-206:/proc/trace_noschedule# cat distribution
Trace noschedule thread:
         msecs           : count     distribution
        20 -> 39         : 1        |**********                              |
        40 -> 79         : 0        |                                        |
        80 -> 159        : 4        |****************************************|
       160 -> 319        : 2        |********************                    |

在內核態有 4 次執行時間在[80, 159]ms 範圍內沒有調度。

5.5 是誰佔用 CPU 不調度

stack_trace 記錄佔用 CPU 時間超過閾值不調度進程的棧。

root@n18-061-206:/proc/trace_noschedule# cat stack_trace
 cpu: 0
     COMM: sh PID: 1270013 DURATION: 100ms
     delay_tsc+0x21/0x50
     nosched_test_write+0x53/0x90 [trace_noschedule]
     proc_reg_write+0x36/0x60
     __vfs_write+0x33/0x190
     vfs_write+0xb0/0x190
     ksys_write+0x52/0xc0
     do_syscall_64+0x4f/0xe0
     entry_SYSCALL_64_after_hwframe+0x44/0xa9

這是個內核態測試的 case，在內核態執行 mdelay(100)佔用 CPU 100ms 不調度。此時記錄的棧如上面所示。"DURATION"記錄的就是執行持續時間。

5.6 清除 stack trace

如果我們需要清除 stack trace 記錄的信息（stack trace buffer 是有大小限制的，必要的時候需要 clear）。

echo 0 > /proc/trace_noschedule/stack_trace

6. 案例展示

這裏以一個實際問題帶你瞭解工具的使用。問題是背景是，業務發現 docker 好像有問題，pull 不下來鏡像。登錄機器會卡頓，執行很多命令也會卡頓。

6.1 首先看下 CPU 使用情況。

有幾個 CPU 100%，而且還是 sys 態使用。系統究竟在幹嗎？

6.2 使用 perf 工具

使用 perf top 看下 CPU 情況，發現 60%左右的時間在 spinlock 上。但是沒看出內核哪個路徑的 spinlock。使用 trace-noschedule 工具看看是否有發現。

6.3 trace-noschedule 跟蹤

root@n131-103-013:/proc/trace_noschedule# cat distribution
Trace noschedule thread:
         msecs           : count     distribution
        20 -> 39         : 760      |****************************************|
        40 -> 79         : 488      |*************************               |
        80 -> 159        : 73       |***                                     |

內核態長時間未調度，而且時間很長。看下工具記錄的棧信息，截取如下：

COMM: runc PID: 499045 DURATION: 75ms
     native_queued_spin_lock_slowpath+0x112/0x190
     _raw_spin_lock+0x1d/0x20
     prepend_path+0x266/0x2d0
     __d_path+0x4b/0x80
     seq_path_root+0x53/0xb0
     show_mountinfo+0xb8/0x290
     seq_read+0x321/0x3f0
     __vfs_read+0x33/0x160
     vfs_read+0x91/0x130
     SyS_read+0x52/0xc0
     do_syscall_64+0x68/0x100
     entry_SYSCALL_64_after_hwframe+0x3d/0xa2
COMM: falcon-agent PID: 3002056 DURATION: 114ms
     native_queued_spin_lock_slowpath+0x10f/0x190
     _raw_spin_lock+0x1d/0x20
     prepend_path+0x266/0x2d0
     __d_path+0x4b/0x80
     seq_path_root+0x53/0xb0
     show_vfsmnt+0x7a/0x170
     seq_read+0x321/0x3f0
     __vfs_read+0x33/0x160
     vfs_read+0x91/0x130
     SyS_read+0x52/0xc0
     do_syscall_64+0x68/0x100
     entry_SYSCALL_64_after_hwframe+0x3d/0xa2

說明內核態確實一直在 spin。主要集中在以上兩個路徑文件的讀取。分別是 /proc/$pid/mounts 和 /proc/$pid/mountinfo 文件。

6.4 查看 mountinfo 信息

可能是 mount 太多，導致遍歷時間很久。而且長時間持鎖。

root@n131-103-013:/var/log/atop# mount -v | wc -l
65803

確實很多，65803 多個。大量的/dev/shm 掛載。以下信息只是其中一部分展示。既然知道了問題原因就可以對症下藥了，下一步就是排查爲什麼/dev/shm 掛載很多。這讓我們很快定位問題原因。

7. 總結

根據字節內部實踐來看，trace-noschedule 安裝便捷且使用靈活度高，能將問題定位耗時縮短至分鐘級別，使用收益可觀，並且已經通過該工具定位一些，提高了工作效率。

更多分享

Kernel trace tools（一）：中斷和軟中斷關閉時間過長問題追蹤

字節跳動混沌工程實踐總結

gdb 提示 coredump 文件 truncated 問題排查

字節跳動系統部 STE 團隊

字節跳動系統部 STE 團隊一直致力於操作系統內核與虛擬化、系統基礎軟件與基礎庫的構建和性能優化、超大規模數據中心的穩定性和可靠性建設、新硬件與軟件的協同設計等基礎技術領域的研發與工程化落地，具備全面的基礎軟件工程能力，爲字節上層業務保駕護航。同時，團隊積極關注社區技術動向，擁抱開源和標準。歡迎更多有志之士加入，如有意向可發送簡歷至 [email protected] 。

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

  點擊閱讀原文，快來加入我們吧！

相關文章