Kernel module vboxdrv : Inconsistent lock state

[mako]

Hi all,

the Linux kernel module vboxdrv of Virtualbox 4.2.6 (and also 4.2.4 and 4.2.2) uses an inconsistent lock state. According to the hint of Thomas Gleixner I enabled the kernel debugging feature "CONFIG_PROVE_LOCKING" in a vanilla kernel 3.2.34. (Please find my kernel config attached).

When loading vboxdrv.ko dmesg shows the following output:

---

vboxdrv: Found 4 processor cores. vboxdrv: fAsync=0 offMin=0x514 offMax=0x57f5

================================= [ INFO: inconsistent lock state ] 3.2.34-2 #2

---

inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage. swapper/1/0 [HC1[1]:SC0[0]:HE0:SE1] takes:

(&(&pThis->Spinlock)->rlock){?.+...}, at: [<f883d7a9>] VBoxHost_RTSpinlockAcquire+0x15/0x24 [vboxdrv]

{HARDIRQ-ON-W} state was registered at:

[<c104b99a>] lock_acquire+0x509/0x1337 [<c104cb3a>] lock_acquire+0x42/0x59 [<c13204d5>] _raw_spin_lock+0x25/0x34 [<f883d7b3>] VBoxHost_RTSpinlockAcquire+0x1f/0x24 [vboxdrv] [<f883a86f>] VBoxHost_RTMpNotificationRegister+0x36/0x11a [vboxdrv] [<f88334f8>] supdrvInitDevExt+0x4f4/0x65c [vboxdrv] [<f8869053>] VBoxDrvLinuxInit+0x53/0xcd [vboxdrv] [<c100106b>] do_one_initcall+0x6b/0x10c [<c1054299>] sys_init_module+0x122f/0x13fa [<c1321990>] sysenter_do_call+0x12/0x36

irq event stamp: 146398 hardirqs last enabled at (146395): [<c1007c3a>] mwait_idle+0x57/0x7c hardirqs last disabled at (146396): [<c1320f34>] call_function_interrupt+0x28/0x34 softirqs last enabled at (146398): [<c102e3db>] _local_bh_enable+0xd/0xf softirqs last disabled at (146397): [<c102e7a8>] irq_enter+0x29/0x4e

other info that might help us debug this:

Possible unsafe locking scenario:

CPU0 ----

lock(&(&pThis->Spinlock)->rlock); <Interrupt>

lock(&(&pThis->Spinlock)->rlock);

* DEADLOCK *

no locks held by swapper/1/0.

stack backtrace: Pid: 0, comm: swapper/1 Tainted: G O 3.2.34-2 #2 Call Trace:

[<c131c0bb>] print_usage_bug.part.27+0x1f0/0x1fa [<c104b313>] mark_lock+0x334/0x4b2 [<c104a95b>] ? check_usage_backwards+0xce/0xce [<c104b92d>] lock_acquire+0x49c/0x1337 [<c104cb3a>] lock_acquire+0x42/0x59 [<f883d7a9>] ? VBoxHost_RTSpinlockAcquire+0x15/0x24 [vboxdrv] [<c1320583>] _raw_spin_lock_irqsave+0x2e/0x3e [<f883d7a9>] ? VBoxHost_RTSpinlockAcquire+0x15/0x24 [vboxdrv] [<f883d7a9>] VBoxHost_RTSpinlockAcquire+0x15/0x24 [vboxdrv] [<f8832d69>] ? supdrvGipMpEventOnline+0x14d/0x14d [vboxdrv] [<f8832c77>] supdrvGipMpEventOnline+0x5b/0x14d [vboxdrv] [<f8832d69>] ? supdrvGipMpEventOnline+0x14d/0x14d [vboxdrv] [<f8832d77>] supdrvGipInitOnCpu+0xe/0x10 [vboxdrv] [<f883c688>] rtmpLinuxWrapper+0x22/0x2d [vboxdrv] [<f883c666>] ? VBoxHost_RTMpCpuId+0xa/0xa [vboxdrv] [<c1051253>] generic_smp_call_function_interrupt+0x6b/0x112 [<c1014595>] smp_call_function_interrupt+0x20/0x2e [<c1320f3b>] call_function_interrupt+0x2f/0x34 [<c104007b>] ? run_hrtimer.isra.28+0x33/0x9e [<c1007c42>] ? mwait_idle+0x5f/0x7c [<c10014c2>] cpu_idle+0x4d/0x76 [<c14ff2e8>] start_secondary+0x1ab/0x1b2

vboxdrv: TSC mode is 'synchronous', kernel timer mode is 'normal'. vboxdrv: Successfully loaded version 4.2.6 (interface 0x001a0004).

---

