kernel bug in kvm_intel

Oct  9 11:55:13 virtvictory-eth0 kernel: BUG: unable to handle kernel paging request at ffffffff9fe9a2b4
Oct  9 11:55:13 virtvictory-eth0 kernel: IP: [<ffffffffa02e1af1>] vmx_vcpu_run+0x26d/0x64f [kvm_intel]
Oct  9 11:55:13 virtvictory-eth0 kernel: PGD 1003067 PUD 1007063 PMD 0 Oct  9 11:55:13 virtvictory-eth0 kernel: Oops: 0000 [#5] SMP Oct  9 11:55:13 virtvictory-eth0 kernel: last sysfs file: /sys/devices/virtual/net/br4/bridge/topology_change_detected
Oct  9 11:55:13 virtvictory-eth0 kernel: CPU 6 Oct  9 11:55:13 virtvictory-eth0 kernel: Modules linked in: oprofile tun hidp l2cap crc16 bluetooth rfkill lockd sunrpc bridge stp af_packet ipv6 binfmt_misc dm_multipath scsi_dh video output sbs sbshc pci_slot fan container battery ac parport_pc lp parport kvm_intel kvm joydev sr_mod cdrom sg cdc_ether usbnet mii usbhid hid serio_raw rtc_cmos rtc_core rtc_lib button thermal thermal_sys hwmon pata_acpi bnx2 i2c_i801 ide_pci_generic iTCO_wdt i2c_core ata_generic iTCO_vendor_support ioatdma dca pcspkr dm_snapshot dm_zero dm_mirror dm_region_hash dm_log dm_mod ide_gd_mod ide_core usb_storage ata_piix libata shpchp pci_hotplug qla2xxx scsi_transport_fc scsi_tgt sd_mod crc_t10dif scsi_mod ext3 jbd mbcache uhci_hcd ohci_hcd ehci_hcd usbcore [last unloaded: oprofile]
Oct  9 11:55:13 virtvictory-eth0 kernel: Pid: 6495, comm: qemu-system-x86 Tainted: G      D    2.6.32-rc3-autokern1 #1 IBM System x -[7947AC1]-
Oct  9 11:55:13 virtvictory-eth0 kernel: RIP: 0010:[<ffffffffa02e1af1>]  [<ffffffffa02e1af1>] vmx_vcpu_run+0x26d/0x64f [kvm_intel]
Oct  9 11:55:13 virtvictory-eth0 kernel: RSP: 0018:ffff8806369ffc80  EFLAGS: 00010002     Oct  9 11:55:13 virtvictory-eth0 kernel: RAX: 000000000004001f RBX: 0000000000000200 RCX: 0000000000000001
Oct  9 11:55:13 virtvictory-eth0 kernel: RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000080000000
Oct  9 11:55:13 virtvictory-eth0 kernel: RBP: 0000000000000000 R08: fffffa80025180a8 R09: fffff800016ca4f0
Oct  9 11:55:13 virtvictory-eth0 kernel: R10: 7797003630747070 R11: fffffa60039039b8 R12: 00000000a0000003
Oct  9 11:55:13 virtvictory-eth0 kernel: R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
Oct  9 11:55:13 virtvictory-eth0 kernel: FS:  0000000040ae6940(0000) GS:ffff88099fe80000(0000) knlGS:00000000ffe66000
Oct  9 11:55:13 virtvictory-eth0 kernel: CS:  0010 DS: 0018 ES: 0018 CR0: 0000000080050033
Oct  9 11:55:13 virtvictory-eth0 kernel: CR2: ffffffff9fe9a2b4 CR3: 00000006375ec000 CR4: 00000000000026f0
Oct  9 11:55:13 virtvictory-eth0 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Oct  9 11:55:13 virtvictory-eth0 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Oct  9 11:55:13 virtvictory-eth0 kernel: Process qemu-system-x86 (pid: 6495, threadinfo ffff8806369fe000, task ffff880632056480)
Oct  9 11:55:13 virtvictory-eth0 kernel: Stack:
Oct  9 11:55:13 virtvictory-eth0 kernel:  ffff8806320916c0 ffff8806369ffd88 0000000000006c14 ffff8806369ffca8
Oct  9 11:55:13 virtvictory-eth0 kernel: <0> ffff8806320916c0 ffff8806369ffce8 ffffffffa0293bfa ffff8806369ffee8
Oct  9 11:55:13 virtvictory-eth0 kernel: <0> 0000000000000001 0000000000000300 ffff8806320916c0 000000000000002c
Oct  9 11:55:13 virtvictory-eth0 kernel: Call Trace:
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffffa0293bfa>] ? emulate_instruction+0x28a/0x2bc [kvm]
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffffa02e129a>] ? handle_apic_access+0x20/0x4b [kvm_intel]
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffffa02e1fb4>] ? vmx_handle_exit+0xe1/0x48b [kvm_intel]
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffffa02de575>] ? save_msrs+0x39/0x50 [kvm_intel]
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffffa02aa328>] ? apic_update_ppr+0x23/0x51 [kvm]
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffff81199f6e>] ? __up_read+0x8f/0x97
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffffa02976a6>] ? kvm_arch_vcpu_ioctl_run+0x6b6/0xa92 [kvm]
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffffa028da38>] ? kvm_vcpu_ioctl+0xf6/0x5c0 [kvm]
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffff8102067f>] ? lapic_next_event+0x18/0x1c
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffff8106ec97>] ? clockevents_program_event+0x73/0x7c
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffff8106fdea>] ? tick_dev_program_event+0x2a/0x9c
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffff810fb324>] ? vfs_ioctl+0x2a/0x77
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffff810fb82e>] ? do_vfs_ioctl+0x445/0x496
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffff810736b9>] ? sys_futex+0x111/0x12f
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffff810fb8d6>] ? sys_ioctl+0x57/0x7a
Oct  9 11:55:13 virtvictory-eth0 kernel:  [<ffffffff8100bc02>] ? system_call_fastpath+0x16/0x1b

