ftraceとfatraceについて

2021.12.21

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

コメント

タイトルとURLをコピーしました