LoginSignup
3

More than 3 years have passed since last update.

SystemTapの使い方(tapset編)

Last updated at Posted at 2019-10-27

1 はじめに

tapsetとは、printf()のようなライブラリ関数のようなものです。
systemtapをインストールすると、tapsetが下記ディレクトリ配下に格納されます。
/usr/share/systemtap/tapset

SystemTapそのもののインストール方法や使い方は、下記を参照ください。
SystemTapの使い方
SystemTapの使い方(その2)
SystemTapの使い方(グルモード編)
SystemTapの使い方(User-Space Probing)

2 環境

VMware Workstation 14 Playerで作成した仮想マシンを使用しました。
仮想マシンのOS版数は以下のとりです。

OS版数
[root@server ~]# cat /etc/redhat-release
CentOS Linux release 7.6.1810 (Core)

[root@server ~]# uname -r
3.10.0-957.el7.x86_64

3 Timestamp Functionsの使い方

Timestamp Functionsの使い方を説明します。

ここでは、スクリプトの動作確認をするため、
クライアントからサーバに対してpingを1回実行します。
クライアントでpingを実行すると、サーバはICMP echo requestパケットを受信します。
ICMP echo requestパケットを受信すると、スクリプトを実行するようにします。

pingの実行方法
[root@client ~]# ping -c 1 server

なお、pingコマンドの使い方は、ここ(pingコマンドの使い方)を参照ください。

3.1 jiffiesの使い方(jiffies)

ICMP echo requestパケットを受信すると、icmp_rcv関数が呼ばれます。
そのときのjiffies(*)を表示するスクリプトを作成します。
(*) カーネルが使用する変数です。
カーネル起動時からの相対時間を表す変数で、1ミリ秒毎にカウントアップされます。

スクリプト
[root@server ~]# cat tp.stp
#!/usr/bin/stap

probe kernel.function("icmp_rcv@net/ipv4/icmp.c")
{
  printf("pp=%s,jiffies=%d\n", pp(),jiffies())
}

ICMP echo requestパケットを受信すると、icmp_rcv関数が呼ばれます。
そのときのjiffiesが表示されていることがわかります。

実行結果
[root@server ~]# stap tp.stp
pp=kernel.function("icmp_rcv@net/ipv4/icmp.c:958"),jiffies=4299256780

3.2 UNIX epochからの時間を表示する方法

ICMP echo requestパケットを受信すると、icmp_rcvが呼ばれます。
そのときのUNIX epochタイムからの時間を、
秒、ミリ秒、マイクロ秒、ナノ秒で表示するスクリプトを作成します。

スクリプト
[root@server ~]# cat tp.stp
#!/usr/bin/stap

probe kernel.function("icmp_rcv@net/ipv4/icmp.c")
{
  printf("pp=%s\n", pp())
  printf("gettimeofday_s =%d\n", gettimeofday_s())
  printf("gettimeofday_ms=%d\n", gettimeofday_ms())
  printf("gettimeofday_us=%d\n", gettimeofday_us())
  printf("gettimeofday_ns=%d\n", gettimeofday_ns())
}
実行結果
[root@server ~]# stap tp.stp
pp=kernel.function("icmp_rcv@net/ipv4/icmp.c:958")
gettimeofday_s =1572136934
gettimeofday_ms=1572136934670
gettimeofday_us=1572136934670708
gettimeofday_ns=1572136934670709720

3.3 UNIX epochタイムをローカルタイムに変更する方法

スクリプト
[root@server ~]# cat tp.stp
#!/usr/bin/stap

probe kernel.function("icmp_rcv@net/ipv4/icmp.c")
{
  printf("pp=%s\n", pp())
  printf("gettimeofday_s =%d,tz_ctime=%s\n", gettimeofday_s(), tz_ctime(gettimeofday_s()))
}
実行結果
[root@server ~]# stap tp.stp
pp=kernel.function("icmp_rcv@net/ipv4/icmp.c:958")
gettimeofday_s =1572138175,tz_ctime=Sun Oct 27 10:02:55 2019 JST

3.4 ストップウオッチの使い方

文字通りストップウオッチの機能を提供します。
ICMP echo requestパケットを受信すると、icmp_rcv関数を呼び出します。
そして、その応答としてICMP echo replyパケットを送信します。
ICMP echo replyパケットを送信する際、icmp_reply関数を呼び出します。
ここでは、icmp_rcv関数を呼び出してから、icmp_reply関数を呼び出すまでの時間を
ストップウオッチを使って計測してみます。