This behaviour leads likely to the freeze on a RT_PREEMPT system as described in ticket #11286. https://www.virtualbox.org/ticket/11286

[mako]

config.gz

[mako]

Sorry for the bad formatting of the dmesg output here it is again:

vboxdrv: Found 4 processor cores.
vboxdrv: fAsync=0 offMin=0x514 offMax=0x57f5

=================================
[ INFO: inconsistent lock state ]
3.2.34-2 #2
---------------------------------
inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
swapper/1/0 [HC1[1]:SC0[0]:HE0:SE1] takes:
 (&(&pThis->Spinlock)->rlock){?.+...}, at: [<f883d7a9>] VBoxHost_RTSpinlockAcquire+0x15/0x24 [vboxdrv]
{HARDIRQ-ON-W} state was registered at:
  [<c104b99a>] __lock_acquire+0x509/0x1337
  [<c104cb3a>] lock_acquire+0x42/0x59
  [<c13204d5>] _raw_spin_lock+0x25/0x34
  [<f883d7b3>] VBoxHost_RTSpinlockAcquire+0x1f/0x24 [vboxdrv]
  [<f883a86f>] VBoxHost_RTMpNotificationRegister+0x36/0x11a [vboxdrv]
  [<f88334f8>] supdrvInitDevExt+0x4f4/0x65c [vboxdrv]
  [<f8869053>] VBoxDrvLinuxInit+0x53/0xcd [vboxdrv]
  [<c100106b>] do_one_initcall+0x6b/0x10c
  [<c1054299>] sys_init_module+0x122f/0x13fa
  [<c1321990>] sysenter_do_call+0x12/0x36
irq event stamp: 146398
hardirqs last  enabled at (146395): [<c1007c3a>] mwait_idle+0x57/0x7c
hardirqs last disabled at (146396): [<c1320f34>] call_function_interrupt+0x28/0x34
softirqs last  enabled at (146398): [<c102e3db>] _local_bh_enable+0xd/0xf
softirqs last disabled at (146397): [<c102e7a8>] irq_enter+0x29/0x4e

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

       CPU0
       ----
  lock(&(&pThis->Spinlock)->rlock);
  <Interrupt>
    lock(&(&pThis->Spinlock)->rlock);

 *** DEADLOCK ***

no locks held by swapper/1/0.

stack backtrace:
Pid: 0, comm: swapper/1 Tainted: G           O 3.2.34-2 #2
Call Trace:
 [<c131c0bb>] print_usage_bug.part.27+0x1f0/0x1fa
 [<c104b313>] mark_lock+0x334/0x4b2
 [<c104a95b>] ? check_usage_backwards+0xce/0xce
 [<c104b92d>] __lock_acquire+0x49c/0x1337
 [<c104cb3a>] lock_acquire+0x42/0x59
 [<f883d7a9>] ? VBoxHost_RTSpinlockAcquire+0x15/0x24 [vboxdrv]
 [<c1320583>] _raw_spin_lock_irqsave+0x2e/0x3e
 [<f883d7a9>] ? VBoxHost_RTSpinlockAcquire+0x15/0x24 [vboxdrv]
 [<f883d7a9>] VBoxHost_RTSpinlockAcquire+0x15/0x24 [vboxdrv]
 [<f8832d69>] ? supdrvGipMpEventOnline+0x14d/0x14d [vboxdrv]
 [<f8832c77>] supdrvGipMpEventOnline+0x5b/0x14d [vboxdrv]
 [<f8832d69>] ? supdrvGipMpEventOnline+0x14d/0x14d [vboxdrv]
 [<f8832d77>] supdrvGipInitOnCpu+0xe/0x10 [vboxdrv]
 [<f883c688>] rtmpLinuxWrapper+0x22/0x2d [vboxdrv]
 [<f883c666>] ? VBoxHost_RTMpCpuId+0xa/0xa [vboxdrv]
 [<c1051253>] generic_smp_call_function_interrupt+0x6b/0x112
 [<c1014595>] smp_call_function_interrupt+0x20/0x2e
 [<c1320f3b>] call_function_interrupt+0x2f/0x34
 [<c104007b>] ? __run_hrtimer.isra.28+0x33/0x9e
 [<c1007c42>] ? mwait_idle+0x5f/0x7c
 [<c10014c2>] cpu_idle+0x4d/0x76
 [<c14ff2e8>] start_secondary+0x1ab/0x1b2
vboxdrv: TSC mode is 'synchronous', kernel timer mode is 'normal'.
vboxdrv: Successfully loaded version 4.2.6 (interface 0x001a0004).

[Frank Mehnert]

Thanks for the report, I can reproduce the problem.

[galitsyn]

The issue has been solved. Fix will be delivered with the next release.

