Linux 有大量用於調試核心和應用程式的工具。 其中大多數會對應用程式效能產生負面影響，並且無法在生產中使用。
幾年前有 - 電子BPF。 它使得以較低的開銷追蹤核心和用戶應用程式成為可能，並且無需重建程式並將第三方模組載入到核心中。
已經有許多應用程式實用程式使用 eBPF，在本文中我們將了解如何基於該程式庫編寫自己的分析實用程式 。 該文章取材自真實事件。 我們將逐一解決問題，以展示如何在特定情況下使用現有實用程式。
Ceph 很慢
Ceph 叢集中已新增主機。 將部分資料遷移到其中後，我們注意到它處理寫入請求的速度比其他伺服器低得多。
與其他平台不同的是，該主機使用了 bcache 和新的 linux 4.15 核心。 這是首次使用這種配置的主機。 在那一刻，很明顯，從理論上講，問題的根源可能是任何事情。
調查主機
讓我們先看看 ceph-osd 進程內部發生了什麼。 為此，我們將使用 и （更多相關內容您可以閱讀 ):
這張圖告訴我們這個函數 fdatasync() 花了大量時間向函數發送請求 generic_make_request()。 這意味著問題的原因很可能是在 osd 守護程式本身之外的某個地方。 這可以是核心或磁碟。 iostat 輸出顯示 bcache 磁碟處理請求時存在較高延遲。
在檢查主機時，我們發現 systemd-udevd 守護程式消耗了大量的 CPU 時間 - 在多個核心上大約消耗了 20%。 這是奇怪的行為，因此您需要找出原因。 由於 Systemd-udevd 與 uevent 一起使用，我們決定透過 udevadm 監視器。 事實證明，系統中的每個區塊設備都產生了大量的變更事件。 這是很不尋常的，所以我們必須看看是什麼產生了所有這些事件。
使用密件副本工具包
正如我們已經發現的，核心（以及系統呼叫中的 ceph 守護程序）花費了大量時間 generic_make_request()。 讓我們試著測量這個函數的速度。 在 已經有一個很棒的實用程式了 - 功能性。 我們將透過 PID 來追蹤守護進程，輸出之間的間隔為 1 秒，並以毫秒為單位輸出結果。
此功能通常見效很快。 它所做的只是將請求傳遞到裝置驅動程式佇列。
快取 是一個複雜的設備，實際上由三個磁碟組成：
- 支援設備（快取磁碟），在本例中是慢速 HDD；
- 快取設備（快取盤），這裡是NVMe設備的一個分區；
- 應用程式運行時使用的 bcache 虛擬設備。
我們知道請求傳輸很慢，但是對於這些設備中的哪一個呢？ 我們稍後會處理這個問題。
我們現在知道 uevent 可能會導致問題。 要找出他們這一代的確切原因並不容易。 我們假設這是某種定期啟動的軟體。 讓我們使用腳本看看系統上運行什麼樣的軟體 執行監聽 來自同一個 。 讓我們運行它並將輸出發送到文件。
例如像這樣：
/usr/share/bcc/tools/execsnoop | tee ./execdump
我們不會在這裡顯示 execsnoop 的完整輸出，但我們感興趣的一行如下所示：
sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'
第三列是進程的 PPID（父 PID）。 PID為5802的進程原來是我們監控系統的執行緒之一。 在檢查監控系統的配置時，發現參數有錯誤。 每 30 秒測量一次 HBA 轉接器的溫度，這比必要的頻率要高得多。 將檢查間隔更改為更長的間隔後，我們發現與其他主機相比，該主機上的請求處理延遲不再突出。
但目前還不清楚為什麼 bcache 設備如此緩慢。 我們準備了一個具有相同配置的測試平台，並嘗試透過在 bcache 上執行 fio、定期執行 udevadm 觸發器來產生 uevent 來重現問題。
編寫基於 BCC 的工具
讓我們嘗試編寫一個簡單的實用程式來追蹤和顯示最慢的調用 generic_make_request()。 我們也對呼叫該函數的驅動器的名稱感興趣。
計劃很簡單：
- 登記 探針 上 generic_make_request():
- 我們將磁碟名稱保存到記憶體中，可以透過函數參數存取；
- 我們保存時間戳。
- 登記 克雷特探針 從返回 generic_make_request():
- 我們得到當前的時間戳記；
- 我們查找已儲存的時間戳並將其與當前時間戳進行比較；
- 如果結果大於指定的值，那麼我們找到已儲存的磁碟名稱並將其顯示在終端上。
探針 и 克雷特探針 使用斷點機制動態變更函數程式碼。 你可以閱讀 и 關於這個主題的文章。 如果您查看以下各種實用程式的程式碼 ，那麼你可以看到它們具有相同的結構。 因此，在本文中，我們將跳過解析腳本參數並繼續討論 BPF 程式本身。
python 腳本中的 eBPF 文字如下所示：
bpf_text = “”” # Here will be the bpf program code “””
為了在函數之間交換數據，eBPF 程式使用 。 我們也會這樣做。 我們將使用進程 PID 作為鍵，並將結構體定義為值：
struct data_t {
u64 pid;
u64 ts;
char comm[TASK_COMM_LEN];
u64 lat;
char disk[DISK_NAME_LEN];
};
BPF_HASH(p, u64, struct data_t);
BPF_PERF_OUTPUT(events);
這裡我們註冊一個哈希表，名為 p, 帶鍵類型 u64 和一個類型的值 結構體data_t。 表將在我們的 BPF 計劃中提供。 BPF_PERF_OUTPUT 巨集註冊了另一個表，稱為 活動，用於 進入使用者空間。
在測量呼叫函數和從函數返回之間或呼叫不同函數之間的延遲時，您需要考慮到接收到的資料必須屬於同一上下文。 換句話說，您需要記住可能的平行啟動功能。 我們能夠測量在一個進程的上下文中呼叫函數與在另一個進程的上下文中從該函數返回之間的延遲，但這可能是無用的。 一個很好的例子是 ，其中哈希表鍵設定為指向 結構請求，反映一個磁碟請求。
接下來，我們需要編寫在呼叫所研究的函數時執行的程式碼：
void start(struct pt_regs *ctx, struct bio *bio) {
u64 pid = bpf_get_current_pid_tgid();
struct data_t data = {};
u64 ts = bpf_ktime_get_ns();
data.pid = pid;
data.ts = ts;
bpf_probe_read_str(&data.disk, sizeof(data.disk), (void*)bio->bi_disk->disk_name);
p.update(&pid, &data);
}
這裡被呼叫函數的第一個參數將被替換為第二個參數 。 之後，我們取得正在工作的進程的 PID，以及當前時間戳記（以奈秒為單位）。 我們將其全部記錄在新選擇的內容中 結構體data_t數據。 我們從結構中取得磁碟名稱 简历，調用時傳遞 generic_make_request()，並將其保存在相同的結構中 數據。 最後一步是將條目新增到前面提到的哈希表中。
返回時將呼叫以下函數 generic_make_request():
void stop(struct pt_regs *ctx) {
u64 pid = bpf_get_current_pid_tgid();
u64 ts = bpf_ktime_get_ns();
struct data_t* data = p.lookup(&pid);
if (data != 0 && data->ts > 0) {
bpf_get_current_comm(&data->comm, sizeof(data->comm));
data->lat = (ts - data->ts)/1000;
if (data->lat > MIN_US) {
FACTOR
data->pid >>= 32;
events.perf_submit(ctx, data, sizeof(struct data_t));
}
p.delete(&pid);
}
}
這個函數和上一個函數類似：我們找出進程的PID和時間戳，但不為新的資料結構分配記憶體。 相反，我們使用 key == current PID 在哈希表中搜尋已經存在的結構。 如果找到該結構，那麼我們找出正在運行的進程的名稱並將其添加到其中。
我們在這裡使用的二進位移位需要取得線程 GID。 那些。 在我們正在工作的上下文中啟動執行緒的主進程的 PID。 我們呼叫的函數 以單一 64 位元值傳回線程的 GID 及其 PID。
當輸出到終端時，我們目前對流不感興趣，但對主進程感興趣。 將產生的延遲與給定閾值進行比較後，我們通過我們的結構 數據 透過表格進入使用者空間 活動，之後我們刪除該條目 p.
在將載入此程式碼的 python 腳本中，我們需要將 MIN_US 和 FACTOR 替換為延遲閾值和時間單位，我們將透過參數傳遞它們：
bpf_text = bpf_text.replace('MIN_US',str(min_usec))
if args.milliseconds:
bpf_text = bpf_text.replace('FACTOR','data->lat /= 1000;')
label = "msec"
else:
bpf_text = bpf_text.replace('FACTOR','')
label = "usec"
現在我們需要透過以下方式準備 BPF 程序 並登記樣品：
b = BPF(text=bpf_text)
b.attach_kprobe(event="generic_make_request",fn_name="start")
b.attach_kretprobe(event="generic_make_request",fn_name="stop")
我們還必須確定 結構體data_t 在我們的腳本中，否則我們將無法讀取任何內容：
TASK_COMM_LEN = 16 # linux/sched.h
DISK_NAME_LEN = 32 # linux/genhd.h
class Data(ct.Structure):
_fields_ = [("pid", ct.c_ulonglong),
("ts", ct.c_ulonglong),
("comm", ct.c_char * TASK_COMM_LEN),
("lat", ct.c_ulonglong),
("disk",ct.c_char * DISK_NAME_LEN)]
最後一步是將資料輸出到終端：
def print_event(cpu, data, size):
global start
event = ct.cast(data, ct.POINTER(Data)).contents
if start == 0:
start = event.ts
time_s = (float(event.ts - start)) / 1000000000
print("%-18.9f %-16s %-6d %-1s %s %s" % (time_s, event.comm, event.pid, event.lat, label, event.disk))
b["events"].open_perf_buffer(print_event)
# format output
start = 0
while 1:
try:
b.perf_buffer_poll()
except KeyboardInterrupt:
exit()
該腳本本身可在 。 讓我們嘗試在運行 fio 的測試平台上運行它，寫入 bcache，並呼叫 udevadm 監視器：
最後！ 現在我們看到，看起來像停止 bcache 設備的實際上是停止調用 generic_make_request() 對於緩存磁碟。
深入內核
請求傳輸過程中到底是什麼減慢了速度？ 我們看到延遲甚至在請求記帳開始之前就發生了，即對進一步輸出統計資料（/proc/diskstats 或 iostat）的具體請求的統計尚未開始。 這可以透過在重現問題時運行 iostat 來輕鬆驗證，或者 ，它是基於請求記帳的開始和結束。 這些實用程式都不會顯示對快取磁碟的請求的問題。
如果我們看一下這個函數 generic_make_request()，然後我們會看到在請求開始計費之前，又呼叫了兩個函數。 第一的 - generic_make_request_checks()，對有關磁碟設定的請求的合法性進行檢查。 第二 - ，這有一個有趣的挑戰 :
ret = wait_event_interruptible(q->mq_freeze_wq,
(atomic_read(&q->mq_freeze_depth) == 0 &&
(preempt || !blk_queue_preempt_only(q))) ||
blk_queue_dying(q));
其中，內核等待隊列解凍。 我們來測量一下延遲 blk_queue_enter():
~# /usr/share/bcc/tools/funclatency blk_queue_enter -i 1 -m
Tracing 1 functions for "blk_queue_enter"... Hit Ctrl-C to end.
msecs : count distribution
0 -> 1 : 341 |****************************************|
msecs : count distribution
0 -> 1 : 316 |****************************************|
msecs : count distribution
0 -> 1 : 255 |****************************************|
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 1 | |
看起來我們已經接近解決方案了。 用於凍結/解凍隊列的函數是 и 。 當需要更改請求佇列設定時使用它們，這對此佇列中的請求存在潛在危險。 打電話時 blk_mq_freeze_queue() функцией 計數器增加 q->mq_freeze_深度。 之後，核心等待佇列清空 .
清除此佇列所需的時間相當於核心等待所有排隊操作完成時的磁碟延遲。 一旦隊列為空，就會套用設定變更。 之後它被稱為 ，遞減計數器 凍結深度.
現在我們已經有足夠的知識來糾正這種情況了。 udevadm 觸發指令會導致應用塊設備的設定。 這些設定在 udev 規則中進行了描述。 我們可以透過嘗試透過 sysfs 更改設定或查看核心原始碼來找到哪些設定凍結了佇列。 我們也可以嘗試 BCC 實用程式 ，它將輸出每次調用終端的內核和用戶空間堆疊追蹤 blk_freeze_queue例如：
~# /usr/share/bcc/tools/trace blk_freeze_queue -K -U
PID TID COMM FUNC
3809642 3809642 systemd-udevd blk_freeze_queue
blk_freeze_queue+0x1 [kernel]
elevator_switch+0x29 [kernel]
elv_iosched_store+0x197 [kernel]
queue_attr_store+0x5c [kernel]
sysfs_kf_write+0x3c [kernel]
kernfs_fop_write+0x125 [kernel]
__vfs_write+0x1b [kernel]
vfs_write+0xb8 [kernel]
sys_write+0x55 [kernel]
do_syscall_64+0x73 [kernel]
entry_SYSCALL_64_after_hwframe+0x3d [kernel]
__write_nocancel+0x7 [libc-2.23.so]
[unknown]
3809631 3809631 systemd-udevd blk_freeze_queue
blk_freeze_queue+0x1 [kernel]
queue_requests_store+0xb6 [kernel]
queue_attr_store+0x5c [kernel]
sysfs_kf_write+0x3c [kernel]
kernfs_fop_write+0x125 [kernel]
__vfs_write+0x1b [kernel]
vfs_write+0xb8 [kernel]
sys_write+0x55 [kernel]
do_syscall_64+0x73 [kernel]
entry_SYSCALL_64_after_hwframe+0x3d [kernel]
__write_nocancel+0x7 [libc-2.23.so]
[unknown]
Udev 規則很少改變，通常以受控方式發生。 因此我們看到，即使應用程式已經設定的值也會導致將請求從應用程式傳輸到磁碟的延遲激增。 當然，在磁碟配置沒有更改（例如，設備未安裝/斷開連接）時產生 udev 事件並不是一個好的做法。 但是，我們可以幫助核心不要做不必要的工作，並在不需要時凍結請求佇列。 糾正這種情況。
結論
eBPF 是一個非常靈活且強大的工具。 在本文中，我們研究了一個實際案例並演示了一小部分可以做的事情。 如果您對開發 BCC 實用程式感興趣，值得一看 ，它很好地描述了基礎知識。
還有其他基於 eBPF 的有趣的調試和分析工具。 其中之一—— ，它允許您使用類似 awk 的語言編寫功能強大的單行程式碼和小程式。 其他 - ，允許您將低級別、高分辨率的指標直接收集到您的普羅米修斯伺服器中，並能夠在以後獲得漂亮的可視化效果甚至警報。
來源： www.habr.com