SystemTapを学習します
Google Cloudが技術的な問題をどのように解決していったかということを「DNS パケット欠落のケース: Google Cloud サポート ストーリー」として記事にして公開してくれていましたので
それを題材にSystemTapを勉強してみました。
こちらの記事では net.core.rmem_default の整数オーバーフローが原因でDNS パケットが欠落する問題を解決するために収集した情報やどのように解決に至ったかについて
詳しく説明されています。
cloud.google.com
あらかじめ v5.4のカーネルとdropwatchを用意しておきます。
v5.4のkernelで起動した直後のUDPの統計情報です。
# netstat -su Udp: 0 packets received 0 packets to unknown port received 0 packet receive errors 0 packets sent 0 receive buffer errors 0 send buffer errors IgnoredMulti: 1 UdpLite: IpExt: InBcastPkts: 1 InOctets: 18613 OutOctets: 16002 InBcastOctets: 272 InNoECTPkts: 98 InECT0Pkts: 82 # nstat -a |grep -i udp UdpInDatagrams 3 0.0 UdpOutDatagrams 3 0.0 UdpIgnoredMulti 1 0.0
sysctl -w net.core.rmem_default=$((2**31-1))を設定し
DNS パケットが欠落する状況を用意してからdig www.google.comしたdropwatchの結果です。
# dropwatch -lkas Initializing kallsyms db dropwatch> start Enabling monitoring... Kernel monitoring activated. Issue Ctrl-C to stop monitoring 16 drops at netlink_broadcast_filtered+257 (0xffffffffadd8e7c7) [software] 1 drops at udp_queue_rcv_one_skb+391 (0xffffffffaddd7061) [software] 1 drops at udpv6_queue_rcv_one_skb+138 (0xffffffffade4f718) [software] 8 drops at netlink_broadcast_filtered+257 (0xffffffffadd8e7c7) [software] 1 drops at udp_queue_rcv_one_skb+391 (0xffffffffaddd7061) [software] 8 drops at netlink_broadcast_filtered+257 (0xffffffffadd8e7c7) [software] 2 drops at udp_queue_rcv_one_skb+391 (0xffffffffaddd7061) [software] 1 drops at udp_queue_rcv_one_skb+391 (0xffffffffaddd7061) [software] 1 drops at __udp4_lib_rcv+ae5 (0xffffffffaddd9185) [software] ^CGot a stop message dropwatch> exit Shutting down ...
receive buffer errorsとpacket receive errorsが増加しているのが分かります。
# netstat -su Udp: 3 packets received 0 packets to unknown port received 6 packet receive errors 9 packets sent 6 receive buffer errors 0 send buffer errors IgnoredMulti: 3 UdpLite: IpExt: InBcastPkts: 3 InOctets: 34027 OutOctets: 27396 InBcastOctets: 816 InNoECTPkts: 223 InECT0Pkts: 175 # nstat -a |grep -i udp UdpInDatagrams 3 0.0 UdpInErrors 6 0.0 UdpOutDatagrams 9 0.0 UdpRcvbufErrors 6 0.0 UdpIgnoredMulti 4 0.0 Udp6InErrors 1 0.0 Udp6OutDatagrams 1 0.0 Udp6RcvbufErrors 1 0.0
dropwatchの結果から udp_queue_rcv_one_skb() を見てみることにします。https://elixir.bootlin.com/linux/v5.4/source/net/ipv4/udp.c#L1993
udp_queue_rcv_one_skb() の実行結果を確認するために __udp_queue_rcv_skb() 及びラベル csum_error と drop にプローブポイントを設定して
別ターミナルでdig www.google.comしてみます。
$ cat stp0.stp #!/usr/bin/stap probe kernel.statement("udp_queue_rcv_one_skb@net/ipv4/udp.c:2085") { printf ("TIME=%s,ProbePoint=%s,func=%s\n",tz_ctime(gettimeofday_s()), pp(),probefunc()) } probe kernel.statement("udp_queue_rcv_one_skb@net/ipv4/udp.c:2088") { printf ("TIME=%s,ProbePoint=%s,func=%s\n",tz_ctime(gettimeofday_s()), pp(),probefunc()) } probe kernel.statement("udp_queue_rcv_one_skb@net/ipv4/udp.c:2090") { printf ("TIME=%s,ProbePoint=%s,func=%s\n",tz_ctime(gettimeofday_s()), pp(),probefunc()) } $ sudo stap -v ./stp0.stp Pass 1: parsed user script and 476 library scripts using 104260virt/90828res/7396shr/83300data kb, in 130usr/30sys/170real ms. Pass 2: analyzed script: 3 probes, 13 functions, 1 embed, 0 globals using 247624virt/226380res/8432shr/226664data kb, in 1120usr/150sys/1268real ms. Pass 3: translated to C into "/tmp/stapfN7K19/stap_91e495a5ab0883939c22b5dffb5db63b_8460_src.c" using 247624virt/226716res/8688shr/226664data kb, in 130usr/90sys/214real ms. Pass 4: compiled C into "stap_91e495a5ab0883939c22b5dffb5db63b_8460.ko" in 4030usr/430sys/4412real ms. Pass 5: starting run. TIME=Thu Dec 10 15:18:44 2020 JST,ProbePoint=kernel.statement("udp_queue_rcv_one_skb@/usr/src/linux-stable/net/ipv4/udp.c:2085"),func=udp_queue_rcv_one_skb TIME=Thu Dec 10 15:18:44 2020 JST,ProbePoint=kernel.statement("udp_queue_rcv_one_skb@/usr/src/linux-stable/net/ipv4/udp.c:2085"),func=udp_queue_rcv_one_skb TIME=Thu Dec 10 15:18:49 2020 JST,ProbePoint=kernel.statement("udp_queue_rcv_one_skb@/usr/src/linux-stable/net/ipv4/udp.c:2085"),func=udp_queue_rcv_one_skb TIME=Thu Dec 10 15:18:54 2020 JST,ProbePoint=kernel.statement("udp_queue_rcv_one_skb@/usr/src/linux-stable/net/ipv4/udp.c:2085"),func=udp_queue_rcv_one_skb ^CPass 5: run completed in 10usr/60sys/27537real ms.
こちらの出力から2085行目 : return __udp_queue_rcv_skb() してることがわかりました。
次に1956行目 : __udp_queue_rcv_skb() を確認してみます。https://elixir.bootlin.com/linux/v5.4/source/net/ipv4/udp.c#L1956
確認すると __udp_queue_rcv_skb() は __udp_enqueue_schedule_skb() を呼び出して結果をrcに代入していますので
1446行目 : __udp_enqueue_schedule_skb() のreturnを確認してみます。https://elixir.bootlin.com/linux/v5.4/source/net/ipv4/udp.c#L1446
$ sudo stap -v -e 'probe kernel.function("__udp_enqueue_schedule_skb").return { printf("%s\n", $$return) }'
Pass 1: parsed user script and 476 library scripts using 104260virt/90888res/7456shr/83300data kb, in 150usr/30sys/171real ms.
Pass 2: analyzed script: 1 probe, 1 function, 0 embeds, 0 globals using 172580virt/159936res/8580shr/151620data kb, in 830usr/210sys/1092real ms.
Pass 3: translated to C into "/tmp/stapsiCjUW/stap_460d03025583944fff84ca26db9eda2b_1217_src.c" using 172580virt/160064res/8708shr/151620data kb, in 30usr/70sys/99real ms.
Pass 4: compiled C into "stap_460d03025583944fff84ca26db9eda2b_1217.ko" in 2090usr/500sys/2536real ms.
Pass 5: starting run.
return=0xfffffffffffffff4
return=0xfffffffffffffff4
return=0xfffffffffffffff4
return=0xfffffffffffffff4
return=0xfffffffffffffff4
0xfffffffffffffff4を返しているので-ENOMEMのようです。
1446行目 : __udp_enqueue_schedule_skb() を詳しくみて行きます。
この関数にはラベル drop と uncharge_drop がありますので関数を使ってプローブポイントをセットしてみます。
$ sudo stap -L 'kernel.function("__udp_enqueue_schedule_skb").label("*")'
kernel.function("__udp_enqueue_schedule_skb@/usr/src/linux-stable/net/ipv4/udp.c:1510").label("uncharge_drop") $sk:struct sock* $skb:struct sk_buff* $delta:int $err:int $busy:spinlock_t* $size:int
kernel.function("__udp_enqueue_schedule_skb@/usr/src/linux-stable/net/ipv4/udp.c:1513").label("drop") $sk:struct sock* $skb:struct sk_buff* $delta:int $err:int $busy:spinlock_t* $size:int
$ cat stp1.stp
#!/usr/bin/env stap
probe kernel.function("__udp_enqueue_schedule_skb").label("drop")
{
printf("drop: TIME=%s\n", tz_ctime(gettimeofday_s()))
}
probe kernel.function("__udp_enqueue_schedule_skb").label("uncharge_drop")
{
printf("uncharge_drop: TIME=%s\n", tz_ctime(gettimeofday_s()))
}
$ sudo stap -v ./stp1.stp
Pass 1: parsed user script and 476 library scripts using 104256virt/90892res/7464shr/83296data kb, in 180usr/20sys/209real ms.
Pass 2: analyzed script: 2 probes, 6 functions, 1 embed, 0 globals using 172576virt/159780res/8388shr/151616data kb, in 860usr/160sys/1013real ms.
Pass 3: translated to C into "/tmp/stapJJI9Hg/stap_279afa261f7ee3edcfb4050fbc405982_5786_src.c" using 172576virt/160100res/8708shr/151616data kb, in 50usr/60sys/115real ms.
Pass 4: compiled C into "stap_279afa261f7ee3edcfb4050fbc405982_5786.ko" in 2160usr/380sys/2493real ms.
Pass 5: starting run.
uncharge_drop: TIME=Tue Dec 15 17:57:38 2020 JST
drop: TIME=Tue Dec 15 17:57:38 2020 JST
uncharge_drop: TIME=Tue Dec 15 17:57:38 2020 JST
drop: TIME=Tue Dec 15 17:57:38 2020 JST
uncharge_drop: TIME=Tue Dec 15 17:57:38 2020 JST
drop: TIME=Tue Dec 15 17:57:38 2020 JST
uncharge_drop: TIME=Tue Dec 15 17:57:43 2020 JST
drop: TIME=Tue Dec 15 17:57:43 2020 JST
uncharge_drop: TIME=Tue Dec 15 17:57:48 2020 JST
drop: TIME=Tue Dec 15 17:57:48 2020 JST
uncharge_drop -> drop の順に実行されているのが分かりました。
uncharge_drop にジャンプする条件は以下になります。
1456 rmem = atomic_add_return(size, &sk->sk_rmem_alloc); 1457 if (rmem > (size + sk->sk_rcvbuf)) 1458 goto uncharge_drop;
rmem の値と (size + sk->sk_rcvbuf) の値を確認します。
$ cat stp2.stp
%{
#include <net/sock.h>
#include <asm/atomic.h>
%}
function get_rmem:long(sk:long, skb:long)
%{
int rmem, size;
struct sock *sk = (struct sock *)((long)STAP_ARG_sk);
struct sk_buff *skb = (struct sk_buff *)((long)STAP_ARG_skb);
size = skb->truesize;
rmem = atomic_add_return(size, &sk->sk_rmem_alloc);
STAP_RETVALUE = rmem;
%}
function calc:long(sk:long, skb:long)
%{
int size, total;
struct sock *sk = (struct sock *)((long)STAP_ARG_sk);
struct sk_buff *skb = (struct sk_buff *)((long)STAP_ARG_skb);
size = skb->truesize;
STAP_RETVALUE = size + sk->sk_rcvbuf;
%}
probe kernel.statement("__udp_enqueue_schedule_skb")
{
printf("rmem=%d total=%d\n", get_rmem($sk, $skb), calc($sk, $skb))
}
$ sudo stap -v -g ./stp2.stp
Pass 1: parsed user script and 476 library scripts using 104260virt/90880res/7448shr/83300data kb, in 130usr/40sys/178real ms.
Pass 2: analyzed script: 1 probe, 4 functions, 1 embed, 0 globals using 176940virt/164372res/8624shr/155980data kb, in 890usr/100sys/985real ms.
Pass 3: translated to C into "/tmp/stap0FmEiy/stap_424f4d030d8e4bcc70ca1d070427c068_2061_src.c" using 176940virt/164500res/8752shr/155980data kb, in 30usr/70sys/107real ms.
Pass 4: compiled C into "stap_424f4d030d8e4bcc70ca1d070427c068_2061.ko" in 2210usr/360sys/2513real ms.
Pass 5: starting run.
rmem=768 total=-2147482881
rmem=768 total=-2147482881
rmem=768 total=-2147482881
rmem=1536 total=-2147482881
rmem=2304 total=-2147482881
^CPass 5: run completed in 30usr/60sys/45548real ms.
size + sk->sk_rcvbufの計算結果が-2147482881となっているのでオーバーフローしていそうです。
sizeとsk->sk_rcvbufの値をそれぞれ確認してみます。
$ cat stp3.stp
%{
#include <net/sock.h>
#include <asm/atomic.h>
%}
function get_rmem:long(sk:long, skb:long)
%{
int rmem, size;
struct sock *sk = (struct sock *)((long)STAP_ARG_sk);
struct sk_buff *skb = (struct sk_buff *)((long)STAP_ARG_skb);
size = skb->truesize;
rmem = atomic_add_return(size, &sk->sk_rmem_alloc);
STAP_RETVALUE = rmem;
%}
function calc:long(sk:long, skb:long)
%{
int size, total;
struct sock *sk = (struct sock *)((long)STAP_ARG_sk);
struct sk_buff *skb = (struct sk_buff *)((long)STAP_ARG_skb);
size = skb->truesize;;
STAP_RETVALUE = size + sk->sk_rcvbuf;
%}
function get_size:long(sk:long, skb:long)
%{
struct sock *sk = (struct sock *)((long)STAP_ARG_sk);
struct sk_buff *skb = (struct sk_buff *)((long)STAP_ARG_skb);
STAP_RETVALUE = skb->truesize;
%}
probe kernel.statement("__udp_enqueue_schedule_skb")
{
printf("rmem=%d %d=%d+%d\n", get_rmem($sk, $skb), calc($sk, $skb), get_size($sk, $skb), $sk->sk_rcvbuf)
}
$ sudo stap -g -v ./stp3.stp
Pass 1: parsed user script and 476 library scripts using 104264virt/90936res/7504shr/83304data kb, in 170usr/20sys/185real ms.
Pass 2: analyzed script: 1 probe, 6 functions, 1 embed, 0 globals using 176948virt/164364res/8608shr/155988data kb, in 870usr/130sys/999real ms.
Pass 3: using cached /root/.systemtap/cache/2b/stap_2b032db9bfd3b47319c8ecdca4d96dda_2476.c
Pass 4: using cached /root/.systemtap/cache/2b/stap_2b032db9bfd3b47319c8ecdca4d96dda_2476.ko
Pass 5: starting run.
rmem=768 -2147482881=768+2147483647
rmem=768 -2147482881=768+2147483647
rmem=768 -2147482881=768+2147483647
rmem=1536 -2147482881=768+2147483647
rmem=2304 -2147482881=768+2147483647
^CPass 5: run completed in 20usr/50sys/22017real ms.
sizeとsk->sk_rcvbuf は int なので整数オーバーフローが起き計算結果が -2147482881 となりDNS パケット欠落の原因がオーバーフローによるものであることが確認できました。
まとめ
SystemTapの学習のためGoogle Cloudのサポートブログを参考にスクリプトを作成しながら カーネルの動作を追ってみました。
- ソースコードを変更しなくても良いので敷居は低そうです。
- printkデバッグのようにカーネルを再構築をする必要がないので時間の節減になります。
- 大変有益な記事を公開してくれたGoogle Cloudさんありがとう。
参考にさせてもらいました。
Linuxカーネルのデバッグでprintk(9)デバッグを卒業したいっ！ - φ(・・*)ゞ ｳｰﾝ カーネルとか弄ったりのメモ
第585回 SystemTapを活用してネットワークの動作を確認する：Ubuntu Weekly Recipe｜gihyo.jp … 技術評論社
