- 1 はじめに
- 2 検証環境
- 3 デバッグメッセージ出力の有効／無効化方法
- 4 行数を表示する方法(l)
- 5 関数名を表示する方法(f)
- 6 出力コンテキストを表示する方法(t)
- 7 特定のデバッグメッセージを表示する方法(line)
- 8 モジュールのデバッグメッセージを表示する方法(module)
- Z 参考情報
1 はじめに
カーネルのデバッグの1つにprintk()を使う方法があります。この方法だと、カーネルをビルドする必要があり、手間がかかります。しかし、DYNAMIC DEBUGを使うと、カーネルをビルドする必要がなくデバッグメッセージを出力することができます。ただし、デバッグメッセージは、あらかじめ決められた関数、フォーマットで出力されるため、デバッグの目的にそわないことがあります。目的に応じて使い分ける必要があります。なお、DYNAMIC DEBUGを使うと、以下に示すpr_debug()のデバッグメッセージを出力できるようになります。
以下は、net/ipv4/ping.cより抜粋したものです。
54 static inline int ping_hashfn(struct net *net, unsigned int num, unsigned int mask)
55 {
56 int res = (num + net_hash_mix(net)) & mask;
57
58 pr_debug("hash(%d) = %d\n", num, res);
59 return res;
60 }
2 検証環境
CentOS版数は以下のとおりです。
[root@server ~]# cat /etc/redhat-release CentOS Linux release 7.9.2009 (Core)
カーネル版数は以下のとおりです。
[root@server ~]# uname -r 3.10.0-1160.el7.x86_64
DYNAMIC DEBUGを使うためには、CONFIG_DYNAMIC_DEBUGが有効になっている必要があります。 私の環境は、デフォルトで有効になっていました。もし無効なら、CONFIG_DYNAMIC_DEBUGを有効にしてカーネルをビルドする必要があります。
[root@server ~]# cat /boot/config-3.10.0-1160.el7.x86_64 |grep CONFIG_DYNAMIC_DEBUG CONFIG_DYNAMIC_DEBUG=y
3 デバッグメッセージ出力の有効／無効化方法
ここでは、デバッグメッセージ出力の有効／無効化の方法を説明します。例として、ping.cファイルのデバッグメッセージ出力の有効／無効化について確認してみます。
3.1 有効化(+p)
controlファイルの初期状態を確認します。"="の右側が"_"になっているので、デバッグメッセージの出力が無効になっていることがわかります。
[root@server ~]# cat /sys/kernel/debug/dynamic_debug/control | grep "net/ipv4/ping.c" net/ipv4/ping.c:242 [ping]ping_close =_ "isk->refcnt = %d\012" net/ipv4/ping.c:241 [ping]ping_close =_ "ping_close(sk=%p,sk->num=%u)\012" net/ipv4/ping.c:481 [ping]ping_sendmsg =_ "ping_sendmsg(sk=%p,sk->num=%u)\012" -snip-
デバッグメッセージの出力を有効化します。
[root@server ~]# echo 'file net/ipv4/ping.c +p' > /sys/kernel/debug/dynamic_debug/control
有効化すると、"="の右側が"p"になっているので、デバッグメッセージの出力が有効になったことがわかるます。
[root@server ~]# cat /sys/kernel/debug/dynamic_debug/control|grep "net/ipv4/ping.c" net/ipv4/ping.c:242 [ping]ping_close =p "isk->refcnt = %d\012" net/ipv4/ping.c:241 [ping]ping_close =p "ping_close(sk=%p,sk->num=%u)\012" net/ipv4/ping.c:481 [ping]ping_sendmsg =p "ping_sendmsg(sk=%p,sk->num=%u)\012" -snip-
3.2 無効化(-p)
次は、デバッグメッセージの出力を無効化してみます。
[root@server ~]# echo 'file net/ipv4/ping.c -p' > /sys/kernel/debug/dynamic_debug/control
controlファイルを確認します。無効化すると、"="の右側が"_"になっているので、デバッグメッセージの出力が無効になっていることがわかります
[root@server ~]# cat /sys/kernel/debug/dynamic_debug/control | grep "net/ipv4/ping.c" net/ipv4/ping.c:242 [ping]ping_close =_ "isk->refcnt = %d\012" net/ipv4/ping.c:241 [ping]ping_close =_ "ping_close(sk=%p,sk->num=%u)\012" net/ipv4/ping.c:481 [ping]ping_sendmsg =_ "ping_sendmsg(sk=%p,sk->num=%u)\012"
3.3 実行結果
ping.cで定義している関数のデバッグメッセージを出力してみます。
[root@server ~]# echo 'file net/ipv4/ping.c +p' > /sys/kernel/debug/dynamic_debug/control
もう1つターミナルを開いて、journalctlコマンドを実行します。
[root@server ~]# journalctl -f
デフォルトGWに対してpingを1回実行してみます。なお、pingの使い方は、pingコマンドの使い方 - hana_shinのLinux技術ブログを参照ください。
[root@server ~]# ping -c 1 192.168.2.1
journalctlコマンドの実行結果を確認すると、ping_v4_unhash(),ping_rcv()のデバッグメッセージが出力されていることがわかります。
[root@server ~]# journalctl -f 1月 02 20:19:13 server kernel: ping_v4_unhash(isk=ffff90f8af2b5000,isk->num=0) 1月 02 20:19:13 server kernel: ping_rcv(skb=ffff90f8b773a300,id=0981,seq=0001) 1月 02 20:19:13 server kernel: hash(2433) = 21 1月 02 20:19:13 server kernel: try to find: num = 2433, daddr = 192.168.2.100, dif = 2 1月 02 20:19:13 server kernel: no socket, dropping
最初(ping_v4_unhash..)のメッセージは、139行目で出力していることがわかります。
134
135 static void ping_v4_unhash(struct sock *sk)
136 {
137 struct inet_sock *isk = inet_sk(sk);
138
139 pr_debug("ping_v4_unhash(isk=%p,isk->num=%u)\n", isk, isk->inet_num);
140 write_lock_bh(&ping_table.lock);
141 if (sk_hashed(sk)) {
142 hlist_nulls_del(&sk->sk_nulls_node);
143 sk_nulls_node_init(&sk->sk_nulls_node);
144 sock_put(sk);
145 isk->inet_num = 0;
146 isk->inet_sport = 0;
147 sock_prot_inuse_add(sock_net(sk), sk->sk_prot, -1);
148 }
149 write_unlock_bh(&ping_table.lock);
150 }
確認が終わったので、controlファイルの設定内容をデフォルトに戻します。
[root@server ~]# echo 'file net/ipv4/ping.c -p' > /sys/kernel/debug/dynamic_debug/control
4 行数を表示する方法(l)
デバッグメッセージを出力する場所（何行目か?）を表示してみます。
[root@server ~]# echo 'file net/ipv4/ping.c +pl' > /sys/kernel/debug/dynamic_debug/control
controlファイルを確認します。"="の右側が"pl"になっているので、デバッグメッセージの出力(p)と行数(l)の出力が有効になっていることがわかります。
[root@server ~]# cat /sys/kernel/debug/dynamic_debug/control |grep "net/ipv4/ping.c" net/ipv4/ping.c:242 [ping]ping_close =pl "isk->refcnt = %d\012" net/ipv4/ping.c:241 [ping]ping_close =pl "ping_close(sk=%p,sk->num=%u)\012" net/ipv4/ping.c:481 [ping]ping_sendmsg =pl "ping_sendmsg(sk=%p,sk->num=%u)\012" -snip-
もう1つターミナルを開いて、journalctlコマンドを実行します。
[root@server ~]# journalctl -f
デフォルトGWに対してpingを1回実行してみます。
[root@server ~]# ping -c 1 192.168.2.1
journalctlコマンドの実行結果を確認します。 ping_v4_unhashはping.cの139行目、ping_rcvはping.cの732行目で表示されていることがわかります。
[root@server ~]# journalctl -f 1月 02 20:37:08 server kernel: 139: ping_v4_unhash(isk=ffff90f8b3799800,isk->num=0) 1月 02 20:37:08 server kernel: 732: ping_rcv(skb=ffff90f9300e6300,id=0a5d,seq=0001) 1月 02 20:37:08 server kernel: 58: hash(2653) = 49 1月 02 20:37:08 server kernel: 161: try to find: num = 2653, daddr = 192.168.2.100, dif = 2 1月 02 20:37:08 server kernel: 745: no socket, dropping
確認が終わったので、controlファイルの設定内容をデフォルトに戻します。
[root@server ~]# echo 'file net/ipv4/ping.c -pl' > /sys/kernel/debug/dynamic_debug/control
5 関数名を表示する方法(f)
デバッグメッセージを出力する関数名を表示してみます。
[root@server ~]# echo 'file net/ipv4/ping.c +plf' > /sys/kernel/debug/dynamic_debug/control
controlファイルを確認します。"="の右側が"pfl"になっているので、デバッグメッセージの出力(p)、関数名(f)、行数(l)の出力が有効になっていることがわかります。
[root@server ~]# cat /sys/kernel/debug/dynamic_debug/control |grep "net/ipv4/ping.c" net/ipv4/ping.c:242 [ping]ping_close =pfl "isk->refcnt = %d\012" net/ipv4/ping.c:241 [ping]ping_close =pfl "ping_close(sk=%p,sk->num=%u)\012" net/ipv4/ping.c:481 [ping]ping_sendmsg =pfl "ping_sendmsg(sk=%p,sk->num=%u)\012" -snip-
もう1つターミナルを開いて、journalctlコマンドを実行します。
[root@server ~]# journalctl -f
デフォルトGWに対してpingを1回実行してみます。
[root@server ~]# ping -c 1 192.168.2.1
journalctlコマンドの実行結果を確認します。
[root@server ~]# journalctl -f 1月 02 21:00:42 server kernel: ping_v4_unhash:139: ping_v4_unhash(isk=ffff90f8b66d8400,isk->num=0) 1月 02 21:00:42 server kernel: ping_rcv:732: ping_rcv(skb=ffff90f8a0e91000,id=0b39,seq=0001) 1月 02 21:00:42 server kernel: ping_hashfn:58: hash(2873) = 13 1月 02 21:00:42 server kernel: ping_v4_lookup:161: try to find: num = 2873, daddr = 192.168.2.100, dif = 2 1月 02 21:00:42 server kernel: ping_rcv:745: no socket, dropping
確認が終わったので、controlファイルの設定内容をデフォルトに戻します。
[root@server ~]# echo 'file net/ipv4/ping.c -plf' > /sys/kernel/debug/dynamic_debug/control
6 出力コンテキストを表示する方法(t)
デバッグメッセージがプロセスコンテキストで出力されたのか、割り込みコンテキストで出力されたのかを表示します。デバッグメッセージが、プロセスコンテキストで出力された場合、PIDが表示されます。割り込みコンテキストで出力された場合、intrと表示されます。
[root@server ~]# echo 'file net/ipv4/ping.c +plft' > /sys/kernel/debug/dynamic_debug/control
controlファイルを確認します。"="の右側が"pflt"になっているので、デバッグメッセージの出力(p)、関数名(f)、行数(l)、コンテキスト(t)の出力が有効になっていることがわかります。
[root@server ~]# cat /sys/kernel/debug/dynamic_debug/control |grep "net/ipv4/ping.c" net/ipv4/ping.c:242 [ping]ping_close =pflt "isk->refcnt = %d\012" net/ipv4/ping.c:241 [ping]ping_close =pflt "ping_close(sk=%p,sk->num=%u)\012" net/ipv4/ping.c:481 [ping]ping_sendmsg =pflt "ping_sendmsg(sk=%p,sk->num=%u)\012"
もう1つターミナルを開いて、journalctlコマンドを実行します。
[root@server ~]# journalctl -f
デフォルトGWに対してpingを1回実行してみます。
[root@server ~]# ping -c 1 192.168.2.1
journalctlコマンドの実行結果を確認します。 1行目は、デバッグメッセージがプロセスコンテキスト(PID=3201)で出力されていることがわかります。そして、2行目以降は割り込みコンテキスト(intr)で出力されていることがわかります。さらに、具体的に言うと、2行目以降は、ソフト割り込み(net_rx_action関数の延長）で実行されています。
[root@server ~]# journalctl -f 1月 02 21:35:44 server kernel: [3201] ping_v4_unhash:139: ping_v4_unhash(isk=ffff90f8b66db000,isk->num=0) 1月 02 21:35:44 server kernel: <intr> ping_rcv:732: ping_rcv(skb=ffff90f8a0e90b00,id=0c81,seq=0001) 1月 02 21:35:44 server kernel: <intr> ping_hashfn:58: hash(3201) = 21 1月 02 21:35:44 server kernel: <intr> ping_v4_lookup:161: try to find: num = 3201, daddr = 192.168.2.100, dif = 2 1月 02 21:35:44 server kernel: <intr> ping_rcv:745: no socket, dropping
確認が終わったので、controlファイルの設定内容をデフォルトに戻します。
[root@server ~]# echo 'file net/ipv4/ping.c -plft' > /sys/kernel/debug/dynamic_debug/control
7 特定のデバッグメッセージを表示する方法(line)
ping.cファイルの139行目のデバッグメッセージを表示してみます。このとき、関数名(f)、コンテキスト(t)も表示してみます。
[root@server ~]# echo 'file net/ipv4/ping.c line 139 +plft' > /sys/kernel/debug/dynamic_debug/control
controlファイルを確認します。"="の右側が"pflt"になっているので、デバッグメッセージの出力(p)、関数名(f)、行数(l)、コンテキスト(t)の出力が有効になっていることがわかります。
[root@server ~]# cat /sys/kernel/debug/dynamic_debug/control | grep "net/ipv4/ping.c" -snip- net/ipv4/ping.c:139 [ping]ping_v4_unhash =pflt "ping_v4_unhash(isk=%p,isk->num=%u)\012" -snip-
もう1つターミナルを開いて、journalctlコマンドを実行します。
[root@server ~]# journalctl -f
デフォルトGWに対してpingを1回実行してみます。
[root@server ~]# ping -c 1 192.168.2.1
journalctlコマンドの実行結果を確認します。 ping.cファイル内の139行目のpr_debugメッセージが出力されていることがわかります。
[root@server ~]# journalctl -f 1月 02 23:51:32 server kernel: [4473] ping_v4_unhash:139: ping_v4_unhash(isk=ffff90f8b379d000,isk->num=0)
確認が終わったので、controlファイルの設定内容をデフォルトに戻します。
[root@server ~]# echo 'file net/ipv4/ping.c line 139 -plft' > /sys/kernel/debug/dynamic_debug/control
8 モジュールのデバッグメッセージを表示する方法(module)
ここでは、nf_conntrackモジュール内の全てのデバッグメッセージを表示してみます。
[root@server ~]# echo 'module nf_conntrack +plft' > /sys/kernel/debug/dynamic_debug/control
[root@server ~]# journalctl -f -snip- 1月 02 23:56:30 server kernel: <intr> tcp_in_window:628: tcp_in_window: 1月 02 23:56:30 server kernel: <intr> tcp_in_window:631: seq=1512910124 ack=1019883933+(0) sack=1019883933+(0) win=4052 end=1512910124 1月 02 23:56:30 server kernel: <intr> tcp_in_window:637: tcp_in_window: sender end=1512910124 maxend=1512942252 maxwin=1051136 scale=8 receiver end=1019883933 maxend=1020921365 maxwin=32128 scale=7 1月 02 23:56:30 server kernel: <intr> tcp_in_window:647: tcp_in_window: I=1 II=1 III=1 IV=1 -snip-
Z 参考情報
私が業務や記事執筆で参考にした書籍を以下のページに記載します。 Linux技術のスキルアップをしよう！ - hana_shinのLinux技術ブログ