This is on latest master branch on kvm.git and qemu-kvm.git, running 12 Windows Server2008 VMs, and using oprofile. I ran again without oprofile and did not get the BUG. I am wondering if anyone else is seeing this.

Thanks,

-Andrew

Quoted 2 lines

Oct  9 11:55:13 virtvictory-eth0 kernel: BUG: unable to handle kernel paging request at ffffffff9fe9a2b4
Oct  9 11:55:13 virtvictory-eth0 kernel: IP: [<ffffffffa02e1af1>] vmx_vcpu_run+0x26d/0x64f [kvm_intel]

Quoted 9 lines · Andrew Theurer

This is on latest master branch on kvm.git and qemu-kvm.git, running 12 Windows Server2008 VMs, and using oprofile. I ran again without oprofile and did not get the BUG. I am wondering if anyone else is seeing this.

Thanks,

-Andrew

Quoted 4 lines

Quoted 4 lines

Oct  9 11:55:13 virtvictory-eth0 kernel: BUG: unable to handle kernel 
paging request at ffffffff9fe9a2b4
Oct  9 11:55:13 virtvictory-eth0 kernel: IP: [<ffffffffa02e1af1>] 

vmx_vcpu_run+0x26d/0x64f [kvm_intel]

Can you run this through objdump or gdb to see what source this corresponds to?

3ad9: 4c 8b b9 90 01 00 00 mov 0x190(%rcx),%r15

    3ae0:       48 8b 89 20 01 00 00    mov    0x120(%rcx),%rcx
    3ae7:       75 05                   jne    3aee <vmx_vcpu_run+0x26a>
    3ae9:       0f 01 c2                vmlaunch
    3aec:       eb 03                   jmp    3af1 <vmx_vcpu_run+0x26d>
    3aee:       0f 01 c3                vmresume
    3af1:       48 87 0c 24             xchg   %rcx,(%rsp)
    3af5:       48 89 81 18 01 00 00    mov    %rax,0x118(%rcx)
    3afc:       48 89 99 30 01 00 00    mov    %rbx,0x130(%rcx)
    3b03:       ff 34 24                pushq  (%rsp)
    3b06:       8f 81 20 01 00 00       popq   0x120(%rcx)
    3b0c:       48 89 91 28 01 00 00    mov    %rdx,0x128(%rcx)

/* Enter guest mode */

                "jne .Llaunched \n\t"
                __ex(ASM_VMX_VMLAUNCH) "\n\t"
                "jmp .Lkvm_vmx_return \n\t"
                ".Llaunched: " __ex(ASM_VMX_VMRESUME) "\n\t"
                ".Lkvm_vmx_return: "
                /* Save guest registers, load host registers, keep flags */
                "xchg %0,     (%%"R"sp) \n\t"
                "mov %%"R"ax, %c[rax](%0) \n\t"
                "mov %%"R"bx, %c[rbx](%0) \n\t"
                "push"Q" (%%"R"sp); pop"Q" %c[rcx](%0) \n\t"
                "mov %%"R"dx, %c[rdx](%0) \n\t"
                "mov %%"R"si, %c[rsi](%0) \n\t"

Quoted 17 lines · Avi Kivity

Quoted 15 lines · Andrew Theurer

This is on latest master branch on kvm.git and qemu-kvm.git, running 12 Windows Server2008 VMs, and using oprofile. I ran again without oprofile and did not get the BUG. I am wondering if anyone else is seeing this.

Thanks,

-Andrew

Quoted 5 lines

Oct  9 11:55:13 virtvictory-eth0 kernel: BUG: unable to handle kernel
paging request at ffffffff9fe9a2b4
Oct  9 11:55:13 virtvictory-eth0 kernel: IP: [<ffffffffa02e1af1>]

vmx_vcpu_run+0x26d/0x64f [kvm_intel]

Quoted 4 lines

Can you run this through objdump or gdb to see what source this corresponds to?

Somewhere here I think (?)

objdump -d

Quoted 19 lines · Andrew Theurer

Quoted 17 lines · Avi Kivity

Quoted 15 lines · Andrew Theurer

This is on latest master branch on kvm.git and qemu-kvm.git, running 12 Windows Server2008 VMs, and using oprofile. I ran again without oprofile and did not get the BUG. I am wondering if anyone else is seeing this.

Thanks,

-Andrew

Quoted 5 lines

Oct  9 11:55:13 virtvictory-eth0 kernel: BUG: unable to handle kernel
paging request at ffffffff9fe9a2b4
Oct  9 11:55:13 virtvictory-eth0 kernel: IP: [<ffffffffa02e1af1>]

vmx_vcpu_run+0x26d/0x64f [kvm_intel]

Quoted 8 lines

Quoted 4 lines

Can you run this through objdump or gdb to see what source this corresponds to?

Somewhere here I think (?)

objdump -d

Look at the address where vmx_vcpu_run starts, add 0x26d, and show the surrounding code.

Thinking about it, it probably _is_ what you showed, due to module page alignment. But please verify this; I can't reconcile the fault address (ffffffff9fe9a2b) with %rsp at the time of the fault.

