inconsistent lock state with tick_broadcast_lock

inconsistent lock state with tick_broadcast_lock

[Sudeep Holla]

Hi Thomas/Rafael,

With latest mainline(commit 27cf3a16b2535a490f8cf1d29a6634f1c70f7831),
and lockdep enabled I see the following inconsistent lock state log.
I am not sure if it's related to recent changes in tick-broadcast or I
might be missing any config ?

=================================
[ INFO: inconsistent lock state ]
4.0.0 #260 Not tainted
---------------------------------
inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
swapper/1/0 [HC0[0]:SC0[0]:HE1:SE1] takes:
  (tick_broadcast_lock){?.-...}, at: [<c0081401>] 
tick_broadcast_oneshot_control+0x45/0x1ec
{IN-HARDIRQ-W} state was registered at:
   [<c051b4d3>] _raw_spin_lock+0x23/0x30
   [<c0081b43>] tick_broadcast_control+0x3f/0x108
   [<c0086483>] flush_smp_call_function_queue+0x57/0x108
   [<c0013897>] handle_IPI+0xcb/0x194
   [<c000932b>] gic_handle_irq+0x4f/0x50
   [<c0011eff>] __irq_svc+0x3f/0x64
   [<c00fa97a>] do_execveat_common+0x96/0x690
   [<c00fa97a>] do_execveat_common+0x96/0x690
   [<c00faf91>] do_execve+0x1d/0x20
   [<c0030d23>] ____call_usermodehelper+0xf3/0x124
   [<c000e7b9>] ret_from_fork+0x11/0x38
irq event stamp: 19215
hardirqs last  enabled at (19215): [<c0011f03>] __irq_svc+0x43/0x64
hardirqs last disabled at (19213): [<c0024cbd>] __do_softirq+0x1d1/0x2d0
softirqs last  enabled at (19214): [<c0024d29>] __do_softirq+0x23d/0x2d0
softirqs last disabled at (19195): [<c00250bf>] irq_exit+0xef/0x15c

other info that might help us debug this:
  Possible unsafe locking scenario:

        CPU0
        ----
   lock(tick_broadcast_lock);
   <Interrupt>
     lock(tick_broadcast_lock);

  *** DEADLOCK ***

no locks held by swapper/1/0.

stack backtrace:
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.0.0 #260
Hardware name: ARM-Versatile Express
[<c0014b1d>] (unwind_backtrace) from [<c0011659>] (show_stack+0x11/0x14)
[<c0011659>] (show_stack) from [<c05168b9>] (dump_stack+0x6d/0x78)
[<c05168b9>] (dump_stack) from [<c0057519>] (print_usage_bug+0x1d9/0x260)
[<c0057519>] (print_usage_bug) from [<c0057713>] (mark_lock+0x173/0x5d0)
[<c0057713>] (mark_lock) from [<c005864d>] (__lock_acquire+0x699/0x19ec)
[<c005864d>] (__lock_acquire) from [<c005a0f9>] (lock_acquire+0x79/0xe8)
[<c005a0f9>] (lock_acquire) from [<c051b4d3>] (_raw_spin_lock+0x23/0x30)
[<c051b4d3>] (_raw_spin_lock) from [<c0081401>] 
(tick_broadcast_oneshot_control+0x45/0x1ec)
[<c0081401>] (tick_broadcast_oneshot_control) from [<c0050273>] 
(cpu_startup_entry+0x2c3/0x2f8)
[<c0050273>] (cpu_startup_entry) from [<800093d1>] (0x800093d1)


Also with CPUIdle enabled, the system has spinlock lockup as below:

BUG: spinlock lockup suspected on CPU#0, swapper/0/0
  lock: tick_broadcast_lock+0x0/0x40, .magic: dead4ead, .owner: 
swapper/0/0, .owner_cpu: 0
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.0.0 #1
Hardware name: ARM-Versatile Express
[<c0014b1d>] (unwind_backtrace) from [<c0011659>] (show_stack+0x11/0x14)
[<c0011659>] (show_stack) from [<c05168b9>] (dump_stack+0x6d/0x78)
[<c05168b9>] (dump_stack) from [<c005c897>] (do_raw_spin_lock+0xc3/0x144)
[<c005c897>] (do_raw_spin_lock) from [<c00811f1>] 
(tick_handle_oneshot_broadcast+0x25/0x164)
[<c00811f1>] (tick_handle_oneshot_broadcast) from [<c001dd21>] 
(sp804_timer_interrupt+0x31/0x34)
[<c001dd21>] (sp804_timer_interrupt) from [<c0067ed9>] 
(handle_irq_event_percpu+0x45/0x154)
[<c0067ed9>] (handle_irq_event_percpu) from [<c0068017>] 
(handle_irq_event+0x2f/0x44)
[<c0068017>] (handle_irq_event) from [<c0069ed3>] 
(handle_fasteoi_irq+0x6f/0xf0)
[<c0069ed3>] (handle_fasteoi_irq) from [<c00677bf>] 
(generic_handle_irq+0x23/0x2c)
[<c00677bf>] (generic_handle_irq) from [<c0067a05>] 
(__handle_domain_irq+0x45/0x84)
[<c0067a05>] (__handle_domain_irq) from [<c0009303>] 
(gic_handle_irq+0x27/0x50)
[<c0009303>] (gic_handle_irq) from [<c0011eff>] (__irq_svc+0x3f/0x64)
Exception stack(0xc07e7ee0 to 0xc07e7f28)
7ee0: 00000000 00000001 00000000 00000000 c07ed938 c07f6e10 c0081431 
60000153
7f00: 00000001 c0865a80 c07e7f88 c051dfc8 00000000 c07e7f28 c005a40b 
c005a466
7f20: 60000173 ffffffff
[<c0011eff>] (__irq_svc) from [<c005a466>] (lock_release+0xaa/0x1c4)
[<c005a466>] (lock_release) from [<c051b679>] (_raw_spin_unlock+0x15/0x1c)
[<c051b679>] (_raw_spin_unlock) from [<c0081431>] 
(tick_broadcast_oneshot_control+0x75/0x1ec)
[<c0081431>] (tick_broadcast_oneshot_control) from [<c0050273>] 
(cpu_startup_entry+0x2c3/0x2f8)
[<c0050273>] (cpu_startup_entry) from [<c077ea47>] 
(start_kernel+0x327/0x330)

