VCPUOP_initialise oops during VM boot

[marmarek]

Reported by rafal on 21 Jul 2011 13:47 UTC
Especially when under cpu load, VM kernel dies with

[    0.128114] kernel BUG at /home/user/kernel-dom0.rafal.git.test/kernel-2.6.38.3/linux-2.6.38.3/drivers/xen/core/smpboot.c:213!

This line is

        if (HYPERVISOR_vcpu_op(VCPUOP_initialise, cpu, &ctxt))
                BUG();

Full log below. RAX seems to be -ENOMEM.

[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Linux version 2.6.38.3-6.xenlinux.qubes.x86_64 (geeko@buildhost) (gcc version 4.5.1 20100924 (Red Hat 4.5.1-4) (GCC) ) #1 SMP Thu Jul 21 07:54:43 EDT 2011
[    0.000000] Command line: root=/dev/mapper/dmroot ro nomodeset xencons=hvc rd_NO_PLYMOUTH 3 
[    0.000000] Xen-provided physical RAM map:
[    0.000000]  Xen: 0000000000000000 - 000000007a100000 (usable)
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] last_pfn = 0x7a100 max_arch_pfn = 0x80000000
[    0.000000] init_memory_mapping: 0000000000000000-000000007a100000
[    0.000000] RAMDISK: 00869000 - 01c09000
[    0.000000] ACPI in unprivileged domain disabled
[    0.000000] Zone PFN ranges:
[    0.000000]   DMA      0x00000000 -> 0x00001000
[    0.000000]   DMA32    0x00001000 -> 0x00100000
[    0.000000]   Normal   empty
[    0.000000] Movable zone start PFN for each node
[    0.000000] early_node_map[active PFN ranges
[    0.000000](2])     0: 0x00000000 -> 0x00019000
[    0.000000]     0: 0x0007a100 -> 0x0007a100
[    0.000000] setup_percpu: NR_CPUS:512 nr_cpumask_bits:512 nr_cpu_ids:4 nr_node_ids:1
[    0.000000] PERCPU: Embedded 18 pages/cpu @ffff880017115000 s43392 r8192 d22144 u73728
[    0.000000] Swapping MFNs for PFN 71a and 1711b (MFN 108c12 and 2d77b)
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 95564
[    0.000000] Kernel command line: root=/dev/mapper/dmroot ro nomodeset xencons=hvc rd_NO_PLYMOUTH 3 
[    0.000000] PID hash table entries: 2048 (order: 2, 16384 bytes)
[    0.000000] Dentry cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 32768 (order: 6, 262144 bytes)
[    0.000000] allocated 19998720 bytes of page_cgroup
[    0.000000] please try 'cgroup_disable=memory' option if you don't want memory cgroups
[    0.000000] Software IO TLB disabled
[    0.000000] Memory: 325052k/1999872k available (4128k kernel code, 1590272k absent, 84548k reserved, 3106k data, 368k init)
[    0.000000] Hierarchical RCU implementation.
[    0.000000]  RCU dyntick-idle grace-period acceleration is enabled.
[    0.000000]  RCU-based detection of stalled CPUs is disabled.
[    0.000000] NR_IRQS:38912 nr_irqs:2624 16
[    0.000000] Xen reported: 3192.122 MHz processor.
[    0.000000] Console: colour dummy device 80x25
[    0.000000] console [enabled
[    0.000000](tty0]) console [enabled
[    0.080013](hvc0]) Calibrating delay using timer specific routine.. 6487.87 BogoMIPS (lpj=12975751)
[    0.080032] pid_max: default: 32768 minimum: 301
[    0.080137] Mount-cache hash table entries: 256
[    0.080240] Initializing cgroup subsys ns
[    0.080246] ns_cgroup deprecated: consider using the 'clone_children' flag without the ns_cgroup.
[    0.080252] Initializing cgroup subsys cpuacct
[    0.080257] Initializing cgroup subsys memory
[    0.080266] Initializing cgroup subsys devices
[    0.080270] Initializing cgroup subsys freezer
[    0.080274] Initializing cgroup subsys net_cls
[    0.080278] Initializing cgroup subsys blkio
[    0.080355] SMP alternatives: switching to UP code
[    0.104002] Brought up 1 CPUs
[    0.104043] devtmpfs: initialized
[    0.104281] print_constraints: dummy: 
[    0.124204] Time: 165:165:165  Date: 165/165/65
[    0.124349] NET: Registered protocol family 16
[    0.128104] ------------[ cut here ]------------
[    0.128114] kernel BUG at /home/user/kernel-dom0.rafal.git.test/kernel-2.6.38.3/linux-2.6.38.3/drivers/xen/core/smpboot.c:213!
[    0.128120] invalid opcode: 0000 [SMP 
[    0.128124](#1]) last sysfs file: 
[    0.128126] CPU 0 
[    0.128127] Modules linked in:
[    0.128132] 
[    0.128134] Pid: 1, comm: swapper Not tainted 2.6.38.3-6.xenlinux.qubes.x86_64 #1  
[    0.128140] RIP: e030:[ [<ffffffff803fb800>](<ffffffff803fb800>]) cpu_initialize_context+0x18b/0x1d3
[    0.128153] RSP: e02b:ffff8800158e1db0  EFLAGS: 00010282
[    0.128156] RAX: fffffffffffffff4 RBX: 0000000000000001 RCX: 0000000000000067
[    0.128160] RDX: ffffffff8083e8a0 RSI: 0000000000000001 RDI: 0000000000000000
[    0.128164] RBP: ffff8800158ec0c0 R08: 00000000000005c0 R09: 00003ffffffff000
[    0.128168] R10: dead000000100100 R11: 0000000000000040 R12: 0000000000000000
[    0.128172] R13: 0000000000000001 R14: 0000000000000000 R15: 0000000000000000
[    0.128181] FS:  0000000000000000(0000) GS:ffff880017115000(0000) knlGS:0000000000000000
[    0.128186] CS:  e033 DS: 0000 ES: 0000 CR0: 000000008005003b
[    0.128190] CR2: 0000000000000000 CR3: 0000000000774000 CR4: 0000000000002660
[    0.128194] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[    0.128198] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[    0.128203] Process swapper (pid: 1, threadinfo ffff8800158e0000, task ffff8800158de040)
[    0.128207] Stack:
[    0.128209]  0000000000000000 0000000100000001 0000000000000001 0000000000000001
[    0.128215]  0000000000000000 ffffffff803fb992 0000000000000000 ffffffff803f977d
[    0.128222]  ffff8800158e1e00 00000019158e1e50 ffff8800158e1e10 0000000000000001
[    0.128228] Call Trace:
[    0.128239]  [__cpu_up+0x13/0x62
[    0.128245](<ffffffff803fb992>])  [_cpu_up+0x92/0xe1
[    0.128252](<ffffffff803f977d>])  [cpu_up+0x46/0x56
[    0.128257](<ffffffff803f9812>])  [vcpu_hotplug+0x9d/0x10f
[    0.128263](<ffffffff803fb4eb>])  [setup_cpu_watcher+0x35/0x83
[    0.128272](<ffffffff803fb5dd>])  [setup_vcpu_hotplug_event+0x1c/0x23
[    0.128280](<ffffffff8073ee2b>])  [do_one_initcall+0x3a/0x190
[    0.128287](<ffffffff8000413a>])  [kernel_init+0x188/0x20f
[    0.128294](<ffffffff8071fcd0>])  [kernel_thread_helper+0x4/0x10
[    0.128299](<ffffffff80007d64>]) Code: ff 89 de 48 89 05 51 44 44 00 89 d8 48 c7 c2 a0 e8 83 80 48 8b 04 c5 80 c2 70 80 48 89 05 c9 44 44 00 e8 04 7b c0 ff 85 c0 74 02 <0f> 0b 66 ff 05 77 30 44 00 8b 35 71 30 44 00 0f a4 f2 10 66 39 
[    0.128338] RIP  [cpu_initialize_context+0x18b/0x1d3
[    0.128344](<ffffffff803fb800>])  RSP <ffff8800158e1db0>
[    0.128352] ---[ end trace 4eaa2a86a8e2da22 ]---

Migrated-From: https://wiki.qubes-os.org/ticket/306

[marmarek]

Modified by rafal on 21 Jul 2011 15:52 UTC

[marmarek]

Modified by rafal on 21 Jul 2011 15:52 UTC

[marmarek]

Comment by rafal on 21 Jul 2011 16:24 UTC
This bug is difficult to reproduce (I am currently at XID 568), but the possible bad scenario (a tight race condition), is:

1. there is a lot of xen free memory (e.g. a domain has just been destroyed)
2. because of 1, qmemman orders domains to increase their memory
3. qmemman receives a request for memory to start a new domain. It sees plenty of it, so does nothing.
4. because of 2), domains start to use up xen free memory. When the new VM kernel finally boots, there is 0 free xen memory, and VCPUOP_initialise hypercall fails with ENOMEM.

It is unclear how to fix this. Moreover, this scenario is unlikely to occur in real life - probably only quick domain destroy/create cycles can trigger this.

[marmarek]

Comment by rafal on 21 Jul 2011 16:24 UTC
This bug is difficult to reproduce (I am currently at XID 568), but the possible bad scenario (a tight race condition), is:

1. there is a lot of xen free memory (e.g. a domain has just been destroyed)
2. because of 1, qmemman orders domains to increase their memory
3. qmemman receives a request for memory to start a new domain. It sees plenty of it, so does nothing.
4. because of 2), domains start to use up xen free memory. When the new VM kernel finally boots, there is 0 free xen memory, and VCPUOP_initialise hypercall fails with ENOMEM.

It is unclear how to fix this. Moreover, this scenario is unlikely to occur in real life - probably only quick domain destroy/create cycles can trigger this.

[marmarek]

Comment by rafal on 22 Jul 2011 13:29 UTC
With the above race fixed, the problem still occurs.
Quite possibly xl child process actions interfere with qmemman. Moving release of qmemman handle past successful qrexec_agent connect allows for 350 successful VM starts.
Fixed at http://git.qubes-os.org/?p=rafal/core.git;a=commit;h=7cfbe1c7d8decada7257c9f9927d4523696e1a8b
prebeta2 branch.

[marmarek]

Comment by rafal on 22 Jul 2011 13:29 UTC
With the above race fixed, the problem still occurs.
Quite possibly xl child process actions interfere with qmemman. Moving release of qmemman handle past successful qrexec_agent connect allows for 350 successful VM starts.
Fixed at http://git.qubes-os.org/?p=rafal/core.git;a=commit;h=7cfbe1c7d8decada7257c9f9927d4523696e1a8b
prebeta2 branch.

[marmarek]

Modified by rafal on 25 Jul 2011 07:43 UTC

[marmarek]

Modified by rafal on 25 Jul 2011 07:43 UTC