ktracer plug

Michael L. Galbraith (mikeg@weiden.de)
Tue, 18 Nov 1997 16:49:03 +0100 (MET)


Hello List,

This is a quick (and enthusiastic) plug for Ingo Molnar's ktracer.

What can a non-guru do with the darn thing? How is it usefull to me?
These are things you may be wondering yourself if you've seen references to
ktrace on the list.. and love tinkering with experimental kernels.

Lets take a look at some random trace output from this >running< kernel
and see.

(>Running<? Of course it's running. Why did he say it that way?)

36979 c0111c6b update_process_times +<f/74> (0.09)
36980 c0111b7f update_one_process +<13/f0> (0.54)
36981 c0122ed2 swap_tick +<e/90> (0.56)
36982 c010b551 do_IRQ +<fd/108> (0.29)
36983 c01111c7 schedule +<13/218> (6837.35)
36984 c010b467 do_IRQ +<13/108> (3.73)
36985 c5867177 _end +<555b35f/3fcf41e7> (4.93)
36986 c01b9221 add_mouse_randomness +<d/28> (0.49)
36987 c01b904b add_timer_randomness +<13/1b4> (2.83)
36988 c011147b wake_up_interruptible +<13/a0> (1.10)
36989 c011147b wake_up_interruptible +<13/a0> (2.61)
36990 c010b539 do_IRQ +<e5/108> (0.06)
36991 c010b551 do_IRQ +<fd/108> (0.63)
36992 c01111c7 schedule +<13/218> (5.83)
36993 c011117b del_timer +<f/48> (6.07)
36994 c586765c _end +<555b844/3fcf41e7> (3.39)
36995 c0170779 sock_poll +<d/2c> (1.51)
36996 c01745f8 datagram_poll +<10/114> (10.55)

Cool, you can see where it was, and how long it took (usecs). But hey,
what can that _end thing at 0xc5867177 be? Lets go take a look. <g>

(gdb) list *0xc5867177
0xc5867177 is in aux_interrupt (psaux.c:233).
228 add_mouse_randomness(queue->buf[head] = inb(KBD_DATA_REG));
229 if (head != maxhead) {
230 head++;
231 head &= AUX_BUF_SIZE-1;
232 }
233 queue->head = head;
234 aux_ready = 1;
235 if (queue->fasync)
236 kill_fasync(queue->fasync, SIGIO);
237 wake_up_interruptible(&queue->proc_list);
(gdb)

Aha.. mouse's interrupt handler. (module :)

Did I neglect to mention that xkgdb works with ktracer? Yup, this is
also an enthusiastic plug for David Hinds' xkgdb. Great combination!
(2.1.x kernel support by Keith Owens)

With xkgdb and ktracer, you can trace and explore your >running< kernel.

37043 c0109f39 ** SYSTEM ENTRY ** (0.51)
37044 c012fbaf sys_ioctl +<13/190> (1.58)
37045 c01b46a0 tty_ioctl +<10/214> (3.15)
37046 c01be952 vt_ioctl +<16/1ed4> (1.40)
37047 c01ba2d9 vc_cons_allocated +<d/2c> (6.92)
37048 c0109f56 ** SYSTEM EXIT ** (3.33)

(gdb) break sys_ioctl
Breakpoint 1 at 0xc012fbb5: file ioctl.c, line 52.
(gdb) c
Continuing.

Breakpoint 1, sys_ioctl (fd=0x0, cmd=0x5402, arg=0xbffffdec) at ioctl.c:52
52 int on, error = -EBADF;
(gdb) s
55 if (fd >= NR_OPEN || !(filp = current->files->fd[fd]))
(gdb) s
57 error = 0;
(gdb) s
58 switch (cmd) {
(gdb)

etc etc etc until your current curiosity spot stops itching.. or you
get tired of fscking your filesystems.

They aren't quite _perfect_ tools.. (compared to what?)

This is what happened when I tried to do a bt of the knfsd that xkgdb
was attached to.

(slices dices chops AND decodes oopsen.. :)

Unable to handle kernel paging request at virtual address 7e83f3aa
current->tss.cr3 = 0484d000, `r3 = 0484d000
*pde = 00000000
Oops: 0000
CPU: 0
EIP: 0010:[<c5869800>]
EFLAGS: 00010246
eax: 00000000 ebx: 7e83f3aa ecx: c586a2ed edx: 00000000
esi: 7e83f3aa edi: 00000004 ebp: c4749f78 esp: c4749d58
ds: 0018 es: 0018 ss: 0018
Process gdb (pid: 255, process nr: 34, stackpage=c4749000)
Stack: bffff31b 0000000e 0000000f c02712c0 00000000 00000004 7e83f3aa c586a2ed
00313045 30633932 61666636 30633931 38363030 31633131 66333032 30633364
66333033 30633364 33666161 65373338 66663566 66666666 33663032 30636362
Call Trace: [<c5869c5f>(0)] [<c0125e3a>(24)] [<c0109f41>(44)] [<ffffffff>] [<c011147b>] [<c01bdad2>] [<c01c47ee>] [<c01ba2d9>] [<c01bdb57>] [<c01f6733>] [<c01f6733>] [<c01f66ee>] [<c01f68e3>] [<c0113df7>] [<c011147b>] [<c01bdad2>] [<c01c47ee>] [<c01ba2d9>

] [<c01bdb57>] [<c01f6733>] [<c01f6733>] [<c01f66ee>] [<c01f68e3>] [<c0113df7>] [<c011147b>] [<c01bdad2>] [<c01c47ee>] [<c01ba2d9>] [<c01bdb57>] [<c01f6733>] [<c01f6733>] [<c01f66ee>] [<c01f68e3>] [<c0113df7>]
Code: 8a 03 c0 e8 04 25 ff 00 00 00 8a 80 20 a2 86 c5 88 84 2a 00
Using `/boot/2.1.65/System.map' to map addresses to symbols.

>>EIP: c5869800 cannot be resolved
Trace: c5869c5f
Trace: c0125e3a <sys_write+ce/128>
Trace: c0109f41 <system_call+41/50>
...

(gdb) list *0xc5869c5f
0xc5869c5f is in generate_fake_regs (xkdebug.c:582).
577 /*
578 * To make gdb happy before the first "continue"
579 * we need to provide registers.
580 */
581 current_debugee_regs = &fake_regs;
582 }
583
584
585 static int debug_open(struct inode *inode, struct file *file)
586 {
(gdb)

OK, so I won't do bt any more after stepping through a kernel-thread.

That was after a reboot however.. The module was not likely loaded into
the same _exact_ location. For an oops that doesn't take out the debug
module, you can get instant decoding with source listing. Very nice.

Oh Boy! Pandora's Toolbox ;-)

-Mike

P.S. the price you pay for all this fun is a mere..
el-kaboom:# du -s /usr/src/linux /lib/modules/2.1.65
150720 /usr/src/linux
7664 /lib/modules/2.1.65