Ceph レイテンシの高さから eBPF/BCC を使用したカーネル パッチまで

Linux には、カーネルとアプリケーションをデバッグするためのツールが多数あります。 それらのほとんどはアプリケーションのパフォーマンスに悪影響を与えるため、運用環境では使用できません。

数年前にはありました 別のツールが開発されました - eBPF。 これにより、プログラムを再構築したり、サードパーティのモジュールをカーネルにロードしたりすることなく、低いオーバーヘッドでカーネルとユーザー アプリケーションをトレースできるようになります。

eBPF を使用するアプリケーション ユーティリティはすでに多数あります。この記事では、ライブラリに基づいて独自のプロファイリング ユーティリティを作成する方法を見ていきます。 PythonBCC。 この記事は実際の出来事に基づいています。 問題から解決へと進み、特定の状況で既存のユーティリティをどのように使用できるかを示します。

Ceph が遅い

新しいホストが Ceph クラスターに追加されました。 一部のデータをそれに移行した後、書き込みリクエストの処理速度が他のサーバーよりもはるかに遅いことに気づきました。

他のプラットフォームとは異なり、このホストは bcache と新しい Linux 4.15 カーネルを使用しました。 この構成のホストがここで使用されたのはこれが初めてでした。 そしてその瞬間、問題の根本は理論的には何でもあり得ることが明らかでした。

ホストの調査

まずは、ceph-osd プロセス内で何が起こっているかを見てみましょう。 このために使用します perf и 火炎鏡 (詳細については、こちらをご覧ください) ここで):

写真はその機能を示しています fdatasync() 関数にリクエストを送信するのに多くの時間を費やした generic_make_request()。 これは、問題の原因が OSD デーモン自体の外部にある可能性が高いことを意味します。 これはカーネルまたはディスクのいずれかです。 iostat の出力では、bcache ディスクによるリクエストの処理で長い遅延が発生していることが示されました。

ホストをチェックすると、systemd-udevd デーモンが大量の CPU 時間を消費していることがわかりました (いくつかのコアで約 20%)。 これは奇妙な動作なので、その理由を調べる必要があります。 Systemd-udevd は uevents と連動するため、uevents を通してそれらを調べることにしました。 udevadm モニタ。 システム内のブロックデバイスごとに、多数の変更イベントが生成されていることがわかりました。 これは非常に珍しいことなので、何がこれらのイベントを生成するのかを調べる必要があります。

BCC ツールキットの使用

すでにわかったように、カーネル (およびシステム コールの ceph デーモン) は、 generic_make_request()。 この関数の速度を測定してみましょう。 で BCC すでに素晴らしいユーティリティがあります - 機能性。 出力間隔を 1 秒にして PID によってデーモンをトレースし、結果をミリ秒単位で出力します。

通常、この機能はすぐに機能します。 行うことは、リクエストをデバイス ドライバー キューに渡すことだけです。

Bキャッシュ は、実際には XNUMX つのディスクで構成される複雑なデバイスです。

• バッキング デバイス (キャッシュされたディスク)、この場合は低速の HDD です。
• キャッシュ デバイス (キャッシュ ディスク)。ここでは、これは NVMe デバイスの XNUMX つのパーティションです。
• アプリケーションを実行する bcache 仮想デバイス。

リクエストの送信が遅いことはわかっていますが、次のどのデバイスに対するものでしょうか? これについては少し後で扱います。

uevents が問題を引き起こす可能性が高いことがわかりました。 彼らの発生の正確な原因を見つけるのはそれほど簡単ではありません。 これが定期的に起動されるある種のソフトウェアであると仮定しましょう。 スクリプトを使用してシステム上でどのようなソフトウェアが実行されるかを見てみましょう エグゼクヌープ 同じから BCCユーティリティキット。 これを実行して、出力をファイルに送信してみましょう。

たとえば、次のようになります。

/usr/share/bcc/tools/execsnoop  | tee ./execdump

ここでは execsnoop の完全な出力は示しませんが、興味深い XNUMX 行は次のようなものでした。

sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'

5802 番目の列はプロセスの PPID (親 PID) です。 PID 30 のプロセスは、監視システムのスレッドの XNUMX つであることが判明しました。 監視システムの構成をチェックしたところ、誤ったパラメータが見つかりました。 HBA アダプタの温度は XNUMX 秒ごとに測定されましたが、これは必要以上に頻繁です。 チェック間隔を長めに変更したところ、このホストのリクエスト処理の遅延が他のホストと比べて目立たなくなったことがわかりました。

しかし、bcache デバイスがなぜこれほど遅かったのかはまだ不明です。 同じ構成のテスト プラットフォームを準備し、bcache で fio を実行し、定期的に udevadm トリガーを実行して uevents を生成することで問題の再現を試みました。

BCC ベースのツールの作成

最も遅い呼び出しを追跡して表示する簡単なユーティリティを作成してみましょう。 generic_make_request()。 この関数が呼び出されたドライブの名前にも興味があります。

計画は単純です：

• 登録する kプローブ на generic_make_request():
  • ディスク名をメモリに保存し、関数の引数を通じてアクセスできます。
  • タイムスタンプを保存します。

• 登録する クレットプローブ からの帰国のために generic_make_request():
  • 現在のタイムスタンプを取得します。
  • 保存されたタイムスタンプを検索し、現在のタイムスタンプと比較します。
  • 結果が指定されたものより大きい場合は、保存されたディスク名を見つけて端末に表示します。

