Re: [lkp-robot] [sched/fair] fbd5188493: WARNING:inconsistent_lock_state

[Dietmar Eggemann]

Hi,

On 07/05/2018 10:02 AM, kernel test robot wrote:
> 
> FYI, we noticed the following commit (built with gcc-7):
> 
> commit: fbd51884933192c9cada60628892024495942482 ("[PATCH] sched/fair: Avoid divide by zero when rebalancing domains")
> url: https://github.com/0day-ci/linux/commits/Matt-Fleming/sched-fair-Avoid-divide-by-zero-when-rebalancing-domains/20180705-024633
> 
> 
> in testcase: trinity
> with following parameters:
> 
> 	runtime: 300s
> 
> test-description: Trinity is a linux system call fuzz tester.
> test-url: http://codemonkey.org.uk/projects/trinity/
> 
> 
> on test machine: qemu-system-x86_64 -enable-kvm -cpu host -smp 2 -m 1G

[...]

> [    0.335612] WARNING: inconsistent lock state

I get the same on arm64 (juno r0) during boot consistently:

[    1.458414] ================================
[    1.462641] WARNING: inconsistent lock state
[    1.466870] 4.18.0-rc3-00016-g1b05c8317958 #2 Not tainted
[    1.472215] --------------------------------
[    1.476440] inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
[    1.482389] rcu_preempt/10 [HC0[0]:SC0[0]:HE1:SE1] takes:
[    1.487733] (____ptrval____) (&rq->lock){?.-.}, at: pick_next_task_fair+0x234/0x8e8
[    1.495342] {IN-HARDIRQ-W} state was registered at:
[    1.500174]   lock_acquire+0xc8/0x290
[    1.503802]   _raw_spin_lock+0x44/0x58
[    1.507517]   scheduler_tick+0x5c/0x118
[    1.511316]   update_process_times+0x48/0x60
[    1.515545]   tick_periodic+0x50/0x108
[    1.519256]   tick_handle_periodic+0x38/0xa8
[    1.523485]   arch_timer_handler_phys+0x3c/0x50
[    1.527973]   handle_percpu_devid_irq+0xcc/0x4a0
[    1.532543]   generic_handle_irq+0x34/0x50
[    1.536598]   __handle_domain_irq+0x68/0xc0
[    1.540738]   gic_handle_irq+0x60/0xb8
[    1.544448]   el1_irq+0xb4/0x130
[    1.547644]   start_kernel+0x34c/0x490
[    1.551353] irq event stamp: 1601
[    1.554637] hardirqs last  enabled at (1601): [<ffff000008d64764>] _raw_spin_unlock_irqrestore+0x74/0xa8
[    1.564026] hardirqs last disabled at (1600): [<ffff000008d64514>] _raw_spin_lock_irqsave+0x2c/0x70
[    1.572986] softirqs last  enabled at (0): [<ffff0000080e9c20>] copy_process.isra.4.part.5+0x430/0x18f0
[    1.582285] softirqs last disabled at (0): [<0000000000000000>]           (null)
[    1.589606] 
[    1.589606] other info that might help us debug this:
[    1.596067]  Possible unsafe locking scenario:
[    1.596067] 
[    1.601926]        CPU0
[    1.604344]        ----
[    1.606761]   lock(&rq->lock);
[    1.609788]   <Interrupt>
[    1.612377]     lock(&rq->lock);
[    1.615576] 
[    1.615576]  *** DEADLOCK ***
[    1.615576] 
[    1.621438] no locks held by rcu_preempt/10.
[    1.625661] 
[    1.625661] stack backtrace:
[    1.629977] CPU: 2 PID: 10 Comm: rcu_preempt Not tainted 4.18.0-rc3-00016-g1b05c8317958 #2
[    1.638160] Hardware name: ARM Juno development board (r0) (DT)
[    1.644018] Call trace:
[    1.646439]  dump_backtrace+0x0/0x170
[    1.650063]  show_stack+0x24/0x30
[    1.653345]  dump_stack+0xac/0xe4
[    1.656625]  print_usage_bug+0x208/0x2a8
[    1.660506]  mark_lock+0x5c0/0x668
[    1.663871]  __lock_acquire+0x550/0x1990
[    1.667752]  lock_acquire+0xc8/0x290
[    1.671290]  _raw_spin_lock+0x44/0x58
[    1.674914]  pick_next_task_fair+0x234/0x8e8
[    1.679142]  __schedule+0x160/0xc40
[    1.682595]  schedule+0x50/0xc0
[    1.685702]  schedule_timeout+0x1f4/0x568
[    1.689673]  rcu_gp_kthread+0x4fc/0x860
[    1.693470]  kthread+0x100/0x130
[    1.696664]  ret_from_fork+0x10/0x1c