SystemTapの使い方(tapset編)

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



SystemTapそのもののインストール方法や使い方は、下記を参照ください。
[SystemTapの使い方](https://qiita.com/hana_shin/items/9b265b4f9a51f98d0f4d)
[SystemTapの使い方(その2)](https://qiita.com/hana_shin/items/13fc31204426f7187e60)
[SystemTapの使い方(グルモード編)](https://qiita.com/hana_shin/items/f2806e68493c89fbbef8)
[SystemTapの使い方（User-Space Probing)](https://qiita.com/hana_shin/items/6bca693206bf5f887cb3)

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

```console: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パケットを受信すると、スクリプトを実行するようにします。

```console:pingの実行方法
[root@client ~]# ping -c 1 server
```
なお、pingコマンドの使い方は、[ここ(pingコマンドの使い方)](https://qiita.com/hana_shin/items/c31b0d05a91244c4db83)を参照ください。


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


```console:スクリプト
[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が表示されていることがわかります。

```console:実行結果
[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タイムからの時間を、
秒、ミリ秒、マイクロ秒、ナノ秒で表示するスクリプトを作成します。

```console:スクリプト
[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())
}
```

```console:実行結果
[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タイムをローカルタイムに変更する方法

```console:スクリプト
[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()))
}
```

```console:実行結果
[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関数を呼び出すまでの時間を
ストップウオッチを使って計測してみます。

```console:スクリプト
[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`

```console:実行結果
[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のレジスタ値を出力するスクリプトを作成します。

```console:スクリプト
[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の全レジスタ値が出力されていることがわかります。

```console:実行結果
[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コマンドの使い方)](https://qiita.com/hana_shin/items/02d8da181c8287580613)を参照ください。

```console: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レジスタの値を出力するスクリプトを作成します。


```console:スクリプト
[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`であることがわかります。

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


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

```console:スクリプト
[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等のプロトコル処理を実行します。

```console:実行結果
[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の名前になります。

```console:スクリプト
[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コマンドの使い方)](https://qiita.com/hana_shin/items/941c208805521f58d462)を参照してください。

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

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

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

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


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

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

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



#Z 参考情報
[SYSTEMTAP タップセットリファレンス](https://access.redhat.com/documentation/ja-jp/red_hat_enterprise_linux/7/html/systemtap_tapset_reference/index)
[SystemTap Tapset Reference Manual](https://sourceware.org/systemtap/tapsets/)
[SystemTap Language Reference](https://sourceware.org/systemtap/langref.pdf)
[systemtap /systemtap-1.8/testsuite/buildok/irq-detailed.stp](https://searchcode.com/codesearch/view/19161395/)