OOPS -ot kiváltó hiba keresése
A HupWiki-ből...
Ez az írás az egyik LKML-en történő levélváltás alapján készült. A thread kezdő levele itt található, a levélváltásról szóló hír a HUP-on pedig itt érhető el. A fordításért köszönet az irc.debian.org szerver #debian.hu csatornáján közreműködő "xbit_" látogatónak. Elnézést a fordításért, ha nem túl pontos, de nem lektorált, és nem lett teljes mélységben átnézve. Viszont segíthet egyeseknek.
A fordítás
Szevasztok srácok,
hasznos lett ez a vázlatos Hogyan? Észrevételek?
Szóval kaptál egy oops hibát, és szeretnéd kideríteni mi történt?
Ebben a Hogyan-ban feltételezem, hogy nem törölted ki és nem is babráltad a kerneled forrását, ezenkívül javaslom ezen opciók használatát a .config-ban:
CONFIG_DEBUG_SLAB=y
CONFIG_FRAME_POINTER=y
Az első megkönnyíti a használd-miután-szabad (? - fordító) hibakeresést, a másodikkal megbízhatóbban követhetsz nyomokat a stackben.
Szóval, és tettel, nézzünk egy példa OOPS üzenetet. A ^^^^ jelölések tőlem vannak. (Az EIP az oops-ot generáló utasításra mutat - fordító)
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
^^^^^^^^^^^^^^^^^^^^^^^^
ax: 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
Próbáljuk meg először megtalálni hol történt a hiba. Keresd meg a kernel fában a prune_dcache-t. Ok, szóval az fs/dcache.c-ben van definiálva! Most futtasd ezt a két parancsot:
# objdump -d fs/dcache.o > fs/dcache.disasm # make fs/dcache.s
Most az fs/ alatt ezeknek kell lennie:
dcache.c - forrás dcache.o - lefordított objektum file dcache.s - C fordító asm kimenete ('félig-fordított' kód) dcache.disasm - visszafejtett objektum file
Nyisd meg a dcache.disasm-t és keresd meg a "prune_dcache"-t:
00000540 <prune_dcache>:
540: 55 push %ebp
Ezután prune_dcache+0x147-et kell megtalálnunk, pl. egy shell parancsal:
# printf "0x%x\n" $((0x540+0x147)) 0x687
A dcache.disasm-ben:
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>
Összehasonlítva a kódot, az OOPS üzeneteivel, egyezik, megvan!
Rendben, keressük meg a megfelelő sorokat a dcache.s és dcache.c-ben is! A prune_dcache-t könnyen megtalálhatjuk az előbbiben:
prune_dcache:
pushl %ebp
és a megfelelő utasításra sem nehéz rátalálni:
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
Az már csöppet sem világos, hogy a C kódban hol a hiba:
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);
}
Most mi legyen? Nos, van egy ostoba eljárás, ami segít megtalálni a megfelelő C sort. Írd át a dcache.c-t, valahogy így:
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);
}
Ezután `make fs/dcache.s` megint, majd jön a kellemetlen meglepeté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
Hogy tudott egyetlen C sor ennyi asm kódot eredményezni?! Az asm("#e") pontosan a prune_one_dentry(dentry) elõtt volt, mi lehet ez a függvény?
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);
}
Hmm…, egy inline függvény. Alkalmazzuk megint az asm() trükköt:
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");
...
...
}
Újra! `make fs/dcache.s`. Az OOPS most a #D megjegyzés után történt, dentry_input-on belül, ami megint csak egy inline függvény. Mikor lesz ennek már vége? Még egy kör után itt kötünk ki:
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
...
A megfelelő rész a dcache.s-ben:
.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
Tehát az "if (dentry->d_op && dentry->d_op->d_iput)" okozza az OOPS-ot, amikor másodszor ellenőriz, így dentry->d_op tartalmazza a bugos mutató értéket, 0x00000e00-át (eax értéke, lásd az OOPS üzenetet - fordító). -- vda
Marcelo Tosatti <marcelo.tosatti () cyclades ! com> válasza:
Talán megéri megemlíteni: "gcc -c file.c -g -Wa,-a,-ad > file.s" ez C és asm kevert kódú kimenetet eredményez.
Nem olyan hatékony mint az általad leírt módszer, de nem is jár annyi munkával, az biztos :)
Az írás jónak tűnik, de jobban belemehetne egypár dologba, mint például a hardver "biteldobás" , szemetes stack (miért lehet a stack megbízhatatlan), stb., hogy még hasznosabb legyen.
Zwane Mwaikambo <zwane () linuxpower ! ca> válasza:
Van itt néhány egyszerű fogás, amiket szoktam használni:
CONFIG_DEBUG_INFO-val fordítom a kernelt (nem gond ha az oops után aktiválod az opciót, és újrafordítod a kernelt), aztán:
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) 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;
Azokban az esetekben, amikor az NMI watchdog (non-maskable interrupt, akkor is vegrehajtódik, amikor egy CPU behal, így figyelve a fagyásokat. Ha egy CPU 5 másodpercen túl sem indítja el a period local timer (periodikus helyi idő) megszakítást, oops generálódik - fordító) egy "behalt" területbeli eip-pel áll elő:
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 }
Bár ez nem túl nagy segítség, mivel egy inline függvényre leltünk és nem az igazi hiba helyére, úgyhogy vonjunk ki pár bájtot:
(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);
Ok, most megvan a keresett hiba helye. Aztán vannak olyan esetek is, amikor "Rossz EIP"-el találkozunk, legtöbb esetben akkor, amikor azt egy hibás függvény-mutató követi, vagy amikor az oops egy modul eltávolításakor keletkezik. Az utóbbi esetben az eip úgy néz ki mint egy érvényes virtuális cím.
(Eredetileg: 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.
(Ez egy ksysmoops nevű program kimenete, ami szintén gyakran használt eszköz oops vizsgálatánál - fordító)
Innen jobb, ha lemondasz a call trace vizsgálatáról, így nem lesz meg a tettes.
