BCC小白寫測試上下文切換延時程序

下文Linux內核版本5.4

學習興趣起源于論文《Linux上下文切換性能測試的一種新方法》的閱讀，該論文提出了一種在用戶態編寫應用程序并且調用schedu_yield()系統調用主動放棄處理器實現任務切換的測試方法，然后與傳統的使用管道讀寫切換、在內核態測試context_switch()函數的開銷等方法進行了對比分析（傳統方法分析見下圖），最后結果表明，使用該方法測試上下文切換的準確性和便捷性均有所提高。

論文中提出的新方法有個明顯的缺陷：原理上獲得的上下文切換延時還包含了系統調用等其他指令的開銷 overhead，但是他這個用戶態的程序無法測量也無法避免這個overhead。

結合所學知識，受此啟發：直接對內核函數context_switch()進行測試才是最準確最可靠的方法，因此可以寫一個ebpf程序直接對context_switch()函數進行測試，這樣的ebpf程序不僅測試出來的結果更加準確，而且操作起來也很方便，于是就有了下面的學習歷程。

首先是整理思路，作為eBPF小白的我一開始也是一籌莫展，于是翻看起了《BPF之巔 ?洞悉Linux系統和應用性能》這本書，書中有這么幾個地方很受啟發：

• P57：

由于：

內核中沒有context_switch的靜態跟蹤點，所以這里選擇用kprobes動態跟蹤。（這里忘記對kprobe進行查詢，導致下面繞了一波遠路，這也提醒學者在寫eBPF程序之前一定要先找探針）

• P49：

kprobes 可以對任何內核函數進行插樁，它還可以對函數內部的指令進行插樁。它可以實時在生產環境系統中啟用，不需要重啟系統，也不需要以特殊方式重啟內核。這是一項令人驚嘆的能力，這意味著我們可以對 Linux 中數以萬計的內核函數任意插樁根據需要生成指標。

kprobes 技術還有另外一個接口，即 kretprobes，用來對內核函數返回時進行插樁以獲取返回值。當用 kprobes 和 kretprobes 對同一個函數進行插時，可以使用時間戳來記錄函數執行的時長。這在性能分析中是一個重要的指標。

• P52：

BCC：attach_kprobe 和 attach_kretprobe

于是我就準備從kprobes和kretprobes這兩種探針入手，對context_switch函數的執行時長進行測量。

最后就是實踐了，我利用不同的映射輸出函數寫了三個版本，每個版本都是上一個版本的優化。

（一）起初代碼

主要涉及函數：

• bpf_trace_printk()

????語法: int bpf_trace_printk(const char *fmt, ...)

????Return: 0 on success

??? printf()到公共trace_pipe (/sys/kernel/debug/tracing/trace_pipe)的一個簡單的內核工具。對于一些快速示例，這是可以的，但有限制:最多3個args，只有1% s，并且trace_pipe是全局共享的。

• trace_print()

????語法: BPF.trace_print(fmt="fields")

????該方法持續讀取全局共享的/sys/kernel/debug/tracing/trace_pipe文件并打印其內容。可以通過BPF和bpf_trace_printk()函數寫入該文件。

????fmt: 可選，并且可以包含字段格式字符串。默認為None。

cs.c 代碼如下：

#include 

BPF_HASH(start, u32);

int do_entry(struct pt_regs *ctx)????????//pt_regs結構定義了在系統調用或其他內核條目期間將寄存器存儲在內核堆棧上的方式
{
????????u32 pid;
????????u64 ts;

????????pid = bpf_get_current_pid_tgid();
    ????????ts = bpf_ktime_get_ns();????????    //bpf_ktime_get_ns返回自系統啟動以來所經過的時間(以納秒為單位)。不包括系統掛起的時間。
????????start.update(&pid,&ts);
????????return 0;
}

int do_return(struct pt_regs *ctx)
{
????????u32 pid;
????????u64 *tsp, delta;

????????pid = bpf_get_current_pid_tgid();
????????tsp = start.lookup(&pid);

????????if (tsp != 0) {
        ????????????????delta = bpf_ktime_get_ns() - *tsp;????????      //獲得context_switch函數執行時間
        ????????????????bpf_trace_printk("The time of context_switch is %lu.\n",delta/1000); 
        ????????????????start.delete(&pid);
}

????????return 0;
}

cs.py 代碼如下：

from __future__ import print_function
from bcc import BPF

# load BPF program
b = BPF(src_file = "cs.c")
b.attach_kprobe(event="context_switch", fn_name="do_entry")
b.attach_kretprobe(event="context_switch", fn_name="do_return")

b.trace_print()

運行結果，遇到如下問題：

一開始以為是因為context_switch函數沒有被導出的原因，經師兄提醒，查看了下探針：

發現沒有context_switch的kprobe，相關函數學習：

nr_context_switches????????     //統計目前所有處理器總共的context switch次數
paravirt_end_context_switch????????     //和半虛擬化相關
paravirt_start_context_switch
rcu_note_context_switch????????         //更新全局狀態為RCU，標識當前CPU發生上下文的切換
xen_end_context_switch????????          //和虛擬話技術相關

