Inconsistent lock state / deadlock in vboxdrv during ACPI S3 host suspend

[Thilo-Alexander Ginkel]

When I suspend my host running

Linux orion 3.3.1 #30 SMP Mon Apr 2 23:33:43 CEST 2012 x86_64 x86_64 x86_64 GNU/Linux

there is a certain probability that vboxdrv will enter a deadlock state causing the suspend operation to fail. While the kernel attempts to recover from the suspend failure there were followup errors that required a hard reset. Having vboxdrv loaded seems to be sufficient, i.e., the problem happens independently from a running VirtualBox VM.

Please find attached the dmesg output from the respective session (search for "DEADLOCK").

[Frank Mehnert]

Could you also attach your compiled vboxdrv module?

[Thilo-Alexander Ginkel]

/var/lib/dkms/vboxhost/4.1.12/3.3.1/x86_64/module/vboxdrv.ko

[Thilo-Alexander Ginkel]

FYI: Still an issue with Linux 3.4.2 and VirtualBox 4.1.16:

Jun 13 07:54:27 orion kernel: [  248.382983] Disabling non-boot CPUs ...
Jun 13 07:54:27 orion kernel: [  248.384323] 
Jun 13 07:54:27 orion kernel: [  248.384328] =================================
Jun 13 07:54:27 orion kernel: [  248.384332] [ INFO: inconsistent lock state ]
Jun 13 07:54:27 orion kernel: [  248.384337] 3.4.2 #33 Tainted: G         C O
Jun 13 07:54:27 orion kernel: [  248.384340] ---------------------------------
Jun 13 07:54:27 orion kernel: [  248.384344] inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
Jun 13 07:54:27 orion kernel: [  248.384349] swapper/1/0 [HC1[1]:SC0[0]:HE0:SE1] takes:
Jun 13 07:54:27 orion kernel: [  248.384353]  (&(&pThis->Spinlock)->rlock){?.+...}, at: [<ffffffffa04bbab2>] VBoxHost_RTSpinlockAcquire+0x12/0x20 [vboxdrv]
Jun 13 07:54:27 orion kernel: [  248.384376] {HARDIRQ-ON-W} state was registered at:
Jun 13 07:54:27 orion kernel: [  248.384380]   [<ffffffff810aba35>] __lock_acquire+0x655/0x1bf0
Jun 13 07:54:27 orion kernel: [  248.384387]   [<ffffffff810ad592>] lock_acquire+0x92/0x120
Jun 13 07:54:27 orion kernel: [  248.384393]   [<ffffffff8164ff31>] _raw_spin_lock+0x31/0x40
Jun 13 07:54:27 orion kernel: [  248.384399]   [<ffffffffa04bbab2>] VBoxHost_RTSpinlockAcquire+0x12/0x20 [vboxdrv]
Jun 13 07:54:27 orion kernel: [  248.384410]   [<ffffffffa04b777b>] VBoxHost_RTMpNotificationRegister+0x6b/0x1c0 [vboxdrv]
Jun 13 07:54:27 orion kernel: [  248.384422]   [<ffffffffa04b136f>] supdrvInitDevExt+0x3ef/0x7b0 [vboxdrv]
Jun 13 07:54:27 orion kernel: [  248.384432]   [<ffffffffa04f6070>] VBoxNetAdpLinuxOpen+0x10/0x20 [vboxnetadp]
Jun 13 07:54:27 orion kernel: [  248.384438]   [<ffffffff8100203f>] do_one_initcall+0x3f/0x170
Jun 13 07:54:27 orion kernel: [  248.384445]   [<ffffffff810bb0ce>] sys_init_module+0xbe/0x230
Jun 13 07:54:27 orion kernel: [  248.384452]   [<ffffffff81658b69>] system_call_fastpath+0x16/0x1b
Jun 13 07:54:27 orion kernel: [  248.384458] irq event stamp: 735386
Jun 13 07:54:27 orion kernel: [  248.384462] hardirqs last  enabled at (735383): [<ffffffff8138a57b>] intel_idle+0xeb/0x150
Jun 13 07:54:27 orion kernel: [  248.384470] hardirqs last disabled at (735384): [<ffffffff81659b1a>] call_function_single_interrupt+0x6a/0x80
Jun 13 07:54:27 orion kernel: [  248.384478] softirqs last  enabled at (735386): [<ffffffff81056ac3>] _local_bh_enable+0x13/0x20
Jun 13 07:54:27 orion kernel: [  248.384486] softirqs last disabled at (735385): [<ffffffff81057475>] irq_enter+0x75/0x90
Jun 13 07:54:27 orion kernel: [  248.384494] 
Jun 13 07:54:27 orion kernel: [  248.384494] other info that might help us debug this:
Jun 13 07:54:27 orion kernel: [  248.384499]  Possible unsafe locking scenario:
Jun 13 07:54:27 orion kernel: [  248.384500] 
Jun 13 07:54:27 orion kernel: [  248.384504]        CPU0
Jun 13 07:54:27 orion kernel: [  248.384506]        ----
Jun 13 07:54:27 orion kernel: [  248.384508]   lock(&(&pThis->Spinlock)->rlock);
Jun 13 07:54:27 orion kernel: [  248.384514]   <Interrupt>
Jun 13 07:54:27 orion kernel: [  248.384516]     lock(&(&pThis->Spinlock)->rlock);
Jun 13 07:54:27 orion kernel: [  248.384522] 
Jun 13 07:54:27 orion kernel: [  248.384522]  *** DEADLOCK ***
Jun 13 07:54:27 orion kernel: [  248.384523] 
Jun 13 07:54:27 orion kernel: [  248.384527] no locks held by swapper/1/0.
Jun 13 07:54:27 orion kernel: [  248.384531] 
Jun 13 07:54:27 orion kernel: [  248.384531] stack backtrace:
Jun 13 07:54:27 orion kernel: [  248.384536] Pid: 0, comm: swapper/1 Tainted: G         C O 3.4.2 #33
Jun 13 07:54:27 orion kernel: [  248.384540] Call Trace:
Jun 13 07:54:27 orion kernel: [  248.384543]  <IRQ>  [<ffffffff81645615>] print_usage_bug+0x1f5/0x206
Jun 13 07:54:27 orion kernel: [  248.384555]  [<ffffffff810222cf>] ? save_stack_trace+0x2f/0x50
Jun 13 07:54:27 orion kernel: [  248.384562]  [<ffffffff810ab385>] mark_lock+0x295/0x2f0
Jun 13 07:54:27 orion kernel: [  248.384568]  [<ffffffff810aa780>] ? print_irq_inversion_bug.part.36+0x1f0/0x1f0
Jun 13 07:54:27 orion kernel: [  248.384574]  [<ffffffff810abc6b>] __lock_acquire+0x88b/0x1bf0
Jun 13 07:54:27 orion kernel: [  248.384580]  [<ffffffff8108cd70>] ? load_balance+0x870/0x870
Jun 13 07:54:27 orion kernel: [  248.384587]  [<ffffffff81078140>] ? lock_hrtimer_base.isra.24+0x30/0x60
Jun 13 07:54:27 orion kernel: [  248.384597]  [<ffffffffa04bbab2>] ? VBoxHost_RTSpinlockAcquire+0x12/0x20 [vboxdrv]
Jun 13 07:54:27 orion kernel: [  248.384603]  [<ffffffff810ad592>] lock_acquire+0x92/0x120
Jun 13 07:54:27 orion kernel: [  248.384612]  [<ffffffffa04bbab2>] ? VBoxHost_RTSpinlockAcquire+0x12/0x20 [vboxdrv]
Jun 13 07:54:27 orion kernel: [  248.384619]  [<ffffffff8164ff31>] _raw_spin_lock+0x31/0x40
Jun 13 07:54:27 orion kernel: [  248.384628]  [<ffffffffa04bbab2>] ? VBoxHost_RTSpinlockAcquire+0x12/0x20 [vboxdrv]
Jun 13 07:54:27 orion kernel: [  248.384638]  [<ffffffffa04bbab2>] VBoxHost_RTSpinlockAcquire+0x12/0x20 [vboxdrv]
Jun 13 07:54:27 orion kernel: [  248.384648]  [<ffffffffa04b7923>] rtMpNotificationDoCallbacks+0x53/0x130 [vboxdrv]
Jun 13 07:54:27 orion kernel: [  248.384659]  [<ffffffffa04ba454>] rtMpNotificationLinuxOnCurrentCpu+0x84/0x120 [vboxdrv]
Jun 13 07:54:27 orion kernel: [  248.384670]  [<ffffffffa04b9f78>] rtmpLinuxWrapper+0x28/0x30 [vboxdrv]
Jun 13 07:54:27 orion kernel: [  248.384677]  [<ffffffff810b50e6>] generic_smp_call_function_single_interrupt+0xc6/0x120
Jun 13 07:54:27 orion kernel: [  248.384684]  [<ffffffff81032e77>] smp_call_function_single_interrupt+0x27/0x40
Jun 13 07:54:27 orion kernel: [  248.384690]  [<ffffffff81659b1f>] call_function_single_interrupt+0x6f/0x80
Jun 13 07:54:27 orion kernel: [  248.384695]  <EOI>  [<ffffffff8138a57f>] ? intel_idle+0xef/0x150
Jun 13 07:54:27 orion kernel: [  248.384704]  [<ffffffff8138a57b>] ? intel_idle+0xeb/0x150
Jun 13 07:54:27 orion kernel: [  248.384710]  [<ffffffff81505499>] cpuidle_enter+0x19/0x20
Jun 13 07:54:27 orion kernel: [  248.384716]  [<ffffffff81505abc>] cpuidle_idle_call+0xac/0x2a0
Jun 13 07:54:27 orion kernel: [  248.384721]  [<ffffffff8101d675>] cpu_idle+0xd5/0x130
Jun 13 07:54:27 orion kernel: [  248.384727]  [<ffffffff8163dc09>] start_secondary+0x1fb/0x202
Jun 13 07:54:27 orion kernel: [  248.487067] CPU 1 is now offline
Jun 13 07:54:27 orion kernel: [  248.590861] CPU 2 is now offline
Jun 13 07:54:27 orion kernel: [  248.591556] Broke affinity for irq 23
Jun 13 07:54:27 orion kernel: [  248.694673] CPU 3 is now offline

P.S.: Can you please add me to the Cc: list of this ticket? I can't seem to find a way to do so myself...

[Thilo-Alexander Ginkel]

FYI: Still an issue with VirtualBox 4.1.18 / Linux 3.3.8 (x86_64, Intel SandyBridge Core i5)

[aeichner]

Please reopen if still relevant with a recent VirtualBox release.