0000000000003884 <vmx_vcpu_run>:

    3884:       55                      push   %rbp
    3885:       48 89 e5                mov    %rsp,%rbp

    3ad2:       4c 8b b1 88 01 00 00    mov    0x188(%rcx),%r14
    3ad9:       4c 8b b9 90 01 00 00    mov    0x190(%rcx),%r15
    3ae0:       48 8b 89 20 01 00 00    mov    0x120(%rcx),%rcx
    3ae7:       75 05                   jne    3aee <vmx_vcpu_run+0x26a>

    3ae9:       0f 01 c2                vmlaunch
    3aec:       eb 03                   jmp    3af1 <vmx_vcpu_run+0x26d>
    3aee:       0f 01 c3                vmresume
    3af1:       48 87 0c 24             xchg   %rcx,(%rsp)
    3af5:       48 89 81 18 01 00 00    mov    %rax,0x118(%rcx)
    3afc:       48 89 99 30 01 00 00    mov    %rbx,0x130(%rcx)
    3b03:       ff 34 24                pushq  (%rsp)
    3b06:       8f 81 20 01 00 00       popq   0x120(%rcx)

Quoted 19 lines · Andrew Theurer

Quoted 17 lines · Avi Kivity

Quoted 15 lines · Andrew Theurer

This is on latest master branch on kvm.git and qemu-kvm.git, running 12 Windows Server2008 VMs, and using oprofile. I ran again without oprofile and did not get the BUG. I am wondering if anyone else is seeing this.

Thanks,

-Andrew

Quoted 5 lines

Oct  9 11:55:13 virtvictory-eth0 kernel: BUG: unable to handle kernel
paging request at ffffffff9fe9a2b4
Oct  9 11:55:13 virtvictory-eth0 kernel: IP: [<ffffffffa02e1af1>]

vmx_vcpu_run+0x26d/0x64f [kvm_intel]

Quoted 8 lines

Quoted 4 lines

Can you run this through objdump or gdb to see what source this corresponds to?

Somewhere here I think (?)

objdump -d

Look at the address where vmx_vcpu_run starts, add 0x26d, and show the surrounding code.

Thinking about it, it probably _is_ what you showed, due to module page alignment. But please verify this; I can't reconcile the fault address (ffffffff9fe9a2b) with %rsp at the time of the fault.

Quoted 8 lines

Look at the address where vmx_vcpu_run starts, add 0x26d, and show the surrounding code.

Thinking about it, it probably _is_ what you showed, due to module page alignment. But please verify this; I can't reconcile the fault address (ffffffff9fe9a2b) with %rsp at the time of the fault.

Here is the start of the function:

Quoted 4 lines

0000000000003884<vmx_vcpu_run>:

     3884:       55                      push   %rbp
     3885:       48 89 e5                mov    %rsp,%rbp

and 0x26d later is 0x3af1:

Quoted 13 lines

     3ad2:       4c 8b b1 88 01 00 00    mov    0x188(%rcx),%r14
     3ad9:       4c 8b b9 90 01 00 00    mov    0x190(%rcx),%r15
     3ae0:       48 8b 89 20 01 00 00    mov    0x120(%rcx),%rcx
     3ae7:       75 05                   jne    3aee<vmx_vcpu_run+0x26a>
     3ae9:       0f 01 c2                vmlaunch
     3aec:       eb 03                   jmp    3af1<vmx_vcpu_run+0x26d>
     3aee:       0f 01 c3                vmresume
     3af1:       48 87 0c 24             xchg   %rcx,(%rsp)
     3af5:       48 89 81 18 01 00 00    mov    %rax,0x118(%rcx)
     3afc:       48 89 99 30 01 00 00    mov    %rbx,0x130(%rcx)
     3b03:       ff 34 24                pushq  (%rsp)
     3b06:       8f 81 20 01 00 00       popq   0x120(%rcx)

Quoted 8 lines · Andrew Theurer

Quoted 8 lines

Look at the address where vmx_vcpu_run starts, add 0x26d, and show the surrounding code.

Thinking about it, it probably _is_ what you showed, due to module page alignment. But please verify this; I can't reconcile the fault address (ffffffff9fe9a2b) with %rsp at the time of the fault.

Quoted 24 lines

Here is the start of the function:

Quoted 4 lines

0000000000003884<vmx_vcpu_run>:

     3884:       55                      push   %rbp
     3885:       48 89 e5                mov    %rsp,%rbp

and 0x26d later is 0x3af1:

Quoted 13 lines

     3ad2:       4c 8b b1 88 01 00 00    mov    0x188(%rcx),%r14
     3ad9:       4c 8b b9 90 01 00 00    mov    0x190(%rcx),%r15
     3ae0:       48 8b 89 20 01 00 00    mov    0x120(%rcx),%rcx
     3ae7:       75 05                   jne    3aee<vmx_vcpu_run+0x26a>
     3ae9:       0f 01 c2                vmlaunch
     3aec:       eb 03                   jmp    3af1<vmx_vcpu_run+0x26d>
     3aee:       0f 01 c3                vmresume
     3af1:       48 87 0c 24             xchg   %rcx,(%rsp)
     3af5:       48 89 81 18 01 00 00    mov    %rax,0x118(%rcx)
     3afc:       48 89 99 30 01 00 00    mov    %rbx,0x130(%rcx)
     3b03:       ff 34 24                pushq  (%rsp)
     3b06:       8f 81 20 01 00 00       popq   0x120(%rcx)

