SystemTapの使い方(tapset編)

16617 ワード
systemtap centos7 centos7 テキストリンク

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が示すアドレスを逆アセンブルしてみます。
0xffffffffb56ba680はicmp_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_action～icmp_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

socketローカルエリアネットワークチャット実装
04 Pythonタイプ