Re: Kernel hang with latest snapshot

[Mike Mason <mmlnx at us dot ibm dot com>]

David Boreham wrote:
> Hi, I'm interested in using LKET to analyse the behavior of a large
> application that has disk i/o-bound performance. My top level goal
> is to be able to record system-wide traces of all i/o activity at a
> system call level (open,close,write,fsync etc). I am using Fedora Core 5
> (although if it would help I'd be happy to use any distribution/custom 
> kernel).
>
> The systemtap that comes with the FC5 distribution is too old to
> include LKET. The LKET from the latest systemtap snapshot
> (20061007) does not work with the systemtap binary in the distribution.
>
> So I removed the distribution systemtap, installed the dependencies
> and built/installed the latest snapshot systemtap.
>
> So far so good.
>
> Unfortunately when I try to use LKET it would appear that my
> kernel hangs (machine totally unresponsive after the kernel module
> is loaded).
>
> This is the command line I'm using :
>
> /usr/local/bin/stap -e "probe addevent.iosyscall.flock.* {}" -bM -vv -k
>
> (btw addevent.iosyscall.* produces C code that will not compile)
>
> It gets this far and then hangs:
>
>  ld -m elf_i386 -m elf_i386 -r -o /tmp/stapA607FG/stap_3312.ko 
> /tmp/stapA607FG/stap_3312.o /tmp/stapA607FG/stap_3312.mod.o
> make: Leaving directory `/usr/src/kernels/2.6.17-1.2187_FC5-i686'
> Pass 4: compiled C into "stap_3312.ko" in 23930usr/2630sys/28585real ms.
> Pass 5: starting run.
> Running sudo /usr/local/bin/staprun -u root -d 3312 
> /tmp/stapA607FG/stap_3312.ko
>
> I'm using this kernel : 2.6.17-1.2187_FC5 (i386/i686) and vmware.


The same kernel and stap script on my x86_64 system produces the
following console output:

BUG: sleeping function called from invalid context at mm/page_alloc.c:940
Unable to handle kernel paging request at ffffffff89512220 RIP: 
<ffffffff8028b14f>{resched_task+18}
PGD 203027 PUD 205027 PMD 0 
Oops: 0000 [1] SMP 
last sysfs file: /block/hda/removable
CPU 0 
Modules linked in: stap_2420(U) ipv6 autofs4 hidp rfcomm l2cap bluetooth sunrpc dm_mirror dm_mod video button battery acpi_memhotplug ac lp parport_pc parport snd_hda_intel snd_hda_codec snd_seq_dummy snd_seq_oss snd_seq_midi_event snd_seq e1000 sg serio_raw snd_seq_device i2c_i801 i2c_core ehci_hcd uhci_hcd snd_pcm_oss snd_mixer_oss snd_pcm snd_timer snd soundcore snd_page_alloc hw_random ext3 jbd ahci libata sd_mod scsi_mod
Pid: 2564, comm: staprun Not tainted 2.6.17-1.2187_FC5 #1
RIP: 0010:[<ffffffff8028b14f>] <ffffffff8028b14f>{resched_task+18}
RSP: 0018:ffff81002c16bc48  EFLAGS: 00010097
RAX: ffffffff80700480 RBX: 0000000000000000 RCX: ffff81002c16c000
RDX: 00000000011ca440 RSI: 52505f4453464e5f RDI: ffff8100301280c0
RBP: ffff81002c16bc48 R08: ffff810001010ac0 R09: ffff8100010403d4
R10: 0000000dffffffff R11: ffffffff80347281 R12: 0000000000000000
R13: ffff810001010ac0 R14: ffff81003cb1d0c0 R15: ffff81000100f480
FS:  00002aaaaaaca850(0000) GS:ffffffff8069e000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: ffffffff89512220 CR3: 00000000300cd000 CR4: 00000000000006e0
Process staprun (pid: 2564, threadinfo ffff81002c16c000, task ffff8100301280c0)
Stack: ffff81002c16bcd8 ffffffff8024a2d7 000000002720726f 0000000000000001 
      000000006c61636f 0000000000000092 0000000000000001 000000008063a6d1 
      000000000000004a ffffffff803992bf 
Call Trace: <ffffffff8024a2d7>{try_to_wake_up+928} <ffffffff803992bf>{serial8250_console_putchar+0}
      <ffffffff8029f422>{autoremove_wake_function+9} <ffffffff8028a06a>{__wake_up_common+62}
      <ffffffff8022faea>{__wake_up+56} <ffffffff802904ab>{vprintk+682}
      <ffffffff80290543>{printk+82} <ffffffff8020b295>{__might_sleep+121}
      <ffffffff8020ef29>{__alloc_pages+61} <ffffffff802180b0>{cache_grow+309}
      <ffffffff80261d36>{cache_alloc_refill+633}

Code: 48 8b 14 d5 20 00 6c 80 48 03 42 08 8b 00 85 c0 7e 0a 0f 0b 
RIP <ffffffff8028b14f>{resched_task+18} RSP <ffff81002c16bc48>
CR2: ffffffff89512220
<0>BUG: spinlock recursion on CPU#0, staprun/2564 (Not tainted)

- Mike