這些函數和上下文切換時間的計算都關聯不上。

教訓：在編寫BCC程序時，一定要先用bpftrace查看一下該插樁點是否存在！

（二）糾正代碼

退一步，如果無法對context_switch函數進行跟蹤，那么對內核函數schedule進行跟蹤就是最好地選擇（不存在__schedule函數的探針），雖然存在一定的誤差，但是相比于通過用戶態程序測量更加準確，相比于在內核里插樁測試更加簡便，經查詢，schedule函數只存在動態插樁點位：

schedule() 源碼：

asmlinkage __visible void __sched schedule(void)
{
????????struct task_struct *tsk = current;

    ????????sched_submit_work(tsk);????????     //sched_submit_work用于檢測當前進程是否有plugged io需要處理，由于當前進程執行schedule后，有可能會進入休眠，所以在休眠之前需要把plugged io處理掉，防止死鎖。
????????do {
????????????????preempt_disable();????????      //禁止搶占
        ????????????????__schedule(false);????????      //->context_switch      false為禁用搶占標志
        ????????????????sched_preempt_enable_no_resched();????????      //開啟內核搶占
    ? ? ????} while (need_resched());????????   //檢查當前進程是否設置了重調度標志
    ????????sched_update_worker(tsk);?????//更新worker的信息,告訴工作隊列我又回來了
}

對于數據的輸出，由于bpf_trace_printk()是把數據寫到公共trace_pipe，可能與其他程序和跟蹤器沖突，因此選用BPF_PERF_OUTPUT()進行數據的輸出，它的工作原理是創建一個BPF表，用于通過緩沖區向用戶空間推出自定義事件數據。這是將每個事件數據推入用戶空間的首選方法。

主要涉及函數：

• BPF_PERF_OUTPUT

????語法: BPF_PERF_OUTPUT(name)

????創建一個BPF表，用于通過緩沖區向用戶空間推出自定義事件數據。這是將每個事件數據推入用戶空間的首選方法。

• perf_submit()

????語法: int perf_submit((void *)ctx, (void *)data, u32 data_size)

????Return: 0 on success

??? BPF_PERF_OUTPUT表的方法，用于向用戶空間提交自定義事件數據。

????ctx參數在kprobes或kretprobes中提供。對于SCHED_CLS或SOCKET_FILTER程序，必須改用struct __sk_buff *skb。

• open_perf_buffer()

????語法: table.open_perf_buffers(callback, page_cnt=N, lost_cb=None)

????它對BPF中定義為BPF_PERF_OUTPUT()的表進行操作，并關聯回調Python函數callback，以便在性能環緩沖區中有可用數據時調用。這是將每個事件數據從內核傳輸到用戶空間的推薦機制的一部分。緩沖區的大小可以通過page_cnt參數指定，該參數必須是兩頁數的冪，默認為8。如果回調處理數據的速度不夠快，一些提交的數據可能會丟失。lost_cb將被調用來記錄/監視丟失的計數。如果lost_cb 是默認的None值，它將只打印一行消息到stderr。

• perf_buffer_poll()

????語法: BPF.perf_buffer_poll(timeout=T)

????它從所有打開的性能環緩沖區輪詢，調用為每個條目調用open_perf_buffer時提供的回調函數。

??? timeout參數是可選的，以毫秒為單位。如果沒有它，輪詢將無限期地繼續進行。

cs.c 代碼如下：

#include 

struct data_t{
????????u64 t1;
????????u64 t2;
????????u64 delay;
};

BPF_PERF_OUTPUT(events);
BPF_HASH(start, u32);

int do_entry(struct pt_regs *ctx)????????//pt_regs結構定義了在系統調用或其他內核條目期間將寄存器存儲在內核堆棧上的方式
{
????????u32 pid;
????????u64 ts;

????????pid = bpf_get_current_pid_tgid();
    ????????ts = bpf_ktime_get_ns()/1000;????????   //bpf_ktime_get_ns返回自系統啟動以來所經過的時間(以納秒為單位)。不包括系統掛起的時間。
????????start.update(&pid,&ts);

????????return 0;
}

int do_return(struct pt_regs *ctx)
{
????????struct data_t data={};
????????data.t2= bpf_ktime_get_ns()/1000;
????????u32 pid;
????????u64 *tsp, delta;

????????pid = bpf_get_current_pid_tgid();
????????tsp = start.lookup(&pid);

????????if (tsp != 0) {
????????????????data.t1 = *tsp;
????????????????data.delay = data.t2 - data.t1;
????????????????start.delete(&pid);
????????????????events.perf_submit(ctx,&data,sizeof(data));
????????}

????????????????return 0;
}

cs.py 代碼如下：

from __future__ import print_function
from bcc import BPF
import time

# load BPF program
b = BPF(src_file = "cs.c")
b.attach_kprobe(event="schedule", fn_name="do_entry")
b.attach_kretprobe(event="schedule", fn_name="do_return")

print("Tracing for Data's... Ctrl-C to end")

