[prev in list] [next in list] [prev in thread] [next in thread]
List: busybox
Subject: Re: busybox post from creder@digitalcpt.com requires approval
From: Denis Vlasenko <vda.linux () googlemail ! com>
Date: 2007-07-21 0:37:49
Message-ID: 200707210137.49632.vda.linux () googlemail ! com
[Download RAW message or body]
On Thursday 01 January 1970 01:00, Christopher Reder wrote:
> Denis, yes, I only realized after sending it that it was too long and in fact, \
> canceled the message on the website. This does have a MMU and is a ARM0, \
> AT91RM9200. When using the Nor Flash, after transferring about 320k, the kernel \
> crashes and the transfer aborts.
Kernel should not crash. Ever. No matter now buggy application is,
kernel should never crash. You see kernel crashing - it means
youu see kernel bug and it should be diagnosed and fixed first,
regardless of whether busybox's tftp is buggy or not.
> Has anyone been able to use tftp for larger files (>1MB) without issues on v1.5.1?
Because of the above this question is sort of off-target here.
I suspect that you just don't try hard enough to actually
look closely and understand the problem, throwing haphazardly
composed posts on semi-relevant mailing lists instead.
Look a at your post again. Oops output is double-spaced
and linewrapped. Did you spend even a second thinking
how people on the list are supposed to read and understand that?
It should be formatted approx. like this:
# tftp -g -r u-boot.bin 192.168.0.38
Unable to handle kernel paging request at virtual address 1a000003
pgd = c1fe4000
[1a000003] *pgd=00000000
Internal error: Oops: 3 [#1]
Modules linked in:
CPU: 0
PC is at __wake_up_common+0x28/0x7c
LR is at 0x1a000003
pc : [<c003bfa8>] lr : [<1a000003>] Not tainted
sp : c1fd9c98 ip : c1fd9cc4 fp : c1fd9cc0
r10: 00000003 r9 : c1fd9cdc r8 : 00000000
r7 : 00000001 r6 : c0000070 r5 : c031d000 r4 : 00000013
r3 : 00000000 r2 : 00000001 r1 : 00000003 r0 : c0000070
Flags: nzcv IRQs off FIQs on Mode SVC_32 Segment user
Control: C000717F
Table: 21FE4000 DAC: 00000015
Process tftp (pid: 773, stack limit = 0xc1fd8250)
Stack: (0xc1fd9c98 to 0xc1fda000)
9c80: 00000013 c031d000
9ca0: 00000200 c03b0258 00000000 00008200 00000000 c1fd9cd8 c1fd9cc4 c003c028
9cc0: c003bf90 c1fd9cdc c031d000 c1fd9cf0 c1fd9cdc c0054a1c c003c00c c031d000
9ce0: 00000000 c1fd9d04 c1fd9cf4 c00622a4 c00549fc 00000200 c1fd9db0 c1fd9d08
9d00: c0064234 c0062270 00000200 c1fd9d18 c01a7e08 c0370840 c0370840 00000200
9d20: 000b3464 c03b01c4 c020bce4 c1edd8a0 00000001 c1fd9ea0 00000000 00000200
9d40: c1fd9e98 c1370840 00000001 00000000 c031d000 c01a7d38 c01a7c1c 000004ce
9d60: 27f95cfb c1fd9d94 c1fd9d90 c1fd9d78 c00445d0 c0044538 c03b01c4 00000000
9d80: c1fd9d94 c1fd9db4 00008000 00000000 00000000 c1fd8000 c03b01c4 c1edd8a0
9da0: 00000200 c1fd9e4c c1fd9db8 c0064b38 c0063f3c 00008000 00000000 c1fd9ee8
9dc0: 00000000 00000200 00000010 c0368320 c1fd9f64 00000204 00000000 c03b0258
9de0: c1fd9ee8 c1fd9e98 c1fd9ea0 00000001 00000200 00008000 00000000 c1fede40
9e00: 00000000 00000000 c1fd9f64 c1fd8000 00000004 00000004 00000001 c1fd8000
9e20: be9a7c30 c1fd9ea0 00008000 00000000 c1fd9ee8 c03b01c4 c1fd9e98 c03b022c
9e40: c1fd9e8c c1fd9e50 c0064ea4 c0064848 00000000 c0368320 c03b0258 c1edd8a0
9e60: 00000001 00008000 00000000 c1fd9ea0 c1fd9e98 c1fd9ee8 c1fd9f78 c1edd8a0
9e80: c1fd9f4c c1fd9e94 c007f154 c0064e40 00008000 00000000 000b3264 00000200
9ea0: be9a7bdc 00000010 00000000 00000001 ffffffff c1edd8a0 00000000 00000000
9ec0: 00000000 00000000 c0368320 00000000 00000000 000b3464 c0368320 c00548cc
9ee0: c1fd9ee0 c1fd9ee0 00008000 00000000 00000000 00000000 00000000 d60c0002
9f00: 2600a8c0 00000200 00000000 c1edd8a0 000b3264 00000200 c1fd9f78 00000000
9f20: 00000000 c1edd8a0 000b3264 c1fd9f78 00000200 c1fd8000 c1fd8000 00000204
9f40: c1fd9f74 c1fd9f50 c007f254 c007f09c 00000000 c1edd8c0 c1edd8a0 c1fd9f78
9f60: 00008000 00000000 c1fd9fa4 c1fd9f78 c007f3ec c007f1b0 00008000 00000000
9f80: 00000000 00000200 00000200 000b3264 00000004 c002af04 00000000 c1fd9fa8
9fa0: c002ad60 c007f3b0 00000200 00000200 00000004 000b3264 00000200 00000001
9fc0: 00000200 00000200 000b3264 00000004 00000003 000b3260 00000204 be9a7ce0
9fe0: 000ae328 be9a7ba0 0003b558 4005ce0c 20000010 00000004 00000000 00000000
Backtrace:
[<c003bf80>] (__wake_up_common+0x0/0x7c) from [<c003c028>] (__wake_up+0x2c/0x34)
[<c003bffc>] (__wake_up+0x0/0x34) from [<c0054a1c>] (__wake_up_bit+0x30/0x38)
r4 = C031D000
[<c00549ec>] (__wake_up_bit+0x0/0x38) from [<c00622a4>] (unlock_page+0x44/0x5c)
[<c0062260>] (unlock_page+0x0/0x5c) from [<c0064234>] \
(generic_file_buffered_write+0x30c/0x674) r4 = 00000200
[<c0063f2c>] (generic_file_buffered_write+0x4/0x674) from [<c0064b38>] \
(__generic_file_aio_write_nolock+0x300/0x5f4) [<c0064838>] \
(__generic_file_aio_write_nolock+0x0/0x5f4) from [<c0064ea4>] \
(generic_file_aio_write+0x78/0x104) [<c0064e30>] (generic_file_aio_write+0x4/0x104) \
from [<c007f154>] (do_sync_write+0xc8/0x114) [<c007f08c>] (do_sync_write+0x0/0x114) \
from [<c007f254>] (vfs_write+0xb4/0x184) [<c007f1a0>] (vfs_write+0x0/0x184) from \
[<c007f3ec>] (sys_write+0x4c/0x7c) r8 = 00000000 r7 = 00008000 r6 = C1FD9F78 r5 = \
C1EDD8A0 r4 = C1EDD8C0
[<c007f3a0>] (sys_write+0x0/0x7c) from [<c002ad60>] (ret_fast_syscall+0x0/0x2c)
r8 = C002AF04 r7 = 00000004 r6 = 000B3264 r5 = 00000200
r4 = 00000200
Code: e1a0a001 e1a07002 e1a08003 e59b9004 (e59e5000)
<1>Unable to handle kernel paging request at virtual address e5902008
pgd = c1fe4000
[e5902008] *pgd=00000000
And yes, I did a few tftp transfers here for testing purposes,
some of them much bigger than 1MB. (If doesn't mean that tftp
can't have bugs. It surely can).
In attachment you may find hints how to hunt down an oops.
--
vda
["HOWTO_find_oops.txt" (text/plain)]
Okay, so you've got an oops and want to find out what happened?
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:
CONFIG_DEBUG_SLAB=y
CONFIG_FRAME_POINTER=y
CONFIG_KALLSYMS=y
CONFIG_KALLSYMS_ALL=y
First one makes use-after-free bug hunt easy, second gives
you much more reliable stacktraces. Next two give you decoded
oops (2.6 only).
If you are running 2.4 kernel, please make sure you run
your klogd with -x switch.
1. An OOPS decoding walkthrough
Ok, let's take a look at example OOPS. ^^^^ marks are mine.
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:[<c0162887>] 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:
[<c0162d1f>] shrink_dcache_memory+0x1f/0x30
[<c0139a2b>] shrink_slab+0x14b/0x190
[<c013add1>] balance_pgdat+0x1b1/0x200
[<c013aee7>] kswapd+0xc7/0xe0
[<c0114270>] autoremove_wake_function+0x0/0x60
[<c0103e9e>] ret_from_fork+0x6/0x14
[<c0114270>] autoremove_wake_function+0x0/0x60
[<c013ae20>] kswapd+0x0/0xe0
[<c01021d1>] 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!
(BTW, if you have _only_ EIP: 0060:[<c0162887>] line (probably because
you're using 2.4), just look into System.map. You will discover that
EIP is in prune_dcache() because you see "c0162740 t prune_dcache"
in System.map and EIP falls between this and next entry.)
Ok, execute these two commands:
# objdump -d fs/dcache.o > fs/dcache.disasm
# make fs/dcache.s
Now in fs/ you should have:
dcache.c - source code
dcache.o - compiled object file
dcache.s - assembler output of C compiler ('half-compiled' code)
dcache.disasm - disassembled object file
Open dcache.disasm and find "prune_dcache":
00000540 <prune_dcache>:
540: 55 push %ebp
We need to find prune_dcache+0x147. Using shell,
# printf "0x%x\n" $((0x540+0x147))
0x687
and in dcache.disasm:
683: 85 c0 test %eax,%eax
685: 74 07 je 68e <prune_dcache+0x14e>
===> 687: 8b 50 14 mov 0x14(%eax),%edx <======== OOPS
68a: 85 d2 test %edx,%edx
68c: 75 27 jne 6b5 <prune_dcache+0x175>
68e: 89 34 24 mov %esi,(%esp)
691: e8 fc ff ff ff call 692 <prune_dcache+0x152>
696: 8b 73 0c mov 0xc(%ebx),%esi
699: 89 1c 24 mov %ebx,(%esp)
69c: e8 9f f9 ff ff call 40 <d_free>
Comparing with "Code: 8b 50 14 85 d2 75 27" - match!
We need to find matching line in dcache.s and, eventually, in dcache.c.
It's easy to find prune_dcache in dcache.s:
prune_dcache:
pushl %ebp
but even though it is not too hard to find matching instruction
(you just have to look for the same instruction sequence):
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:
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:
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:
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?
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 which is an inline too.
Will this ever end? Luckily, yes. After yet another round of asm
insertion, we arrive at:
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:
.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 (see %eax value in OOPS
message we started with).
1.1. Accesses of structure members via NULL pointer
If kernel says "Unable to handle kernel _NULL_ pointer dereference",
it does not really 100% guaranteed that NULL pointer was to blame.
You can check that by examining the code and register values. In our
example, dentry->d_op pointer wasn't NULL. Real NULL pointer would have
caused "Unable to handle kernel NULL pointer dereference at virtual
address 00000014" message and EAX register would be 00000000.
1.2. Bit flips
If you see that only one bit in the referenced address is set
(example: "Unable to handle kernel paging request at virtual address
00040000"), you probably have faulty memory which sometimes can
flip bit from 0 to 1. It converted legitimate NULL pointer into
non-NULL one. Code which expected to stop on NULL pointer saw
a non-NULL value and happily used it.
Test your box with memtest86, cpuburn and/or memburn.
1.3. OOPSes scrolling off the screen
If your OOPS is so long that it scrolls off the screen, and box freeze
after the OOPS with nothing in logs, you can try the following:
1. Boot with video=N such that you get large console size.
Most x86 machines have 50- and 60-line mode.
2. Connect your box with null modem cable to another one,
start terminal emulator there and boot with console=ttyS0
kernel parameter.
3. Use netconsole (I never used that yet).
2. Other decoding tricks
Marcelo Tosatti <marcelo.tosatti@cyclades.com> and
Johannes Stezenbach <js@convergence.de> suggest using
make EXTRA_CFLAGS="-g -Wa,-a,-ad" fs/dcache.o >dcache.asm
instead of asm trick. This works at least on 2.6.
Note that GCC may produce slightly different assembler code
with these options. This is normal.
Herbert Poetzl <herbert@13thfloor.at> suggested simply using
addr2line -e vmlinux c012609d
(this might require CONFIG_DEBUG_KERNEL and recompile).
Zwane Mwaikambo <zwane@linuxpower.ca> has another tips
for you:
==============================================
Date: Sat, 14 Aug 2004 09:41:10 -0400 (EDT)
From: Zwane Mwaikambo <zwane@linuxpower.ca>
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;
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:[<c046a188>] 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:
NMI Watchdog detected LOCKUP on CPU0,
eip c0119e5e, registers:
Modules linked in:
CPU: 0
EIP: 0060:[<c0119e5e>] 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 <Letext+132>: repz nop
0xc0119e5b <Letext+134>: cmpb $0x0,(%edi)
0xc0119e5e <Letext+137>: jle 0xc0119e59 <Letext+132>
0xc0119e60 <Letext+139>: jmp 0xc0118183 <scheduler_tick+487>
(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.
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:
[<c01dbbfb>] smb_readdir+0x4fb/0x6e0
[<c0165560>] filldir64+0x0/0x130
[<c016524a>] vfs_readdir+0x8a/0x90
[<c0165560>] filldir64+0x0/0x130
[<c01656fd>] sys_getdents64+0x6d/0xa6
[<c0165560>] filldir64+0x0/0x130
[<c010adff>] syscall_call+0x7/0xb
Code: Bad EIP value.
From there you're best off examining the call trace to find the culprit.
======================================================
3. Looking around in C code
Not written. I think live example of chasing bug further by following call
chain, placing printks etc will be most interesting to have here.
4. More obscure oopses
Not written.
--
vda
_______________________________________________
busybox mailing list
busybox@busybox.net
http://busybox.net/cgi-bin/mailman/listinfo/busybox
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic