■レンタルサーバご利用参考資料
サーバご利用の参考にJF Project によるJF (Japanese FAQ)を掲載しています。
Linux JF(Japanese FAQ)Project.
JF は, Linux に関する解説文書・FAQ などを作成・収集・配布するプロジェクトです.
グリーンネット・トップページへ戻る
一覧に戻る
List: linux-kernel
Subject: [RFC] HOWTO find oops location, v2
From: Denis Vlasenko
Date: 2004-08-15 11:39:31
Message-ID: <200408151439.31891.vda@port.imtp.ilyichevsk.odessa.ua>
I've got some useful feedback. This is v2 of the HOWTO.
いくつか便利なテクニックを送ってもらったよ。これは HOWTO の第２版。
CFLAGS="-g -Wa,-a,-ad" trick almost, but not quite works.
CFLAGS="-g -Wa,-a,-ad" トリックもいけそうなんだけど、ちゃんとは動かない。
--- cut here ------ cut here ------ cut here ------ cut here ---
--- 切り取り ------ 切り取り ------ 切り取り ------ 切り取り ---
Okay, so you've got an oops and want to find out what happened?
OK。じゃー、Oops を見て、何が起こったのか知りたいかい？
In this HOWTO, I presume you did not delete and did not
tamper with your kernel build tree. Also, I recommend you
to enable these options in the .config:
この HOWTO では、あなたのカーネルビルドツリーが消されたりいじられたり
していないと仮定するよ。それと、.config 中で次のオプションを有効にする
のをお勧めするよ。
CONFIG_DEBUG_SLAB=y
CONFIG_FRAME_POINTER=y
First one makes use-after-free bug hunt easy, second gives
you much more reliable stacktraces.
１つめは「開放後にアクセスした」バグ追跡を簡単にしてくれて、２つめはス
タックトレースの内容をずっと信頼できるものにしてくれるんだ。
Ok, let's take a look at example OOPS. ^^^^ marks are mine.
OK。OOPS の例を見てみよう。^^^^ は私の付けた印。
Unable to handle kernel NULL pointer dereference at virtual address 00000e14
printing eip:
c0162887
*pde = 00000000
Oops: 0000 [#1]
PREEMPT
Modules linked in: eeprom snd_seq_oss snd_seq_midi_event..........
CPU: 0
EIP: 0060:[] Not tainted
EFLAGS: 00010206 (2.6.7-nf2)
EIP is at prune_dcache+0x147/0x1c0
^^^^^^^^^^^^^^^^^^^^^^^^
eax: 00000e00 ebx: d1bde050 ecx: f1b3c050 edx: f1b3ac50
esi: f1b3ac40 edi: c1973000 ebp: 00000036 esp: c1973ef8
ds: 007b es: 007b ss: 0068
Process kswapd0 (pid: 65, threadinfo=c1973000 task=c1986050)
Stack: d7721178 c1973ef8 0000007a 00000000 c1973000 f7ffea48 c0162d1f 0000007a
c0139a2b 0000007a 000000d0 00025528 049dbb00 00000000 000001fa 00000000
c0364564 00000001 0000000a c0364440 c013add1 00000080 000000d0 00000000
Call Trace:
[] shrink_dcache_memory+0x1f/0x30
[] shrink_slab+0x14b/0x190
[] balance_pgdat+0x1b1/0x200
[] kswapd+0xc7/0xe0
[] autoremove_wake_function+0x0/0x60
[] ret_from_fork+0x6/0x14
[] autoremove_wake_function+0x0/0x60
[] kswapd+0x0/0xe0
[] kernel_thread_helper+0x5/0x14
Code: 8b 50 14 85 d2 75 27 89 34 24 e8 4a 2b 00 00 8b 73 0c 89 1c
Let's try to find out where did that exactly happen.
Grep in your kernel tree for prune_dcache. Aha, it is defined in
fs/dcache.c! Ok, execute these two commands:
どこで正に起こったのかを探してみよう。
prune_dcache をカーネルツリーで grep してね。あは、fs/dcache.c で定義
されてる！ OK、次の２コマンドを実行して。
# objdump -d fs/dcache.o > fs/dcache.disasm
# make fs/dcache.s
Now in fs/ you should have:
これで、fs/ には次の物が出来ているはず。
dcache.c - source code
dcache.o - compiled object file
dcache.s - assembler output of C compiler ('half-compiled' code)
dcache.disasm - disasembled object file
Open dcache.disasm and find "prune_dcache":
dcache.disasm を開いて、prune_dcache を探してね。
00000540 :
540: 55 push %ebp
We need to find prune_dcache+0x147. Using shell,
prune_dcache+0x147 を探さないとね。シェルを使って、
# printf "0x%x\n" $((0x540+0x147))
0x687
and in dcache.disasm:
これは dcache.disasm では、
683: 85 c0 test %eax,%eax
685: 74 07 je 68e
687: 8b 50 14 mov 0x14(%eax),%edx <======== OOPS
68a: 85 d2 test %edx,%edx
68c: 75 27 jne 6b5
68e: 89 34 24 mov %esi,(%esp)
691: e8 fc ff ff ff call 692
696: 8b 73 0c mov 0xc(%ebx),%esi
699: 89 1c 24 mov %ebx,(%esp)
69c: e8 9f f9 ff ff call 40
Comparing with "Code: 8b 50 14 85 d2 75 27" - match!
"Code: 8b 50 14 85 d2 75 27" と比較してみよう - ピッタリ！
We need to find matching line in dcache.s and, eventually, in dcache.c.
It's easy to find prune_dcache in dcache.s:
dcache.s と結果的に dcache.c の中で一致する行を探さないといけない。
dcache.s で prune_dcache を探すのは簡単。
prune_dcache:
pushl %ebp
but even though it is not too hard to find matching instruction:
でも、一致する命令を見つけるのはそう難しくはないは言っても、
movl 8(%edi), %eax
decl 20(%edi)
testb $8, %al
jne .L593
.L517:
movl 68(%ebx), %eax
testl %eax, %eax
je .L532
movl 20(%eax), %edx <========= OOPS
testl %edx, %edx
jne .L594
.L532:
movl %esi, (%esp)
call iput
.L565:
movl 12(%ebx), %esi
movl %ebx, (%esp)
call d_free
it is unclear to which part of .c code it belongs:
これじゃ .c コードのどこの部分に存在するかがはっきりしない。
static void prune_dcache(int count)
{
spin_lock(&dcache_lock);
for (; count ; count--) {
struct dentry *dentry;
struct list_head *tmp;
tmp = dentry_unused.prev;
if (tmp == &dentry_unused)
break;
list_del_init(tmp);
prefetch(dentry_unused.prev);
dentry_stat.nr_unused--;
dentry = list_entry(tmp, struct dentry, d_lru);
spin_lock(&dentry->d_lock);
/*
* We found an inuse dentry which was not removed from
* dentry_unused because of laziness during lookup. Do not free
* it - just keep it off the dentry_unused list.
*/
if (atomic_read(&dentry->d_count)) {
spin_unlock(&dentry->d_lock);
continue;
}
/* If the dentry was recently referenced, don't free it. */
if (dentry->d_flags & DCACHE_REFERENCED) {
dentry->d_flags &= ~DCACHE_REFERENCED;
list_add(&dentry->d_lru, &dentry_unused);
dentry_stat.nr_unused++;
spin_unlock(&dentry->d_lock);
continue;
}
prune_one_dentry(dentry);
}
spin_unlock(&dcache_lock);
}
What now?! Well, I have a silly method which helps to find
C code line corresponding to that asm one. Edit your
prune_dcache in dcache.c like this:
どうする？えー、アセンブラの物と一致する C コードラインを見つけるバカ
正直な方法があるよ。dcache.c の prune_dcache をこんな感じに編集してね。
static void prune_dcache(int count)
{
spin_lock(&dcache_lock);
for (; count ; count--) {
struct dentry *dentry;
struct list_head *tmp;
asm("#1");
tmp = dentry_unused.prev;
asm("#2");
if (tmp == &dentry_unused)
break;
asm("#3");
list_del_init(tmp);
asm("#4");
prefetch(dentry_unused.prev);
asm("#5");
dentry_stat.nr_unused--;
asm("#6");
...
...
asm("#e");
prune_one_dentry(dentry);
}
asm("#f");
spin_unlock(&dcache_lock);
}
and do "make fs/dcache.s" again. Look into new dcache.s.
Nasty surprize:
そして、"make fs/dcache.s" を再度実行。新しい dcache.s を見てみよう。
ほうらびっくり：
APP
#e
#NO_APP
testb $16, %al
jne .L495
orl $16, %eax
leal 72(%ecx), %esi
movl %eax, 4(%ebx)
movl 4(%esi), %edx
movl 72(%ecx), %eax
testl %eax, %eax
movl %eax, (%edx)
je .L493
movl %edx, 4(%eax)
.L493:
movl $2097664, 4(%esi)
.L495:
leal 40(%ebx), %ecx
movl 40(%ebx), %eax
movl 4(%ecx), %edx
movl %edx, 4(%eax)
movl %eax, (%edx)
movl $2097664, 4(%ecx)
movl $1048832, 40(%ebx)
decl dentry_stat
movl 8(%ebx), %esi
testl %esi, %esi
je .L536
leal 56(%ebx), %eax
movl $0, 8(%ebx)
movl 56(%ebx), %edx
movl 4(%eax), %ecx
movl %ecx, 4(%edx)
movl %edx, (%ecx)
movl %eax, 4(%eax)
movl %eax, 56(%ebx)
movl 8(%edi), %eax
decl 20(%edi)
testb $8, %al
jne .L592
.L518:
movl 8(%edi), %eax
decl 20(%edi)
testb $8, %al
jne .L593
.L517:
movl 68(%ebx), %eax
testl %eax, %eax
je .L532
movl 20(%eax), %edx <======== OOPS
testl %edx, %edx
jne .L594
.L532:
movl %esi, (%esp)
call iput
How come one line of C code expanded in so much asm?!
Hmm... asm("#e") was directly before prune_one_dentry(dentry),
what's that?
どうして C コード１行がこんな大量のアセンブラに展開されているのだろう？
ふむ… asm("#e") は prune_one_dentry(dentry) の直前のようだ。これは何？
static inline void prune_one_dentry(struct dentry * dentry)
{
struct dentry * parent;
__d_drop(dentry);
list_del(&dentry->d_child);
dentry_stat.nr_dentry--; /* For d_free, below */
dentry_iput(dentry);
parent = dentry->d_parent;
d_free(dentry);
if (parent != dentry)
dput(parent);
spin_lock(&dcache_lock);
}
Argh! An inline function. Do asm trick to it too:
あが！インライン関数だった。こいつにもアセンブラトリックを仕掛けよう：
static inline void prune_one_dentry(struct dentry * dentry)
{
struct dentry * parent;
asm("#A");
__d_drop(dentry);
asm("#B");
list_del(&dentry->d_child);
asm("#C");
dentry_stat.nr_dentry--; /* For d_free, below */
asm("#D");
dentry_iput(dentry);
asm("#E");
...
...
}
"make fs/dcache.s", rinse, repeat. You will discover that OOPS
happened after #D mark, inside dentry_iput wich is an inline too.
Will this ever end? Luckily, yes. After yet another round of asm
insertion, we arrive at:
"make fs/dcache.s"、リンス(訳注：後処理の事)、繰り返して。これで OOPS
が #D マークの後、これもインライン関数の dentry_iput で起こっている事
が判るね。これはいつか終わるのかな？嬉しい事に yes。もうひとまわりアセ
ンブラを挿入して回った後、俺達は遂にたどり着いた。
static inline void dentry_iput(struct dentry * dentry)
{
struct inode *inode = dentry->d_inode;
if (inode) {
asm("#K");
dentry->d_inode = NULL;
asm("#L");
list_del_init(&dentry->d_alias);
asm("#M");
spin_unlock(&dentry->d_lock);
asm("#N");
spin_unlock(&dcache_lock);
asm("#O");
if (dentry->d_op && dentry->d_op->d_iput)
{
asm("#P");
dentry->d_op->d_iput(dentry, inode);
}
else
...
Which corresponds to this part of new dcache.s:
新しい dcache.s のこの部分に一致するのは：
.L517:
#APP
#O
#NO_APP
movl 68(%ebx), %eax
testl %eax, %eax
je .L532
movl 20(%eax), %edx <=== OOPS
testl %edx, %edx
jne .L594
.L532:
#APP
#Q
#NO_APP
This is "if (dentry->d_op && dentry->d_op->d_iput)" condition
check, and it is oopsing trying to do second check. dentry->d_op
contains bogus pointer value 0x00000e00.
これは、"if (dentry->d_op && dentry->d_op->d_iput)" 状態チェックで、２
番目のチェックをしようとして Oops を吐いているんだよ。dentry->d_op は
デタラメなポインタ値 0x00000e00 を持っているんだ。
======================================================
Date: Sat, 14 Aug 2004 11:06:42 -0300
From: Marcelo Tosatti
======================================================
Might be also worth mentioning "gcc -c file.c -g -Wa,-a,-ad > file.s"
which makes gcc output C code mixed with asm output.
gcc に、C のコードにアセンブラを混ぜて出力させる
"gcc -c file.c -g -Wa,-a,-ad > file.s" も言っとく価値がある。
Sometimes its not as effective as the comment method you describe,
but it will be less work for sure :)
時々この方法はあなたの説明したコメント手法ほどの効果がないが、より楽を
させてくれるよ :)
======================================================
Yes, this would be useful as soon as we will figure out
how to to preserve exact build environment.
よし、ビルドした環境を正確に再現する方法さえ突き止めりゃ、すぐにこいつ
が使えるに違いない。
I tried
試してみた
make CFLAGS="-g -Wa,-a,-ad" fs/dcache.o >dcache.asm
but result was very dirrerent because in this case gcc was run
without these flags:
しかし、この場合は gcc が下記のフラグなしで実行されるので、結果はとて
も異なる。
-Wall -Wstrict-prototypes -Wno-trigraphs -fno-strict-aliasing
-fno-common -pipe -msoft-float -mpreferred-stack-boundary=2
-march=i486 -I/.1/usr/srcdevel/kernel/linux-2.6.7-bk20.src/include/asm-i386/mach-default
-Iinclude/asm-i386/mach-default -O2 -falign-functions=1 -falign-labels=1 -falign-loops=1
-falign-jumps=1
and dcache.asm was useless.
そして、dcache.asm は使えなかった。
==============================================
Date: Sat, 14 Aug 2004 09:41:10 -0400 (EDT)
From: Zwane Mwaikambo
Subject: Re: [RFC] HOWTO find oops location
==============================================
There are a few very simple methods i use all the time:
私がいつも使っているいくつかの簡単な方法があります。
compile with CONFIG_DEBUG_INFO (it's safe to select the option and
recompile after the oops even) and then;
CONFIG_DEBUG_INFO 付きでコンパイル(オプションで選択して、oops の後でもリコンパイルするのが安全)して、その後；
Unable to handle kernel NULL pointer dereference at virtual address 0000000c
printing eip:
c046a188
*pde = 00000000
Oops: 0000 [#1]
PREEMPT SMP DEBUG_PAGEALLOC
Modules linked in:
CPU: 0
EIP: 0060:[] Not tainted VLI
EFLAGS: 00010246 (2.6.6-mm3)
EIP is at serial_open+0x38/0x170
[...]
# gdb vmlinux
GNU gdb 5.2
Copyright 2002 Free Software Foundation, Inc.
...
(gdb) list *serial_open+0x38
0xc046a188 is in serial_open (drivers/usb/serial/usb-serial.c:465).
460
461 /* get the serial object associated with this tty pointer */
462 serial = usb_serial_get_by_index(tty->index);
463
464 /* set up our port structure making the tty driver remember our port object, and us it */
465 portNumber = tty->index - serial->minor;
466 port = serial->port[portNumber];
467 tty->driver_data = port;
468
469 port->tty = tty;
And then for cases where you deadlock and the NMI watchdog triggers with
%eip in a lock section:
そしてこのケースでは、あるロックセクションの中でデッドロックが発生して、
%eip で NMI ワッチドッグタイマが発生した場所は：
NMI Watchdog detected LOCKUP on CPU0,
eip c0119e5e, registers:
Modules linked in:
CPU: 0
EIP: 0060:[] Tainted:
EFLAGS: 00000086 (2.6.7)
EIP is at .text.lock.sched+0x89/0x12b
[...]
(gdb) disassemble 0xc0119e5e
Dump of assembler code for function Letext:
[...]
0xc0119e59 : repz nop
0xc0119e5b : cmpb $0x0,(%edi)
0xc0119e5e : jle 0xc0119e59
0xc0119e60 : jmp 0xc0118183
(gdb) list *scheduler_tick+487
0xc0118183 is in scheduler_tick (include/asm/spinlock.h:124).
119 if (unlikely(lock->magic != SPINLOCK_MAGIC)) {
120 printk("eip: %p\n", &&here);
121 BUG();
122 }
123 #endif
124 __asm__ __volatile__(
125 spin_lock_string
126 :"=m" (lock->lock) : : "memory");
127 }
But that's not much help since it's pointing to an inline function and not
the real lock location, so just subtract a few bytes:
しかし、これではインライン関数を指しているのでそれほど助けにならないし、
本当のロック位置でもありません。なので、ここで数バイト引いてみます。
(gdb) list *scheduler_tick+450
0xc011815e is in scheduler_tick (kernel/sched.c:2021).
2016 cpustat->system += sys_ticks;
2017
2018 /* Task might have expired already, but not scheduled off yet */
2019 if (p->array != rq->active) {
2020 set_tsk_need_resched(p);
2021 goto out;
2022 }
2023 spin_lock(&rq->lock);
So we have our lock location. Then there are cases where there is a
"Bad EIP" most common ones are when a bad function pointer is followed
or if some of the kernel text or a module got unloaded/unmapped
(e.g. via __init). You can normally determine which is which by
noting that bad eip for unloaded text normally looks like a valid
virtual address.
これでロック位置が得られました。それで、"Bad EIP" がある最も一般的な場
所は、悪い関数ポインタが後に続いている時や、何かカーネルテキストまたは
モジュールがアンロード／アンマップされた(例えば __init を介して)場合で
す。アンロードされたテキスト領域の "Bad eip" が通常は有効な仮想アドレ
スのに見える事に注意すれば、普通はどちらの場合なのかを判断できます。
Unable to handle kernel NULL pointer dereference at virtual address 00000000
00000000
*pde = 00000000
Oops: 0000 [#1]
CPU: 0
EIP: 0060:[<00000000>] Not tainted
Using defaults from ksymoops -t elf32-i386 -a i386
EFLAGS: 00210246
[...]
Call Trace:
[] smb_readdir+0x4fb/0x6e0
[] filldir64+0x0/0x130
[] vfs_readdir+0x8a/0x90
[] filldir64+0x0/0x130
[] sys_getdents64+0x6d/0xa6
[] filldir64+0x0/0x130
[] syscall_call+0x7/0xb
Code: Bad EIP value.
>From there you're best off examining the call trace to find the culprit.
犯人探しの為には、そこからコールトレースを調べるのが一番です。
======================================================
--
vda
-
(訳注：以下は上記メールのフォロー)
List: linux-kernel
Subject: Re: [RFC] HOWTO find oops location, v2
From: Johannes Stezenbach
Date: 2004-08-17 9:30:34
Message-ID: <20040817093034.GA14077@convergence.de>
On Sun, Aug 15, 2004 at 02:39:31PM +0300, Denis Vlasenko wrote:
> I've got some useful feedback. This is v2 of the HOWTO.
>
> CFLAGS="-g -Wa,-a,-ad" trick almost, but not quite works.
...
> I tried
>
> make CFLAGS="-g -Wa,-a,-ad" fs/dcache.o >dcache.asm
>
> but result was very dirrerent because in this case gcc was run
> without these flags:
>
> -Wall -Wstrict-prototypes -Wno-trigraphs -fno-strict-aliasing
> -fno-common -pipe -msoft-float -mpreferred-stack-boundary=2
> -march=i486 -I/.1/usr/srcdevel/kernel/linux-2.6.7-bk20.src/include/asm-i386/mach-default
> -Iinclude/asm-i386/mach-default -O2 -falign-functions=1 -falign-labels=1 -falign-loops=1
> -falign-jumps=1
>
> and dcache.asm was useless.
Try: make EXTRA_CFLAGS="-g -Wa,-a,-ad" fs/dcache.o >dcache.asm
make EXTRA_CFLAGS="-g -Wa,-a,-ad" fs/dcache.o >dcache.asm
を試してみて。
Or, what I usually do, "make V=1 fs/dcache.o" and then copy&paste
and edit the commandline manually.
でなきゃ、いつも私がやるのは、"make V=1 fs/dcache.o" としてからカット
＆ペーストして、手でコマンドラインを編集する方法。
Johannes
一覧に戻る
グリーンネット・トップページへ戻る
|