Ok. So it faults on the xchg instruction, rsp is ffff8806369ffc80 but the fault address is ffffffff9fe9a2b4. So it looks like the IDT is corrupted.

Can you check what's around ffffffff9fe9a2b4 in System.map?

Quoted 34 lines · Avi Kivity

Quoted 32 lines · Andrew Theurer

Quoted 8 lines

Look at the address where vmx_vcpu_run starts, add 0x26d, and show the surrounding code.

Thinking about it, it probably _is_ what you showed, due to module page alignment. But please verify this; I can't reconcile the fault address (ffffffff9fe9a2b) with %rsp at the time of the fault.

Here is the start of the function:

Quoted 4 lines

0000000000003884<vmx_vcpu_run>:

     3884:       55                      push   %rbp
     3885:       48 89 e5                mov    %rsp,%rbp

and 0x26d later is 0x3af1:

Quoted 13 lines

     3ad2:       4c 8b b1 88 01 00 00    mov    0x188(%rcx),%r14
     3ad9:       4c 8b b9 90 01 00 00    mov    0x190(%rcx),%r15
     3ae0:       48 8b 89 20 01 00 00    mov    0x120(%rcx),%rcx
     3ae7:       75 05                   jne    3aee<vmx_vcpu_run+0x26a>
     3ae9:       0f 01 c2                vmlaunch
     3aec:       eb 03                   jmp    3af1<vmx_vcpu_run+0x26d>
     3aee:       0f 01 c3                vmresume
     3af1:       48 87 0c 24             xchg   %rcx,(%rsp)
     3af5:       48 89 81 18 01 00 00    mov    %rax,0x118(%rcx)
     3afc:       48 89 99 30 01 00 00    mov    %rbx,0x130(%rcx)
     3b03:       ff 34 24                pushq  (%rsp)
     3b06:       8f 81 20 01 00 00       popq   0x120(%rcx)

Quoted 4 lines

Ok. So it faults on the xchg instruction, rsp is ffff8806369ffc80 but the fault address is ffffffff9fe9a2b4. So it looks like the IDT is corrupted.

Merge branch 'for-linus' of git://git./linux/kernel/git/tj/percpu

* 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tj/percpu: (46 commits)
powerpc64: convert to dynamic percpu allocator
sparc64: use embedding percpu first chunk allocator
percpu: kill lpage first chunk allocator
x86,percpu: use embedding for 64bit NUMA and page for 32bit NUMA
percpu: update embedding first chunk allocator to handle sparse units
percpu: use group information to allocate vmap areas sparsely
vmalloc: implement pcpu_get_vm_areas()
vmalloc: separate out insert_vmalloc_vm()
percpu: add chunk->base_addr
percpu: add pcpu_unit_offsets[]
percpu: introduce pcpu_alloc_info and pcpu_group_info
percpu: move pcpu_lpage_build_unit_map() and pcpul_lpage_dump_cfg() upward

percpu: add @align to pcpu_fc_alloc_fn_t
percpu: make @dyn_size mandatory for pcpu_setup_first_chunk()
percpu: drop @static_size from first chunk allocators
percpu: generalize first chunk allocator selection
percpu: build first chunk allocators selectively
percpu: rename 4k first chunk allocator to page
percpu: improve boot messages
percpu: fix pcpu_reclaim() locking

I have finally bisected and isolated this to the following commit:

ada3fa15057205b7d3f727bba5cd26b5912e350f
http://git.kernel.org/?p=virt/kvm/kvm.git;a=commit;h=ada3fa15057205b7d3f727bba5cd26b5912e350f

Quoted 15 lines

Merge branch 'for-linus' of git://git./linux/kernel/git/tj/percpu

* 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tj/percpu: (46 commits)
powerpc64: convert to dynamic percpu allocator
sparc64: use embedding percpu first chunk allocator
percpu: kill lpage first chunk allocator
x86,percpu: use embedding for 64bit NUMA and page for 32bit NUMA
percpu: update embedding first chunk allocator to handle sparse units
percpu: use group information to allocate vmap areas sparsely
vmalloc: implement pcpu_get_vm_areas()
vmalloc: separate out insert_vmalloc_vm()
percpu: add chunk->base_addr
percpu: add pcpu_unit_offsets[]
percpu: introduce pcpu_alloc_info and pcpu_group_info
percpu: move pcpu_lpage_build_unit_map() and pcpul_lpage_dump_cfg() upward

Quoted 9 lines

percpu: add @align to pcpu_fc_alloc_fn_t
percpu: make @dyn_size mandatory for pcpu_setup_first_chunk()
percpu: drop @static_size from first chunk allocators
percpu: generalize first chunk allocator selection
percpu: build first chunk allocators selectively
percpu: rename 4k first chunk allocator to page
percpu: improve boot messages
percpu: fix pcpu_reclaim() locking

The previous commit (5579fd7e6aed8860ea0c8e3f11897493153b10ad) does not this problem. FYI, this problem only occurs when oprofile is active.

Any idea what in this commit might be the issue?

Quoted 32 lines · Andrew Theurer

I have finally bisected and isolated this to the following commit:

ada3fa15057205b7d3f727bba5cd26b5912e350f
http://git.kernel.org/?p=virt/kvm/kvm.git;a=commit;h=ada3fa15057205b7d3f727bba5cd26b5912e350f

Quoted 16 lines

Merge branch 'for-linus' of git://git./linux/kernel/git/tj/percpu

