When running the systemtap testsuite on a RHEL4 machine with the 2.6.9-37.EL
kernel, the systemtap.base/probesfunc.exp crashes the machine with the following
message on the console:


Linux slingshot.devel.redhat.com 2.6.9-37.EL #1 Fri May 19 17:55:44 EDT 2006
i686 athlon i386 GNU/Linux

Kernel panic - not sync: kernel/module.c:2114:
spin_lock(kernel/module.c:c036b280) already locked by kernel/module.c:2114

 Badness in panic at kernel/panic.c:118


systemtap.base/probefunc.exp definitely causes the crash when trying to probe
kernel.function("scheduler_tick"). I don't have a great deal of details about
the failure on the RHEL4 UP kernel. There wasn't a traceback or oops on the screen.

------- Additional Comment #1 From prasadav@us.ibm.com 2006-06-01 19:58 -------

Subject: Re:  New: systemtap.base/probefunc.exp crash in
 kernel/module.c:2114 on RHEL4

Hi Will,

Can we reproduce this on FC5/FC6, if se we can configure dump to get 
additional info.
If you get a dump we can help you analyze the dump.

bye,
Vara Prasad

wcohen at redhat dot com wrote:

>When running the systemtap testsuite on a RHEL4 machine with the 2.6.9-37.EL
>kernel, the systemtap.base/probesfunc.exp crashes the machine with the following
>message on the console:
>
>
>Linux slingshot.devel.redhat.com 2.6.9-37.EL #1 Fri May 19 17:55:44 EDT 2006
>i686 athlon i386 GNU/Linux
>
>Kernel panic - not sync: kernel/module.c:2114:
>spin_lock(kernel/module.c:c036b280) already locked by kernel/module.c:2114
>
> Badness in panic at kernel/panic.c:118
>
>
>systemtap.base/probefunc.exp definitely causes the crash when trying to probe
>kernel.function("scheduler_tick"). I don't have a great deal of details about
>the failure on the RHEL4 UP kernel. There wasn't a traceback or oops on the screen.
>
>  
>

------- Additional Comment #2 From William Cohen 2006-06-01 20:29 -------

> Hi Will,
> 
> Can we reproduce this on FC5/FC6, if se we can configure dump to get 
> additional info.
> If you get a dump we can help you analyze the dump.
> 
> bye,
> Vara Prasad

I have nightly tests running on dual-processor pentium III running FC6 and a
Pentium M running FC5. I have not seen the problem on the FC machines. RHEL4
does have netdump. wouldn't it be possible to set up netdump to collect that
information?

------- Additional Comment #3 From bibo,mao 2006-06-02 05:13 -------

I run systemtap testsuites in cvs on both 2.6.9-37.ELhugemem and 2.6.9-36.EL
kernel version, it does not crash on both version, but my kernel configuration
is smp. maybe it will be useful if kernel configuration file is post in the
attachment.

------- Additional Comment #4 From William Cohen 2006-06-05 17:29 -------

Friday setup netdump to get better information about what is happening when the
system crashs. However, I haven't gotten a dump from the failure. Monday set up
a serial console on the machine to collect any console output.

------- Additional Comment #5 From William Cohen 2006-06-05 19:24 -------

The variable being locked is modlist_lock, which is a static variable only
visible within modules.c. It looks like a number of functions in module.c use
that lock.

Looking at the code in linux/include/linux/spinlock.h. The spin_lock_init() sets
the babble field to 5. This is decremented by _raw_spin_lock(), and when it
reaches 0 the message is printed out. However, there doesn't appear to be a
place where the field babble is ever reset. Does this mean 5 tries at the lock?

This is a UP kernel, so shouldn't the spinlocks be a no-op? Could voluntary
preemption be affecting things? The kernel was built with:

CONFIG_PREEMPT_VOLUNTARY=y

------- Additional Comment #6 From Ananth Mavinakayanahalli 2006-06-12 14:47 -------

I tried this script successfully on a 4-way x86 box running 2.6.9-39.ELsmp. I
used the systemtap snapshot from 10th June.

