crashコマンド ライブシステムでデバッグ

前回の(crashコマンド ライブシステム)では現在のプロセス情報を見るだけでした。

今回はcrashライブシステムで起動中のカーネルに書き込みもしたいと思います。書き込みをすることでデバッグ情報を、あるときだけ出力させます。またカーネル内の関数コールシーケンスを出力させてみます。

カーネルのデバッグをしていたり、調査をしていると内部の情報を見たい場合があります。また再現TPのような、あるプロセスが動いているときだけログを出力させたいときもあります。しかしながら単純にprintk()を入れると起動すらしない場合もあります。

例えばタイマーの割り込みハンドラで表示したい変数があるとします。タイマー割り込みは１秒間に1000(x86_64の場合)回発生します。またOSが起動してかすぐに割り込みハンドラが動作するため、printk()を入れると起動しません。試しにmain_timer_handler()の中にあるlost変数をprinkt()で表示させてみます。

最新のカーネル(2.6.25)を使うとcrashが対応していないなどいろいろあったので、今回はAsianux Server 3の上でストックカーネル2.6.18を使うことにします。

以下のパッチを当てて再起動しました。

--- arch/x86_64/kernel/time.c.orig      2008-05-31 16:29:25.000000000 +0900
+++ arch/x86_64/kernel/time.c   2008-06-01 15:31:18.000000000 +0900
@@ -426,6 +426,8 @@ void main_timer_handler(struct pt_regs *
                jiffies += lost;
        }

+       printk("lost %d\n", lost);
+
/*
  * Do the timer stuff.
  */

結果は画面に大量のメッセージが出力されて、ログインもできず、起動したかどうかもわからない状態になりました。そこで少し仕掛けを入れてあげます。以下のパッチです。

--- arch/x86_64/kernel/time.c.orig      2008-05-31 16:29:25.000000000 +0900
+++ arch/x86_64/kernel/time.c   2008-06-01 15:30:42.000000000 +0900
@@ -349,6 +349,8 @@ static noinline void handle_lost_ticks(i
#endif
}

