﻿id,summary,reporter,owner,description,type,status,component,version,resolution,keywords,cc,guest,host
11318,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:

----------- BEGIN dmesg ------------
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).
----------- END dmesg ------------

This behaviour leads likely to the freeze on a RT_PREEMPT system as described in ticket #11286.
[https://www.virtualbox.org/ticket/11286]


",defect,closed,other,VirtualBox 4.2.6,obsolete,,,other,Linux
