Failed device allocation

[johny...@sigaint.org]

Quite frequently, under Debian-8, when I go to assign a device, it quietly
appears to work (Qubes Manager shows it assigned), but the device never
shows up, and the VM's dmesg shows things like this:

[Tue Sep 20 13:17:09 2016] xenwatch: page allocation failure: order:5,
mode:0x240c0c0
[Tue Sep 20 13:17:09 2016] CPU: 0 PID: 16 Comm: xenwatch Tainted: G
O 4.4.14-11.pvops.qubes.x86_64 #1
[Tue Sep 20 13:17:09 2016] 000000000000023a 0000000037654cb4
ffff880004b6b928 ffffffff813b06f3
[Tue Sep 20 13:17:09 2016] 000000000240c0c0 0000000000000000
ffff880004b6b9b8 ffffffff811a58fa
[Tue Sep 20 13:17:09 2016] 0000000100000040 0000000004b6b950
0000000037654cb4 0000000000000005
[Tue Sep 20 13:17:09 2016] Call Trace:
[Tue Sep 20 13:17:09 2016] [<ffffffff813b06f3>] dump_stack+0x63/0x90
[Tue Sep 20 13:17:09 2016] [<ffffffff811a58fa>] warn_alloc_failed+0xfa/0x160
[Tue Sep 20 13:17:09 2016] [<ffffffff811a9509>]
__alloc_pages_nodemask+0x349/0xb40
[Tue Sep 20 13:17:09 2016] [<ffffffff811f4a4c>]
alloc_pages_current+0x8c/0x110
[Tue Sep 20 13:17:09 2016] [<ffffffff811a7b39>] alloc_kmem_pages+0x19/0x90
[Tue Sep 20 13:17:09 2016] [<ffffffff811c523e>]
kmalloc_order_trace+0x2e/0xe0
[Tue Sep 20 13:17:09 2016] [<ffffffff8147dcb2>] ?
xenbus_read_otherend_details+0x62/0xd0
[Tue Sep 20 13:17:09 2016] [<ffffffffa000603e>] blkfront_probe+0x8e/0x236
[xen_blkfront]
[Tue Sep 20 13:17:09 2016] [<ffffffff8147e1d9>] xenbus_dev_probe+0x89/0x160
[Tue Sep 20 13:17:09 2016] [<ffffffff8147f8b8>]
xenbus_frontend_dev_probe+0x48/0x50
[Tue Sep 20 13:17:09 2016] [<ffffffff814e59b2>]
driver_probe_device+0x222/0x490
[Tue Sep 20 13:17:09 2016] [<ffffffff814e5d21>]
__device_attach_driver+0x71/0xa0
[Tue Sep 20 13:17:09 2016] [<ffffffff814e5cb0>] ? __driver_attach+0x90/0x90
[Tue Sep 20 13:17:09 2016] [<ffffffff814e3557>] bus_for_each_drv+0x67/0xb0
[Tue Sep 20 13:17:09 2016] [<ffffffff814e568c>] __device_attach+0xdc/0x170
[Tue Sep 20 13:17:09 2016] [<ffffffff814e5d93>]
device_initial_probe+0x13/0x20
[Tue Sep 20 13:17:09 2016] [<ffffffff814e4942>] bus_probe_device+0x92/0xa0
[Tue Sep 20 13:17:09 2016] [<ffffffff814e24db>] device_add+0x40b/0x680
[Tue Sep 20 13:17:09 2016] [<ffffffff814e276a>] device_register+0x1a/0x20
[Tue Sep 20 13:17:09 2016] [<ffffffff8147df02>]
xenbus_probe_node+0x172/0x190
[Tue Sep 20 13:17:09 2016] [<ffffffff8147e0e9>]
xenbus_dev_changed+0x1c9/0x1d0
[Tue Sep 20 13:17:09 2016] [<ffffffff8147cb00>] ?
register_xenbus_watch+0xf0/0xf0
[Tue Sep 20 13:17:09 2016] [<ffffffff8147fdc5>] frontend_changed+0x25/0x50
[Tue Sep 20 13:17:09 2016] [<ffffffff8147cb91>] xenwatch_thread+0x91/0x140
[Tue Sep 20 13:17:09 2016] [<ffffffff810e11c0>] ?
wake_atomic_t_function+0x70/0x70
[Tue Sep 20 13:17:09 2016] [<ffffffff810bd548>] kthread+0xd8/0xf0
[Tue Sep 20 13:17:09 2016] [<ffffffff810bd470>] ?
kthread_create_on_node+0x190/0x190
[Tue Sep 20 13:17:09 2016] [<ffffffff81756c8f>] ret_from_fork+0x3f/0x70
[Tue Sep 20 13:17:09 2016] [<ffffffff810bd470>] ?
kthread_create_on_node+0x190/0x190
[Tue Sep 20 13:17:09 2016] Mem-Info:
[Tue Sep 20 13:17:09 2016] active_anon:7391 inactive_anon:8741
isolated_anon:0
active_file:11006 inactive_file:10713 isolated_file:0
unevictable:2407 dirty:0 writeback:0 unstable:0
slab_reclaimable:4436 slab_unreclaimable:2617
mapped:4353 shmem:444 pagetables:1547 bounce:0
free:504 free_pcp:0 free_cma:0
[Tue Sep 20 13:17:09 2016] Node 0 DMA free:480kB min:268kB low:332kB
high:400kB active_anon:736kB inactive_anon:824kB active_file:1312kB
inactive_file:1116kB unevictable:16kB isolated(anon):0kB
isolated(file):0kB present:15996kB managed:15912kB mlocked:16kB dirty:0kB
writeback:0kB mapped:988kB shmem:20kB slab_reclaimable:2700kB
slab_unreclaimable:1632kB kernel_stack:224kB pagetables:304kB unstable:0kB
bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB
pages_scanned:0 all_unreclaimable? no
[Tue Sep 20 13:17:09 2016] lowmem_reserve[]: 0 38 38 38
[Tue Sep 20 13:17:09 2016] Node 0 DMA32 free:1536kB min:668kB low:832kB
high:1000kB active_anon:28828kB inactive_anon:34140kB active_file:42712kB
inactive_file:41736kB unevictable:9612kB isolated(anon):0kB
isolated(file):0kB present:1028096kB managed:216048kB mlocked:9612kB
dirty:0kB writeback:0kB mapped:16424kB shmem:1756kB
slab_reclaimable:15044kB slab_unreclaimable:8836kB kernel_stack:2032kB
pagetables:5884kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB
free_cma:0kB writeback_tmp:0kB pages_scanned:8 all_unreclaimable? no
[Tue Sep 20 13:17:09 2016] lowmem_reserve[]: 0 0 0 0
[Tue Sep 20 13:17:09 2016] Node 0 DMA: 68*4kB (UE) 18*8kB (UME) 4*16kB
(UM) 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB =
480kB
[Tue Sep 20 13:17:09 2016] Node 0 DMA32: 67*4kB (ME) 33*8kB (ME) 17*16kB
(ME) 17*32kB (UME) 3*64kB (UE) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB
0*4096kB = 1540kB
[Tue Sep 20 13:17:09 2016] 23086 total pagecache pages
[Tue Sep 20 13:17:09 2016] 924 pages in swap cache
[Tue Sep 20 13:17:09 2016] Swap cache stats: add 9783, delete 8859, find
3262/4914
[Tue Sep 20 13:17:09 2016] Free swap = 1024996kB
[Tue Sep 20 13:17:09 2016] Total swap = 1048572kB
[Tue Sep 20 13:17:09 2016] 261023 pages RAM
[Tue Sep 20 13:17:09 2016] 0 pages HighMem/MovableOnly
[Tue Sep 20 13:17:09 2016] 203033 pages reserved
[Tue Sep 20 13:17:09 2016] 0 pages hwpoisoned
[Tue Sep 20 13:17:09 2016] vbd vbd-51856: 12 allocating info structure
[Tue Sep 20 13:17:09 2016] vbd vbd-51856: 12 xenbus_dev_probe on
device/vbd/51856
[Tue Sep 20 13:17:09 2016] vbd: probe of vbd-51856 failed with error -12
[Tue Sep 20 13:17:22 2016] xenwatch: page allocation failure: order:5,
mode:0x240c0c0
[Tue Sep 20 13:17:22 2016] CPU: 0 PID: 16 Comm: xenwatch Tainted: G
O 4.4.14-11.pvops.qubes.x86_64 #1
[Tue Sep 20 13:17:22 2016] 000000000000023a 0000000037654cb4
ffff880004b6b928 ffffffff813b06f3
[Tue Sep 20 13:17:22 2016] 000000000240c0c0 0000000000000000
ffff880004b6b9b8 ffffffff811a58fa
[Tue Sep 20 13:17:22 2016] 0000000100000040 0000000004b6b950
0000000037654cb4 0000000000000005
[Tue Sep 20 13:17:22 2016] Call Trace:
[Tue Sep 20 13:17:22 2016] [<ffffffff813b06f3>] dump_stack+0x63/0x90
[Tue Sep 20 13:17:22 2016] [<ffffffff811a58fa>]
warn_alloc_failed+0xfa/0x160[Tue Sep 20 13:17:09 2016] xenwatch: page
allocation failure: order:5, mode:0x240c0c0
[Tue Sep 20 13:17:09 2016] CPU: 0 PID: 16 Comm: xenwatch Tainted: G
O 4.4.14-11.pvops.qubes.x86_64 #1
[Tue Sep 20 13:17:09 2016] 000000000000023a 0000000037654cb4
ffff880004b6b928 ffffffff813b06f3
[Tue Sep 20 13:17:09 2016] 000000000240c0c0 0000000000000000
ffff880004b6b9b8 ffffffff811a58fa
[Tue Sep 20 13:17:09 2016] 0000000100000040 0000000004b6b950
0000000037654cb4 0000000000000005
[Tue Sep 20 13:17:09 2016] Call Trace:
[Tue Sep 20 13:17:09 2016] [<ffffffff813b06f3>] dump_stack+0x63/0x90
[Tue Sep 20 13:17:09 2016] [<ffffffff811a58fa>] warn_alloc_failed+0xfa/0x160
[Tue Sep 20 13:17:09 2016] [<ffffffff811a9509>]
__alloc_pages_nodemask+0x349/0xb40
[Tue Sep 20 13:17:09 2016] [<ffffffff811f4a4c>]
alloc_pages_current+0x8c/0x110
[Tue Sep 20 13:17:09 2016] [<ffffffff811a7b39>] alloc_kmem_pages+0x19/0x90
[Tue Sep 20 13:17:09 2016] [<ffffffff811c523e>]
kmalloc_order_trace+0x2e/0xe0
[Tue Sep 20 13:17:09 2016] [<ffffffff8147dcb2>] ?
xenbus_read_otherend_details+0x62/0xd0
[Tue Sep 20 13:17:09 2016] [<ffffffffa000603e>] blkfront_probe+0x8e/0x236
[xen_blkfront]
[Tue Sep 20 13:17:09 2016] [<ffffffff8147e1d9>] xenbus_dev_probe+0x89/0x160
[Tue Sep 20 13:17:09 2016] [<ffffffff8147f8b8>]
xenbus_frontend_dev_probe+0x48/0x50
[Tue Sep 20 13:17:09 2016] [<ffffffff814e59b2>]
driver_probe_device+0x222/0x490
[Tue Sep 20 13:17:09 2016] [<ffffffff814e5d21>]
__device_attach_driver+0x71/0xa0
[Tue Sep 20 13:17:09 2016] [<ffffffff814e5cb0>] ? __driver_attach+0x90/0x90
[Tue Sep 20 13:17:09 2016] [<ffffffff814e3557>] bus_for_each_drv+0x67/0xb0
[Tue Sep 20 13:17:09 2016] [<ffffffff814e568c>] __device_attach+0xdc/0x170
[Tue Sep 20 13:17:09 2016] [<ffffffff814e5d93>]
device_initial_probe+0x13/0x20
[Tue Sep 20 13:17:09 2016] [<ffffffff814e4942>] bus_probe_device+0x92/0xa0
[Tue Sep 20 13:17:09 2016] [<ffffffff814e24db>] device_add+0x40b/0x680
[Tue Sep 20 13:17:09 2016] [<ffffffff814e276a>] device_register+0x1a/0x20
[Tue Sep 20 13:17:09 2016] [<ffffffff8147df02>]
xenbus_probe_node+0x172/0x190
[Tue Sep 20 13:17:09 2016] [<ffffffff8147e0e9>]
xenbus_dev_changed+0x1c9/0x1d0
[Tue Sep 20 13:17:09 2016] [<ffffffff8147cb00>] ?
register_xenbus_watch+0xf0/0xf0
[Tue Sep 20 13:17:09 2016] [<ffffffff8147fdc5>] frontend_changed+0x25/0x50
[Tue Sep 20 13:17:09 2016] [<ffffffff8147cb91>] xenwatch_thread+0x91/0x140
[Tue Sep 20 13:17:09 2016] [<ffffffff810e11c0>] ?
wake_atomic_t_function+0x70/0x70
[Tue Sep 20 13:17:09 2016] [<ffffffff810bd548>] kthread+0xd8/0xf0
[Tue Sep 20 13:17:09 2016] [<ffffffff810bd470>] ?
kthread_create_on_node+0x190/0x190
[Tue Sep 20 13:17:09 2016] [<ffffffff81756c8f>] ret_from_fork+0x3f/0x70
[Tue Sep 20 13:17:09 2016] [<ffffffff810bd470>] ?
kthread_create_on_node+0x190/0x190
[Tue Sep 20 13:17:09 2016] Mem-Info:
[Tue Sep 20 13:17:09 2016] active_anon:7391 inactive_anon:8741
isolated_anon:0
active_file:11006 inactive_file:10713 isolated_file:0
unevictable:2407 dirty:0 writeback:0 unstable:0
slab_reclaimable:4436 slab_unreclaimable:2617
mapped:4353 shmem:444 pagetables:1547 bounce:0
free:504 free_pcp:0 free_cma:0
[Tue Sep 20 13:17:09 2016] Node 0 DMA free:480kB min:268kB low:332kB
high:400kB active_anon:736kB inactive_anon:824kB active_file:1312kB
inactive_file:1116kB unevictable:16kB isolated(anon):0kB
isolated(file):0kB present:15996kB managed:15912kB mlocked:16kB dirty:0kB
writeback:0kB mapped:988kB shmem:20kB slab_reclaimable:2700kB
slab_unreclaimable:1632kB kernel_stack:224kB pagetables:304kB unstable:0kB
bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB
pages_scanned:0 all_unreclaimable? no
[Tue Sep 20 13:17:09 2016] lowmem_reserve[]: 0 38 38 38
[Tue Sep 20 13:17:09 2016] Node 0 DMA32 free:1536kB min:668kB low:832kB
high:1000kB active_anon:28828kB inactive_anon:34140kB active_file:42712kB
inactive_file:41736kB unevictable:9612kB isolated(anon):0kB
isolated(file):0kB present:1028096kB managed:216048kB mlocked:9612kB
dirty:0kB writeback:0kB mapped:16424kB shmem:1756kB
slab_reclaimable:15044kB slab_unreclaimable:8836kB kernel_stack:2032kB
pagetables:5884kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB
free_cma:0kB writeback_tmp:0kB pages_scanned:8 all_unreclaimable? no
[Tue Sep 20 13:17:09 2016] lowmem_reserve[]: 0 0 0 0
[Tue Sep 20 13:17:09 2016] Node 0 DMA: 68*4kB (UE) 18*8kB (UME) 4*16kB
(UM) 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB =
480kB
[Tue Sep 20 13:17:09 2016] Node 0 DMA32: 67*4kB (ME) 33*8kB (ME) 17*16kB
(ME) 17*32kB (UME) 3*64kB (UE) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB
0*4096kB = 1540kB
[Tue Sep 20 13:17:09 2016] 23086 total pagecache pages
[Tue Sep 20 13:17:09 2016] 924 pages in swap cache
[Tue Sep 20 13:17:09 2016] Swap cache stats: add 9783, delete 8859, find
3262/4914
[Tue Sep 20 13:17:09 2016] Free swap = 1024996kB
[Tue Sep 20 13:17:09 2016] Total swap = 1048572kB
[Tue Sep 20 13:17:09 2016] 261023 pages RAM
[Tue Sep 20 13:17:09 2016] 0 pages HighMem/MovableOnly
[Tue Sep 20 13:17:09 2016] 203033 pages reserved
[Tue Sep 20 13:17:09 2016] 0 pages hwpoisoned
[Tue Sep 20 13:17:09 2016] vbd vbd-51856: 12 allocating info structure
[Tue Sep 20 13:17:09 2016] vbd vbd-51856: 12 xenbus_dev_probe on
device/vbd/51856
[Tue Sep 20 13:17:09 2016] vbd: probe of vbd-51856 failed with error -12
[Tue Sep 20 13:17:22 2016] xenwatch: page allocation failure: order:5,
mode:0x240c0c0
[Tue Sep 20 13:17:22 2016] CPU: 0 PID: 16 Comm: xenwatch Tainted: G
O 4.4.14-11.pvops.qubes.x86_64 #1
[Tue Sep 20 13:17:22 2016] 000000000000023a 0000000037654cb4
ffff880004b6b928 ffffffff813b06f3
[Tue Sep 20 13:17:22 2016] 000000000240c0c0 0000000000000000
ffff880004b6b9b8 ffffffff811a58fa
[Tue Sep 20 13:17:22 2016] 0000000100000040 0000000004b6b950
0000000037654cb4 0000000000000005
[Tue Sep 20 13:17:22 2016] Call Trace:
[Tue Sep 20 13:17:22 2016] [<ffffffff813b06f3>] dump_stack+0x63/0x90
[Tue Sep 20 13:17:22 2016] [<ffffffff811a58fa>] warn_alloc_failed+0xfa/0x160
[Tue Sep 20 13:17:22 2016] [<ffffffff811a9509>]
__alloc_pages_nodemask+0x349/0xb40
[Tue Sep 20 13:17:22 2016] [<ffffffff811f4a4c>]
alloc_pages_current+0x8c/0x110

[Tue Sep 20 13:17:22 2016] [<ffffffff811a9509>]
__alloc_pages_nodemask+0x349/0xb40
[Tue Sep 20 13:17:22 2016] [<ffffffff811f4a4c>]
alloc_pages_current+0x8c/0x110
. . .
-----

Sometimes retrying will work, sometimes it won't, even after repeated
attempts. Restarting the VM usually helps. It's usually after assigning
other devices as well (but not always).

3.2 rc3 testing.

Cheers.

JJ

[johny...@sigaint.org]

> Quite frequently, under Debian-8, when I go to assign a device, it quietly
> appears to work (Qubes Manager shows it assigned), but the device never
> shows up, and the VM's dmesg shows things like this:

A bit more info:

I repeatedly failed to add a device to one VM.

I close another VM, freeing up some memory.

Then adding the device to the first VM works fine.

So it does appear to be a memory allocation problem (as the stack traces
indicate).

I can start new programs, and do other things in that same VM that
increase its memory usage, so it's not starved (some VM swap is in use).
However, in lower memory conditions, devices won't assign.

Cheers.

JJ