#聲明了一個名為print_event()的回調函數,用于處理來自perf緩沖區的一個事件
def print_event(cpu, data, size):
????????event = b["events"].event(data)
????????print("t1:%d  t2:%d  delay:%d" % (event.t1,event.t2,event.delay))

#將回調函數注冊到名為events的perf事件緩沖區
b["events"].open_perf_buffer(print_event)
while 1:
????????try:
 ??????????????? b.perf_buffer_poll()????????#輪詢打開perf緩沖區。如果有事件，回調函數會執行
????????????????time.sleep(1)           
??????? except KeyboardInterrupt:????????#Python的except用來捕獲所有異常， 因為Python里面的每次錯誤都會拋出 一個異常，所以每個程序的錯誤都被當作一個運行時錯誤。捕獲指定異常except <異常名>
????????????????exit()

cs.py 代碼中time.sleep(1)說明：由于上下文切換延時特別小，因此schedule函數的觸發非常頻繁，每次b.perf_buffer_poll()的輸出數據都特別多，會導致ctrl+c很難搶占到CPU對這個程序關閉，所以得加入time.sleep(1)以使得能有時間間隙去關閉該程序

避坑：加載到內核中的代碼（這里即cs.c ）不要用全局變量，用map相關函數

運行結果：

弊端：雖然可以正常運行，但是事件發生地很頻繁，導致輸出過快、輸出量過大，不能直觀的了解到數據的情況。

（三）優化代碼

可以對事件進行匯總后再輸出，打印為以2為冪的直方圖。

主要涉及函數：

• BPF_HISTOGRAM

????語法: BPF_HISTOGRAM(name [, key_type [, size ]])

????創建一個名為name的直方圖映射，帶有可選參數。

????默認: BPF_HISTOGRAM(name, key_type=int, size=64)

• map.increment()

????語法: map.increment(key[, increment_amount])

????按 increment_amount增加鍵的值，默認為1。用于直方圖。

• bpf_log2l()

????語法: unsigned int bpf_log2l(unsigned long v)

????返回所提供值的log-2。這通常用于為直方圖創建索引，以構造2次方的直方圖。

• print_log2_hist()

????語法: table.print_log2_hist(val_type="value", section_header="Bucket ptr", section_print_fn=None)

????將表打印為ASCII中的log2直方圖。表必須存儲為log2，這可以使用BPF函數 bpf_log2l()來實現。

????參數：val_type: 可選，列標題；section_header: 如果直方圖有一個輔助鍵，那么將打印多個表，section_header可以用作每個表的頭描述；section_print_fn: 如果section_print_fn不是None，它將被傳遞桶值。

cs.c 代碼如下：

#include 

BPF_HASH(start, u32);
BPF_HISTOGRAM(dist);

int do_entry(struct pt_regs *ctx)????????//pt_regs結構定義了在系統調用或其他內核條目期間將寄存器存儲在內核堆棧上的方式
{
    ????????u64 t1= bpf_ktime_get_ns()/1000;????????    //bpf_ktime_get_ns返回自系統啟動以來所經過的時間(以納秒為單位)。不包括系統掛起的時間。;
????????u32 pid = bpf_get_current_pid_tgid();
????????start.update(&pid,&t1);

????????return 0;
}

int do_return(struct pt_regs *ctx)
{
????????u64 t2= bpf_ktime_get_ns()/1000;
????????u32 pid;
????????u64 *tsp, delay;

????????pid = bpf_get_current_pid_tgid();
????????tsp = start.lookup(&pid);

????????if (tsp != 0)
????????{
????????????????delay = t2 - *tsp;
????????????????start.delete(&pid);
????????????????dist.increment(bpf_log2l(delay));
????????}

????????return 0;
}

cs.py 代碼如下：

from __future__ import print_function
from bcc import BPF
from time import sleep

# load BPF program
b = BPF(src_file = "cs.c")
b.attach_kprobe(event="schedule", fn_name="do_entry")
b.attach_kretprobe(event="schedule", fn_name="do_return")

print("Tracing for Data's... Ctrl-C to end")

#trace until Ctrl-C
try:
????????sleep(99999999)
except KeyboardInterrupt:
????????print()

#output
b["dist"].print_log2_hist("cs delay")

運行結果：

疑惑：這個運行結果和上面的那個運行結果差別比較大，這個運行結果的的值總體上偏大，而上面那個運行結果的值更符合常理，這個運行結果不應該是對上面那個運行結果的統計輸出嗎？為什么差別這么大呢？

解決：考慮到可能是不同進程環境導致的，于是我同時運行這兩個測試程序，以保證進程環境的相同，得到以下運行結果：

經過數據對比，在數值上，這些數據是對的上的，說明優化后的測試程序就是對優化前的測試程序數據的統計輸出，之前單獨運行這兩個測試程序的運行結果不同就是因為不同進程環境導致的。

1. bcc Reference Guide https://github.com/iovisor/bcc/blob/master/docs/reference_guide.md

2. 《BPF之巔 ?洞悉Linux系統和應用性能》