#!/bin/stap

probe kernel.function("scheduler_tick")
{
        printf("%s: %s (%d)\n", execname(), probefunc(), pid())
}

Will, would it be possible to share the exact testcase that failed?

------- Additional Comment #7 From Ananth Mavinakayanahalli 2006-06-12 14:55 -------

I just tried the same test booting a uni kernel on the machine. The test ran fine.
And yes, both kernels have CONFIG_PREEMPT_VOLUNTARY=y

------- Additional Comment #8 From William Cohen 2006-06-12 18:21 -------

The following probe caused the -39 kernel and the current snapshot (20060612)
systemtap to crash the system. It looks like there needs to be some load for
things to crash:

#!/bin/stap

probe kernel.function("scheduler_tick")
{
        printf("%s: %s (%d)\n", execname(), probefunc(), pid())
}

The tail end of the output from the instrumentation:

swapper: scheduler_tick (0)
login: scheduler_tick (4159)
swapper: scheduler_tick (0)
bash: scheduler_tick (4159)
bash: scheduler_tick (4159)
bash: scheduler_tick (4160)
id: scheduler_tick (4161)
bash: scheduler_tick (4160)
bash: scheduler_tick (4163)
swapper: scheduler_tick (0)
egrep: scheduler_tick (4163)
bash: scheduler_tick (4164)
egrep: scheduler_tick (4165)
egrep: scheduler_tick (4165)
bash: scheduler_tick (4167)
egrep: scheduler_tick (4167)
bash: scheduler_tick (4168)
egrep: scheduler_tick (4169)
bash: scheduler_tick (4170)
id: scheduler_tick (4171)
bash: scheduler_tick (4159)
hostname: scheduler_tick (4173)
bash: scheduler_tick (4159)


I got the following output on the console:


Kernel panic - not syncing: kernel/module.c:2114
Kernel panic - not syncing: kernel/module.c:2114: spin_lock(kernel/module.c:c034
Kernel panic - not syncing: kernel/module.c:2114: spin_lock(kernel/module.c:c034
Kernel panic - not syncing: kernel/module.c:2114: spin_lock(kernel/module.c:c034
Kernel panic - not syncing: kernel/module.c:2114: spin_lock(kernel/module.c:c034
Kernel panic - not syncing: kernel/module.c:2114: spin_lock(kernel/module.c:c034
Kernel panic - not syncing: kernel/module.c:2114: spin_lock(kernel/module.c:c034
Kernel panic - not syncing: kernel/module.c:2114: spin_lock(kernel/module.c:c034
Kernel panic - not syncing: kernel/module.c:2114: spin_lock(kernel/module.c:c034
Kernel panic - not syncing: kernel/module.c:2114: spin_lock(kernel/module.c:c034

Details about the system:

$ more /proc/cpuinfo
processor       : 0
vendor_id       : AuthenticAMD
cpu family      : 6
model           : 6
model name      : AMD Athlon(TM) XP 2000+
stepping        : 2
cpu MHz         : 1687.684
cache size      : 256 KB
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 1
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat
pse36 mmx fxsr sse syscall mmxext 3dnowext 3dnow
bogomips        : 3377.23

$ free
             total       used       free     shared    buffers     cached
Mem:        515612     129772     385840          0      25868      48924
-/+ buffers/cache:      54980     460632
Swap:      1020116          0    1020116

------- Additional Comment #9 From William Cohen 2006-06-12 18:41 -------

It seems that things work better under the -39.ELsmp version of the kernel. The
machine crashes consistently when running the instrumentation with the -39.EL
(UP) kernel, but doesn't crash with the equivalent SMP kernel.

------- Additional Comment #10 From Ananth Mavinakayanahalli 2006-06-13 07:06 -------

Created an attachment (id=1082)
C module probing scheduler_tick()

I've now tried today's systemtap snapshot with UNI and SMP .39 kernels while
simultaneously running:

1. A kernel build
2. The scheduler_tick script (with a timeout of 5 seconds) in a loop (to
simulate any issues with module loading/unloading)
3. The C module probing scheduler_tick() (attached to this bug)
4. The strace-open.stp example from the systemtap tutorial

I haven't been able to see a problem or any fatal errors in the dmesg (except:
ERROR: user string copy fault at 0x080c571a near identifier '$filename' at
/usr/local/share/systemtap/tapset/syscalls2.stp:27:25
when running the strace-open.stp).


[root@...]# cat /proc/cpuinfo
processor	: 0
vendor_id	: GenuineIntel
cpu family	: 15
model		: 2
model name	: Intel(R) Xeon(TM) CPU 2.80GHz
stepping	: 7
cpu MHz 	: 2795.658
cache size	: 512 KB
physical id	: 0
siblings	: 2
core id 	: 0
cpu cores	: 1
fdiv_bug	: no
hlt_bug 	: no
f00f_bug	: no
coma_bug	: no
fpu		: yes
fpu_exception	: yes
cpuid level	: 2
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat
pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe cid xtpr
bogomips	: 5591.89

Will, could you please try recreating the problem with the plain C module?

------- Additional Comment #11 From William Cohen 2006-06-13 22:59 -------

Trying the test Ananth suggested. The new c code work, but the
previous schduler_tick.stp still crashes the -39.EL UP kernel. This
was using the following version of stap on a RHEL4U3 machine:


$ stap -V
SystemTap translator/driver (version 0.5.7 built 2006-06-12)
(Using Red Hat elfutils 0.120 libraries.)
Copyright (C) 2005-2006 Red Hat, Inc. and others
This is free software; see the source for copying conditions.

Ther was some output on the console for the C code.

For 2.6.9-39.ELsmp	kpmod3.ko:

registered kprobe3
kprobe unregistered3
0:      count_pre = 13089       count_post = 13089
[...UP machine so rest are 0...]


For 2.6.9-39.EL		kpmod3.ko:

registered kprobe3
kprobe unregistered3
0:      count_pre = 47884       count_post = 47884

------- Additional Comment #12 From William Cohen 2006-06-15 19:36 -------

Created an attachment (id=1095)
even simpler example that cause crash.

In an effort to further simplify the example found that an empty probe on
schedule_tick function will cause the same failure.

------- Additional Comment #13 From William Cohen 2006-06-15 19:51 -------

Set up old dual procesor penium III machine with RHEL4U4 snapshot. Ran with the
scheduler_tick.stp Got the same message,

Kernel panic - not syncing: kernel/module.c:2114:
spin_lock(kernel/module.c:c036280) already locked by kernel/module.c/2114.

Looking through the configuration of the kernel:

CONFIG_DEBUG_SPINLOCK=y
CONFIG_DEBUG_SPINLOCK_SLEEP=y

the actual message looks like it is coming from one of the messages in
include/linux/spinlock.h

------- Additional Comment #14 From Ananth Mavinakayanahalli 2006-06-16 10:11 -------

Created an attachment (id=1096)
systemtap generated files for scheduler_tick5.stp on a successful run

Still no luck trying to recreate the problem. Will's scheduler_tick5.stp also
runs just fine. I am now suspecting this behaviour *may* be something to do
with the module load/unload infrastructure/races therein.

FYR, I am attaching tarballs of the systemtap generated directory for the test.

------- Additional Comment #15 From Ananth Mavinakayanahalli 2006-06-16 10:47 -------

Created an attachment (id=1097)
ps aux output indicating systemtap tasks in interruptible sleep states

Sometime between the 3 June and 10 June snapshots, a patch has sneaked in to
systemtap that causes the systemtap tasks to hang around in interruptible sleep
states, long after the test has been terminated. Attached here is the ps aux
output indicating this. I'll attach a sysrq-t output in a subsequent
attachment.

I am not certain if this has something to do with the problem being
investigated on this bug though.

------- Additional Comment #16 From Ananth Mavinakayanahalli 2006-06-16 10:52 -------

Created an attachment (id=1098)
sysrq-t output indicating the wait states of systemtap tasks

This behaviour is not restricted to RHEL4. I've observed the same on a FC5 box.

------- Additional Comment #17 From Martin Hunt 2006-06-16 15:33 -------

Subject: Re:  systemtap.base/probefunc.exp crash in
	kernel/module.c:2114 on RHEL4

On Fri, 2006-06-16 at 10:47 +0000, ananth at in dot ibm dot com wrote:
> ------- Additional Comments From ananth at in dot ibm dot com  2006-06-16 10:47 -------
> Created an attachment (id=1097)
>  --> (http://sourceware.org/bugzilla/attachment.cgi?id=1097&action=view)
> ps aux output indicating systemtap tasks in interruptible sleep states
> 
> Sometime between the 3 June and 10 June snapshots, a patch has sneaked in to
> systemtap that causes the systemtap tasks to hang around in interruptible sleep
> states, long after the test has been terminated. Attached here is the ps aux
> output indicating this. I'll attach a sysrq-t output in a subsequent
> attachment.
> 
> I am not certain if this has something to do with the problem being
> investigated on this bug though.

AFAIK, that problem existed only over this last weekend.  Is this
current code?

------- Additional Comment #18 From William Cohen 2006-06-16 19:58 -------

Created an attachment (id=1099)
difference between ananth's and will's translator generated code.

The attached differences are so similar in the C code generated by the stap
translator that it looks unlikely that this is due to a problem in the
translator or the runtimes. One noticeable difference is is the address of the
probe:

-static struct kprobe dwarf_kprobe_probe_606[1]= {
-  {.addr= (void *) 0xc011e3b5}
+static struct kprobe dwarf_kprobe_probe_610[1]= {
+  {.addr= (void *) 0xc011fba5}

Given that this is a function in the kernel and not a module these addresses
should be the same. The kernel used on the problem system is the following:

$ uname -a
Linux slingshot.devel.redhat.com 2.6.9-39.EL #1 Thu Jun 1 17:47:24 EDT 2006
i686 athlon i386 GNU/Linux

------- Additional Comment #19 From Frank Ch. Eigler 2006-06-16 20:04 -------

"stap -vvv -p2" should go some way toward explaining the probe address
differences.  Perhaps there is a kernel vs debuginfo version or arch mismatch.

------- Additional Comment #20 From William Cohen 2006-06-16 20:29 -------

The sysrq-t.out explains the difference in probe addresses. First line of the
sysrq-t.out:

Linux version 2.6.9-39.ELsmp (root@x345b.in.ibm.com) (gcc version 3.4.5 20051201
(Red Hat 3.4.5-2)) #1 SMP Mon Jun 12 15:19:18 IST 2006

This is the smp kernel which hasn't exhibited the problem behavior.

------- Additional Comment #21 From Chuck Ebbert 2006-06-19 06:34 -------

Could someone post the source for the function containing line 2114
in module.c?  From looking at 2.6.17, it should be in either
module_text_address() or search_module_extables()

------- Additional Comment #22 From Ananth Mavinakayanahalli 2006-06-19 07:18 -------

Yes, line 2114 falls in search_module_extables(). The routine in rhel matches
upstream and 2114 corresponds to:

...
  2110          unsigned long flags;
  2111          const struct exception_table_entry *e = NULL;
  2112          struct module *mod;
  2113
  2114          spin_lock_irqsave(&modlist_lock, flags);
  2115          list_for_each_entry(mod, &modules, list) {
  2116                  if (mod->num_exentries == 0)
  2117                          continue;
...

------- Additional Comment #23 From Ananth Mavinakayanahalli 2006-06-19 09:22 -------

(In reply to comment #17)
> 
> AFAIK, that problem existed only over this last weekend.  Is this
> current code?

Martin, I tried with the current snapshot. The problem no longer exists.

As an aside, I've tried Will's testcase on another Pentium 4 box running
RHEL4-U4 (both 2.6.9-39.EL and 2.6.9-39.ELsmp). Runs without any errors.

------- Additional Comment #24 From Chuck Ebbert 2006-06-20 06:50 -------

I think this is what is happening:

  http://lkml.org/lkml/2006/6/19/106

but nobody responded to that on LKML.

------- Additional Comment #25 From William Cohen 2006-10-12 15:30 -------

The simple test function scheduler_tick5.stp still crashes the 2.6.9-42.0.3.EL
kernel on a i686 (athlon) RHEL4 machine.

------- Additional Comment #26 From Jeff Layton 2006-11-08 17:35 -------

The kernel patch suggested in Chuck's LKML post (comment #24) does seem to fix
this. The question I guess at this point is whether that's indicative of a real
kernel bug, or that stap is doing something wrong here.

I'm not clear enough on the exception tables to know either way.

------- Additional Comment #27 From William Cohen 2007-01-16 16:57 -------

Created an attachment (id=1503)
schedule_tick5.stp code generated by systemtap-0.5.8-1.EL4

Code the crashes with kernel.

------- Additional Comment #28 From William Cohen 2007-01-16 16:58 -------

Created an attachment (id=1504)
code for schedule_tick5.stp generated by systemtap snapshot checked out
20070116

------- Additional Comment #29 From William Cohen 2007-01-16 17:00 -------

The current snapshot of systemtap is not crashing on scheduler_tick5.stp. The
code generated by the older systemtap insalled on the system,
systemtap-0.5.8-1.EL4, crashes. The output of the each of the version have been
attached to the bug.

------- Additional Comment #30 From William Cohen 2007-03-01 21:24 -------

I tried running scheduler_tick5.stp RHEL4 machine with Kernel 2.6.9-42.0.10.EL
on an i686. The machine stayed up and did not crash. The script was compiled
using a cvs checkout from  200702280930. The following script also ran fine
under load (rebuilding systemtap object code):

#!/bin/stap

probe kernel.function("scheduler_tick")
{
        printf("%s: %s (%d)\n", execname(), probefunc(), pid())
}

------- Additional Comment #31 From Nicolas Fabre 2007-05-01 10:34 -------

Hi,
I've got this kernel panic on a server :
Kernel panic - not sync: kernel/module.c:2114:
spin_lock(kernel/module.c:c036b280) already locked by kernel/module.c:2114.

Find here some first informations :

[root@localhost ~]# uname -a
Linux localhost.localdomain 2.6.9-42.EL #1 Sat Aug 12 09:17:58 CDT 2006 i686
i686 i386 GNU/Linux
[root@localhost ~]# more /proc/cpuinfo
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 15
model           : 1
model name      : Intel(R) Pentium(R) 4 CPU 1.60GHz
stepping        : 2
cpu MHz         : 1595.623
cache size      : 256 KB
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 2
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic mtrr pge mca cmov pat
pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm
bogomips        : 3192.16


What other informations do you need to investigate on this bug ?

Regards,
Nicolas

------- Additional Comment #32 From Frank Ch. Eigler 2007-05-01 13:51 -------

> Kernel panic - not sync: kernel/module.c:2114:
> spin_lock(kernel/module.c:c036b280) already locked by kernel/module.c:2114.

This sounds like an old kernel problem related to searching modules for
exception handling data.  The patch for that was in limbo IIRC.  Can someone
find e.g. the LKML discussion?  Google is failing me (gasp!).

> Find here some first informations :
> What other informations do you need to investigate on this bug ?

http://sourceware.org/systemtap/wiki/HowToReportBugs

------- Additional Comment #33 From Ananth Mavinakayanahalli 2007-06-22 11:49 -------

Will,

Could you please see if you can get more debug information by recreating this
bug on a kernel with lockdep enabled? It surely looks like a deadlock from the
panic messages from the various recreates.

Ananth

------- Additional Comment #34 From William Cohen 2007-06-22 15:17 -------

The RHEL4 kernels do not have lockdep option. I am running things with an SMP
2.6.22-rc5 kernel that does have lockdep enabled to see if I can get a similar
failure form "make installcheck".