bug#27684: Can't build disk-images or vm-images on core-updates

bug#27684: Can't build disk-images or vm-images on core-updates

[Leo Famulari]

[-- Attachment #1.1: Type: text/plain, Size: 9987 bytes --]

Both `guix system disk-image` and `guix system vm-image` fail for me on
core-updates. Read-only VMs seem to work fine. I'm currently checking to
see if it fails when building on GuixSD.

I'm using x86_64-linux on a foreign distro with Linux 4.12.1. The host
filesystem is ext4. I'm building a kernel on GuixSD so I can test it
there.

I changed the value of 'memory-size' to 4096 (4 GB) in (gnu build vm)
for some of my tests, but the problem persists. I also tried using QEMU
without any of the bug-fix patches, but no joy.

Your help is requested! I'll continue debugging, but I'm sort of "in the
dark" right now.

The disk-image build seems to fail at the point shown below (full logs
attached), which occurs after copying files into the image for a while:

[  108.852534] init: page allocation stalls for 10004ms, order:0, mode:0x1400040(GFP_NOFS), nodemask=(null)
[  108.853423] init cpuset=/ mems_allowed=0
[  108.853781] CPU: 0 PID: 1 Comm: init Not tainted 4.12.0-gnu #1
[  108.854356] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.10.2-0-g5f4c7b1-prebuilt.qemu-project.org 04/01/2014
[  108.855441] Call Trace:
[  108.855825]  dump_stack+0x63/0x82
[  108.856355]  warn_alloc+0x114/0x1b0
[  108.856838]  __alloc_pages_slowpath+0x91d/0xd90
[  108.857265]  __alloc_pages_nodemask+0x245/0x260
[  108.857937]  alloc_pages_current+0x95/0x140
[  108.858581]  __page_cache_alloc+0xb5/0xc0
[  108.859194]  pagecache_get_page+0x88/0x220
[  108.859582]  ext4_mb_load_buddy_gfp+0x214/0x400
[  108.860030]  ext4_mb_regular_allocator+0x177/0x470
[  108.860460]  ext4_mb_new_blocks+0x619/0xae0
[  108.860846]  ? __kmalloc+0x1c7/0x200
[  108.861171]  ? ext4_find_extent+0x1f1/0x2f0
[  108.861575]  ? ext4_find_extent+0x1f1/0x2f0
[  108.862014]  ext4_ext_map_blocks+0x8d0/0x14c0
[  108.862503]  ext4_map_blocks+0x16e/0x5d0
[  108.862879]  _ext4_get_block+0x92/0x100
[  108.863231]  ext4_get_block+0x16/0x20
[  108.863576]  __block_write_begin_int+0x160/0x5d0
[  108.864007]  ? _ext4_get_block+0x100/0x100
[  108.864389]  ? ext4_write_begin+0x141/0x4c0
[  108.864786]  __block_write_begin+0x11/0x20
[  108.865270]  ext4_write_begin+0x1c4/0x4c0
[  108.865635]  pagecache_write_begin+0x13/0x20
[  108.866043]  __page_symlink+0xab/0xf0
[  108.866382]  ext4_symlink+0x2f3/0x3b0
[  108.866700]  vfs_symlink+0x10a/0x170
[  108.866997]  SyS_symlink+0xd4/0x100
[  108.867293]  entry_SYSCALL_64_fastpath+0x1e/0xa9
[  108.867673] RIP: 0033:0x5fb497
[  108.867964] RSP: 002b:00007ffc1b49fa68 EFLAGS: 00000207 ORIG_RAX: 0000000000000058
[  108.868641] RAX: ffffffffffffffda RBX: 0000000000000056 RCX: 00000000005fb497
[  108.869575] RDX: 0000000002e33a70 RSI: 00000000011beed0 RDI: 00000000011aa4d0
[  108.870210] RBP: 00007ffc1b49ef70 R08: 0000000000000000 R09: 0000000000000060
[  108.870865] R10: 00007ffc1b49f9d8 R11: 0000000000000207 R12: 00007ffc1b49ef70
[  108.871501] R13: 0000000000000001 R14: 00007ffc1b49ef70 R15: 00000000017850b0
[  108.872610] Mem-Info:
[  108.873076] active_anon:52330 inactive_anon:1271 isolated_anon:0
[  108.873076]  active_file:327 inactive_file:326 isolated_file:0
[  108.873076]  unevictable:0 dirty:0 writeback:0 unstable:0
[  108.873076]  slab_reclaimable:2108 slab_unreclaimable:1497
[  108.873076]  mapped:1227 shmem:1639 pagetables:565 bounce:0
[  108.873076]  free:481 free_pcp:14 free_cma:0
[  108.877937] Node 0 active_anon:209320kB inactive_anon:5084kB active_file:1308kB inactive_file:1304kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:4908kB dirty:0kB writeback:0kB shmem:6556kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? yes
[  108.882074] Node 0 DMA32 free:1924kB min:1928kB low:2408kB high:2888kB active_anon:209320kB inactive_anon:5084kB active_file:1308kB inactive_file:1304kB unevictable:0kB writepending:0kB present:261616kB managed:242028kB mlocked:0kB slab_reclaimable:8432kB slab_unreclaimable:5988kB kernel_stack:1216kB pagetables:2260kB bounce:0kB free_pcp:56kB local_pcp:56kB free_cma:0kB
[  108.885220] lowmem_reserve[]: 0 0 0 0
[  108.885557] Node 0 DMA32: 81*4kB (UME) 34*8kB (ME) 7*16kB (ME) 0*32kB 1*64kB (M) 1*128kB (M) 2*256kB (M) 1*512kB (M) 0*1024kB 0*2048kB 0*4096kB = 1924kB
[  108.886783] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[  108.887551] 2295 total pagecache pages
[  108.887895] 0 pages in swap cache
[  108.888239] Swap cache stats: add 0, delete 0, find 0/0
[  108.889031] Free swap  = 0kB
[  108.889470] Total swap = 0kB
[  108.890041] 65404 pages RAM
[  108.890468] 0 pages HighMem/MovableOnly
[  108.891062] 4897 pages reserved
[  108.891540] 0 pages cma reserved
[  108.892049] 0 pages hwpoisoned

The vm-image fails in a different way, but also related to memory
allocation:

[   91.369442] init invoked oom-killer: gfp_mask=0x14280ca(GFP_HIGHUSER_MOVABLE|__GFP_ZERO), nodemask=(null),  order=0, oom_score_adj=0
[   91.371477] init cpuset=/ mems_allowed=0
[   91.372153] CPU: 0 PID: 1 Comm: init Not tainted 4.12.0-gnu #1
[   91.373147] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.10.2-0-g5f4c7b1-prebuilt.qemu-project.org 04/01/2014
[   91.375127] Call Trace:
[   91.375557]  dump_stack+0x63/0x82
[   91.376124]  dump_header+0x97/0x21a
[   91.376668]  out_of_memory+0x333/0x480
[   91.377256]  __alloc_pages_slowpath+0xcbb/0xd90
[   91.377963]  ? n_tty_open+0xd0/0xd0
[   91.378505]  __alloc_pages_nodemask+0x245/0x260
[   91.379200]  alloc_pages_vma+0xa2/0x270
[   91.379825]  __handle_mm_fault+0xc1b/0xfd0
[   91.380467]  handle_mm_fault+0xf3/0x210
[   91.381067]  __do_page_fault+0x240/0x4e0
[   91.381681]  trace_do_page_fault+0x37/0xe0
[   91.382324]  do_async_page_fault+0x19/0x70
[   91.382968]  async_page_fault+0x28/0x30
[   91.383570] RIP: 0033:0x58294f
[   91.384061] RSP: 002b:00007ffde18566f0 EFLAGS: 00010212
[   91.384870] RAX: 0000000000000030 RBX: 0000000046a74000 RCX: 0000000000000030
[   91.385969] RDX: 00007ffde185692d RSI: 0000000000000000 RDI: 0000000046a74004
[   91.387068] RBP: 00007ffde185693a R08: 0000000000000000 R09: 0000000000000000
[   91.388182] R10: 0000000000000004 R11: 000000000000000c R12: 0000000046a73da0
[   91.389279] R13: 0000000046a7bd90 R14: 00007ffde18568b0 R15: 0000000046a73e10
[   91.390411] Mem-Info:
[   91.390776] active_anon:52990 inactive_anon:1285 isolated_anon:0
[   91.390776]  active_file:71 inactive_file:69 isolated_file:0
[   91.390776]  unevictable:0 dirty:7 writeback:0 unstable:0
[   91.390776]  slab_reclaimable:1909 slab_unreclaimable:1525
[   91.390776]  mapped:1227 shmem:1639 pagetables:562 bounce:0
[   91.390776]  free:476 free_pcp:32 free_cma:0
[   91.395603] Node 0 active_anon:211960kB inactive_anon:5140kB active_file:284kB inactive_file:276kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:4908kB dirty:28kB writeback:0kB shmem:6556kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? yes
[   91.399747] Node 0 DMA32 free:1904kB min:1928kB low:2408kB high:2888kB active_anon:211960kB inactive_anon:5140kB active_file:284kB inactive_file:276kB unevictable:0kB writepending:28kB present:261616kB managed:242028kB mlocked:0kB slab_reclaimable:7636kB slab_unreclaimable:6100kB kernel_stack:1200kB pagetables:2248kB bounce:0kB free_pcp:128kB local_pcp:128kB free_cma:0kB
[   91.404739] lowmem_reserve[]: 0 0 0 0
[   91.405322] Node 0 DMA32: 220*4kB (UE) 128*8kB (UE) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1904kB
[   91.407155] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[   91.408485] 1778 total pagecache pages
[   91.409074] 0 pages in swap cache
[   91.409599] Swap cache stats: add 0, delete 0, find 0/0
[   91.410413] Free swap  = 0kB
[   91.410867] Total swap = 0kB
[   91.411327] 65404 pages RAM
[   91.411777] 0 pages HighMem/MovableOnly
[   91.412372] 4897 pages reserved
[   91.412875] 0 pages cma reserved
[   91.413385] 0 pages hwpoisoned
[   91.413868] [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
[   91.415189] Kernel panic - not syncing: Out of memory and no killable processes...
[   91.415189] 
[   91.416579] CPU: 0 PID: 1 Comm: init Not tainted 4.12.0-gnu #1
[   91.417476] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.10.2-0-g5f4c7b1-prebuilt.qemu-project.org 04/01/2014
[   91.419256] Call Trace:
[   91.419661]  dump_stack+0x63/0x82
[   91.420187]  panic+0xe4/0x22d
[   91.420651]  out_of_memory+0x33f/0x480
[   91.421243]  __alloc_pages_slowpath+0xcbb/0xd90
[   91.421949]  ? n_tty_open+0xd0/0xd0
[   91.422498]  __alloc_pages_nodemask+0x245/0x260
[   91.423203]  alloc_pages_vma+0xa2/0x270
[   91.423810]  __handle_mm_fault+0xc1b/0xfd0
[   91.424454]  handle_mm_fault+0xf3/0x210
[   91.425056]  __do_page_fault+0x240/0x4e0
[   91.425674]  trace_do_page_fault+0x37/0xe0
[   91.426284]  do_async_page_fault+0x19/0x70
[   91.426699]  async_page_fault+0x28/0x30
[   91.427306] RIP: 0033:0x58294f
[   91.427797] RSP: 002b:00007ffde18566f0 EFLAGS: 00010212
[   91.428605] RAX: 0000000000000030 RBX: 0000000046a74000 RCX: 0000000000000030
[   91.429673] RDX: 00007ffde185692d RSI: 0000000000000000 RDI: 0000000046a74004
[   91.430765] RBP: 00007ffde185693a R08: 0000000000000000 R09: 0000000000000000
[   91.431872] R10: 0000000000000004 R11: 000000000000000c R12: 0000000046a73da0
[   91.432957] R13: 0000000046a7bd90 R14: 00007ffde18568b0 R15: 0000000046a73e10
[   91.433754] Kernel Offset: 0x6000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[   91.434746] ---[ end Kernel panic - not syncing: Out of memory and no killable processes...

[-- Attachment #1.2: core-updates-disk-image.log.xz --]
[-- Type: application/octet-stream, Size: 173728 bytes --]

[-- Attachment #1.3: core-updates-vm-image.log.xz --]
[-- Type: application/octet-stream, Size: 169640 bytes --]

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

bug#27684: Can't build disk-images or vm-images on core-updates

[Leo Famulari]

[-- Attachment #1: Type: text/plain, Size: 60 bytes --]

It fails the same way on the Debian kernel 4.9.30-2+deb9u2.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

bug#27684: Can't build disk-images or vm-images on core-updates

[Danny Milosavljevic]

Hi Leo,

On Thu, 13 Jul 2017 17:57:21 -0400
Leo Famulari <leo@famulari.name> wrote:

> Both `guix system disk-image` and `guix system vm-image` fail for me on
> core-updates. Read-only VMs seem to work fine. I'm currently checking to
> see if it fails when building on GuixSD.
> 
> I'm using x86_64-linux on a foreign distro with Linux 4.12.1. The host
> filesystem is ext4. I'm building a kernel on GuixSD so I can test it
> there.
> 
> I changed the value of 'memory-size' to 4096 (4 GB) in (gnu build vm)
> for some of my tests, but the problem persists. I also tried using QEMU
> without any of the bug-fix patches, but no joy.

Does the system image work when you run it on the bare metal (without qemu or anything)?

bug#27684: Can't build disk-images or vm-images on core-updates

[Leo Famulari]

[-- Attachment #1: Type: text/plain, Size: 978 bytes --]

On Fri, Jul 14, 2017 at 04:14:57PM +0200, Danny Milosavljevic wrote:
> Hi Leo,
> 
> On Thu, 13 Jul 2017 17:57:21 -0400
> Leo Famulari <leo@famulari.name> wrote:
> 
> > Both `guix system disk-image` and `guix system vm-image` fail for me on
> > core-updates. Read-only VMs seem to work fine. I'm currently checking to
> > see if it fails when building on GuixSD.
> > 
> > I'm using x86_64-linux on a foreign distro with Linux 4.12.1. The host
> > filesystem is ext4. I'm building a kernel on GuixSD so I can test it
> > there.
> > 
> > I changed the value of 'memory-size' to 4096 (4 GB) in (gnu build vm)
> > for some of my tests, but the problem persists. I also tried using QEMU
> > without any of the bug-fix patches, but no joy.
> 
> Does the system image work when you run it on the bare metal (without qemu or anything)?

Which system image? I can use the 0.13.0 release disk-image without any
trouble, but I can't create new ones from core-updates.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

bug#27684: Can't build disk-images or vm-images on core-updates

[Ludovic Courtès]

Hi Leo,

Leo Famulari <leo@famulari.name> skribis:

> Both `guix system disk-image` and `guix system vm-image` fail for me on
> core-updates. Read-only VMs seem to work fine. I'm currently checking to
> see if it fails when building on GuixSD.

The log shows that building the disk-image derivation starts with:

--8<---------------cut here---------------start------------->8---
creating raw image of 102400.00 MiB...
Formatting '/gnu/store/yv5r65584aaml86hc0xrgyffnp70ri36-disk-image', fmt=raw size=107374182400
--8<---------------cut here---------------end--------------->8---

That’s a lot, no?

Regardless, memory consumption in the VM is not supposed to be
proportional to the size of the image being created.

The allocation failure happens while copying files:

--8<---------------cut here---------------start------------->8---
`/gnu/store/rmawlm76aib9yxnp6srrrcq57slc2sy1-profile/share/man/man8/resize2fs.8.gz' -> `/fs/gnu/store/rmawlm76aib9yxnp6srrrcq57slc2sy1-profile/share/man/man8/resize2fs.8.gz'
`/gnu/store/rmawlm76aib9yxnp6srrrcq57slc2sy1-profile/share/man/man8/setkeycodes.8.gz' -> `/fs/gnu/store/rmawlm76aib9yxnp6srrrcq57slc2sy1-profile/share/man/man8/setkeycodes.8.gz'
[  108.852534] init: page allocation stalls for 10004ms, order:0, mode:0x1400040(GFP_NOFS), nodemask=(null)
[  108.853423] init cpuset=/ mems_allowed=0
[  108.853781] CPU: 0 PID: 1 Comm: init Not tainted 4.12.0-gnu #1
[  108.854356] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.10.2-0-g5f4c7b1-prebuilt.qemu-project.org 04/01/2014
[  108.855441] Call Trace:
[  108.855825]  dump_stack+0x63/0x82
[  108.856355]  warn_alloc+0x114/0x1b0
[  108.856838]  __alloc_pages_slowpath+0x91d/0xd90
[  108.857265]  __alloc_pages_nodemask+0x245/0x260
[  108.857937]  alloc_pages_current+0x95/0x140
[  108.858581]  __page_cache_alloc+0xb5/0xc0
[  108.859194]  pagecache_get_page+0x88/0x220
[  108.859582]  ext4_mb_load_buddy_gfp+0x214/0x400
--8<---------------cut here---------------end--------------->8---

Does that work on previous master with Linux-libre 4.12.0 (current
master is at 4.12.2)?  (This would allow us to determine if this is an
ext4 bug, who knows…)

If it does, then the only other issue I can think of is if Guile itself,
while running ‘copy-recursively’ from (guix build utils), eats memory
proportional to the number of files, leading to an OOM condition.
However the kernel message don’t report it as an OOM, AFAICS.

Thanks,
Ludo’.

bug#27684: Can't build disk-images or vm-images on core-updates

[Leo Famulari]

[-- Attachment #1: Type: text/plain, Size: 1536 bytes --]

On Mon, Jul 17, 2017 at 04:02:14PM +0200, Ludovic Courtès wrote:
> The log shows that building the disk-image derivation starts with:
> 
> --8<---------------cut here---------------start------------->8---
> creating raw image of 102400.00 MiB...
> Formatting '/gnu/store/yv5r65584aaml86hc0xrgyffnp70ri36-disk-image', fmt=raw size=107374182400
> --8<---------------cut here---------------end--------------->8---
> 
> That’s a lot, no?

Yes, I specified it manually while debugging.

> Regardless, memory consumption in the VM is not supposed to be
> proportional to the size of the image being created.

Indeed, the problem exists also when I don't pick a size manually.

> The allocation failure happens while copying files:

[...]

> Does that work on previous master with Linux-libre 4.12.0 (current
> master is at 4.12.2)?  (This would allow us to determine if this is an
> ext4 bug, who knows…)

Yes, I tested with a variety of kernels and on the master branch as
well.

> If it does, then the only other issue I can think of is if Guile itself,
> while running ‘copy-recursively’ from (guix build utils), eats memory
> proportional to the number of files, leading to an OOM condition.
> However the kernel message don’t report it as an OOM, AFAICS.

I'm wondering if it's related to the Guile 2.0 / 2.2 mismatch in the
initrd, discussed previously:

https://lists.gnu.org/archive/html/guix-devel/2017-07/msg00220.html

Guile 2.0 would need to rebuild all the 2.2 modules it finds.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

bug#27684: Can't build disk-images or vm-images on core-updates

[Ludovic Courtès]

Leo Famulari <leo@famulari.name> skribis:

> On Mon, Jul 17, 2017 at 04:02:14PM +0200, Ludovic Courtès wrote:
>> The log shows that building the disk-image derivation starts with:
>> 
>> --8<---------------cut here---------------start------------->8---
>> creating raw image of 102400.00 MiB...
>> Formatting '/gnu/store/yv5r65584aaml86hc0xrgyffnp70ri36-disk-image', fmt=raw size=107374182400
>> --8<---------------cut here---------------end--------------->8---
>> 
>> That’s a lot, no?
>
> Yes, I specified it manually while debugging.
>
>> Regardless, memory consumption in the VM is not supposed to be
>> proportional to the size of the image being created.
>
> Indeed, the problem exists also when I don't pick a size manually.
>
>> The allocation failure happens while copying files:
>
> [...]
>
>> Does that work on previous master with Linux-libre 4.12.0 (current
>> master is at 4.12.2)?  (This would allow us to determine if this is an
>> ext4 bug, who knows…)
>
> Yes, I tested with a variety of kernels and on the master branch as
> well.
>
>> If it does, then the only other issue I can think of is if Guile itself,
>> while running ‘copy-recursively’ from (guix build utils), eats memory
>> proportional to the number of files, leading to an OOM condition.
>> However the kernel message don’t report it as an OOM, AFAICS.
>
> I'm wondering if it's related to the Guile 2.0 / 2.2 mismatch in the
> initrd, discussed previously:
>
> https://lists.gnu.org/archive/html/guix-devel/2017-07/msg00220.html
>
> Guile 2.0 would need to rebuild all the 2.2 modules it finds.

This works for me now:

--8<---------------cut here---------------start------------->8---
$ ./pre-inst-env guix system disk-image gnu/system/install.scm 
*** output flushed ***
$ file /gnu/store/37ppm08ggdds3i06h4la0wdzilcnladm-disk-image
/gnu/store/37ppm08ggdds3i06h4la0wdzilcnladm-disk-image: DOS/MBR boot sector
$ git describe
v0.13.0-1474-gef03d8dc3
--8<---------------cut here---------------end--------------->8---

Could you check if it works for you?

It’s a much smaller image than what you tried (1G vs. 102G).

Ludo’.

bug#27684: Can't build disk-images or vm-images on core-updates

[Leo Famulari]

[-- Attachment #1: Type: text/plain, Size: 730 bytes --]

On Tue, Jul 18, 2017 at 03:57:46PM +0200, Ludovic Courtès wrote:
> This works for me now:
> 
> --8<---------------cut here---------------start------------->8---
> $ ./pre-inst-env guix system disk-image gnu/system/install.scm 
> *** output flushed ***
> $ file /gnu/store/37ppm08ggdds3i06h4la0wdzilcnladm-disk-image
> /gnu/store/37ppm08ggdds3i06h4la0wdzilcnladm-disk-image: DOS/MBR boot sector
> $ git describe
> v0.13.0-1474-gef03d8dc3
> --8<---------------cut here---------------end--------------->8---
> 
> Could you check if it works for you?
> 
> It’s a much smaller image than what you tried (1G vs. 102G).

Yes, it works for me! I think the issue must have been that Guile was
compiling in the initrd.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]