* 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tj/percpu: (46 commits)
powerpc64: convert to dynamic percpu allocator
sparc64: use embedding percpu first chunk allocator
percpu: kill lpage first chunk allocator
x86,percpu: use embedding for 64bit NUMA and page for 32bit NUMA
percpu: update embedding first chunk allocator to handle sparse units
percpu: use group information to allocate vmap areas sparsely
vmalloc: implement pcpu_get_vm_areas()
vmalloc: separate out insert_vmalloc_vm()
percpu: add chunk->base_addr
percpu: add pcpu_unit_offsets[]
percpu: introduce pcpu_alloc_info and pcpu_group_info
percpu: move pcpu_lpage_build_unit_map() and
pcpul_lpage_dump_cfg() upward

Quoted 9 lines

percpu: add @align to pcpu_fc_alloc_fn_t
percpu: make @dyn_size mandatory for pcpu_setup_first_chunk()
percpu: drop @static_size from first chunk allocators
percpu: generalize first chunk allocator selection
percpu: build first chunk allocators selectively
percpu: rename 4k first chunk allocator to page
percpu: improve boot messages
percpu: fix pcpu_reclaim() locking

Quoted 6 lines

The previous commit (5579fd7e6aed8860ea0c8e3f11897493153b10ad) does not this problem. FYI, this problem only occurs when oprofile is active.

Any idea what in this commit might be the issue?

5579 is not the preceding commit, it is the merged branch:

commit ada3fa15057205b7d3f727bba5cd26b5912e350f
Merge: 2f82af0 5579fd7
Author: Linus Torvalds <[email protected]>
Date: Tue Sep 15 09:39:44 2009 -0700

Merge branch 'for-linus' of
git://git.kernel.org/pub/scm/linux/kernel/git/tj/percpu

What happens with 2f82af0?

Nicolas Pitre has a new email address

Due to problems at cam.org, my [email protected] email address is no longer valid. FRom now on, [email protected] should be used instead.

Quoted 7 lines

5579 is not the preceding commit, it is the merged branch:

commit ada3fa15057205b7d3f727bba5cd26b5912e350f
Merge: 2f82af0 5579fd7
Author: Linus Torvalds <[email protected]>
Date: Tue Sep 15 09:39:44 2009 -0700

Quoted 6 lines

Merge branch 'for-linus' of
git://git.kernel.org/pub/scm/linux/kernel/git/tj/percpu

What happens with 2f82af0?

2f82af0 is:

Quoted 4 lines

Nicolas Pitre has a new email address

Due to problems at cam.org, my [email protected] email address is no longer valid. FRom now on, [email protected] should be used instead.

I have not tested that, but it doesn't seem likely that it would have anything to do with the problem. Or maybe I am misunderstanding the impact of this commit?

Oh, wait, that commit was tested, in the middle of the log above.

Quoted 21 lines · Andrew Theurer

Quoted 7 lines

5579 is not the preceding commit, it is the merged branch:

commit ada3fa15057205b7d3f727bba5cd26b5912e350f
Merge: 2f82af0 5579fd7
Author: Linus Torvalds <[email protected]>
Date: Tue Sep 15 09:39:44 2009 -0700

Quoted 6 lines

Merge branch 'for-linus' of
git://git.kernel.org/pub/scm/linux/kernel/git/tj/percpu

What happens with 2f82af0?

2f82af0 is:

Quoted 4 lines

Nicolas Pitre has a new email address

Due to problems at cam.org, my [email protected] email address is no longer valid. FRom now on, [email protected] should be used instead.

Quoted 1 line

I have not tested that, but it doesn't seem likely that it would have anything to do with the problem. Or maybe I am misunderstanding the impact of this commit?

ada3fa15 is known broken. It is the merge of two branches: 2f82 (mainline) and 5597. Testing both branches would indicate the problem is in the merge if both test ok.

Quoted 1 line

Oh, wait, that commit was tested, in the middle of the log above.

So the problem is the merge. Will look.

Only, that merge doesn't change virt/kvm or arch/x86/kvm.

Tejun, anything known bad about that merge? ada3fa15 kills kvm.

Hello,

Quoted 2 lines · Avi Kivity

Only, that merge doesn't change virt/kvm or arch/x86/kvm.

Quoted 2 lines

Tejun, anything known bad about that merge? ada3fa15 kills kvm.

Nothing rings a bell at the moment. How does it kill kvm? One big difference caused by that merge is use of sparse areas near the top of vmalloc area. This caused vmalloc area shortage on sparc64 and exposed paging code bug on ppc64 which caused the cpu to fault repeatedly on the same address. Maybe something similiar is happening with kvm?

    3ae7:       75 05                   jne    3aee<vmx_vcpu_run+0x26a>
      3ae9:       0f 01 c2                vmlaunch
      3aec:       eb 03                   jmp    3af1<vmx_vcpu_run+0x26d>
      3aee:       0f 01 c3                vmresume
      3af1:       48 87 0c 24             xchg   %rcx,(%rsp)

      3af5:       48 89 81 18 01 00 00    mov    %rax,0x118(%rcx)
      3afc:       48 89 99 30 01 00 00    mov    %rbx,0x130(%rcx)

We get a page fault immediately (next instruction) after returning from the guest when running with oprofile. The page fault address does not match anything the instruction does, so presumably it is one of the accesses the processor performs in order to service an NMI (ordinary interrupts are masked; and the fact that it happens with oprofile strengthens this assumption).

If this is correct, the fault is not in the NMI handler itself, but in one of the memory areas the cpu looks in to vector the NMI, which can be:

- the IDT
- the GDT
- the TSS
- the NMI stack

