Hi Ingo,
Below is a snippet from the bootup log, and attached .config
Let me know if there is anything else you need.
Enjoy,
Sven
lockdep says:
---------%<-----------
NET: Registered protocol family 2
IP route cache hash table entries: 131072 (order: 8, 1048576 bytes)
TCP established hash table entries: 16384 (order: 9, 3014656 bytes)
TCP bind hash table entries: 16384 (order: 9, 2883584 bytes)
TCP: Hash tables configured (established 16384 bind 16384)
TCP reno registered
checking if image is initramfs... it is
Freeing initrd memory: 7629k freed
stopped custom tracer.
=========================================================
[ INFO: possible irq lock inversion dependency detected ]
[ 2.6.21-rt6-smp-rt-debug #3
---------------------------------------------------------
swapper/1 just changed the state of lock:
(rtc_lock#2){-...}, at: [<ffffffff8085b185>] sbf_init+0x25/0xe0
but this lock was taken by another, hard-irq-safe lock in the past:
(xtime_lock){+...}
and interrupts could create inverse lock ordering between them.
other info that might help us debug this:
no locks held by swapper/1.
the first lock's dependencies:
-> (rtc_lock#2){-...} ops: 2 {
initial-use at:
[<ffffffff8025d383>] mark_lock+0xf3/0x5b0
[<ffffffff8025e6f4>] __lock_acquire+0x664/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047e2c5>] rt_spin_lock+0x35/0x40
[<ffffffff8020e162>] read_persistent_clock+0x22/0x1b0
[<ffffffff80867e86>] timekeeping_init+0x86/0x100
[<ffffffff808537af>] start_kernel+0x1bf/0x350
[<ffffffff80853179>] _sinittext+0x179/0x180
[<ffffffffffffffff>] 0xffffffffffffffff
hardirq-on-W at:
[<ffffffff8025d383>] mark_lock+0xf3/0x5b0
[<ffffffff8025e6b4>] __lock_acquire+0x624/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047e2c5>] rt_spin_lock+0x35/0x40
[<ffffffff8085b185>] sbf_init+0x25/0xe0
[<ffffffff80853b28>] init+0x1e8/0x490
[<ffffffff8020b248>] child_rip+0xa/0x12
[<ffffffffffffffff>] 0xffffffffffffffff
}
... key at: [<ffffffff8066b110>] rtc_lock+0x90/0x100
the second lock's dependencies:
-> (xtime_lock){+...} ops: 11343 {
initial-use at:
[<ffffffff8025d383>] mark_lock+0xf3/0x5b0
[<ffffffff8025e6f4>] __lock_acquire+0x664/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047eb24>] __spin_lock+0x34/0x50
[<ffffffff80867e21>] timekeeping_init+0x21/0x100
[<ffffffff808537af>] start_kernel+0x1bf/0x350
[<ffffffff80853179>] _sinittext+0x179/0x180
[<ffffffffffffffff>] 0xffffffffffffffff
in-hardirq-W at:
[<ffffffff8025d383>] mark_lock+0xf3/0x5b0
[<ffffffff8025e631>] __lock_acquire+0x5a1/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047eb24>] __spin_lock+0x34/0x50
[<ffffffff80259e2d>] tick_periodic+0x1d/0x80
[<ffffffff80259eb4>] tick_handle_periodic+0x24/0x80
[<ffffffff8020dee6>] timer_interrupt+0x16/0x20
[<ffffffff80288059>] handle_IRQ_event+0x69/0x110
[<ffffffff8028a52d>] handle_level_irq+0xed/0x150
[<ffffffff8020d139>] do_IRQ+0x149/0x1d0
[<ffffffff8020a8d6>] ret_from_intr+0x0/0xf
[<ffffffff80872fe0>] console_init+0x0/0x50
[<ffffffff808537e0>] start_kernel+0x1f0/0x350
[<ffffffff80853179>] _sinittext+0x179/0x180
[<ffffffffffffffff>] 0xffffffffffffffff
}
... key at: [<ffffffff806786a0>] xtime_lock+0x20/0x80
-> (clocksource_lock){....} ops: 5098 {
initial-use at:
[<ffffffff8025d383>] mark_lock+0xf3/0x5b0
[<ffffffff8025e6f4>] __lock_acquire+0x664/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047eee5>] __spin_lock_irqsave+0x45/0x60
[<ffffffff802582a5>] clocksource_get_next+0x15/0x60
[<ffffffff80867e32>] timekeeping_init+0x32/0x100
[<ffffffff808537af>] start_kernel+0x1bf/0x350
[<ffffffff80853179>] _sinittext+0x179/0x180
[<ffffffffffffffff>] 0xffffffffffffffff
}
... key at: [<ffffffff80678b18>] clocksource_lock+0x18/0x80
... acquired at:
[<ffffffff8025bdc4>] add_lock_to_list+0xa4/0xe0
[<ffffffff8025ed67>] __lock_acquire+0xcd7/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047eee5>] __spin_lock_irqsave+0x45/0x60
[<ffffffff802582a5>] clocksource_get_next+0x15/0x60
[<ffffffff80867e32>] timekeeping_init+0x32/0x100
[<ffffffff808537af>] start_kernel+0x1bf/0x350
[<ffffffff80853179>] _sinittext+0x179/0x180
[<ffffffffffffffff>] 0xffffffffffffffff
-> (rtc_lock){....} ops: 3 {
initial-use at:
[<ffffffff8025d383>] mark_lock+0xf3/0x5b0
[<ffffffff8025e6f4>] __lock_acquire+0x664/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047eee5>] __spin_lock_irqsave+0x45/0x60
[<ffffffff8047d608>] rt_spin_lock_slowlock+0x38/0x210
[<ffffffff8047e2a6>] rt_spin_lock+0x16/0x40
[<ffffffff8020e162>] read_persistent_clock+0x22/0x1b0
[<ffffffff80867e86>] timekeeping_init+0x86/0x100
[<ffffffff808537af>] start_kernel+0x1bf/0x350
[<ffffffff80853179>] _sinittext+0x179/0x180
[<ffffffffffffffff>] 0xffffffffffffffff
}
... key at: [<ffffffff8066b098>] rtc_lock+0x18/0x100
... acquired at:
[<ffffffff8025bdc4>] add_lock_to_list+0xa4/0xe0
[<ffffffff8025ed67>] __lock_acquire+0xcd7/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047eee5>] __spin_lock_irqsave+0x45/0x60
[<ffffffff8047d608>] rt_spin_lock_slowlock+0x38/0x210
[<ffffffff8047e2a6>] rt_spin_lock+0x16/0x40
[<ffffffff8020e162>] read_persistent_clock+0x22/0x1b0
[<ffffffff80867e86>] timekeeping_init+0x86/0x100
[<ffffffff808537af>] start_kernel+0x1bf/0x350
[<ffffffff80853179>] _sinittext+0x179/0x180
[<ffffffffffffffff>] 0xffffffffffffffff
-> (rtc_lock#2){-...} ops: 2 {
initial-use at:
[<ffffffff8025d383>] mark_lock+0xf3/0x5b0
[<ffffffff8025e6f4>] __lock_acquire+0x664/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047e2c5>] rt_spin_lock+0x35/0x40
[<ffffffff8020e162>] read_persistent_clock+0x22/0x1b0
[<ffffffff80867e86>] timekeeping_init+0x86/0x100
[<ffffffff808537af>] start_kernel+0x1bf/0x350
[<ffffffff80853179>] _sinittext+0x179/0x180
[<ffffffffffffffff>] 0xffffffffffffffff
hardirq-on-W at:
[<ffffffff8025d383>] mark_lock+0xf3/0x5b0
[<ffffffff8025e6b4>] __lock_acquire+0x624/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047e2c5>] rt_spin_lock+0x35/0x40
[<ffffffff8085b185>] sbf_init+0x25/0xe0
[<ffffffff80853b28>] init+0x1e8/0x490
[<ffffffff8020b248>] child_rip+0xa/0x12
[<ffffffffffffffff>] 0xffffffffffffffff
}
... key at: [<ffffffff8066b110>] rtc_lock+0x90/0x100
... acquired at:
[<ffffffff8025bdc4>] add_lock_to_list+0xa4/0xe0
[<ffffffff8025ed67>] __lock_acquire+0xcd7/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047e2c5>] rt_spin_lock+0x35/0x40
[<ffffffff8020e162>] read_persistent_clock+0x22/0x1b0
[<ffffffff80867e86>] timekeeping_init+0x86/0x100
[<ffffffff808537af>] start_kernel+0x1bf/0x350
[<ffffffff80853179>] _sinittext+0x179/0x180
[<ffffffffffffffff>] 0xffffffffffffffff
-> (__vsyscall_gtod_data.lock){....} ops: 5093 {
initial-use at:
[<ffffffff8025d383>] mark_lock+0xf3/0x5b0
[<ffffffff8025e6f4>] __lock_acquire+0x664/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047eb24>] __spin_lock+0x34/0x50
[<ffffffff8021108d>] update_vsyscall+0x2d/0x180
[<ffffffff80245fbb>] run_timer_softirq+0x43b/0x850
[<ffffffff80241ca2>] ksoftirqd+0x182/0x2a0
[<ffffffff802529f4>] kthread+0xf4/0x130
[<ffffffff8020b248>] child_rip+0xa/0x12
[<ffffffffffffffff>] 0xffffffffffffffff
}
... key at: [<ffffffff80849220>] sysctl_unix_max_dgram_qlen+0xbe0/0x19c0
... acquired at:
[<ffffffff8025bdc4>] add_lock_to_list+0xa4/0xe0
[<ffffffff8025ed67>] __lock_acquire+0xcd7/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047eb24>] __spin_lock+0x34/0x50
[<ffffffff8021108d>] update_vsyscall+0x2d/0x180
[<ffffffff80245fbb>] run_timer_softirq+0x43b/0x850
[<ffffffff80241ca2>] ksoftirqd+0x182/0x2a0
[<ffffffff802529f4>] kthread+0xf4/0x130
[<ffffffff8020b248>] child_rip+0xa/0x12
[<ffffffffffffffff>] 0xffffffffffffffff
stack backtrace:
Call Trace:
[<ffffffff8020b936>] dump_trace+0xc6/0x380
[<ffffffff8020bc3d>] show_trace+0x4d/0x80
[<ffffffff8020bc8a>] dump_stack+0x1a/0x20
[<ffffffff8025ca71>] print_irq_inversion_bug+0x141/0x160
[<ffffffff8025d14f>] check_usage_backwards+0x4f/0x60
[<ffffffff8025d591>] mark_lock+0x301/0x5b0
[<ffffffff8025e6b4>] __lock_acquire+0x624/0xf80
[<ffffffff8025f098>] lock_acquire+0x88/0xc0
[<ffffffff8047e2c5>] rt_spin_lock+0x35/0x40
[<ffffffff8085b185>] sbf_init+0x25/0xe0
[<ffffffff80853b28>] init+0x1e8/0x490
[<ffffffff8020b248>] child_rip+0xa/0x12
INFO: lockdep is turned off.
---------------------------
| preempt count: 00000000 ]
| 0-level deep critical section nesting:
----------------------------------------
Simple Boot Flag at 0x7a set to 0x1
Registering sysdev class '<NULL>'
Registering sys device 'i82370'
------------%<-------------------
cat /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 15
model name : Intel(R) Xeon(R) CPU 5130 @ 2.00GHz
stepping : 6
cpu MHz : 1995.000
cache size : 4096 KB
physical id : 0
siblings : 2
core id : 0
cpu cores : 2
fpu : yes
fpu_exception : yes
cpuid level : 10
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmovm
bogomips : 3993.06
clflush size : 64
cache_alignment : 64
address sizes : 36 bits physical, 48 bits virtual
power management:
processor : 1
vendor_id : GenuineIntel
cpu family : 6
model : 15
model name : Intel(R) Xeon(R) CPU 5130 @ 2.00GHz
stepping : 6
cpu MHz : 1995.000
cache size : 4096 KB
physical id : 3
siblings : 2
core id : 0
cpu cores : 2
fpu : yes
fpu_exception : yes
cpuid level : 10
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmovm
bogomips : 3990.04
clflush size : 64
cache_alignment : 64
address sizes : 36 bits physical, 48 bits virtual
power management:
processor : 2
vendor_id : GenuineIntel
cpu family : 6
model : 15
model name : Intel(R) Xeon(R) CPU 5130 @ 2.00GHz
stepping : 6
cpu MHz : 1995.000
cache size : 4096 KB
physical id : 0
siblings : 2
core id : 1
cpu cores : 2
fpu : yes
fpu_exception : yes
cpuid level : 10
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmovm
bogomips : 3990.04
clflush size : 64
cache_alignment : 64
address sizes : 36 bits physical, 48 bits virtual
power management:
processor : 3
vendor_id : GenuineIntel
cpu family : 6
model : 15
model name : Intel(R) Xeon(R) CPU 5130 @ 2.00GHz
stepping : 6
cpu MHz : 1995.000
cache size : 4096 KB
physical id : 3
siblings : 2
core id : 1
cpu cores : 2
fpu : yes
fpu_exception : yes
cpuid level : 10
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmovm
bogomips : 3990.04
clflush size : 64
cache_alignment : 64
address sizes : 36 bits physical, 48 bits virtual
power management:
On Tue, 2007-05-22 at 17:19 -0700, Sven-Thorsten Dietrich wrote:
> swapper/1 just changed the state of lock:
> (rtc_lock#2){-...}, at: [<ffffffff8085b185>] sbf_init+0x25/0xe0
> but this lock was taken by another, hard-irq-safe lock in the past:
> (xtime_lock){+...}
>
> and interrupts could create inverse lock ordering between them.
>
>
> other info that might help us debug this:
> no locks held by swapper/1.
>
> the first lock's dependencies:
> -> (rtc_lock#2){-...} ops: 2 {
> initial-use at:
> [<ffffffff8025d383>] mark_lock+0xf3/0x5b0
> [<ffffffff8025e6f4>] __lock_acquire+0x664/0xf80
> [<ffffffff8025f098>] lock_acquire+0x88/0xc0
> [<ffffffff8047e2c5>] rt_spin_lock+0x35/0x40
> [<ffffffff8020e162>] read_persistent_clock+0x22/0x1b0
> [<ffffffff80867e86>] timekeeping_init+0x86/0x100
> [<ffffffff808537af>] start_kernel+0x1bf/0x350
> [<ffffffff80853179>] _sinittext+0x179/0x180
> [<ffffffffffffffff>] 0xffffffffffffffff
Hmm. That's the code in question:
void __init timekeeping_init(void)
{
unsigned long flags;
unsigned long sec = read_persistent_clock();
write_seqlock_irqsave(&xtime_lock, flags);
The rtc_lock is never taken inside the xtime_lock.
Looks like code reordering due to gcc extra magic. Which compiler ?
Thanks,
tglx
* Thomas Gleixner <[email protected]> wrote:
> Hmm. That's the code in question:
>
> void __init timekeeping_init(void)
> {
> unsigned long flags;
> unsigned long sec = read_persistent_clock();
>
> write_seqlock_irqsave(&xtime_lock, flags);
>
> The rtc_lock is never taken inside the xtime_lock.
>
> Looks like code reordering due to gcc extra magic. Which compiler ?
i dont think it's due to code reordering. The code that lockdep flagged
is the new code in arch/i386/kernel/bootflag.c, sbf_read() and
sbf_write(). It does:
spin_lock_irqsave(&rtc_lock, flags);
CMOS_WRITE(v, sbf_port);
spin_unlock_irqrestore(&rtc_lock, flags);
and:
spin_lock_irqsave(&rtc_lock, flags);
v = CMOS_READ(sbf_port);
spin_unlock_irqrestore(&rtc_lock, flags);
and is apparently called with the xtime_lock held. Was that code ever
booted with CONFIG_PROVE_LOCKING enabled?
Ingo