#1 はじめに
tapsetとは、printf()のようなライブラリ関数のようなものです。
systemtapをインストールすると、tapsetが下記ディレクトリ配下に格納されます。
/usr/share/systemtap/tapset
SystemTapそのもののインストール方法や使い方は、下記を参照ください。
SystemTapの使い方
SystemTapの使い方(その2)
SystemTapの使い方(グルモード編)
SystemTapの使い方(User-Space Probing)
#2 環境
VMware Workstation 14 Playerで作成した仮想マシンを使用しました。
仮想マシンの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パケットを受信すると、スクリプトを実行するようにします。
[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> 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コマンドの使い方)を参照してください。
[root@client ~]# arping -c 1 192.168.3.20
このときのイーサタイプは、0x0806
になります。
protocol=806,dev_name=eth0,length=46
次に、クライアントからサーバにIPv6パケットを送信します。
なお、pingコマンドの使い方は、ここ(pingコマンドの使い方)を参照ください。
[root@client ~]# ping -6 -c 1 -I eth0 fe80::a27b:67a6:4261:c852
このときのイーサタイプは、0x86DD
になります。
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