スクリプト
[root@server ~]# cat tp.stp
#!/usr/bin/stap

probe kernel.function("icmp_rcv@net/ipv4/icmp.c")
{
  printf("pp=%s,  gettimeofday_ns()=%d\n", pp(), gettimeofday_ns())
  start_stopwatch("icmp")
}

probe kernel.function("icmp_reply@net/ipv4/icmp.c")
{
  printf("pp=%s,gettimeofday_ns()=%d,stopwatch=%d\n", pp(), gettimeofday_ns(), read_stopwatch_ns("icmp"))
  delete_stopwatch("icmp")
}

icmp_rcvからicmp_reply実行までの時間は、stopwatchを使うと4060(ナノ秒)となっています。
gettimeofday_nsを使った場合は、以下のとおり、6353(ナノ秒)となっています。
1572161288487214922-1572161288487208569=6353

実行結果
[root@server ~]# stap tp.stp
pp=kernel.function("icmp_rcv@net/ipv4/icmp.c:958"),  gettimeofday_ns()=1572161288487208569
pp=kernel.function("icmp_reply@net/ipv4/icmp.c:399"),gettimeofday_ns()=1572161288487214922,stopwatch=4060

4 Context Functionsの使い方

4.1 CPUの全レジスタ値を表示する方法(print_regs)

ICMP echo requestパケットを受信すると、icmp_rcvが呼ばれます。
そのときのCPUのレジスタ値を出力するスクリプトを作成します。

スクリプト
[root@server ~]# cat tp.stp
#!/usr/bin/stap

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

ICMP echoパケットを受信すると、icmp_rcvが呼ばれます。
そのときのCPUの全レジスタ値が出力されていることがわかります。

実行結果
[root@server ~]# stap tp.stp
pp=kernel.function("icmp_rcv@net/ipv4/icmp.c:958")
RIP: ffffffffb56ba680
RSP: ffff9b12d952fa40  EFLAGS: 00000202
RAX: ffffffffb56ba680 RBX: ffff9b128c3a2d00 RCX: 0000000000000000
RDX: ffff9b12d764c200 RSI: 0000000000000001 RDI: ffff9b128c3a2d00
RBP: ffff9b12d952fa60 R08: ffffffffb5d11640 R09: 00000000f0514df6
R10: ffff9b1291434070 R11: ffffffffc04605f8 R12: ffffffffb58a1360
R13: ffffffffb5d11640 R14: ffff9b12d82ca000 R15: 0000000000000008
FS:  0000000000000000(0000) GS:ffff9b12dfd00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fe59ff50000 CR3: 00000000d9340000 CR4: 00000000000606e0

次に、crashコマンドを実行して、print_regsで取得したRIPが示すアドレスを逆アセンブルしてみます。
0xffffffffb56ba680icmp_rcvであることがわかります。
なお、crashコマンドの使い方は、ここ(crashコマンドの使い方)を参照ください。

crashの実行結果
crash> dis ffffffffb56ba680
0xffffffffb56ba680 <icmp_rcv>:  nopl   0x0(%rax,%rax,1) [FTRACE NOP]
0xffffffffb56ba685 <icmp_rcv+5>:        push   %rbp
0xffffffffb56ba686 <icmp_rcv+6>:        mov    %rsp,%rbp
-snip-

4.2 指定したレジスタ値を表示する方法(register)

ICMP echo requestパケットを受信すると、icmp_rcvが呼ばれます。
そのときのRIPとEFLAGSレジスタの値を出力するスクリプトを作成します。

スクリプト
[root@server ~]# cat tp.stp
#!/usr/bin/stap

probe kernel.function("icmp_rcv@net/ipv4/icmp.c")
{
  printf("RIP=0x%x, EFLAGS=0x%x\n", register("rip"), register("eflags"))
}

RIPは0xffffffffb56ba680、EFLAGSは0x202であることがわかります。

実行結果
[root@server ~]# stap tp.stp
RIP=0xffffffffb56ba680, EFLAGS=0x202

4.3 カーネルスタックを表示する方法(print_backtrace)

ICMP echo requestパケットを受信すると、icmp_rcvが呼ばれます。
そのときのカーネルスタックを出力するスクリプトを作成します。

