dump解析(1) 一の巻
本エントリはダンプ解析について知ってもらうために多少編集している部分がありますが、ご了承ください。
ML40でのダンプ解析には、
- vmcore(ダンプ本体)
- vmlinux(kernel-debuginfoに入っている)
- System.map(kernelパッケージに入っている)
が必要です。
ダンプの解析開始は、通常こんな感じで始まります。
-----
# cd /var/crash/10.1.0.111-xxxx/
# crash /boot/System.map-2.6.9-34.21AXsmp /usr/lib/debug/lib/modules/2.6.9-34.21AXsmp/modules/vmlinux vmcore
----
まず何をするかというと、どこでpanicしたのか確認するために、btです。
----
crash> bt
PID: 0 TASK: c0322a80 CPU: 0 COMMAND: "swapper"
#0 [c0393f10] start_disk_dump at f8e0eced
#1 [c0393f2c] die_nmi at c0106bbb
#2 [c0393f44] unknown_nmi_panic_callback at c0117a97
#3 [c0393f9c] do_nmi at c0106cec
#4 [c0393fa4] nmi at c02d536c
EAX: 00000000 EBX: c0393000 ECX: 00000000 EDX: 00000000 EBP: 004ba007
DS: 007b ESI: 00000000 ES: 007b EDI: c03cf120
CS: 0060 EIP: c01040e8 ERR: 00000000 EFLAGS: 00000246
#5 [c0393fe0] mwait_idle at c01040e8
#6 [c0393fec] start_kernel at c039478f
#7 [c0393ffc] is386 at c010020c
-----
これを見ると、swaperプロセスなので、idleプロセス中でpanicが発生していることが分かります。
しかも、#4 [c0393fa4] nmi at c02d536c これは、NMIによる割り込みが発生したのがpanicの要因であることも見て取れます。
普通、こういう場合は、マシンのNMIボタンを押すなどして、能動的に取得したdumpファイルであることがほとんどです。こういったパターンでは、マシンがストールして、何も操作を受け付けなくなり、最後の手段としてNMIによるダンプ取得を行うのが普通です。
次にどんなプロセスが動いていたのか調べてみます。
-----
crash> ps
PID PPID CPU TASK ST %MEM VSZ RSS COMM
> 0 0 0 c0322a80 RU 0.0 0 0 [swapper]
> 0 1 1 f7e110b0 RU 0.0 0 0 [swapper]
> 0 1 2 f7e10b30 RU 0.0 0 0 [swapper]
> 0 1 3 f7e105b0 RU 0.0 0 0 [swapper]
1 0 0 f7e11630 IN 0.1 3280 632 init
2 1 0 f7e10030 IN 0.0 0 0 [migration/0]
3 1 0 f7e256b0 RU 0.0 0 0 [ksoftirqd/0]
4 1 1 f7e25130 IN 0.0 0 0 [migration/1]
5 1 1 f7e24bb0 IN 0.0 0 0 [ksoftirqd/1]
6 1 2 f7e24630 IN 0.0 0 0 [migration/2]
7 1 2 f7e240b0 IN 0.0 0 0 [ksoftirqd/2]
8 1 3 f7e99730 IN 0.0 0 0 [migration/3]
9 1 3 f7e991b0 IN 0.0 0 0 [ksoftirqd/3]
10 1 0 f7e98c30 IN 0.0 0 0 [events/0]
11 1 1 f7e986b0 IN 0.0 0 0 [events/1]
... 以下略 ...
------
各プロセスごとに、どのような状況にあるか確認するためには、btにPIDを付けます。
------
crash> bt 11
PID: 11 TASK: f7e986b0 CPU: 1 COMMAND: "events/1"
#0 [f7feef08] schedule at c02d2699
#1 [f7feef6c] worker_thread at c013109f
#2 [f7feefd0] kthread at c01346eb
#3 [f7feeff0] kernel_thread_helper at c01041f3
------
今回、ストールが発生しているということで、ステータスが「 UN」になっているプロセスについて調べた結果、PID 287(kjournald)のプロセスのタスクが__wait_on_buffer()で、バッファがロックされたままで、ロックが
解放されるのを待っている状態でした。
__wait_on_buffer()は、
-----
void __wait_on_buffer(struct buffer_head * bh)
-----
と宣言されているので、buffer_headへのポインタを引数として1つだけ持ちます。
そのため、どこのバッファを待っているのか確認するために、btに-fオプションを付けてみました。
------
crash > bt -f 287
PID: 287 TASK: f760aeb0 CPU: 2 COMMAND: "kjournald"
#0 [f7551d30] schedule at c02d26a5
[RA: c02d2e36 SP: f7551d30 FP: f7551d94 SIZE: 104]
f7551d30: f7551d90 00000046 0000001b 00000000
f7551d40: f7e10b30 f74fc630 00000019 c2025de0
f7551d50: f74fc630 00000000 c202e740 c2025de0
f7551d60: 00000002 0000031e 1fa4329b 00000180
f7551d70: f7e10b30 f760aeb0 f760b01c 00000018
f7551d80: 00000008 c2025de0 c0469b80 f39e765c
f7551d90: f7551d9c c02d2e36
#1 [f7551d94] io_schedule at c02d2e31
[RA: c015c6d4 SP: f7551d98 FP: f7551da0 SIZE: 12]
f7551d98: f54819d4 f4307e00 c015c6d4
#2 [f7551da0] __wait_on_buffer at c015c6cf
[RA: f8e96ac2 SP: f7551da4 FP: f7551dec SIZE: 76]
f7551da4: f54819d4 00000000 f760aeb0 c015c57c
f7551db4: f7551dd4 f7551dd4 c015f391 00006e30
f7551dc4: f54819d4 00000000 f760aeb0 c015c57c
f7551dd4: c0469b88 c0469b88 00000013 f7551de8
f7551de4: f54819d4 00000013 f8e96ac2
#3 [f7551dec] journal_commit_transaction at f8e96abd
[RA: f8e98e8d SP: f7551df0 FP: f7551f68 SIZE: 380]
f7551df0: 00000001 00000000 00000f54 f679e0ac
f7551e00: 00000000 00000000 00000000 f7f2b200
f7551e10: f39e765c 00000dc6 00000000 f760aeb0
f7551e20: c0120a59 f7551e44 f7551e44 f74f21a0
f7551e30: f7e38dc0 00000001 00000000 f760aeb0
f7551e40: c0120a59 f7551e44 f7551e44 00000007
f7551e50: ffffffe3 00003029 f677c5c4 f3d98ba8
f7551e60: f3d987cc f3d98b40 f3d98ee8 f3d985c4
f7551e70: f3d98b0c f3d98d14 f3d98320 f3d98590
f7551e80: f3871180 f3871694 f5f1c938 f5e00b40
f7551e90: f5e00250 f5e00c44 f3c99f84 f54815c4
f7551ea0: f54819d4 f3d98660 f3d98660 f3d98660
f7551eb0: f3d98660 f3d98660 f3d98660 f3d98660
f7551ec0: f3d98660 f3d98660 f3d98660 f3d98660
------
__wait_on_bufferのbh(buffer_head)をきちんと特定するため、もう少し調べると、
-----
void __wait_on_buffer(struct buffer_head * bh)
{
wait_queue_head_t *wqh = bh_waitq_head(bh);
DEFINE_BH_WAIT(wait, bh);
do {
prepare_to_wait(wqh, &wait.wait, TASK_UNINTERRUPTIBLE);
if (buffer_locked(bh)) {
sync_buffer(bh);
io_schedule();
}
} while (buffer_locked(bh));
finish_wait(wqh, &wait.wait);
}
----------------
というコードになっています。
さらに DEFINE_BH_WAIT(wait, bh);はマクロなので、内容をみると、
------
#define __DEFINE_BH_WAIT(name, b, f) \
struct bh_wait_queue name = { \
.bh = b, \
.wait = { \
.task = current, \
.flags = f, \
.func = bh_wake_function, \
.task_list = \
LIST_HEAD_INIT(name.wait.task_list),\
}, \
}
#define DEFINE_BH_WAIT(name, bh) __DEFINE_BH_WAIT(name, bh, 0)
-----
このようになっています。
もういちど__wait_on_buffer()のスタックに注目します。
------
#2 [f7551da0] __wait_on_buffer at c015c6cf
[RA: f8e96ac2 SP: f7551da4 FP: f7551dec SIZE: 76]
f7551da4: f54819d4 00000000 f760aeb0 c015c57c
f7551db4: f7551dd4 f7551dd4 c015f391 00006e30
f7551dc4: f54819d4 00000000 f760aeb0 c015c57c
f7551dd4: c0469b88 c0469b88 00000013 f7551de8
f7551de4: f54819d4 00000013 f8e96ac2
-----
この部分の
-----
f7551da4: f54819d4 00000000 f760aeb0 c015c57c
-----
に注目すると、00000000のエントリ、つまり 0がスタックに入れられている箇所があります。
0をスタックに入れている箇所を探すために、disコマンドで__wait_on_buffer()を逆アセンブルします。
-----
crash> dis __wait_on_buffer
0xc015c668 <__wait_on_buffer>: push %esi
0xc015c669 <__wait_on_buffer+1>: push %ebx
0xc015c66a <__wait_on_buffer+2>: sub $0x40,%esp
0xc015c66d <__wait_on_buffer+5>: mov %eax,%ebx
0xc015c66f <__wait_on_buffer+7>: call 0xc015c53b <bh_waitq_head>
0xc015c674 <__wait_on_buffer+12>: mov %ebx,(%esp)
0xc015c677 <__wait_on_buffer+15>: mov %eax,%esi
0xc015c679 <__wait_on_buffer+17>: mov $0xfffff000,%eax
0xc015c67e <__wait_on_buffer+22>: movl $0x0,0x4(%esp)
0xc015c686 <__wait_on_buffer+30>: and %esp,%eax
-----
すると0xc015c67eの命令でスタックに0を入れています。
これは、さきほどの
-----
#define DEFINE_BH_WAIT(name, bh) __DEFINE_BH_WAIT(name, bh, 0)
-----
の0のことだと気づきます。(ここは経験と勘です。)
すると、そのマクロの中に、
-----
.task = current, \
-----
という行があることが分かります。currentというと、このプロセスのtask_structのポインタを表しますので、psの結果、
------
287 1 2 f760aeb0 UN 0.0 0 0 [kjournald]
------
より、currentがf760aeb0であることが分かります。
再度、さきほどのスタックのデータを見るとまさに同じ値が格納されています。
-----
f7551da4: f54819d4 00000000 f760aeb0 c015c57c
-----
さらに、
-----
f7551da4: f54819d4 00000000 f760aeb0 c015c57c
-----
の値を確認するために、次のコマンドを実行します。
-----
crash> sym c015c57c
c015c57c (t) bh_wake_function
----
これはまさに先ほどのマクロ中の
-----
.func = bh_wake_function, \
-----
です。ということは、必然的に、その前にある
-----
.bh = b,
------
が
------
f7551da4: f54819d4 00000000 f760aeb0 c015c57c
-----
であることが分かります。
そこで、このbuffer_head構造体のデータをstructコマンドで確認してみます。
-------
crash> struct buffer_head 0xf54819d4
struct buffer_head {
b_state = 24605,
b_this_page = 0x0,
b_page = 0xc16c71e0,
b_count = {
counter = 2
},
b_size = 4096,
b_blocknr = 3526,
b_data = 0xf638f000 "<A4>\201",
b_bdev = 0xf7f10a80,
b_end_io = 0xf8e96184,
b_private = 0xf39e765c,
b_assoc_buffers = {
next = 0xf5481a00,
prev = 0xf5481a00
}
}
-----
b_end_io = 0xf8e96184 が設定されています。b_end_ioは、IO完了時に呼び出す後処理の関数アドレスなので、調べてみます。
-----
crash > sym 0xf8e96184
f8e96184 (t) journal_end_buffer_io_sync
-----
普通に、ジャーナルの完了処理のようです。
では、このページのロックが解放されない理由を探さなければなりません。
このバッファのページは、b_bdev = 0xf7f10a80 ですので、これが指すブロックデバイスを特定します。
b_bdevは、buffer_head構造体の中で、次のように宣言されています。
------
struct block_device *b_bdev;
------
そこで、ブロックデバイスの情報を確認します。
-------
crash > struct block_device 0xf8e96184
struct block_device {
bd_dev = 9437185,
bd_inode = 0xf7f10af4,
bd_openers = 1,
bd_sem = {
count = {
counter = 1
},
sleepers = 0,
wait = {
lock = {
lock = 1,
magic = 3735899821
},
task_list = {
next = 0xf7f10a9c,
prev = 0xf7f10a9c
}
}
},
bd_mount_sem = {
count = {
counter = 1
},
sleepers = 0,
wait = {
lock = {
lock = 1,
magic = 3735899821
},
task_list = {
next = 0xf7f10ab4,
prev = 0xf7f10ab4
}
}
},
bd_inodes = {
next = 0xf754fc10,
prev = 0xf754fc10
},
bd_holder = 0xf885ac60,
bd_holders = 2,
bd_contains = 0xf7f10a80,
bd_block_size = 4096,
bd_part = 0x0,
bd_part_count = 0,
bd_invalidated = 0,
bd_disk = 0xf7e2a180,
bd_list = {
next = 0xf740db64,
prev = 0xf740d964
},
bd_inode_backing_dev_info = 0x0,
bd_private = 0
}
--------
どのデバイスであるかは、block_device構造体の先頭に
-----
struct block_device {
dev_t bd_dev;
-----
のように宣言されているので確認してみます。
-----
bd_dev = 9437185,
-----
ブロックデバイス dev_tは、include/linux/kdev_t.hで、以下のように、メジャーマイナーが設定されています。
-----
#define MINORBITS 20
#define MINORMASK ((1U << MINORBITS) - 1)
#define MAJOR(dev) ((unsigned int) ((dev) >> MINORBITS))
#define MINOR(dev) ((unsigned int) ((dev) & MINORMASK))
#define MKDEV(ma,mi) (((ma) << MINORBITS) | (mi))
-----
9437185を計算に入れると、Major 9、Minor 1という結果になりました。
これが確認に使ったプログラム。
-------
#include <stdio.h>
#define MINORBITS 20
#define MINORMASK ((1U << MINORBITS) - 1)
#define MAJOR(dev) ((unsigned int) ((dev) >> MINORBITS))
#define MINOR(dev) ((unsigned int) ((dev) & MINORMASK))
#define MKDEV(ma,mi) (((ma) << MINORBITS) | (mi))
int main(int argc, char **argv)
{
printf("MAJOR:%d\n", MAJOR(9437185));
printf("MINOR:%d\n", MINOR(9437185));
printf("%d\n", MKDEV(9,1));
}
---------
これは、/dev/の下でmajor 9、minor 1のデバイスを探すと、/dev/md1を表していました。
-----
$ ls -l /dev/md1
brw-r----- 1 root disk 9, 1 7月 16 02:34 /dev/md1
-----
投稿者 yasuma
日時 2006年7月18日09:00
カーネルダンプ
おお、ついに始まりましたね。期待が大きいです。
話が横にそれてしまうかもしれないのですが、NMIで強制的にダンプをとった場合は、どっかでロックを握っていてハングしている場合かと思うのですが、それって、先日話題になっていたSPINLOCKのマジックナンバーを検索すればどこでデッドロックしているかわかるかと思うのですが、それを検索するのは大変なのでしょうか？
たぶん機械的に検索すればいいような感じがするのですが、いかがでしょう？
仮に、そうだとしたらAliciaのスクリプトで一発検索なりという素晴らしいおまけがあったりして。
投稿： hyoshiok | 2006年7月18日 (火) 18:36
ご期待に沿えるかどうかは分かりませんが、少しはみなさんのお役には立てるかなと。
先日のコメントにもありましたが、spinlockのオーナーをいかにして探すかですよね。多分。
最新カーネルだと楽勝ってやつですかね。
このあたりはノウハウになりそうですね。
投稿： やすま | 2006年7月19日 (水) 05:55