Re: Oopses with Oprofile and qemu-kvm

["Yang, Sheng" <sheng.yang@intel.com>]

On Friday 14 March 2008 20:31:50 Zdenek Kabelac wrote:
> Hi
>
> I'm trying various thing with qemu to resolve my other issue and I've
> tried to use oprofile.
> But as soon  as I run these:
>
> opcontrol --vmlinux=mine/vmlinux
> opcontrol --start
>
> I get kernel oops (see bellow)

That's known, because the performance counter (a part of PMU) is not ready in 
KVM, which oprofile used for profiling. The MSRs oprofile want to accessed is 
not exist, so KVM inject a #GP to the guest, causing this oops. And even the 
PMU is ready, current KVM also can't support virtual NMI, so oprofile won't 
get sample file in normal condition. 

There is one way to work around this: using oprofile with timer interrupt 
mode. Add "timer=1" module parameter to oprofile. Please refer to oprofile 
manual for detail. 

BTW: I am working on NMI supporting now. 

-- 
Thanks
Yang, Sheng

>
> Is the fault in qemu (i.e. NMI is not emulated) or do I have to use
> some other tools ?
> Or should I report this to lkml ?
>
> [   59.423311] oprofile: using NMI interrupt.
> [   65.125411] general protection fault: 0000 [1] PREEMPT SMP
> [   65.128156] CPU 1
> [   65.128156] Modules linked in: oprofile nfs lockd nfs_acl sunrpc
> autofs4 dm_mod loop rtc psmouse evdev serio_raw i2c
> _piix4 pcnet32 mii i2c_core button
> [   65.128156] Pid: 2584, comm: udevd Not tainted 2.6.25-rc5-replic-server
> #52 [   65.128156] RIP: 0010:[<ffffffff881043e9>]  [<ffffffff881043e9>]
>
> :oprofile:nmi_save_registers+0x49/0xb0
>
> [   65.128156] RSP: 0000:ffff81001f89bf78  EFLAGS: 00000002
> [   65.128156] RAX: 0000000000000001 RBX: 0000000000000000 RCX:
> 00000000000000c1 [   65.128156] RDX: ffffffff88106400 RSI: 0000000000000000
> RDI: ffff81001b9513a8 [   65.128156] RBP: ffff81001f89bf78 R08:
> 0000000000000020 R09: ffff81001b951410 [   65.128156] R10: 0000000000000002
> R11: 0000000000000001 R12: ffffffff881043a0 [   65.128156] R13:
> 0000000000000001 R14: 0000000000000000 R15: ffff81001c1c65a0 [   65.128156]
> FS:  0000000000000000(0000) GS:ffff81001f80f190(0063)
> knlGS:00000000f7d79720
> [   65.128156] CS:  0010 DS: 002b ES: 002b CR0: 000000008005003b
> [   65.128156] CR2: 00000000f7dad1b0 CR3: 000000001b93b000 CR4:
> 00000000000006e0 [   65.128156] DR0: 0000000000000000 DR1: 0000000000000000
> DR2: 0000000000000000 [   65.128156] DR3: 0000000000000000 DR6:
> 00000000ffff0ff0 DR7: 0000000000000400 [   65.128156] Process udevd (pid:
> 2584, threadinfo ffff81001b004000, task ffff81001bba8000)
> [   65.128156] Stack:  ffff81001f89bfa8 ffffffff8101f74f
> aaaaaaaaaaaaaaab ffff81001c0f1d68
> [   65.128156]  ffff810002666220 0000000000000000 ffff81001b005c30
> ffffffff8100d25b
> [   65.128156]  ffff81001b005c30 <EOI>  ffff81001b005d48
> 0000000000000001 0000000000000000
> [   65.128156] Call Trace:
> [   65.128156]  <IRQ>  [<ffffffff8101f74f>]
> smp_call_function_interrupt+0x4f/0x80
> [   65.128156]  [<ffffffff8100d25b>] call_function_interrupt+0x6b/0x70
> [   65.128156]  <EOI>  [<ffffffff8109bd60>] ? __do_fault+0x240/0x580
> [   65.128156]  [<ffffffff8109bcdd>] ? __do_fault+0x1bd/0x580
> [   65.128156]  [<ffffffff8109df4d>] ? handle_mm_fault+0x26d/0x8c0
> [   65.128156]  [<ffffffff812f8cac>] ? do_page_fault+0x3fc/0xb50
> [   65.128156]  [<ffffffff81058171>] ? hrtimer_start+0xe1/0x1a0
> [   65.128156]  [<ffffffff8106157a>] ? get_lock_stats+0x2a/0x70
> [   65.128156]  [<ffffffff810615ce>] ? put_lock_stats+0xe/0x30
> [   65.128156]  [<ffffffff810415b3>] ? do_setitimer+0x393/0x3b0
> [   65.128156]  [<ffffffff812f59b2>] ? _spin_unlock_irq+0x32/0x80
> [   65.128156]  [<ffffffff81063461>] ? trace_hardirqs_on+0x131/0x190
> [   65.128156]  [<ffffffff812f59bd>] ? _spin_unlock_irq+0x3d/0x80
> [   65.128156]  [<ffffffff810415b3>] ? do_setitimer+0x393/0x3b0
> [   65.128156]  [<ffffffff812f5151>] ? trace_hardirqs_on_thunk+0x35/0x3a
> [   65.128156]  [<ffffffff812f646d>] ? error_exit+0x0/0xa9
> [   65.128156]
> [   65.128156]
> [   65.128156] Code: b8 60 c6 10 88 4c 8b 88 68 c6 10 88 85 c9 74 3b
> 8d 41 ff 31 f6 4c 8d 40 01 49 c1 e0 04 0f 1f 44 00
>  00 48 8b 0c 37 48 85 c9 74 17 <0f> 32 48 c1 e2 20 89 c0 48 09 c2 89
> 54 37 0c 48 c1 ea 20 89 54
> [   65.128156] RIP  [<ffffffff881043e9>]
> :oprofile:nmi_save_registers+0x49/0xb0 [   65.128156]  RSP
> <ffff81001f89bf78>
> [   65.128156] ---[ end trace e503d3702565a4da ]---
> [   65.128156] Kernel panic - not syncing: Aiee, killing interrupt handler!
>
>
> Or another one:
>
> [   69.388548] oprofile: using NMI interrupt.
> [   78.377689] general protection fault: 0000 [1] PREEMPT SMP
> [   78.378754] CPU 0
> [   78.378754] Modules linked in: oprofile nfs lockd nfs_acl sunrpc
> autofs4 dm_mod loop psmouse i2c_piix4 evdev rtc ser
> io_raw i2c_core pcnet32 mii button
> [   78.378754] Pid: 506, comm: udevd Not tainted 2.6.25-rc5-replic-server
> #52 [   78.378754] RIP: 0010:[<ffffffff881063e9>]  [<ffffffff881063e9>]
>
> :oprofile:nmi_save_registers+0x49/0xb0
>
> [   78.378754] RSP: 0018:ffffffff81559f78  EFLAGS: 00000002
> [   78.378754] RAX: 0000000000000001 RBX: 0000000000000000 RCX:
> 00000000000000c1 [   78.378754] RDX: ffffffff88108400 RSI: 0000000000000000
> RDI: ffff81001b589000 [   78.378754] RBP: ffffffff81559f78 R08:
> 0000000000000020 R09: ffff81001b589270 [   78.378754] R10: 0000000000000002
> R11: 0000000000000001 R12: ffffffff881063a0 [   78.378754] R13:
> 0000000000000001 R14: ffff81001f20c000 R15: ffffffffffffffff [   78.378754]
> FS:  0000000000000000(0000) GS:ffffffff8148c000(0063)
> knlGS:00000000f7e59720
> [   78.378754] CS:  0010 DS: 002b ES: 002b CR0: 000000008005003b
> [   78.378754] CR2: 00000000080f0d78 CR3: 000000001f109000 CR4:
> 00000000000006e0 [   78.378754] DR0: 0000000000000000 DR1: 0000000000000000
> DR2: 0000000000000000 [   78.378754] DR3: 0000000000000000 DR6:
> 00000000ffff0ff0 DR7: 0000000000000400 [   78.378754] Process udevd (pid:
> 506, threadinfo ffff81001f204000, task ffff81001f20c000)
> [   78.378754] Stack:  ffffffff81559fa8 ffffffff8101f74f
> 0000000000059897 ffff81001f2401e0
> [   78.378754]  ffff81001f2401e8 0000000000000246 ffff81001f205d90
> ffffffff8100d25b
> [   78.378754]  ffff81001f205d90 <EOI>  ffff81001f205e98
> 0000000000000001 0000000000000001
> [   78.378754] Call Trace:
> [   78.378754]  <IRQ>  [<ffffffff8101f74f>]
> smp_call_function_interrupt+0x4f/0x80
> [   78.378754]  [<ffffffff8100d25b>] call_function_interrupt+0x6b/0x70
> [   78.378754]  <EOI>  [<ffffffff812f3938>] ? mutex_lock_nested+0x2a8/0x330
> [   78.378754]  [<ffffffff810c601c>] ? do_unlinkat+0xbc/0x1d0
> [   78.378754]  [<ffffffff810c601c>] ? do_unlinkat+0xbc/0x1d0
> [   78.378754]  [<ffffffff810babbd>] ? fput+0x1d/0x30
> [   78.378754]  [<ffffffff812f518b>] ? trace_hardirqs_off_thunk+0x35/0x37
> [   78.378754]  [<ffffffff810c6141>] ? sys_unlink+0x11/0x20
> [   78.378754]  [<ffffffff81028e22>] ? sysenter_do_call+0x1b/0x70
> [   78.378754]  [<ffffffff812f5151>] ? trace_hardirqs_on_thunk+0x35/0x3a
> [   78.378754]
> [   78.378754]
> [   78.378754] Code: b8 60 e6 10 88 4c 8b 88 68 e6 10 88 85 c9 74 3b
> 8d 41 ff 31 f6 4c 8d 40 01 49 c1 e0 04 0f 1f 44 00
>  00 48 8b 0c 37 48 85 c9 74 17 <0f> 32 48 c1 e2 20 89 c0 48 09 c2 89
> 54 37 0c 48 c1 ea 20 89 54
> [   78.378754] RIP  [<ffffffff881063e9>]
> :oprofile:nmi_save_registers+0x49/0xb0 [   78.378754]  RSP
> <ffffffff81559f78>
> [   78.378754] ---[ end trace b14ff686483a94a5 ]---
> [   78.378754] Kernel panic - not syncing: Aiee, killing interrupt handler!
>
> Or others....
>
> Zdenek
>
> -------------------------------------------------------------------------
> This SF.net email is sponsored by: Microsoft
> Defy all challenges. Microsoft(R) Visual Studio 2008.
> http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/
> _______________________________________________
> kvm-devel mailing list
> kvm-devel@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/kvm-devel




-------------------------------------------------------------------------
This SF.net email is sponsored by: Microsoft
Defy all challenges. Microsoft(R) Visual Studio 2008.
http://clk.atdmt.com/MRT/go/vse0120000070mrt/direct/01/