Regards,
Sudeep

Re: inconsistent lock state with tick_broadcast_lock

[Thomas Gleixner]

On Thu, 23 Apr 2015, Sudeep Holla wrote:

> Hi Thomas/Rafael,
> 
> With latest mainline(commit 27cf3a16b2535a490f8cf1d29a6634f1c70f7831),
> and lockdep enabled I see the following inconsistent lock state log.
> I am not sure if it's related to recent changes in tick-broadcast or I
> might be missing any config ?

It's surely not the config.
 
> inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.

> [<c0014b1d>] (unwind_backtrace) from [<c0011659>] (show_stack+0x11/0x14)
> [<c0011659>] (show_stack) from [<c05168b9>] (dump_stack+0x6d/0x78)
> [<c05168b9>] (dump_stack) from [<c0057519>] (print_usage_bug+0x1d9/0x260)
> [<c0057519>] (print_usage_bug) from [<c0057713>] (mark_lock+0x173/0x5d0)
> [<c0057713>] (mark_lock) from [<c005864d>] (__lock_acquire+0x699/0x19ec)
> [<c005864d>] (__lock_acquire) from [<c005a0f9>] (lock_acquire+0x79/0xe8)
> [<c005a0f9>] (lock_acquire) from [<c051b4d3>] (_raw_spin_lock+0x23/0x30)
> [<c051b4d3>] (_raw_spin_lock) from [<c0081401>]
> (tick_broadcast_oneshot_control+0x45/0x1ec)
> [<c0081401>] (tick_broadcast_oneshot_control) from [<c0050273>]
> (cpu_startup_entry+0x2c3/0x2f8)
> [<c0050273>] (cpu_startup_entry) from [<800093d1>] (0x800093d1)

So tick_broadcast_oneshot_control is called from cpu_startup_entry
with interrupts enabled. That's from the guts of the idle loop. So
something in the idle magic enables interrupts where it should not.
 
> Also with CPUIdle enabled, the system has spinlock lockup as below:
> 
> BUG: spinlock lockup suspected on CPU#0, swapper/0/0
>  lock: tick_broadcast_lock+0x0/0x40, .magic: dead4ead, .owner: swapper/0/0,
> .owner_cpu: 0
> CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.0.0 #1
> Hardware name: ARM-Versatile Express
> [<c0014b1d>] (unwind_backtrace) from [<c0011659>] (show_stack+0x11/0x14)
> [<c0011659>] (show_stack) from [<c05168b9>] (dump_stack+0x6d/0x78)
> [<c05168b9>] (dump_stack) from [<c005c897>] (do_raw_spin_lock+0xc3/0x144)
> [<c005c897>] (do_raw_spin_lock) from [<c00811f1>]
> (tick_handle_oneshot_broadcast+0x25/0x164)
> [<c00811f1>] (tick_handle_oneshot_broadcast) from [<c001dd21>]
> (sp804_timer_interrupt+0x31/0x34)
> [<c001dd21>] (sp804_timer_interrupt) from [<c0067ed9>]
> (handle_irq_event_percpu+0x45/0x154)
> [<c0067ed9>] (handle_irq_event_percpu) from [<c0068017>]
> (handle_irq_event+0x2f/0x44)
> [<c0068017>] (handle_irq_event) from [<c0069ed3>]
> (handle_fasteoi_irq+0x6f/0xf0)
> [<c0069ed3>] (handle_fasteoi_irq) from [<c00677bf>]
> (generic_handle_irq+0x23/0x2c)
> [<c00677bf>] (generic_handle_irq) from [<c0067a05>]
> (__handle_domain_irq+0x45/0x84)
> [<c0067a05>] (__handle_domain_irq) from [<c0009303>]
> (gic_handle_irq+0x27/0x50)
> [<c0009303>] (gic_handle_irq) from [<c0011eff>] (__irq_svc+0x3f/0x64)
> Exception stack(0xc07e7ee0 to 0xc07e7f28)
> 7ee0: 00000000 00000001 00000000 00000000 c07ed938 c07f6e10 c0081431 60000153
> 7f00: 00000001 c0865a80 c07e7f88 c051dfc8 00000000 c07e7f28 c005a40b c005a466
> 7f20: 60000173 ffffffff
> [<c0011eff>] (__irq_svc) from [<c005a466>] (lock_release+0xaa/0x1c4)
> [<c005a466>] (lock_release) from [<c051b679>] (_raw_spin_unlock+0x15/0x1c)
> [<c051b679>] (_raw_spin_unlock) from [<c0081431>]
> (tick_broadcast_oneshot_control+0x75/0x1ec)
> [<c0081431>] (tick_broadcast_oneshot_control) from [<c0050273>]
> (cpu_startup_entry+0x2c3/0x2f8)
> [<c0050273>] (cpu_startup_entry) from [<c077ea47>] (start_kernel+0x327/0x330)

Which is exactly the lockup which lockdep warned about ....

Thanks,

	tglx