+unsigned long lost_debug=0;
+
void main_timer_handler(struct pt_regs *regs)
{
        static unsigned long rtc_update = 0;
@@ -426,6 +428,11 @@ void main_timer_handler(struct pt_regs *
                jiffies += lost;
        }

+       if(lost_debug){
+               printk("lost %d\n", lost);
+               lost_debug=0;
+       }
+
/*
  * Do the timer stuff.
  */

lost_debug変数をグローバルで用意します。lost_debugが0以外であればprinkt()でlostを出力します。prinkt()のあとはlost_debugを0に戻してデバッグ文が出力されないようにします。

これだと普通に起動しますが、ログも出力しません。出力させるにはlost_debugを１などに変更すればよいので、crashのライブシステムで1にしてみます。

# crash -s /boot/vmlinux-2.6.18 /dev/mem                      ・・・・(1)
crash> rd lost_debug                                          ・・・・(2)
ffffffff8137f2c0:  0000000000000000                    ........
crash> wr lost_debug 1                                        ・・・・(3)
crash> log                                                    ・・・・(4)
・・・・・
eth2: no IPv6 routers present
eth3: no IPv6 routers present
SCTP: Hash tables configured (established 65536 bind 65536)
Module sctp cannot be unloaded due to unsafe usage in net/sctp/protocol.c:1189
lost 0                                                        ・・・・(5)crash> 

(1)  vmlinuxを指定してcrashライブシステムを起動します。/dev/memはなくても大丈夫です。
        "-s"オプションはサイレントでcrashコマンドが起動したときに出力されるメッセージを省略します。

(2)  lost_debug変数を見てみました。0になっています。

(3)  書き込みをしています。"wr"コマンドで/dev/memを通して書き込みます。ここでは
       lost_debug変数を1にしています。

           注意：今回lost_debug変数はunsigned longで定義しました。intで定義した場合は
                       「wr -32 lost_debug 1」のように32bitだけ書き込みするようにします。
                        x86_64マシンではwrコマンドのデフォルトは64bit書き込みなのでメモリを
                       破壊してしまいます。

(4)  logでprintk()の出力を確認しています。(5)の出力が確認できました。

手軽にデバッグでき、タイミングを自分で調整できるのが利点です。
(本当であればタイマー割り込みの調整をlost変数で実際に見てみたかったのですが、CPUやメモリに負荷をかけても見ることができませんでした。)

次にカーネル内の関数コールシーケンスを出力させてみます。e1000ドライバの送信処理がシステムコールからどのようなシーケンスになっているかを確認します。drivers/net/e1000/e1000_main.cのe1000_tx_queue()に仕掛けを入れます。今回は1000回に1回出力するようにし、また任意のタイミングでデバッグ開始・停止ができるようにしました。

--- drivers/net/e1000/e1000_main.c.orig 2006-09-20 12:42:06.000000000 +0900
+++ drivers/net/e1000/e1000_main.c      2008-06-01 17:30:38.000000000 +0900
@@ -2736,6 +2736,9 @@ e1000_tx_map(struct e1000_adapter *adapt
        return count;
}

+unsigned long e1000_tx_debug=0;
+unsigned long e1000_debug_cnt=0;
+
static void
e1000_tx_queue(struct e1000_adapter *adapter, struct e1000_tx_ring *tx_ring,
                int tx_flags, int count)
@@ -2786,6 +2789,13 @@ e1000_tx_queue(struct e1000_adapter *ada

        tx_ring->next_to_use = i;
        writel(i, adapter->hw.hw_addr + tx_ring->tdt);
+
+       if(e1000_tx_debug){
+               e1000_debug_cnt++;
+               if((e1000_debug_cnt % 1000) == 0)
+                       WARN_ON(1);
+       }
+
}

/**

このパッチをあてて、カーネルを起動させました。デバッグを開始させるcrashのコマンドと、実際のログを載せます。

# crash -s /boot/vmlinux-2.6.18
crash> wr e1000_tx_debug 1
crash> q
# ping -I<e1000のNICを指定> -A <IPアドレス>
# tail -f /var/log/messages
・・・・・
BUG: warning at drivers/net/e1000/e1000_main.c:2796/e1000_tx_queue()
Call Trace:
[<ffffffff8814f8cb>] :e1000:e1000_xmit_frame+0xa3e/0xad3 ・・・・e1000ドライバの送信処理
[<ffffffff81208aa1>] __qdisc_run+0xf6/0x1bb
[<ffffffff8102fb6f>] dev_queue_xmit+0x131/0x24b       ・・・・netデバイス(eth0など)の送信処理
[<ffffffff81031fbf>] ip_output+0x1fd/0x241            ・・・・IP層の送信処理
[<ffffffff8121679a>] ip_push_pending_frames+0x374/0x447
[<ffffffff81225f39>] raw_sendmsg+0x631/0x6e1
[<ffffffff8101df43>] __pollwait+0x0/0xe0
[<ffffffff81053cfb>] sock_sendmsg+0xf3/0x110          ・・・・sendmsg()
[<ffffffff8109964a>] autoremove_wake_function+0x0/0x2e
[<ffffffff8102e583>] __wake_up+0x38/0x4f
[<ffffffff811f2208>] sock_from_file+0x7/0x60
[<ffffffff811f28ce>] sys_sendmsg+0x217/0x28a
[<ffffffff8105503c>] pty_write+0x32/0x3a
[<ffffffff81177d10>] tty_default_put_char+0x1d/0x1f
[<ffffffff81085e28>] default_wake_function+0x0/0xe
[<ffffffff8103a5e8>] tty_ldisc_deref+0x68/0x7b
[<ffffffff8105fc5d>] __sched_text_start+0x16d/0xa8b
[<ffffffff8105bc4e>] system_call+0x7e/0x83            ・・・・システムコール
・・・・・

pingコマンドに"-A"オプションをつけるとパケットの送信間隔が短くてすぐに1000パケット送信するので、つけました。(manには出てこないオプション)
e1000ドライバにデバッグ文を入れたことで送信処理を確認できました。
crashで「wr e1000_tx_debug 0」を実行するとデバッグ表示が停止します。自動化する場合は"crash　-i"を使うのが便利です。開始するときの例を以下に載せます。

# cat start.txt
wr e1000_tx_debug 1
exit
# cat stop.txt 
wr e1000_tx_debug 0
wr e1000_debug_cnt 0
exit
# crash -i start.txt /boot/vmlinux-2.6.18
・・・・・
     COMMAND: "crash"
        TASK: ffff81007d8b9830  [THREAD_INFO: ffff8100720a4000]
         CPU: 1
       STATE: TASK_RUNNING (ACTIVE)
crash> wr e1000_tx_debug 1
crash> exit
#

WARN_ON()は関数シーケンスを確認できるので便利です。
このような方法を使えば手軽で簡単にカーネル内のデータを読み書きし、いろんな情報を得ることできます。

注意：RedHatやAsianuxではcrashコマンドで書き込みができないようになっています。セキュリティーのためですが、今回紹介したデバッグ方法を使用するときは/dev/mem、/dev/kmemにwriteメソッドを用意するなどしないとできません。