Except for the IDT these are per-cpu structure, though I don't know whether they are allocated with the percpu infrastructure.

Here is the code in question:

Quoted 5 lines

    3ae7:       75 05                   jne    3aee<vmx_vcpu_run+0x26a>
      3ae9:       0f 01 c2                vmlaunch
      3aec:       eb 03                   jmp    3af1<vmx_vcpu_run+0x26d>
      3aee:       0f 01 c3                vmresume
      3af1:       48 87 0c 24             xchg   %rcx,(%rsp)

^^^ fault, but not at (%rsp)

Hello,

Quoted 7 lines · Avi Kivity

We get a page fault immediately (next instruction) after returning from the guest when running with oprofile. The page fault address does not match anything the instruction does, so presumably it is one of the accesses the processor performs in order to service an NMI (ordinary interrupts are masked; and the fact that it happens with oprofile strengthens this assumption).

Ah... okay, that's tricky but IIRC faults like that can be distinguished from regular ones via processor state, right?

Quoted 9 lines

Here is the code in question:

Quoted 6 lines

     3ae7:       75 05                   jne    3aee<vmx_vcpu_run+0x26a>
       3ae9:       0f 01 c2                vmlaunch
       3aec:       eb 03                   jmp    3af1<vmx_vcpu_run+0x26d>
       3aee:       0f 01 c3                vmresume
       3af1:       48 87 0c 24             xchg   %rcx,(%rsp)

Quoted 2 lines

^^^ fault, but not at (%rsp)

Can you please post the full oops (including kernel debug messages during boot) or give me a pointer to the original message?

Also, does
the faulting address coincide with any symbol?

Quoted 11 lines

Quoted 11 lines

Here is the code in question:

Quoted 8 lines

3ae7: 75 05 jne
3aee<vmx_vcpu_run+0x26a>

       3ae9:       0f 01 c2                vmlaunch
       3aec:       eb 03                   jmp   
3af1<vmx_vcpu_run+0x26d>
       3aee:       0f 01 c3                vmresume
       3af1:       48 87 0c 24             xchg   %rcx,(%rsp)

Quoted 4 lines

Quoted 2 lines

^^^ fault, but not at (%rsp)

Can you please post the full oops (including kernel debug messages during boot) or give me a pointer to the original message?

http://www.mail-archive.com/[email protected]/msg23458.html

Quoted 3 lines

Also, does
the faulting address coincide with any symbol?

No (at least, not in System.map).

Hello,

Quoted 15 lines · Avi Kivity

Quoted 15 lines

Quoted 11 lines

Here is the code in question:

Quoted 8 lines

3ae7: 75 05 jne
3aee<vmx_vcpu_run+0x26a>

       3ae9:       0f 01 c2                vmlaunch
       3aec:       eb 03                   jmp   
3af1<vmx_vcpu_run+0x26d>
       3aee:       0f 01 c3                vmresume
       3af1:       48 87 0c 24             xchg   %rcx,(%rsp)

Quoted 2 lines

^^^ fault, but not at (%rsp)

Can you please post the full oops (including kernel debug messages during boot) or give me a pointer to the original message?

Quoted 6 lines

http://www.mail-archive.com/[email protected]/msg23458.html

Quoted 3 lines

Also, does
the faulting address coincide with any symbol?

No (at least, not in System.map).

Has there been any progress? Is kvm + oprofile still broken?

NMI backtrace for cpu 9
CPU 9:

Modules linked in: tun sunrpc af_packet bridge stp ipv6 binfmt_misc dm_mirror dm_region_hash dm_log dm_multipath scsi_dh dm_mod kvm_intel kvm uinput sr_mod cdrom ata_generic pata_acpi ata_piix joydev libata ide_pci_generic usbhid ide_core hid serio_raw cdc_ether usbnet mii matroxfb_base matroxfb_DAC1064 matroxfb_accel matroxfb_Ti3026 matroxfb_g450 g450_pll matroxfb_misc iTCO_wdt i2c_i801 i2c_core pcspkr iTCO_vendor_support ioatdma thermal rtc_cmos rtc_core bnx2 rtc_lib dca thermal_sys hwmon sg button shpchp pci_hotplug qla2xxx scsi_transport_fc scsi_tgt sd_mod scsi_mod crc_t10dif ext3 jbd mbcache uhci_hcd ohci_hcd ehci_hcd usbcore [last unloaded: processor]
Pid: 5687, comm: qemu-system-x86 Not tainted 2.6.32-rc7-5e8cb552cb8b48244b6d07bff984b3c4080d4bc9-autokern1 #1  -[7947AC1]-
RIP: 0010:[<ffffffff810b802b>]  [<ffffffff810b802b>] fire_user_return_notifiers+0x31/0x36
RSP: 0018:ffff88095024df08  EFLAGS: 00000246
RAX: 0000000000000000 RBX: 0000000000000800 RCX: ffff88095024c000
RDX: ffff880028340000 RSI: 0000000000000000 RDI: ffff88095024df58
RBP: ffff88095024df18 R08: 0000000000000000 R09: 0000000000000001
R10: 000000caf1fff62d R11: ffff8805b584de40 R12: 00007fffae48e0f0
R13: 0000000000000000 R14: 0000000000000001 R15: 0000000000000000
FS:  00007f45c69d57c0(0000) GS:ffff880028340000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: fffff9800121056e CR3: 0000000953d36000 CR4: 00000000000026e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Call Trace:
 <#DB[1]>  <<EOE>> Pid: 5687, comm: qemu-system-x86 Not tainted 2.6.32-rc7-5e8cb552cb8b48244b6d07bff984b3c4080d4bc9-autokern1 #1
