ftraceとは？
ftrace は、Linux カーネル内で何が起きているかを理解するためのトレースやプロファイルするツールです。
ftraceとのやりとりはユーザスペースからはdebugfsを通じておこないます。
はじめに、debugfsがマウントされているか確認してみましょう。
# findmnt -t debugfs
TARGET SOURCE FSTYPE OPTIONS
/sys/kernel/debug debugfs debugfs rw,nosuid,nodev,noexec,relatime,seclabel
debugfsがマウントされていない場合は、次のようにマウントしてください。
# mount -t debugfs nodev /sys/kernel/debug
次に、ftrace_enabledが有効になっているか確認してください。
# sysctl -a | grep kernel.ftrace_enabled
kernel.ftrace_enabled = 1
有効になっていない場合は、次のように有効にしましょう。
# echo "kernel.ftrace_enabled = 1" >> /etc/sysctl.conf
# sysctl -a
ftraceのどんなトレーサーが利用可能かは、次のように確認できます。
# cat /sys/kernel/debug/tracing/available_tracers
hwlat blk function_graph wakeup_dl wakeup_rt wakeup function nop
/sys/kernel/debug/tracing/にftraceの制御や出力ファイルがあります。
# ll /sys/kernel/debug/tracing/
合計 0
-r--r--r--. 1 root root 0 12月 20 09:10 README
-r--r--r--. 1 root root 0 12月 20 09:10 available_events
-r--r--r--. 1 root root 0 12月 20 09:10 available_filter_functions
-r--r--r--. 1 root root 0 12月 20 09:10 available_tracers
-r--r--r--. 1 root root 0 12月 20 09:10 buffer_percent
-rw-r--r--. 1 root root 0 12月 20 09:10 buffer_size_kb
-r--r--r--. 1 root root 0 12月 20 09:10 buffer_total_size_kb
-rw-r--r--. 1 root root 0 12月 20 09:10 current_tracer
-r--r--r--. 1 root root 0 12月 20 09:10 dyn_ftrace_total_info
-rw-r--r--. 1 root root 0 12月 20 09:10 dynamic_events
-r--r--r--. 1 root root 0 12月 20 09:10 enabled_functions
-rw-r--r--. 1 root root 0 12月 20 09:10 error_log
-r--r--r--. 1 root root 0 12月 20 09:10 eval_map
drwxr-xr-x. 116 root root 0 12月 20 09:10 events
...
実際にトレースする前に、利用可能なトレーサーを確認してみましょう。
# cat /sys/kernel/debug/tracing/available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
それではfunctionを設定して、トレースしてみましょう。
# echo function > /sys/kernel/debug/tracing/current_tracer
# cat /sys/kernel/debug/tracing/current_tracer
function
# echo 1 > /sys/kernel/debug/tracing/tracing_on
# cat /sys/kernel/debug/tracing/tracing_on
1
例えば、viのpidを指定してvfs_writeをトレースしてみましょう。
# curl -L -O https://raw.githubusercontent.com/brendangregg/perf-tools/master/kernel/funcgraph
# chmod u+x funcgraph
# pgrep vi
99786
# ./funcgraph -Htp 99786 vfs_write
Tracing "vfs_write" for PID 99786... Ctrl-C to end.
# tracer: function_graph
#
# TIME CPU DURATION FUNCTION CALLS
# | | | | | | | |
2317526.425184 | 9) | vfs_write() {
2317526.425185 | 9) | rw_verify_area() {
2317526.425185 | 9) | security_file_permission() {
2317526.425185 | 9) | selinux_file_permission() {
2317526.425185 | 9) | __inode_security_revalidate() {
2317526.425185 | 9) 0.040 us | _cond_resched();
2317526.425186 | 9) 0.600 us | }
2317526.425186 | 9) 0.031 us | avc_policy_seqno();
2317526.425186 | 9) 1.337 us | }
2317526.425187 | 9) 1.668 us | }
2317526.425187 | 9) 1.968 us | }
2317526.425187 | 9) | tty_write() {
2317526.425187 | 9) 0.025 us | tty_paranoia_check();
2317526.425187 | 9) | tty_ldisc_ref_wait() {
2317526.425188 | 9) | ldsem_down_read() {
2317526.425188 | 9) 0.030 us | _cond_resched();
2317526.425188 | 9) 0.316 us | }
2317526.425188 | 9) 0.586 us | }
2317526.425188 | 9) | tty_write_lock() {
2317526.425188 | 9) 0.058 us | mutex_trylock();
2317526.425189 | 9) 0.339 us | }
2317526.425189 | 9) | __check_object_size() {
2317526.425189 | 9) 0.025 us | static_key_enabled();
2317526.425189 | 9) 0.036 us | __virt_addr_valid();
2317526.425190 | 9) 0.043 us | __check_heap_object();
2317526.425190 | 9) 0.035 us | check_stack_object();
2317526.425190 | 9) 1.354 us | }
...
最後に、トレースを無効にするには0を設定します。
# echo 0 > /sys/kernel/debug/tracing/tracing_on
# cat /sys/kernel/debug/tracing/tracing_on
0
fatraceとは？
fatraceは、file access traceの略で、
fatraceを実行すると、次のような出力結果が表示できます。
# fatrace
firefox(3052): CW /home/user/.mozilla/firefox/fame4579.default-release/sessionstore-backups/recovery.jsonlz4.tmp
firefox(3052): <> /home/user/.mozilla/firefox/fame4579.default-release/sessionstore-backups
firefox(3052): <> /home/user/.mozilla/firefox/fame4579.default-release/sessionstore-backups
sssd_kcm(2674): W /var/log/sssd/sssd_kcm.log-20211221
geoclue(1990): O /etc/hosts
geoclue(1990): RC /etc/hosts
geoclue(1990): O /etc/pki/ca-trust/source/anchors
geoclue(1990): R /etc/pki/ca-trust/source/anchors
geoclue(1990): RC /etc/pki/ca-trust/source/anchors
プロセス名firefoxが、C(Close)、W(Write)を実行していることがわかります。
O(Open)、R(Read)も上記結果から読み取ることができます。
例えば、w(write)とだけ表示するには、次のように指定します。
# fatrace -f w
sssd_kcm(2674): W /var/log/sssd/sssd_kcm.log-20211221
firefox(3052): W /home/user/.cache/mozilla/firefox/fame4579.default-release/cache2/entries/CA108A3DF2A4D3F4DECFDD9A94629BF2A0D0125E
firefox(3052): W /home/user/.cache/mozilla/firefox/fame4579.default-release/cache2/entries/CA108A3DF2A4D3F4DECFDD9A94629BF2A0D0125E
firefox(3052): W /home/user/.cache/mozilla/firefox/fame4579.default-release/cache2/entries/CA108A3DF2A4D3F4DECFDD9A94629BF2A0D0125E
firefox(3052): CW /home/user/.cache/mozilla/firefox/fame4579.default-release/cache2/entries/CA108A3DF2A4D3F4DECFDD9A94629BF2A0D0125E
sssd_kcm(2674): W /var/log/sssd/sssd_kcm.log-20211221
コメント