Tracepoint とは何か？
カーネルに埋め込まれたイベントに処理を追加する仕組み。
- disabled のときはハンドラが実行されない。
- enabledのときはハンドラが実行される。
- 分岐処理のコストが余分にかかるが、アセンブリレベルで最適化されている。
- すでにカーネルコードに分岐は埋め込まれているので、ビルド時に Tracepoint を無効にしない限りコストは変わらない
- ハンドラを登録してイベントを有効にすると、ハンドラ実行分のオーバーヘッドが増える
- どの程度のオーバーヘッドかはハンドラの処理内容とイベント発生頻度に依存するため、一概には何もいえない。WEB 上の事例https://elinux.org/images/9/9f/CELFJAM20100903-shigeoka-How-to-use-tracepoints.pdf などを見るに、そこまでのオーバーヘッドにはならないと思う
動的に処理を差し込める Kprobes や Uprobes と比べると劣化版な印象もあるが、次のような利点がある。
- 堅牢さ
- Kprobes や Uprobes はフック時にシンボル名を指定するため、カーネルバージョンアップ時に関数名が変更されると動作しなくなる。
- Tracepoint はユーザ空間に宣言された API になっていて保守する責任がカーネルにあるため、ある程度はバージョンアップ時にも保守される。
- ローカル変数へのアクセス
- Kprobes や Uprobes はシンボル情報をもとに解決するので、シンボルが割り当てられないローカル変数などは解決できない。
- Tracepoint はカーネルコード内に関数呼び出しが埋め込まれているため、ローカル変数も参照できる。
- ただし、イベントとして定義された値にしかアクセスできない。
検証バージョン
CentOS 8 を利用する。
]# cat /etc/redhat-release CentOS Linux release 8.1.1911 (Core) ]# uname -a Linux localhost.localdomain 4.18.0-80.11.2.el8.x86_64 #3 SMP Tue May 19 07:55:46 JST 2020 x86_64 x86_64 x86_64 GNU/Linux
全体像
おおむね次の流れで利用する。が、99.9999% の場合は perf や tracefs といったユーザ空間に提供されているラップされた仕組みを使うため、通常は気にしなくてよさそう。
- イベントを定義する
- コールバックを作成する
- コールバックをイベントハンドラとして登録する
- カーネルコードからイベントを発行する
- イベント発生時に登録されたコールバックを実行する
イベントの一覧
Tracepoint で利用可能なイベントは /sys/kernel/debug/tracing/available_events に載っている。検証バージョンは 1826 のイベントが登録されていた。
]# cat /sys/kernel/debug/tracing/available_events ext4:ext4_other_inode_update_time ext4:ext4_free_inode ext4:ext4_request_inode ext4:ext4_allocate_inode ext4:ext4_evict_inode ext4:ext4_drop_inode ext4:ext4_mark_inode_dirty ext4:ext4_begin_ordered_truncate ext4:ext4_write_begin ext4:ext4_da_write_begin ]# cat /sys/kernel/debug/tracing/available_events | wc -l 1826
使いかた
tracefs
ファイルインタフェースを介して Tracepoint を操作できる。
]# find /sys/kernel/debug/tracing/events -type d /sys/kernel/debug/tracing/events /sys/kernel/debug/tracing/events/ext4 /sys/kernel/debug/tracing/events/ext4/ext4_other_inode_update_time /sys/kernel/debug/tracing/events/ext4/ext4_free_inode /sys/kernel/debug/tracing/events/ext4/ext4_request_inode /sys/kernel/debug/tracing/events/ext4/ext4_allocate_inode ...
コールバックはあらかじめ用意されており、formatに定義された形式でリングバッファに出力する。
]# cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/format
name: sched_wakeup
ID: 311
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:char comm[16]; offset:8; size:16; signed:1;
field:pid_t pid; offset:24; size:4; signed:1;
field:int prio; offset:28; size:4; signed:1;
field:int success; offset:32; size:4; signed:1;
field:int target_cpu; offset:36; size:4; signed:1;
print fmt: "comm=%s pid=%d prio=%d target_cpu=%03d", REC->comm, REC->pid, REC->prio, REC->target_cpu
[root@localhost linux-4.18.0-147.5.1.el8.x86_64]#
各イベントは、set_eventによって有効にできる。
# 空にする
]# echo > /sys/kernel/debug/tracing/set_event
# sched_wakeup を有効にする
]# echo sched_wakeup >> /sys/kernel/debug/tracing/set_event
# 表示する
]# cat /sys/kernel/debug/tracing/trace_pipe
<idle>-0 [000] dNs. 161775.001839: sched_wakeup: comm=sshd pid=24717 prio=120 target_cpu=000
sshd-24717 [000] d... 161775.002157: sched_wakeup: comm=kworker/u4:0 pid=1371 prio=120 target_cpu=001
kworker/u4:0-1371 [001] d... 161775.002325: sched_wakeup: comm=bash pid=24718 prio=120 target_cpu=000
bash-24718 [000] d... 161775.002596: sched_wakeup: comm=kworker/u4:0 pid=1371 prio=120 target_cpu=001
kworker/u4:0-1371 [001] d... 161775.002753: sched_wakeup: comm=sshd pid=24717 prio=120 target_cpu=000
...
# 無効にする
]# echo "!sched_wakeup" >> /sys/kernel/debug/tracing/set_event
イベントごとにディレクトリが切られていて、イベントごとに有効にすることもできる。
# 有効にする
]# echo 1 > /sys//kernel/debug/tracing/events/sched/sched_wakeup/enable
# 表示する
]# cat /sys/kernel/debug/tracing/trace_pipe | head
kworker/u4:0-1371 [001] d... 162101.810451: sched_wakeup: comm=kworker/u4:2 pid=1482 prio=120 target_cpu=000
kworker/u4:0-1371 [001] d.h. 162101.810487: sched_wakeup: comm=cat pid=1481 prio=120 target_cpu=001
kworker/u4:2-1482 [000] d... 162101.810491: sched_wakeup: comm=sshd pid=24717 prio=120 target_cpu=000
kworker/u4:0-1371 [001] d... 162101.810507: sched_wakeup: comm=kworker/u4:2 pid=1482 prio=120 target_cpu=000
cat-1481 [001] d... 162101.810838: sched_wakeup: comm=bash pid=24718 prio=120 target_cpu=000
...
# 無効にする
]# echo 0 > /sys//kernel/debug/tracing/events/sched/sched_wakeup/enable
使い方の詳細は Documentation/trace/events.rst が参考になる。
perf
perf で利用できるイベントは perf list で一覧表示できる。
]# perf list | grep Tracepoint alarmtimer:alarmtimer_cancel [Tracepoint event] alarmtimer:alarmtimer_fired [Tracepoint event] alarmtimer:alarmtimer_start [Tracepoint event] alarmtimer:alarmtimer_suspend [Tracepoint event] block:block_bio_backmerge [Tracepoint event] block:block_bio_bounce [Tracepoint event] block:block_bio_complete [Tracepoint event] block:block_bio_frontmerge [Tracepoint event] block:block_bio_queue [Tracepoint event]
たとえば特定のシステムコールの実行回数を数えたり、
]# perf stat -e syscalls:sys_enter_openat -- sleep 10
Performance counter stats for 'sleep 10':
30 syscalls:sys_enter_openat
10.001504300 seconds time elapsed
0.001124000 seconds user
0.000000000 seconds sys
ブロックデバイスへのリクエスト実行時のスタックトレースを取ったり、
]# perf record -e block:block_rq_insert -ag ^C[ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.247 MB perf.data (8 samples) ] ]# perf report Samples: 8 of event 'block:block_rq_insert', Event count (approx.): 8 Children Self Trace output + 75.00% 75.00% 0,0 N 8 () 0 + 0 [kworker/1:0] + 12.50% 12.50% 8,0 RA 16384 () 240394720 + 32 [bash] + 12.50% 12.50% 8,0 RA 77824 () 240394752 + 152 [dd]
スケジューラのレイテンシを測定できる。
]# perf sched record -- sleep 0.1 [ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 0.311 MB perf.data (53 samples) ] ]# perf sched latency -------------------------------------------------------------------------------------------> Task | Runtime ms | Switches | Average delay ms | Maximum delay ms | M> -------------------------------------------------------------------------------------------> perf:21736 | 1.759 ms | 1 | avg: 0.075 ms | max: 0.075 ms | m> xfsaild/dm-0:704 | 0.016 ms | 2 | avg: 0.032 ms | max: 0.058 ms | m> kworker/1:1-eve:21530 | 0.014 ms | 1 | avg: 0.028 ms | max: 0.028 ms | m> kworker/0:2-eve:21553 | 0.007 ms | 1 | avg: 0.021 ms | max: 0.021 ms | m> sleep:21737 | 1.141 ms | 2 | avg: 0.018 ms | max: 0.029 ms | m> in:imjournal:1676 | 0.033 ms | 1 | avg: 0.014 ms | max: 0.014 ms | m> rcu_sched:10 | 0.032 ms | 4 | avg: 0.004 ms | max: 0.007 ms | m> -------------------------------------------------------------------------------------------> TOTAL: | 3.000 ms | 12 | ---------------------------------------------------
perf を用いたパフォーマンス解析の勘所は、Brendan Gregg の perf Examplesが参考になる。Brendan Gregg さんは詳解 システム・パフォーマンスの著者で、パフォーマンス解析に関する知識がすごい。いま自分が尊敬するエンジニアの第一位(自分調べ)に輝いている。
詳解 システム・パフォーマンス は名著なので、パフォーマンス解析に興味がある方はぜひ読んだほうがいい。自分は 2 週目に突入したけど、読むたびに「なるほど」と思っている(身についてないとも言えるが)。
Tracepoint の仕組み
途中まで調べたけどマクロが複雑すぎてあきらめた。以下、メモ。
TRACE_EVENT マクロ
イベントの定義は TRACE_EVENT マクロで行う。include/linux/tracepoint.h に例が書いてあるのと、次のリンクが参考になる。
TRACE_EVENT マクロを利用したイベント定義は include/trace/events/ 配下に大体(60% くらい)まとめられている。カーネルモジュールやアーキテクチャに固有のものは他の場所に配置されている。
例 include/trace/events/sched.h
TRACE_EVENT(sched_process_fork,
TP_PROTO(struct task_struct *parent, struct task_struct *child),
TP_ARGS(parent, child),
TP_STRUCT__entry(
__array( char, parent_comm, TASK_COMM_LEN )
__field( pid_t, parent_pid )
__array( char, child_comm, TASK_COMM_LEN )
__field( pid_t, child_pid )
),
TP_fast_assign(
memcpy(__entry->parent_comm, parent->comm, TASK_COMM_LEN);
__entry->parent_pid = parent->pid;
memcpy(__entry->child_comm, child->comm, TASK_COMM_LEN);
__entry->child_pid = child->pid;
),
TP_printk("comm=%s pid=%d child_comm=%s child_pid=%d",
__entry->parent_comm, __entry->parent_pid,
__entry->child_comm, __entry->child_pid)
);
TRACE_EVENT マクロは次のように定義されてる。
include/linux/tracepoint.h
#define TRACE_EVENT(name, proto, args, struct, assign, print) \ DECLARE_TRACE(name, PARAMS(proto), PARAMS(args)) ... #define DECLARE_TRACE(name, proto, args) \ __DECLARE_TRACE(name, PARAMS(proto), PARAMS(args), \ cpu_online(raw_smp_processor_id()), \ PARAMS(void *__data, proto), \ PARAMS(__data, args)) ... #define __DECLARE_TRACE(name, proto, args, cond, data_proto, data_args) \ extern struct tracepoint __tracepoint_##name; \ static inline void trace_##name(proto) \ { \ // イベントが on の場合のみ、コールバックを呼び出す if (static_key_false(&__tracepoint_##name.key)) \ __DO_TRACE(&__tracepoint_##name, \ TP_PROTO(data_proto), \ TP_ARGS(data_args), \ TP_CONDITION(cond), 0); \ if (IS_ENABLED(CONFIG_LOCKDEP) && (cond)) { \ rcu_read_lock_sched_notrace(); \ rcu_dereference_sched(__tracepoint_##name.funcs);\ rcu_read_unlock_sched_notrace(); \ } \ } \ __DECLARE_TRACE_RCU(name, PARAMS(proto), PARAMS(args), \ PARAMS(cond), PARAMS(data_proto), PARAMS(data_args)) \ static inline int \ register_trace_##name(void (*probe)(data_proto), void *data) \ { \ return tracepoint_probe_register(&__tracepoint_##name, \ (void *)probe, data); \ } \ static inline int \ register_trace_prio_##name(void (*probe)(data_proto), void *data,\ int prio) \ { \ return tracepoint_probe_register_prio(&__tracepoint_##name, \ (void *)probe, data, prio); \ } \ static inline int \ unregister_trace_##name(void (*probe)(data_proto), void *data) \ { \ return tracepoint_probe_unregister(&__tracepoint_##name,\ (void *)probe, data); \ } \ static inline void \ check_trace_callback_type_##name(void (*cb)(data_proto)) \ { \ } \ static inline bool \ trace_##name##_enabled(void) \ { \ return static_key_false(&__tracepoint_##name.key); \ } ... #define __DO_TRACE(tp, proto, args, cond, rcucheck) \ do { \ struct tracepoint_func *it_func_ptr; \ void *it_func; \ void *__data; \ \ if (!(cond)) \ return; \ if (rcucheck) \ rcu_irq_enter_irqson(); \ rcu_read_lock_sched_notrace(); \ it_func_ptr = rcu_dereference_sched((tp)->funcs); \ if (it_func_ptr) { \ do { \ it_func = (it_func_ptr)->func; \ __data = (it_func_ptr)->data; \ ((void(*)(proto))(it_func))(args); \ } while ((++it_func_ptr)->func); \ } \ rcu_read_unlock_sched_notrace(); \ if (rcucheck) \ rcu_irq_exit_irqson(); \ } while (0)
上記マクロ定義には、だいたい次の内容が含まれる。
- イベントを定義する(
trace_##name) - イベントが有効の場合はコールバックを実行する(
if (static_key_false(...)の部分) - 登録されているコールバックを呼び出す(
__DO_TRACE) - コールバックを登録する関数を用意する(
register_trace_##name) - コールバックを削除する関数を用意する(
unregister_trace_##name)
このマクロで作成された関数を利用し、カーネルコードにイベントを埋め込む。
kernel/fork.c
long _do_fork(unsigned long clone_flags, unsigned long stack_start, unsigned long stack_size, int __user *parent_tidptr, int __user *child_tidptr, unsigned long tls) { ... trace_sched_process_fork(current, p); ... }
またマクロで作成された関数を利用し、コールバックを登録する。(なおコールバックの登録は動的に行うことが多いので grep してもヒットしないことが多い)
kernel/trace/ftrace.c
void ftrace_pid_follow_fork(struct trace_array *tr, bool enable) { if (enable) { register_trace_sched_process_fork(ftrace_pid_follow_sched_process_fork, tr); register_trace_sched_process_exit(ftrace_pid_follow_sched_process_exit, tr); } else { unregister_trace_sched_process_fork(ftrace_pid_follow_sched_process_fork, tr); unregister_trace_sched_process_exit(ftrace_pid_follow_sched_process_exit, tr); } }
※ ちなみにマクロの文字列結合を利用して定義された関数は ctags でジャンプできない。「なぜジャンプできないシンボルがあるのか…」と思いつつ無視していたが、1 年越しにようやく理解した。
Static Keys
static_key_false(...) 部分は Static Keys という仕組みらしい。
if 文による分岐はグローバル変数のチェックが必要になる。通常は気にならないほどのコストだが、キャッシュがひっ迫しているときにこの参照コストが高くなる可能性があり、この影響を最小化したい。そのために、変数のチェックを毎回しなくて済むように分岐処理を noop 命令でコンパイルして常に処理しておき、分岐を切り替えたいときだけ jump 命令に書き換えるらしい。詳細は https://lwn.net/Articles/487426/ が参考になる。
マクロの詳細
大まかな流れを説明するためにすっ飛ばしたが、TRACE_EVENT はマクロの再定義が多用されている。前提としてマクロの再定義の仕組みをまず理解する。次のように C というマクロを再定義すると、
#define DOGS { C(JACK_RUSSELL), C(BULL_TERRIER), C(ITALIAN_GREYHOUND) } #undef C #define C(a) ENUM_##a enum dog_enums DOGS; #undef C #define C(a) #a char *dog_strings[] = DOGS; char *dog_to_string(enum dog_enums dog) { return dog_strings[dog]; }
プリプロセス後は次のようになる。つまりマクロの再定義前後で、展開内容が変わる。
# 1 "main.c" # 1 "<組み込み>" # 1 "<コマンドライン>" # 31 "<コマンドライン>" # 1 "/usr/include/stdc-predef.h" 1 3 4 # 32 "<コマンドライン>" 2 # 1 "main.c" enum dog_enums { ENUM_JACK_RUSSELL, ENUM_BULL_TERRIER, ENUM_ITALIAN_GREYHOUND }; char *dog_strings[] = { "JACK_RUSSELL", "BULL_TERRIER", "ITALIAN_GREYHOUND" }; char *dog_to_string(enum dog_enums dog) { return dog_strings[dog]; }
この仕組みを利用すると、同じデータをもとに異なる処理を追加できる。TRACE_EVENT やサブマクロは、 tracepoint や syscall といった用途ごとに再定義と include を繰り返すことで複数の異なる処理を差し込むようになっている。
先ほどの include/trace/events/sched.h をもう一度見てみると、ヘッダーファイルの先頭で #define TRACE_SYSTEM sched を定義して tracepoint.h を読み込み、末尾で trace/define_trace.h を読み込んでいる。
#undef TRACE_SYSTEM #define TRACE_SYSTEM sched #if !defined(_TRACE_SCHED_H) || defined(TRACE_HEADER_MULTI_READ) #define _TRACE_SCHED_H #include <linux/sched/numa_balancing.h> #include <linux/tracepoint.h> #include <linux/binfmts.h> ... TRACE_EVENT(sched_process_fork, TP_PROTO(struct task_struct *parent, struct task_struct *child), TP_ARGS(parent, child), TP_STRUCT__entry( __array( char, parent_comm, TASK_COMM_LEN ) __field( pid_t, parent_pid ) __array( char, child_comm, TASK_COMM_LEN ) __field( pid_t, child_pid ) ), TP_fast_assign( memcpy(__entry->parent_comm, parent->comm, TASK_COMM_LEN); __entry->parent_pid = parent->pid; memcpy(__entry->child_comm, child->comm, TASK_COMM_LEN); __entry->child_pid = child->pid; ), TP_printk("comm=%s pid=%d child_comm=%s child_pid=%d", __entry->parent_comm, __entry->parent_pid, __entry->child_comm, __entry->child_pid) ); ... #endif /* _TRACE_SCHED_H */ /* This part must be outside protection */ #include <trace/define_trace.h>
linux/tracepoint.h は先ほど説明したように TRACE_EVENT を定義しているので、このマクロがまず適用される。
#define TRACE_EVENT(name, proto, args, struct, assign, print) \ DECLARE_TRACE(name, PARAMS(proto), PARAMS(args)) ... #define DECLARE_TRACE(name, proto, args) \ __DECLARE_TRACE(name, PARAMS(proto), PARAMS(args), \ cpu_online(raw_smp_processor_id()), \ PARAMS(void *__data, proto), \ PARAMS(__data, args)) ... #define __DECLARE_TRACE(name, proto, args, cond, data_proto, data_args) \ extern struct tracepoint __tracepoint_##name; \ static inline void trace_##name(proto) \ { \ // イベントが on の場合のみ、コールバックを呼び出す if (static_key_false(&__tracepoint_##name.key)) \ __DO_TRACE(&__tracepoint_##name, \ TP_PROTO(data_proto), \ TP_ARGS(data_args), \ TP_CONDITION(cond), 0); \ if (IS_ENABLED(CONFIG_LOCKDEP) && (cond)) { \ rcu_read_lock_sched_notrace(); \ rcu_dereference_sched(__tracepoint_##name.funcs);\ rcu_read_unlock_sched_notrace(); \ } \ } \
include/trace/events/sched.h は末尾で include/trace/define_trace.h を読み込む。include/trace/define_trace.h は TRACE_EVENT を再定義する。
// include/trace/define_trace.h の定義 #ifdef CREATE_TRACE_POINTS /* Prevent recursion */ #undef CREATE_TRACE_POINTS #include <linux/stringify.h> #undef TRACE_EVENT #define TRACE_EVENT(name, proto, args, tstruct, assign, print) \ DEFINE_TRACE(name) // include/linux/tracepoint.h の定義 #define DEFINE_TRACE_FN(name, reg, unreg) \ static const char __tpstrtab_##name[] \ __attribute__((section("__tracepoints_strings"))) = #name; \ struct tracepoint __tracepoint_##name \ __attribute__((section("__tracepoints"))) = \ { __tpstrtab_##name, STATIC_KEY_INIT_FALSE, reg, unreg, NULL };\ static struct tracepoint * const __tracepoint_ptr_##name __used \ __attribute__((section("__tracepoints_ptrs"))) = \ &__tracepoint_##name; ... #define DEFINE_TRACE(name) \ DEFINE_TRACE_FN(name, NULL, NULL);
続いて、 include/trace/define_trace.h の読み込み元で設定していた #define TRACE_SYSTEM sched に基づいて sched.h のヘッダーファイルをもう一度読み込む(つまり TRACE_EVENT(...) のイベント定義ファイルを再度展開させる)。この include のときは include/trace/define_trace.h で再定義した TRACE_EVENT マクロで展開される。
/* * Trace files that want to automate creation of all tracepoints defined * in their file should include this file. The following are macros that the * trace file may define: * * TRACE_SYSTEM defines the system the tracepoint is for * * TRACE_INCLUDE_FILE if the file name is something other than TRACE_SYSTEM.h * This macro may be defined to tell define_trace.h what file to include. * Note, leave off the ".h". * * TRACE_INCLUDE_PATH if the path is something other than core kernel include/trace * then this macro can define the path to use. Note, the path is relative to * define_trace.h, not the file including it. Full path names for out of tree * modules must be used. */ ... #ifndef TRACE_INCLUDE_FILE # define TRACE_INCLUDE_FILE TRACE_SYSTEM # define UNDEF_TRACE_INCLUDE_FILE #endif #ifndef TRACE_INCLUDE_PATH # define __TRACE_INCLUDE(system) <trace/events/system.h> # define UNDEF_TRACE_INCLUDE_PATH #else # define __TRACE_INCLUDE(system) __stringify(TRACE_INCLUDE_PATH/system.h) #endif # define TRACE_INCLUDE(system) __TRACE_INCLUDE(system) /* Let the trace headers be reread */ #define TRACE_HEADER_MULTI_READ #include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
続いて include/trace/trace_events.h は trace_events.h を読み込む。
#include TRACE_INCLUDE(TRACE_INCLUDE_FILE) /* Make all open coded DECLARE_TRACE nops */ #undef DECLARE_TRACE #define DECLARE_TRACE(name, proto, args) #ifdef TRACEPOINTS_ENABLED #include <trace/trace_events.h> #include <trace/perf.h> #include <trace/bpf_probe.h> #endif
trace_events.h でも同じく TRACE_EVENT を再定義したのちに sched.h をまた読み込む。このファイルだけで 5-6 回マクロを再定義して include してる…。もうダメだ頭がおかしくなりそうだ。
さいごに
まあなんか、いろいろやってますね。すごい。以上。