スクリプト
[root@server ~]# cat tp.stp
#!/usr/bin/stap

probe kernel.function("icmp_rcv@net/ipv4/icmp.c")
{
  printf("%s\n", print_backtrace())
}

stap tp.stpと実行すると、systemtapがワーニングを出力します。
systemtapの指示通り、-d e1000(*)を付けて、stapコマンドを実行します。

(*) -d オプションは環境によって異なります。
systemtapの指示通り、ご自身の環境にあわせて、オプションを指定してください。

icmp_rcv実行時のカーネルスタックが出力されていることがわかります。
以下のスタックは、ハード割り込み、ソフト割り込みで構成されています。
net_rx_actionicmp_rcvはソフト割り込みになります。
ソフト割り込みで、TCP/IP等のプロトコル処理を実行します。

実行結果
[root@server ~]# stap tp.stp -d e1000
WARNING: DWARF expression stack underflow in CFI
 0xffffffffb56ba680 : icmp_rcv+0x0/0x370 [kernel]
 0xffffffffb568285d : ip_local_deliver_finish+0xbd/0x200 [kernel]
 0xffffffffb5682b49 : ip_local_deliver+0x59/0xd0 [kernel]
 0xffffffffb56824c0 : ip_rcv_finish+0x90/0x370 [kernel]
 0xffffffffb5682e79 : ip_rcv+0x2b9/0x410 [kernel]
 0xffffffffb56394f9 : __netif_receive_skb_core+0x729/0xa10 [kernel]
 0xffffffffb56397f8 : __netif_receive_skb+0x18/0x60 [kernel]
 0xffffffffb5639880 : netif_receive_skb_internal+0x40/0xc0 [kernel]
 0xffffffffb563a508 : napi_gro_receive+0xd8/0x100 [kernel]
 0xffffffffc013943b : e1000_clean_rx_irq+0x2bb/0x510 [e1000]
 0xffffffffc013a0dd : e1000_clean+0x27d/0x8e0 [e1000]
 0xffffffffb5639e9f : net_rx_action+0x26f/0x390 [kernel]
 0xffffffffb50a0f05 : __do_softirq+0xf5/0x280 [kernel]
 0xffffffffb577832c : call_softirq+0x1c/0x30 [kernel]
 0xffffffffb502e675 : do_softirq+0x65/0xa0 [kernel]
 0xffffffffb50a1285 : irq_exit+0x105/0x110 [kernel]
 0xffffffffb57795e6 : __irqentry_text_start+0x56/0xf0 [kernel]
 0xffffffffb576b362 : ret_from_intr+0x0/0x15 [kernel]

5 Networking Tapsetの使い方

5.1 netdev.receiveの使い方

netdev.receiveは、NICにパケットが届いたら実行するプローブです。

下記スクリプト中のprotocolはイーサタイプを表します。
たとえば、IPv4なら0x0800、IPv6なら0x86DD、ARPなら0x0806です。
dev_nameは、パケットを受信したNICの名前になります。

スクリプト
[root@server ~]# cat tp.stp
#!/usr/bin/stap

probe netdev.receive
{
  printf("protocol=%x,dev_name=%s,length=%d\n",ntohs(protocol),dev_name,length)
}

クライアントからサーバにARP requestパケットを1つ送信します。
192.168.3.20は、サーバのIPアドレスです。
なお、arpingコマンドの使い方は、ここ(arpingコマンドの使い方)を参照してください。

ARP_requestをサーバに送信
[root@client ~]# arping -c 1 192.168.3.20

このときのイーサタイプは、0x0806になります。

ARP_requestを受信した場合
protocol=806,dev_name=eth0,length=46

次に、クライアントからサーバにIPv6パケットを送信します。
なお、pingコマンドの使い方は、ここ(pingコマンドの使い方)を参照ください。

IPv6パケットをサーバに送信
[root@client ~]# ping -6 -c 1 -I eth0 fe80::a27b:67a6:4261:c852

このときのイーサタイプは、0x86DDになります。

IPv6パケットを受信した場合
protocol=86dd,dev_name=eth0,length=104

Z 参考情報

SYSTEMTAP タップセットリファレンス
SystemTap Tapset Reference Manual
SystemTap Language Reference
systemtap /systemtap-1.8/testsuite/buildok/irq-detailed.stp

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
3