Kプローブ и クレットプローブ ブレークポイント メカニズムを使用して、関数コードをオンザフライで変更します。 あなたは読むことができます ドキュメンテーション и 良い このトピックに関する記事。 さまざまなユーティリティのコードを見ると、 BCC, すると、同じ構造であることがわかります。 したがって、この記事では、スクリプト引数の解析を省略して、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 および type の値 構造体データ_t。 このテーブルは、BPF プログラムのコンテキストで利用可能になります。 BPF_PERF_OUTPUT マクロは、BPF_PERF_OUTPUT という別のテーブルを登録します。 イベントに使用されます。 データ送信 ユーザー空間に。

関数の呼び出しと関数からの戻りの間の遅延、または異なる関数の呼び出し間の遅延を測定する場合は、受信したデータが同じコンテキストに属している必要があることを考慮する必要があります。 言い換えれば、関数の並行起動の可能性について覚えておく必要があります。 あるプロセスのコンテキストで関数を呼び出してから、別のプロセスのコンテキストでその関数から戻るまでの待ち時間を測定する機能がありますが、おそらく役に立ちません。 ここでの良い例は次のとおりです バイオレイテンシーユーティリティここで、ハッシュ テーブル キーは、へのポインタに設定されます。 構造体リクエスト、これは XNUMX つのディスク要求を反映します。

次に、調査対象の関数が呼び出されたときに実行されるコードを記述する必要があります。

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);
}

ここでは、呼び出された関数の最初の引数が XNUMX 番目の引数として置き換えられます。 generic_make_request()。 この後、作業中のコンテキスト内のプロセスの 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 とタイムスタンプを見つけますが、新しいデータ構造にメモリを割り当てません。 代わりに、キー == 現在の PID を使用して、ハッシュ テーブルで既存の構造を検索します。 構造が見つかった場合は、実行中のプロセスの名前を見つけて、それに追加します。

ここで使用するバイナリ シフトは、スレッド GID を取得するために必要です。 それらの。 作業中のコンテキストでスレッドを開始したメインプロセスの PID。 呼び出す関数 bpf_get_current_pid_tgid() スレッドの GID とその PID の両方を単一の 64 ビット値で返します。

ターミナルに出力するとき、現時点ではスレッドには関心がありませんが、メインプロセスには関心があります。 結果として生じる遅延を指定されたしきい値と比較した後、構造体を渡します。 データ テーブル経由でユーザー空間にアクセス イベント、その後エントリを削除します 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 プログラムを準備する必要があります。 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")

私たちも判断しなければなりません 構造体データ_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()

スクリプト自体は次の場所から入手できます。 GitHub。 fio が実行され、bcache に書き込まれ、udevadm Monitor を呼び出しているテスト プラットフォームで実行してみましょう。

ついに！ これで、ストールしている bcache デバイスのように見えたものが、実際にはストールしている呼び出しであることがわかります。 generic_make_request() キャッシュされたディスクの場合。

カーネルを詳しく調べる

リクエストの送信中に何が遅くなっているのでしょうか? リクエスト アカウンティングの開始前であっても遅延が発生していることがわかります。 統計情報 (/proc/diskstats または iostat) をさらに出力するための特定のリクエストの処理はまだ開始されていません。 これは、問題の再現中に iostat を実行することで簡単に確認できます。 BCC スクリプトのバイオレイテンシー、これはリクエスト アカウンティングの開始と終了に基づいています。 これらのユーティリティでは、キャッシュされたディスクへのリクエストに関して問題が発生することはありません。

機能を見てみると generic_make_request(), 次に、リクエストがアカウンティングを開始する前に、さらに XNUMX つの関数が呼び出されることがわかります。 初め - generic_make_request_checks()、ディスク設定に関するリクエストの正当性のチェックを実行します。 XNUMX番 - blk_queue_enter()、興味深い挑戦があります wait_event_interruptible():

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 и blk_mq_unfreeze_queue。 これらは、このキュー内のリクエストにとって潜在的に危険な、リクエスト キューの設定を変更する必要がある場合に使用されます。 電話をかけるとき blk_mq_freeze_queue() функцией blk_freeze_queue_start() カウンターがインクリメントされる q->mq_freeze_ Depth。 この後、カーネルはキューが空になるのを待ちます。 blk_mq_freeze_queue_wait().

このキューをクリアするのにかかる時間は、カーネルがキューに入れられたすべての操作が完了するまで待機するため、ディスクの遅延に相当します。 キューが空になると、設定の変更が適用されます。 その後、それは呼び出されます blk_mq_unfreeze_queue()、カウンターをデクリメントします フリーズ深度.

これで、状況を修正するのに十分なことがわかりました。 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 は非常に柔軟で強力なツールです。 この記事では、実際の事例を XNUMX つ取り上げ、何ができるのかの一部を示しました。 BCC ユーティリティの開発に興味がある場合は、検討してみる価値があります。 公式チュートリアル、基本がよく説明されています。

eBPF に基づいた興味深いデバッグ ツールやプロファイリング ツールは他にもあります。 それらの中の一つ - bpftraceを使用すると、awk に似た言語で強力なワンライナーや小さなプログラムを作成できます。 別の - ebpf_exporterを使用すると、低レベルの高解像度のメトリクスを直接 prometheus サーバーに収集でき、後で美しい視覚化やアラートも取得できるようになります。

出所： habr.com