Call Trace:
 <NMI>  [<ffffffff8100af53>] ? show_regs+0x44/0x49
 [<ffffffff812e57b2>] nmi_watchdog_tick+0xc2/0x1b9
 [<ffffffff812e4e73>] do_nmi+0xb0/0x252
 [<ffffffff812e48a0>] nmi+0x20/0x30
 [<ffffffff810b802b>] ? fire_user_return_notifiers+0x31/0x36
 <<EOE>>  [<ffffffff8100b844>] do_notify_resume+0x62/0x69
 [<ffffffff8100bf48>] ? int_check_syscall_exit_work+0x9/0x3d
 [<ffffffff8100bf8e>] int_signal+0x12/0x17

NMI backtrace for cpu 13
CPU 13:

Modules linked in: tun sunrpc af_packet bridge stp ipv6 binfmt_misc dm_mirror dm_region_hash dm_log dm_multipath scsi_dh dm_mod kvm_intel kvm uinput sr_mod cdrom ata_generic pata_acpi ata_piix joydev libata ide_pci_generic usbhid ide_core hid serio_raw cdc_ether usbnet mii matroxfb_base matroxfb_DAC1064 matroxfb_accel matroxfb_Ti3026 matroxfb_g450 g450_pll matroxfb_misc iTCO_wdt i2c_i801 i2c_core pcspkr iTCO_vendor_support ioatdma thermal rtc_cmos rtc_core bnx2 rtc_lib dca thermal_sys hwmon sg button shpchp pci_hotplug qla2xxx scsi_transport_fc scsi_tgt sd_mod scsi_mod crc_t10dif ext3 jbd mbcache uhci_hcd ohci_hcd ehci_hcd usbcore [last unloaded: processor]
Pid: 5792, comm: qemu-system-x86 Not tainted 2.6.32-rc7-5e8cb552cb8b48244b6d07bff984b3c4080d4bc9-autokern1 #1  -[7947AC1]-
RIP: 0010:[<ffffffff8100bfb0>]  [<ffffffff8100bfb0>] int_restore_rest+0x1d/0x3d
RSP: 0018:ffff88124f491f58  EFLAGS: 00000292
RAX: 0000000000000800 RBX: 00007fff9df852e0 RCX: ffff88124f490000
RDX: ffff88099ff40000 RSI: 0000000000000000 RDI: 000000000000fe2e
RBP: 00007fff9df85260 R08: ffff88124f490000 R09: 0000000000000000
R10: 0000000000000005 R11: ffff880954971da0 R12: 00007fff9df851e0
R13: 0000000000000000 R14: 0000000000000001 R15: 0000000000000000
FS:  00007f73b5b1d7c0(0000) GS:ffff88099ff40000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 00007f8d5a8de9d0 CR3: 0000000eb34d7000 CR4: 00000000000026e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Call Trace:

 <#DB[1]>  <<EOE>> Pid: 5792, comm: qemu-system-x86 Not tainted 2.6.32-rc7-5e8cb552cb8b48244b6d07bff984b3c4080d4bc9-autokern1 #1
Call Trace:
 <NMI>  [<ffffffff8100af53>] ? show_regs+0x44/0x49
 [<ffffffff812e57b2>] nmi_watchdog_tick+0xc2/0x1b9
 [<ffffffff812e4e73>] do_nmi+0xb0/0x252
 [<ffffffff812e48a0>] nmi+0x20/0x30
 [<ffffffff8100bfb0>] ? int_restore_rest+0x1d/0x3d
 <<EOE>> 

I just tried testing tip of kvm.git, but unfortunately I think I might be hitting a different problem, where processes run 100% in kernel mode. In my case, cpus 9 and 13 were stuck, running qemu processes. A stack backtrace for both cpus are below. FWIW, kernel.org 2.6.32-rc7 does not have this problem, or the original problem.

Quoted 21 lines

NMI backtrace for cpu 9
CPU 9:

Modules linked in: tun sunrpc af_packet bridge stp ipv6 binfmt_misc dm_mirror dm_region_hash dm_log dm_multipath scsi_dh dm_mod kvm_intel kvm uinput sr_mod cdrom ata_generic pata_acpi ata_piix joydev libata ide_pci_generic usbhid ide_core hid serio_raw cdc_ether usbnet mii matroxfb_base matroxfb_DAC1064 matroxfb_accel matroxfb_Ti3026 matroxfb_g450 g450_pll matroxfb_misc iTCO_wdt i2c_i801 i2c_core pcspkr iTCO_vendor_support ioatdma thermal rtc_cmos rtc_core bnx2 rtc_lib dca thermal_sys hwmon sg button shpchp pci_hotplug qla2xxx scsi_transport_fc scsi_tgt sd_mod scsi_mod crc_t10dif ext3 jbd mbcache uhci_hcd ohci_hcd ehci_hcd usbcore [last unloaded: processor]
Pid: 5687, comm: qemu-system-x86 Not tainted 2.6.32-rc7-5e8cb552cb8b48244b6d07bff984b3c4080d4bc9-autokern1 #1  
-[7947AC1]-
RIP: 0010:[<ffffffff810b802b>]  [<ffffffff810b802b>] fire_user_return_notifiers+0x31/0x36
RSP: 0018:ffff88095024df08  EFLAGS: 00000246
RAX: 0000000000000000 RBX: 0000000000000800 RCX: ffff88095024c000
RDX: ffff880028340000 RSI: 0000000000000000 RDI: ffff88095024df58
RBP: ffff88095024df18 R08: 0000000000000000 R09: 0000000000000001
R10: 000000caf1fff62d R11: ffff8805b584de40 R12: 00007fffae48e0f0
R13: 0000000000000000 R14: 0000000000000001 R15: 0000000000000000
FS:  00007f45c69d57c0(0000) GS:ffff880028340000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: fffff9800121056e CR3: 0000000953d36000 CR4: 00000000000026e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Call Trace:
<#DB[1]> <<EOE>> Pid: 5687, comm: qemu-system-x86 Not tainted 2.6.32-rc7-5e8cb552cb8b48244b6d07bff984b3c4080d4bc9-autokern1 #1
Call Trace:

Quoted 8 lines

<NMI>  [<ffffffff8100af53>] ? show_regs+0x44/0x49
 [<ffffffff812e57b2>] nmi_watchdog_tick+0xc2/0x1b9
 [<ffffffff812e4e73>] do_nmi+0xb0/0x252
 [<ffffffff812e48a0>] nmi+0x20/0x30
 [<ffffffff810b802b>] ? fire_user_return_notifiers+0x31/0x36
<<EOE>>  [<ffffffff8100b844>] do_notify_resume+0x62/0x69
 [<ffffffff8100bf48>] ? int_check_syscall_exit_work+0x9/0x3d
 [<ffffffff8100bf8e>] int_signal+0x12/0x17

Quoted 21 lines · Andrew Theurer

Quoted 21 lines

NMI backtrace for cpu 9
CPU 9:

Modules linked in: tun sunrpc af_packet bridge stp ipv6 binfmt_misc dm_mirror dm_region_hash dm_log dm_multipath scsi_dh dm_mod kvm_intel kvm uinput sr_mod cdrom ata_generic pata_acpi ata_piix joydev libata ide_pci_generic usbhid ide_core hid serio_raw cdc_ether usbnet mii matroxfb_base matroxfb_DAC1064 matroxfb_accel matroxfb_Ti3026 matroxfb_g450 g450_pll matroxfb_misc iTCO_wdt i2c_i801 i2c_core pcspkr iTCO_vendor_support ioatdma thermal rtc_cmos rtc_core bnx2 rtc_lib dca thermal_sys hwmon sg button shpchp pci_hotplug qla2xxx scsi_transport_fc scsi_tgt sd_mod scsi_mod crc_t10dif ext3 jbd mbcache uhci_hcd ohci_hcd ehci_hcd usbcore [last unloaded: processor]
Pid: 5687, comm: qemu-system-x86 Not tainted 2.6.32-rc7-5e8cb552cb8b48244b6d07bff984b3c4080d4bc9-autokern1 #1  
-[7947AC1]-
RIP: 0010:[<ffffffff810b802b>]  [<ffffffff810b802b>] fire_user_return_notifiers+0x31/0x36
RSP: 0018:ffff88095024df08  EFLAGS: 00000246
RAX: 0000000000000000 RBX: 0000000000000800 RCX: ffff88095024c000
RDX: ffff880028340000 RSI: 0000000000000000 RDI: ffff88095024df58
RBP: ffff88095024df18 R08: 0000000000000000 R09: 0000000000000001
R10: 000000caf1fff62d R11: ffff8805b584de40 R12: 00007fffae48e0f0
R13: 0000000000000000 R14: 0000000000000001 R15: 0000000000000000
FS:  00007f45c69d57c0(0000) GS:ffff880028340000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: fffff9800121056e CR3: 0000000953d36000 CR4: 00000000000026e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Call Trace:
<#DB[1]> <<EOE>> Pid: 5687, comm: qemu-system-x86 Not tainted 2.6.32-rc7-5e8cb552cb8b48244b6d07bff984b3c4080d4bc9-autokern1 #1
Call Trace:

Quoted 9 lines

Quoted 8 lines

<NMI>  [<ffffffff8100af53>] ? show_regs+0x44/0x49
 [<ffffffff812e57b2>] nmi_watchdog_tick+0xc2/0x1b9
 [<ffffffff812e4e73>] do_nmi+0xb0/0x252
 [<ffffffff812e48a0>] nmi+0x20/0x30
 [<ffffffff810b802b>] ? fire_user_return_notifiers+0x31/0x36
<<EOE>>  [<ffffffff8100b844>] do_notify_resume+0x62/0x69
 [<ffffffff8100bf48>] ? int_check_syscall_exit_work+0x9/0x3d
 [<ffffffff8100bf8e>] int_signal+0x12/0x17

That's a bug with the new user return notifiers. Is your host kernel preemptible?

I think I saw this once but I'm not sure. I can't reproduce with a host kernel build, some silly guest workload, and 'perf top' to generate an nmi load.

I just tried testing tip of kvm.git, but unfortunately I think I might be hitting a different problem, where processes run 100% in kernel mode. In my case, cpus 9 and 13 were stuck, running qemu processes. A stack backtrace for both cpus are below. FWIW, kernel.org 2.6.32-rc7 does not have this problem, or the original problem.

Quoted 5 lines · Andrew Theurer

I just tried testing tip of kvm.git, but unfortunately I think I might be hitting a different problem, where processes run 100% in kernel mode. In my case, cpus 9 and 13 were stuck, running qemu processes. A stack backtrace for both cpus are below. FWIW, kernel.org 2.6.32-rc7 does not have this problem, or the original problem.

I just posted a patch fixing this, titled "[PATCH tip:x86/entry] core:
fix user return notifier on fork()".