[galitsyn]

Found an extra issue when CONFIG_PROVE_LOCKING is enabled.

[ 5899.433724] =============================================
[ 5899.433727] [ INFO: possible recursive locking detected ]
[ 5899.433733] 3.7.4 #5 Tainted: G           O
[ 5899.433738] ---------------------------------------------
[ 5899.433744] EMT-0/8581 is trying to acquire lock:
[ 5899.433751]  (&(&pThis->Spinlock)->rlock#2){+.+...}, at: [<ffffffffa03fca6b>] VBoxHost_RTSpinlockAcquire+0x1b/0x40 [vboxdrv]
[ 5899.433804] 
[ 5899.433804] but task is already holding lock:
[ 5899.433811]  (&(&pThis->Spinlock)->rlock#2){+.+...}, at: [<ffffffffa03fca6b>] VBoxHost_RTSpinlockAcquire+0x1b/0x40 [vboxdrv]
[ 5899.433851] 
[ 5899.433851] other info that might help us debug this:
[ 5899.433855]  Possible unsafe locking scenario:
[ 5899.433855] 
[ 5899.433859]        CPU0
[ 5899.433863]        ----
[ 5899.433868]   lock(&(&pThis->Spinlock)->rlock#2);
[ 5899.433879]   lock(&(&pThis->Spinlock)->rlock#2);
[ 5899.433889] 
[ 5899.433889]  *** DEADLOCK ***
[ 5899.433889] 
[ 5899.433897]  May be due to missing lock nesting notation
[ 5899.433897] 
[ 5899.433906] 1 lock held by EMT-0/8581:
[ 5899.433909]  #0:  (&(&pThis->Spinlock)->rlock#2){+.+...}, at: [<ffffffffa03fca6b>] VBoxHost_RTSpinlockAcquire+0x1b/0x40 [vboxdrv]
[ 5899.433941] 
[ 5899.433941] stack backtrace:
[ 5899.433952] Pid: 8581, comm: EMT-0 Tainted: G           O 3.7.4 #5
[ 5899.433958] Call Trace:
[ 5899.433978]  [<ffffffff81082f3a>] __lock_acquire+0x84a/0x1d20
[ 5899.433993]  [<ffffffff810848d8>] lock_acquire+0x58/0x70
[ 5899.434020]  [<ffffffffa03fca6b>] ? VBoxHost_RTSpinlockAcquire+0x1b/0x40 [vboxdrv]
[ 5899.434032]  [<ffffffff815451dc>] _raw_spin_lock+0x3c/0x50
[ 5899.434052]  [<ffffffffa03fca6b>] ? VBoxHost_RTSpinlockAcquire+0x1b/0x40 [vboxdrv]
[ 5899.434079]  [<ffffffffa03fca6b>] VBoxHost_RTSpinlockAcquire+0x1b/0x40 [vboxdrv]
[ 5899.434098]  [<ffffffffa03ec434>] SUPR0ObjAddRefEx+0x94/0x1f0 [vboxdrv]
[ 5899.434119]  [<ffffffffa03fca6b>] ? VBoxHost_RTSpinlockAcquire+0x1b/0x40 [vboxdrv]
[ 5899.434143]  [<ffffffffa03ec5b4>] supdrvSessionObjHandleRetain+0x14/0x20 [vboxdrv]
[ 5899.434169]  [<ffffffffa0403ef0>] VBoxHost_RTHandleTableFreeWithCtx+0x100/0x1a0 [vboxdrv]
[ 5899.434195]  [<ffffffffa03f2e0e>] SUPSemEventClose+0x4e/0xa0 [vboxdrv]
[ 5899.434216]  [<ffffffffa03f0f66>] supdrvIOCtl+0x1916/0x2bd0 [vboxdrv]
[ 5899.434226]  [<ffffffff810dc55b>] ? might_fault+0x3b/0x90
[ 5899.434249]  [<ffffffffa03eb457>] VBoxDrvLinuxIOCtl_4_2_51+0x117/0x1f0 [vboxdrv]
[ 5899.434265]  [<ffffffff811166f7>] do_vfs_ioctl+0x97/0x580
[ 5899.434275]  [<ffffffff81120da7>] ? fget_light+0xd7/0x140
[ 5899.434283]  [<ffffffff81120d0b>] ? fget_light+0x3b/0x140
[ 5899.434295]  [<ffffffff81116c2b>] sys_ioctl+0x4b/0x90
[ 5899.434308]  [<ffffffff8122017e>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 5899.434321]  [<ffffffff8154b352>] system_call_fastpath+0x16/0x1b

So, lets keep it open.

[aeichner]

Please reopen if still relevant with a recent VirtualBox release.