KVM host kernel hang

Hi,

while trying to run a current openSUSE in VMWare ESX in KVM (using NPT), some KVM code seems to be stuck in an endless loop. The qemu process hangs, I can't attach gdb to it and the kernel module seems to be hanging in a place where I don't see any looping code. One CPU is definitely stuck in sys at 100% though.

This is running git as of yesterday with some minor ESX modifications that should not touch any of these parts (userspace and MSRs).

Maybe one of you guys has a clue what's going on here. You'll find a snippet of a t-sysrq trace with all qemu relevant parts below. The registers (incl. IP) of these don't change over time.

Alex

qemu-system-x D ffff810001025280 0 27900 9501
ffff8101000e5c58 0000000000000082 0000000000000000 ffff8101000e5c1c ffff81011446e728 ffffffff807e6280 ffffffff807e6280 ffff8100388ca680 ffffffff80601890 ffff8100388ca9c0 0000000000200200 ffff8100388ca9c0

Call Trace:
 [<ffffffff804485ec>] __mutex_lock_slowpath+0x72/0xa9
 [<ffffffff8044847a>] mutex_lock+0x1e/0x22
 [<ffffffff88d7f630>] :kvm:kvm_arch_vm_ioctl+0x30e/0x5ae
 [<ffffffff88d7c78e>] :kvm:kvm_vm_ioctl+0x744/0x777
 [<ffffffff802acada>] vfs_ioctl+0x2a/0x78
 [<ffffffff802acd6f>] do_vfs_ioctl+0x247/0x261
 [<ffffffff802acdde>] sys_ioctl+0x55/0x77
 [<ffffffff8020bffa>] system_call_after_swapgs+0x8a/0x8f
 [<00007f2f3b15eb67>]

qemu-system-x R running task 0 27908 9501
0000000000000000 ffffffff88d7d3ad 0000000000000390 ffff810100120040 ffff810116491000 00000000fee00390 0000000000000000 0000000000000000 ffff81011b361d08 ffffffff88d7f1fb 0000000000000000 0000000100000000

Call Trace:

Inexact backtrace:

[<ffffffff88d7d3ad>] :kvm:kvm_get_cs_db_l_bits+0x27/0x3e [<ffffffff88d7f1fb>] :kvm:emulate_instruction+0x199/0x266 [<ffffffff88d86700>] :kvm:kvm_mmu_page_fault+0x49/0x86 [<ffffffff88a3ebe8>] :kvm_amd:pf_interception+0xa8/0xb1 [<ffffffff88a3e1b4>] :kvm_amd:handle_exit+0x218/0x221 [<ffffffff88d810f6>] :kvm:kvm_arch_vcpu_ioctl_run+0x600/0x81a [<ffffffff88d7a4f0>] :kvm:kvm_vcpu_ioctl+0xf6/0x485

 [<ffffffff802acada>] vfs_ioctl+0x2a/0x78
 [<ffffffff802acd6f>] do_vfs_ioctl+0x247/0x261
 [<ffffffff802a13a3>] fget_light+0x1/0x83
 [<ffffffff802acdde>] sys_ioctl+0x55/0x77
 [<ffffffff802a0b48>] sys_writev+0x60/0x94
 [<ffffffff8020bffa>] system_call_after_swapgs+0x8a/0x8f

Quoted 30 lines · Alexander Graf

Hi,

while trying to run a current openSUSE in VMWare ESX in KVM (using NPT), some KVM code seems to be stuck in an endless loop. The qemu process hangs, I can't attach gdb to it and the kernel module seems to be hanging in a place where I don't see any looping code. One CPU is definitely stuck in sys at 100% though.

This is running git as of yesterday with some minor ESX modifications that should not touch any of these parts (userspace and MSRs).

Maybe one of you guys has a clue what's going on here. You'll find a snippet of a t-sysrq trace with all qemu relevant parts below. The registers (incl. IP) of these don't change over time.

Alex

qemu-system-x D ffff810001025280 0 27900 9501
ffff8101000e5c58 0000000000000082 0000000000000000 ffff8101000e5c1c ffff81011446e728 ffffffff807e6280 ffffffff807e6280 ffff8100388ca680 ffffffff80601890 ffff8100388ca9c0 0000000000200200 ffff8100388ca9c0

Call Trace:
[<ffffffff804485ec>] __mutex_lock_slowpath+0x72/0xa9
[<ffffffff8044847a>] mutex_lock+0x1e/0x22
[<ffffffff88d7f630>] :kvm:kvm_arch_vm_ioctl+0x30e/0x5ae
[<ffffffff88d7c78e>] :kvm:kvm_vm_ioctl+0x744/0x777
[<ffffffff802acada>] vfs_ioctl+0x2a/0x78
[<ffffffff802acd6f>] do_vfs_ioctl+0x247/0x261
[<ffffffff802acdde>] sys_ioctl+0x55/0x77
[<ffffffff8020bffa>] system_call_after_swapgs+0x8a/0x8f

Quoted 3 lines

[<00007f2f3b15eb67>]

Waiting for kvm->lock, so can't kill or strace.

Quoted 14 lines

qemu-system-x R running task 0 27908 9501
0000000000000000 ffffffff88d7d3ad 0000000000000390 ffff810100120040 ffff810116491000 00000000fee00390 0000000000000000 0000000000000000 ffff81011b361d08 ffffffff88d7f1fb 0000000000000000 0000000100000000

Call Trace:

Inexact backtrace:

[<ffffffff88d7d3ad>] :kvm:kvm_get_cs_db_l_bits+0x27/0x3e [<ffffffff88d7f1fb>] :kvm:emulate_instruction+0x199/0x266 [<ffffffff88d86700>] :kvm:kvm_mmu_page_fault+0x49/0x86 [<ffffffff88a3ebe8>] :kvm_amd:pf_interception+0xa8/0xb1 [<ffffffff88a3e1b4>] :kvm_amd:handle_exit+0x218/0x221 [<ffffffff88d810f6>] :kvm:kvm_arch_vcpu_ioctl_run+0x600/0x81a [<ffffffff88d7a4f0>] :kvm:kvm_vcpu_ioctl+0xf6/0x485

Quoted 7 lines

[<ffffffff802acada>] vfs_ioctl+0x2a/0x78
[<ffffffff802acd6f>] do_vfs_ioctl+0x247/0x261
[<ffffffff802a13a3>] fget_light+0x1/0x83
[<ffffffff802acdde>] sys_ioctl+0x55/0x77
[<ffffffff802a0b48>] sys_writev+0x60/0x94
[<ffffffff8020bffa>] system_call_after_swapgs+0x8a/0x8f

But the mutex is not taken here. Looks like we lost it, maybe CONFIG_LOCKDEP can find out where.

I have CONFIG_LOCKDEP_SUPPORT=y. How do I make it detect that it's actually locking itself up?
Btw: The issue seems to be easily reproducible :-)

Quoted 4 lines · Alexander Graf

I have CONFIG_LOCKDEP_SUPPORT=y. How do I make it detect that it's actually locking itself up?
Btw: The issue seems to be easily reproducible :-)

Perhaps CONFIG_PROVE_LOCKING and CONFIG_LOCKDEP. _SUPPORT just indicates the arch can do it if you want, IIUC.

Quoted 9 lines · Avi Kivity

Quoted 4 lines · Alexander Graf

I have CONFIG_LOCKDEP_SUPPORT=y. How do I make it detect that it's actually locking itself up?
Btw: The issue seems to be easily reproducible :-)

Perhaps CONFIG_PROVE_LOCKING and CONFIG_LOCKDEP. _SUPPORT just indicates the arch can do it if you want, IIUC.

I just added some debug #define's to show me where exactly things break.

Jan  7 14:34:46 linux-dp8n kernel: 2149: Grabbing lock {
Jan  7 14:34:46 linux-dp8n kernel: 1908: Grabbing lock {

   2145 mmio:
   2146         /*
   2147          * Is this MMIO handled locally?
   2148          */
   2149         mutex_lock(&vcpu->kvm->lock);
   2150         mmio_dev = vcpu_find_mmio_dev(vcpu, gpa, bytes, 0);
   2151         if (mmio_dev) {
   2152                 kvm_iodevice_read(mmio_dev, gpa, bytes, val);
   2153                 mutex_unlock(&vcpu->kvm->lock);
   2154                 return X86EMUL_CONTINUE;
   2155         }
   2156         mutex_unlock(&vcpu->kvm->lock);

   1901         case KVM_IRQ_LINE: {
   1902                 struct kvm_irq_level irq_event;
   1903
   1904                 r = -EFAULT;
   1905                 if (copy_from_user(&irq_event, argp, sizeof
irq_event))
   1906                         goto out;
   1907                 if (irqchip_in_kernel(kvm)) {
   1908                         mutex_lock(&kvm->lock);

   1909                         kvm_set_irq(kvm,
KVM_USERSPACE_IRQ_SOURCE_ID,
   1910                                     irq_event.irq, irq_event.level);
   1911                         mutex_unlock(&kvm->lock);
   1912                         r = 0;
   1913                 }
   1914                 break;
   1915         }

Quoted 18 lines · Alexander Graf

Quoted 9 lines · Avi Kivity

Quoted 4 lines · Alexander Graf

I have CONFIG_LOCKDEP_SUPPORT=y. How do I make it detect that it's actually locking itself up?
Btw: The issue seems to be easily reproducible :-)

Perhaps CONFIG_PROVE_LOCKING and CONFIG_LOCKDEP. _SUPPORT just indicates the arch can do it if you want, IIUC.

I just added some debug #define's to show me where exactly things break.

Jan  7 14:34:46 linux-dp8n kernel: 2149: Grabbing lock {
Jan  7 14:34:46 linux-dp8n kernel: 1908: Grabbing lock {

Quoted 14 lines

  2145 mmio:
  2146         /*
  2147          * Is this MMIO handled locally?
  2148          */
  2149         mutex_lock(&vcpu->kvm->lock);
  2150         mmio_dev = vcpu_find_mmio_dev(vcpu, gpa, bytes, 0);
  2151         if (mmio_dev) {
  2152                 kvm_iodevice_read(mmio_dev, gpa, bytes, val);
  2153                 mutex_unlock(&vcpu->kvm->lock);
  2154                 return X86EMUL_CONTINUE;
  2155         }
  2156         mutex_unlock(&vcpu->kvm->lock);

The lock was lost here. But how?

Quoted 10 lines

1901 case KVM_IRQ_LINE: {
1902 struct kvm_irq_level irq_event;
1903
1904 r = -EFAULT;
1905 if (copy_from_user(&irq_event, argp, sizeof
irq_event))
1906 goto out;
1907 if (irqchip_in_kernel(kvm)) {
1908 mutex_lock(&kvm->lock);
1909 kvm_set_irq(kvm,

Quoted 10 lines

KVM_USERSPACE_IRQ_SOURCE_ID,
1910 irq_event.irq,
irq_event.level);
1911 mutex_unlock(&kvm->lock);
1912 r = 0;
1913 }
1914 break;
1915 }

This is your hung iothread trying to inject an interrupt. It's waiting for the lost lock.

I suggest enabling all the lock debug magic you can find in kconfig.

Signature · 2 lines

-- 
error compiling committee.c: too many arguments to function