hana_shinのLinux技術ブログ

Linuxの技術情報を掲載しています。特にネットワークをメインに掲載していきます。

SystemTapの使い方

AlmaLinux 8 systemtap トラブルシューティング


1 SystemTapとは?

SystemTapは、カーネルやアプリの動作を追跡するツールです。SystemTapを使うと、プログラムのバグやパフォーマンス問題の原因を特定することができます。本記事では、SystemTapの基本的な使い方を説明します。

2 検証環境

AlmaLinuxの版数は以下のとおりです。

[root@server ~]# cat /etc/redhat-release
AlmaLinux release 8.6 (Sky Tiger)

カーネル版数は以下のとおりです。

[root@server ~]# uname -r
4.18.0-372.9.1.el8.x86_64

3 事前準備

systemtapパッケージをインストールします。

[root@server ~]# dnf -y install systemtap

kernel-debuginfoパッケージをインストールするため、リポジトリを追加します。

[root@server ~]# dnf config-manager --add-repo=https://repo.almalinux.org/vault/8.6/BaseOS/debug/x86_64/

kernel-debuginfoパッケージをインストールします。

[root@server ~]# dnf install kernel-debuginfo-4.18.0-372.9.1.el8

kernel-develパッケージをインストールするため、リポジトリを追加します。

[root@server ~]# dnf config-manager --add-repo=https://repo.almalinux.org/vault/8.6/BaseOS/x86_64/os/

kernel-develパッケージをインストールします。

[root@server ~]# dnf install kernel-devel-4.18.0-372.9.1.el8.x86_64

4 プローブの設定方法

プローブは以下のソースコードに設定することができます。

・カーネル
・カーネルモジュール(lsmodで表示されるモジュールのことです。たとえばbridge）
・アプリ(Apache等)

ソースコードに設定したプローブが実行されると、あらかじめプローブに定義した処理が実行されます。ここでは、カーネルとカーネルモジュールにプローブを設定する方法を説明します。アプリにプローブを設定する方法については、SystemTapの使い方(User-Space Probing) - hana_shinのLinux技術ブログを参照してください。

ソースコードに設定するプローブの書式は以下のとおりです、

書式 概要
kernel.function("関数名@ファイルのパス名") カーネル関数の入り口にプローブを設定
kernel.function("関数名@ファイルのパス名").return カーネル関数から復帰する場所にプローブを設定
kernel.statement("関数名@ファイルのパス名:行数") ファイルの指定した場所にプローブを設定
module("モジュール名").function("関数名@ファイルのパス名") カーネルモジュールで定義されている関数の入り口にプローブを設定
module("モジュール名").function("関数名@ファイルのパス名").return カーネルモジュールで定義されている関数から復帰する場所にプローブを設定
module("モジュール名").statement("関数名@ファイルのパス名") ファイルの指定した場所にプローブを設定
process("アプリの実行ファイルのパス名").function("関数名") アプリの関数入り口にプローブを設定
process("アプリの実行ファイルのパス名").function("関数名").return アプリの関数から復帰する場所にプローブを設定

4.1 カーネルにプローブを設定する方法

4.1.1 カーネル関数の入り口にプローブを設定する方法

カーネル関数にping_v4_sendmsg()があります。pingコマンドを実行すると実行されます。ここでは、ping_v4_sendmsg()の入り口に設定したプローブが実行されると、pp()を実行するスクリプトを作成します。pp()は後述しますが、プローブの情報（関数名、ファイルのパス名）を表示するSystemTapの組み込み関数です。

[root@server ~]# cat ping.stp
#!/usr/bin/stap

probe kernel.function("ping_v4_sendmsg@net/ipv4/ping.c")
{
  printf("pp=%s\n",pp())
}

スクリプトを実行します。

[root@server ~]# stap -vg ping.stp
Pass 1: parsed user script and 485 library scripts using 295520virt/96632res/18204shr/80236data kb, in 360usr/110sys/482real ms.
Pass 2: analyzed script: 1 probe, 1 function, 0 embeds, 0 globals using 487036virt/270636res/19320shr/271752data kb, in 1740usr/480sys/2363real ms.
Pass 3: using cached /root/.systemtap/cache/87/stap_87a3e7f96d3549d2ec26065140f22b46_1174.c
Pass 4: using cached /root/.systemtap/cache/87/stap_87a3e7f96d3549d2ec26065140f22b46_1174.ko
Pass 5: starting run.

pingコマンドを1回実行します。なお、pingコマンドの使い方は、pingコマンドの使い方 - hana_shinのLinux技術ブログを参照してください。

[root@server ~]# ping -c 1 192.168.122.1

SystemTapの実行結果の一番下を確認すると、プローブの情報(ping_v4_sendmsg()がping.cファイルの701行目で定義されている)が表示されていることがわかります。

[root@server ~]# stap -vg ping.stp
Pass 1: parsed user script and 485 library scripts using 295520virt/96632res/18204shr/80236data kb, in 360usr/110sys/482real ms.
Pass 2: analyzed script: 1 probe, 1 function, 0 embeds, 0 globals using 487036virt/270636res/19320shr/271752data kb, in 1740usr/480sys/2363real ms.
Pass 3: using cached /root/.systemtap/cache/87/stap_87a3e7f96d3549d2ec26065140f22b46_1174.c
Pass 4: using cached /root/.systemtap/cache/87/stap_87a3e7f96d3549d2ec26065140f22b46_1174.ko
Pass 5: starting run.
pp=kernel.function("ping_v4_sendmsg@net/ipv4/ping.c:701")

一方、カーネルのソースファイルを確認すると、ping_v4_sendmsg()がping.cファイルの701行目で定義されていることがわかります。

[root@server ~]# less -N /usr/src/debug/kernel-4.18.0-372.9.1.el8/linux-4.18.0-372.9.1.el8.x86_64/net/ipv4/ping.c
-snip-
    701 static int ping_v4_sendmsg(struct sock *sk, struct msghdr *msg, size_t len)
    702 {
    703         struct net *net = sock_net(sk);
4.1.2 カーネル関数から復帰する場所にプローブを設定する方法

ping_v4_sendmsg()が復帰する場所に設定したプローブが実行されると、pp()の実行とping_v4_sendmsg()の戻り値を表示するスクリプトを作成します。

[root@server ~]# cat ping.stp
#!/usr/bin/stap

probe kernel.function("ping_v4_sendmsg@net/ipv4/ping.c").return
{
  printf("pp=%s, ret=%d\n",pp(), $return)
}

スクリプトを実行します。

[root@server ~]# stap -vg ping.stp

pingコマンドを1回実行します。

[root@server ~]# ping -c 1 192.168.122.1

SystemTapの実行結果を確認すると、プローブの情報とping_v4_sendmsg()の戻り値(64)が表示されていることがわかります。なお、ping_v4_sendmsg()の戻り値はICMP echoパケットのパケット長を表します。

[root@server ~]# stap -vg ping.stp
-snip-
pp=kernel.function("ping_v4_sendmsg@net/ipv4/ping.c:701").return, ret=64
4.1.3 ファイルの指定した場所にプローブを設定する方法

プローブを設定する場所を確認するため、lessコマンドでping.cを参照します。ここでは、ping.cの749行目にプローブを設定します。

[root@server ~]# less -N /usr/src/debug/kernel-4.18.0-372.9.1.el8/linux-4.18.0-372.9.1.el8.x86_64/net/ipv4/ping.c
-snip-
    701 static int ping_v4_sendmsg(struct sock *sk, struct msghdr *msg, size_t len)
    702 {
    703         struct net *net = sock_net(sk);

    -snip-

    748         ipc.tos = -1;
    749         ipc.sockc.transmit_time = 0;
    750
    751         if (msg->msg_controllen) {

ping.cの749行目に設定したプローブが実行されると、pp()を実行するスクリプトを作成します。

[root@server ~]# cat ping.stp
#!/usr/bin/stap

probe kernel.statement("ping_v4_sendmsg@net/ipv4/ping.c:749")
{
  printf("pp=%s\n",pp())
}

スクリプトを実行します。

[root@server ~]# stap -vg ping.stp

pingコマンドを1回実行します。

[root@server ~]# ping -c 1 192.168.122.1

SystemTapの実行結果を確認すると、プローブの情報(設定したプローブがping.cの749行目)が表示されていることがわかります。

[root@server ~]# stap -vg ping.stp
-snip-
pp=kernel.statement("ping_v4_sendmsg@net/ipv4/ping.c:749")

4.2 カーネルモジュールにプローブを設定する方法

4.2.1 モジュール内の特定の関数にプローブを設定する方法

nf_conntrackモジュールにnf_ct_net()という関数が定義されています。ここでは、pingプロセスがnf_ct_net()を実行するとプローブ情報を表示するスクリプトを作成します。

[root@server ~]# cat nf.stp
#!/usr/bin/stap

probe module("nf_conntrack").function("nf_ct_net")
{
  if(execname()=="ping"){
    printf("pp=%s\n", pp())
  }
}

スクリプトを実行します。

[root@server ~]# stap -vg nf.stp

pingコマンドを1回実行します。

[root@server ~]# ping -c 1 192.168.122.1

SystemTapの実行結果を確認すると、プローブの情報(設定したプローブがnf_conntrack.hの138行目)が表示されていることがわかります。

[root@server ~]# stap -vg nf.stp
-snip-
pp=module("nf_conntrack").function("nf_ct_net@./include/net/netfilter/nf_conntrack.h:138")
pp=module("nf_conntrack").function("nf_ct_net@./include/net/netfilter/nf_conntrack.h:138")
pp=module("nf_conntrack").function("nf_ct_net@./include/net/netfilter/nf_conntrack.h:138")
-snip-
4.2.2 モジュール内の全ての関数にプローブを設定する方法

pingプロセスがnf_conntrackモジュールの関数を実行すると、プローブの情報を表示するスクリプトを作成します。

[root@server stap]# cat ping.stp
#!/usr/bin/stap

probe module("nf_conntrack").function("*")
{
  if(execname()=="ping"){
    printf("pp=%s\n", pp())
  }
}

スクリプトを実行します。

[root@server stap]# stap -vg ping.stp

pingコマンドを1回実行します。

[root@server ~]# ping -c 1 192.168.122.1

SystemTapの実行結果を確認すると、nf_conntrackモジュールに定義されている関数が表示されていることがわかります。

[root@server stap]# stap -vg ping
-snip-
pp=module("nf_conntrack").function("ipv4_conntrack_local@net/netfilter/nf_conntrack_proto.c:406")
pp=module("nf_conntrack").function("skb_network_header@./include/linux/skbuff.h:2551")
pp=module("nf_conntrack").function("ip_hdr@./include/linux/ip.h:23")
pp=module("nf_conntrack").function("nf_conntrack_in@net/netfilter/nf_conntrack_core.c:1786")
pp=module("nf_conntrack").function("nf_ct_get@./include/net/netfilter/nf_conntrack.h:157")
pp=module("nf_conntrack").function("skb_network_header@./include/linux/skbuff.h:2551")
-snip-

5 関数の使い方

今までの説明でpp()という関数を使用してきましたが、pp()はSystemTapの組み込み関数です。組み込み関数は、stapコマンドのオプションに--dump-functionsを指定すると、その一覧を表示することができます。

[root@server ~]# stap --dump-functions
AF_INET6:long () /* unprivileged */
AF_INET:long () /* unprivileged */
HZ:long () /* unprivileged */
MAJOR:long (dev:long)
MINOR:long (dev:long)
MKDEV:long (major:long, minor:long)
-snip-

また、関数への引数の変数名、型は次のようにして確認することができます。tcp_v4_rcv()で使える変数名はskb、型はsk_buff構造体へのポインタであることがわかります。

[root@server ~]# stap -L 'kernel.function("tcp_v4_rcv")'
kernel.function("tcp_v4_rcv@net/ipv4/tcp_ipv4.c:1846") $skb:struct sk_buff*

もう1つip_rcv()で使える変数、変数の型を調べてみます。ip_rcv()使える変数名はskb,dev,pt,orig_devの4つであることがわかります。

[root@server ~]# stap -L 'kernel.function("ip_rcv")'
kernel.function("ip_rcv@net/ipv4/ip_input.c:417") $skb:struct sk_buff* $dev:struct net_device* $pt:struct packet_type* $orig_dev:struct net_device*

5.1 プローブの情報を表示する方法(pp)

pp()はプローブの情報を表示する関数です。ping_v4_sendmsg()を実行したら、プローブの情報を表示するスクリプトを作成します。

[root@server ~]# cat ping.stp
#!/usr/bin/stap

probe kernel.function("ping_v4_sendmsg@net/ipv4/ping.c")
{
  printf("pp=%s\n",pp())
}

スクリプトを実行します。

[root@server ~]# stap -vg ping.stp
Pass 1: parsed user script and 485 library scripts using 295520virt/96632res/18204shr/80236data kb, in 360usr/110sys/482real ms.
Pass 2: analyzed script: 1 probe, 1 function, 0 embeds, 0 globals using 487036virt/270636res/19320shr/271752data kb, in 1740usr/480sys/2363real ms.
Pass 3: using cached /root/.systemtap/cache/87/stap_87a3e7f96d3549d2ec26065140f22b46_1174.c
Pass 4: using cached /root/.systemtap/cache/87/stap_87a3e7f96d3549d2ec26065140f22b46_1174.ko
Pass 5: starting run.

pingコマンドを1回実行します。なお、pingコマンドの使い方は、pingコマンドの使い方 - hana_shinのLinux技術ブログを参照してください。

[root@server ~]# ping -c 1 192.168.122.1

SystemTapの実行結果を確認すると、プローブの情報(ping_v4_sendmsg()がping.cファイルの701行目で定義されている)が表示されていることがわかります。

[root@server ~]# stap -vg ping.stp
Pass 1: parsed user script and 485 library scripts using 295520virt/96632res/18204shr/80236data kb, in 360usr/110sys/482real ms.
Pass 2: analyzed script: 1 probe, 1 function, 0 embeds, 0 globals using 487036virt/270636res/19320shr/271752data kb, in 1740usr/480sys/2363real ms.
Pass 3: using cached /root/.systemtap/cache/87/stap_87a3e7f96d3549d2ec26065140f22b46_1174.c
Pass 4: using cached /root/.systemtap/cache/87/stap_87a3e7f96d3549d2ec26065140f22b46_1174.ko
Pass 5: starting run.
pp=kernel.function("ping_v4_sendmsg@net/ipv4/ping.c:701")

一方、カーネルのソースファイルを確認すると、ping_v4_sendmsg()がping.cファイルの701行目で定義されていることがわかります。

[root@server ~]# less -N /usr/src/debug/kernel-4.18.0-372.9.1.el8/linux-4.18.0-372.9.1.el8.x86_64/net/ipv4/ping.c
-snip-
    701 static int ping_v4_sendmsg(struct sock *sk, struct msghdr *msg, size_t len)
    702 {
    703         struct net *net = sock_net(sk);

5.2 呼び出し元の関数名を表示する方法(caller)

caller()は関数の呼び出し元の関数名を表示する関数です。ping_v4_sendmsg()の入り口に設定したプローブが実行されると、ping_v4_sendmsgの呼びだし元関数名を表示するスクリプトを作成します。

[root@server ~]# cat ping.stp
#!/usr/bin/stap

probe kernel.function("ping_v4_sendmsg@net/ipv4/ping.c")
{
  printf("caller=%s\n",caller())
}

スクリプトを実行します。

[root@server ~]# stap -vg ping.stp

pingコマンドを1回実行します。

[root@server ~]# ping -c 1 192.168.122.1

SystemTapの実行結果を確認すると、ping_v4_sendmsg()の呼び出し元関数がsock_sendmsg()であることがわかります。

[root@server ~]# stap -vg ping.stp
-snip-
caller=sock_sendmsg 0xffffffffb43b752e

5.3 時刻を表示する方法(gettimeofday_s,tz_ctime)

ping_v4_sendmsg()の入り口に設定したプローブが実行されると、ping_v4_sendmsg()実行時の時刻を表示するスクリプトを作成します。なお、gettimeofday_s()は、Unix epoch (1970年1月1日) からの秒数を求める関数です。tz_ctime()は、Unix epoch からの経過時間(秒)をタイムゾーンにもとずいて時刻に変換する関数です。

[root@server ~]# cat ping.stp
#!/usr/bin/stap

probe kernel.function("ping_v4_sendmsg@net/ipv4/ping.c")
{
  printf("time=%s\n", tz_ctime(gettimeofday_s()))
}

スクリプトを実行します。

[root@server ~]# stap -vg ping.stp

pingコマンドを1回実行します。

[root@server ~]# ping -c 1 192.168.122.1

SystemTapの実行結果を確認すると、ping_v4_sendmsg()を実行したときの時刻が、2023年1月13日 22:22:11であることがわかります。

[root@server ~]# stap -vg ping.stp
-snip-
time=Fri Jan 13 22:22:11 2023 JST

5.4 関数を実行するプロセス名を表示する方法(execname)

ping_v4_sendmsg()の入り口に設定したプローブが実行されると、ping_v4_sendmsg()を実行するプロセス名を表示するスクリプトを作成します。

[root@server ~]# cat ping.stp
#!/usr/bin/stap

probe kernel.function("ping_v4_sendmsg@net/ipv4/ping.c")
{
  printf("execname=%s\n",execname())
}

スクリプトを実行します。

[root@server ~]# stap -vg ping.stp

pingコマンドを1回実行します。

[root@server ~]# ping -c 1 192.168.122.1

SystemTapの実行結果を確認すると、ping_v4_sendmsg()を実行したプロセスがpingプロセスであることがわかります。

[root@server ~]# stap -vg ping.stp
-snip-
execname=ping

もう1つexecname()の使い方を紹介します。pingプロセスがip_output()を実行したときの時刻を表示してみます。なお、時刻表示をpingプロセスに限定している理由は、様々なプロセスが外部と通信をするときにip_output()を実行するので、pingプロセスに限定しないと大量にSystemTapの実行結果が表示されるためです。

[root@server ~]# cat ping.stp
#!/usr/bin/stap

probe kernel.function("ip_output@net/ipv4/ip_output.c")
{
  if(execname()=="ping")
  {
    printf("time=%s\n", tz_ctime(gettimeofday_s()))
  }
}

スクリプトを実行します。

[root@server ~]# stap -vg ping.stp

pingコマンドを1回実行します。

[root@server ~]# ping -c 1 192.168.122.1

SystemTapの実行結果を確認すると、pingプロセスがip_output()を実行したときの時刻が1/13(金) 22:25:59であることがわかります。

[root@server ~]# stap -vg ping.stp
-snip-
time=Fri Jan 13 22:25:59 2023 JST

5.5 バックトレースを表示する方法(print_backtrace)

ip_output()の入り口に設定したプローブをpingプロセスが実行したときだけ、バックトレースを表示するスクリプトを作成します。バックトレースとは、関数の呼び出し元を大元の呼び出しもとに向かって関数名を表示する機能です。

[root@server ~]# cat ping.stp
#!/usr/bin/stap

probe kernel.function("ip_output@net/ipv4/ip_output.c")
{
  if(execname()=="ping")
  {
    printf("backtrace=%s\n", print_backtrace())
  }
}

スクリプトを実行します。

[root@server ~]# stap -vg ping.stp

pingコマンドを1回実行します。

[root@server ~]# ping -c 1 192.168.122.1

SystemTapの実行結果を確認すると、ip_output()ｍの呼び出し元はip_send_skb()、ip_send_skb()の呼び出し元はping_v4_sendmsg()であることがわかります。そして大元の呼び出し元がentry_SYSCALL_64_after_hwframe()であることがわかります。

[root@server ~]# stap -vg ping.stp
Pass 1: parsed user script and 485 library scripts using 295516virt/96608res/18180shr/80232data kb, in 330usr/80sys/425real ms.
Pass 2: analyzed script: 1 probe, 2 functions, 0 embeds, 0 globals using 487044virt/270768res/19296shr/271760data kb, in 1550usr/370sys/1996real ms.
Pass 3: using cached /root/.systemtap/cache/b5/stap_b5b4816c556b1e0b346fac195cb11a8a_1350.c
Pass 4: using cached /root/.systemtap/cache/b5/stap_b5b4816c556b1e0b346fac195cb11a8a_1350.ko
Pass 5: starting run.
 0xffffffffae47c780 : ip_output+0x0/0xe0 [kernel]
 0xffffffffae47d155 : ip_send_skb+0x15/0x40 [kernel]
 0xffffffffae4cdf92 : ping_v4_sendmsg+0x582/0x7b0 [kernel]
 0xffffffffae3b752e : sock_sendmsg+0x3e/0x50 [kernel]
 0xffffffffae3b949e : __sys_sendto+0xee/0x160 [kernel]
 0xffffffffae3b9534 : __x64_sys_sendto+0x24/0x30 [kernel]
 0xffffffffadc0430b : do_syscall_64+0x5b/0x1a0 [kernel]
 0xffffffffae6000ad : entry_SYSCALL_64_after_hwframe+0x65/0xca [kernel]
 0xffffffffae6000ad : entry_SYSCALL_64_after_hwframe+0x65/0xca [kernel] (inexact)
backtrace=

5.6 CPU番号を表示する方法(cpu)

ip_output()の入り口に設定したプローブをpingプロセスが実行したときだけ、CPU番号を表示するスクリプトを作成します。

[root@server ~]# cat ping.stp
#!/usr/bin/stap

probe kernel.function("ip_output@net/ipv4/ip_output.c")
{
  if(execname()=="ping")
  {
    printf("cpu=%d\n", cpu())
  }
}

スクリプトを実行します。

[root@server ~]# stap -vg ping.stp

pingコマンドを3回実行します。

[root@server ~]# ping -c 3 192.168.122.1

実行結果を確認すると、pingプロセスは1回目はip_output()をCPU2で実行しています。そして、2回目,3回目はip_output()をCPU3で実行していることがわかります。

[root@server stap]# stap -vg ping.stp
-snip-
cpu=2
cpu=3
cpu=3

Z 参考情報

私が業務や記事執筆で参考にした書籍を以下のページに記載します。
Linux技術のスキルアップをしよう！ - hana_shinのLinux技術ブログ

SystemTap Examples
SystemTap ビギナーズガイド Red Hat Enterprise Linux 7 | Red Hat Customer Portal
https://sourceware.org/systemtap/tutorial.pdf
https://lrita.github.io/images/posts/systemtap/langref.pdf