Re: 4.6.2 frequent crashes under memory + IO pressure
(adding back Cc:, just dropped it to send the logs)
On Mon, Jun 27, 2016 at 01:35:14AM +0900, Tetsuo Handa wrote:
>
> It seems to me that GFP_NOIO allocation requests are depleting memory reserves
> because they are passing ALLOC_NO_WATERMARKS to get_page_from_freelist().
> But I'm not familiar with block layer / swap I/O operation. So, will you post
> to linux-mm ML for somebody else to help you?
Frankly I don't care that much about 4.6.y when 4.7 is fixed.
Or, maybe the root issue is not fixed but the new oom code
covers it. Below I see both dm and kcryptd so there is no
surprise when using swap on lvm on dm-crypt triggers it.
Maybe it's not a new issue on 4.6 but just some random variation
that makes it trigger easier with my particular workload.
So, unless you would like to keep going at it I'd
like to put the issue at rest.
> kswapd0(766) 0x2201200
> 0x81167522 : get_page_from_freelist+0x0/0x82b [kernel]
> 0x81168127 : __alloc_pages_nodemask+0x3da/0x978 [kernel]
> 0x8119fb2a : new_slab+0xbc/0x3bb [kernel]
> 0x811a1acd : ___slab_alloc.constprop.22+0x2fb/0x37b [kernel]
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x810c502d : put_lock_stats.isra.9+0xe/0x20 [kernel] (inexact)
> 0x811a1ba4 : __slab_alloc.isra.17.constprop.21+0x57/0x8b [kernel]
> (inexact)
> 0x811a1ba4 : __slab_alloc.isra.17.constprop.21+0x57/0x8b [kernel]
> (inexact)
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x811a1c78 : kmem_cache_alloc+0xa0/0x1d6 [kernel] (inexact)
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x81162b7a : mempool_alloc+0x72/0x154 [kernel] (inexact)
> 0x810c6438 : __lock_acquire.isra.16+0x55e/0xb4c [kernel] (inexact)
> 0x8133fdc1 : bio_alloc_bioset+0xe8/0x1d7 [kernel] (inexact)
> 0x816342ea : alloc_tio+0x2d/0x47 [kernel] (inexact)
> 0x8163587e : __split_and_process_bio+0x310/0x3a3 [kernel] (inexact)
> 0x81635e15 : dm_make_request+0xb5/0xe2 [kernel] (inexact)
> 0x81347ae7 : generic_make_request+0xcc/0x180 [kernel] (inexact)
> 0x81347c98 : submit_bio+0xfd/0x145 [kernel] (inexact)
>
> kswapd0(766) 0x2201200
> 0x81167522 : get_page_from_freelist+0x0/0x82b [kernel]
> 0x81168127 : __alloc_pages_nodemask+0x3da/0x978 [kernel]
> 0x8119fb2a : new_slab+0xbc/0x3bb [kernel]
> 0x811a1acd : ___slab_alloc.constprop.22+0x2fb/0x37b [kernel]
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x81640e29 : kcryptd_queue_crypt+0x63/0x68 [kernel] (inexact)
> 0x811a1ba4 : __slab_alloc.isra.17.constprop.21+0x57/0x8b [kernel]
> (inexact)
> 0x811a1ba4 : __slab_alloc.isra.17.constprop.21+0x57/0x8b [kernel]
> (inexact)
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x811a1c78 : kmem_cache_alloc+0xa0/0x1d6 [kernel] (inexact)
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x81162b7a : mempool_alloc+0x72/0x154 [kernel] (inexact)
> 0x8101f5ba : sched_clock+0x9/0xd [kernel] (inexact)
> 0x810ae420 : local_clock+0x20/0x22 [kernel] (inexact)
> 0x8133fdc1 : bio_alloc_bioset+0xe8/0x1d7 [kernel] (inexact)
> 0x811983d0 : end_swap_bio_write+0x0/0x6a [kernel] (inexact)
> 0x8119854b : get_swap_bio+0x25/0x6c [kernel] (inexact)
> 0x811983d0 : end_swap_bio_write+0x0/0x6a [kernel] (inexact)
> 0x811988ef : __swap_writepage+0x1a9/0x225 [kernel] (inexact)
>
> >
> > > # ~/systemtap.tmp/bin/stap -e 'global traces_bt[65536];
> > > probe begin { printf("Probe start!\n"); }
> > > function dump_if_new(mask:long) {
> > > bt = backtrace();
> > > if (traces_bt[bt]++ == 0) {
> > > printf("%s(%u) 0x%lx\n", execname(), pid(), mask);
> > > print_backtrace();
> > > printf("\n");
> > > }
> > > }
> > > probe kernel.function("get_page_from_freelist") { if ($alloc_flags & 0x4)
> > > dump_if_new($gfp_mask); }
> > > probe kernel.function("gfp_pfmemalloc_allowed").return { if ($return !=
> > > 0) dump_if_new($gfp_mask); }
> > > probe end { delete traces_bt; }'
> > ...
> > > # addr2line -i -e /usr/src/linux-4.6.2/vmlinux 0x811b9c82
> > > /usr/src/linux-4.6.2/mm/memory.c:1162
> > > /usr/src/linux-4.6.2/mm/memory.c:1241
> > > /usr/src/linux-4.6.2/mm/memory.c:1262
> > > /usr/src/linux-4.6.2/mm/memory.c:1283
> >
> > I'm attaching both the stap output and the serial console log,
> > not sure what you're looking for with addr2line. Let me know.
>
> I just meant how to find location in source code from addresses.
I meant the log is so large I wouldn't know which
addresses would be interesting to look up.
Thanks,
Johannes
Re: 4.6.2 frequent crashes under memory + IO pressure
(adding back Cc:, just dropped it to send the logs)
On Mon, Jun 27, 2016 at 01:35:14AM +0900, Tetsuo Handa wrote:
>
> It seems to me that GFP_NOIO allocation requests are depleting memory reserves
> because they are passing ALLOC_NO_WATERMARKS to get_page_from_freelist().
> But I'm not familiar with block layer / swap I/O operation. So, will you post
> to linux-mm ML for somebody else to help you?
Frankly I don't care that much about 4.6.y when 4.7 is fixed.
Or, maybe the root issue is not fixed but the new oom code
covers it. Below I see both dm and kcryptd so there is no
surprise when using swap on lvm on dm-crypt triggers it.
Maybe it's not a new issue on 4.6 but just some random variation
that makes it trigger easier with my particular workload.
So, unless you would like to keep going at it I'd
like to put the issue at rest.
> kswapd0(766) 0x2201200
> 0x81167522 : get_page_from_freelist+0x0/0x82b [kernel]
> 0x81168127 : __alloc_pages_nodemask+0x3da/0x978 [kernel]
> 0x8119fb2a : new_slab+0xbc/0x3bb [kernel]
> 0x811a1acd : ___slab_alloc.constprop.22+0x2fb/0x37b [kernel]
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x810c502d : put_lock_stats.isra.9+0xe/0x20 [kernel] (inexact)
> 0x811a1ba4 : __slab_alloc.isra.17.constprop.21+0x57/0x8b [kernel]
> (inexact)
> 0x811a1ba4 : __slab_alloc.isra.17.constprop.21+0x57/0x8b [kernel]
> (inexact)
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x811a1c78 : kmem_cache_alloc+0xa0/0x1d6 [kernel] (inexact)
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x81162b7a : mempool_alloc+0x72/0x154 [kernel] (inexact)
> 0x810c6438 : __lock_acquire.isra.16+0x55e/0xb4c [kernel] (inexact)
> 0x8133fdc1 : bio_alloc_bioset+0xe8/0x1d7 [kernel] (inexact)
> 0x816342ea : alloc_tio+0x2d/0x47 [kernel] (inexact)
> 0x8163587e : __split_and_process_bio+0x310/0x3a3 [kernel] (inexact)
> 0x81635e15 : dm_make_request+0xb5/0xe2 [kernel] (inexact)
> 0x81347ae7 : generic_make_request+0xcc/0x180 [kernel] (inexact)
> 0x81347c98 : submit_bio+0xfd/0x145 [kernel] (inexact)
>
> kswapd0(766) 0x2201200
> 0x81167522 : get_page_from_freelist+0x0/0x82b [kernel]
> 0x81168127 : __alloc_pages_nodemask+0x3da/0x978 [kernel]
> 0x8119fb2a : new_slab+0xbc/0x3bb [kernel]
> 0x811a1acd : ___slab_alloc.constprop.22+0x2fb/0x37b [kernel]
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x81640e29 : kcryptd_queue_crypt+0x63/0x68 [kernel] (inexact)
> 0x811a1ba4 : __slab_alloc.isra.17.constprop.21+0x57/0x8b [kernel]
> (inexact)
> 0x811a1ba4 : __slab_alloc.isra.17.constprop.21+0x57/0x8b [kernel]
> (inexact)
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x811a1c78 : kmem_cache_alloc+0xa0/0x1d6 [kernel] (inexact)
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
> 0x81162b7a : mempool_alloc+0x72/0x154 [kernel] (inexact)
> 0x8101f5ba : sched_clock+0x9/0xd [kernel] (inexact)
> 0x810ae420 : local_clock+0x20/0x22 [kernel] (inexact)
> 0x8133fdc1 : bio_alloc_bioset+0xe8/0x1d7 [kernel] (inexact)
> 0x811983d0 : end_swap_bio_write+0x0/0x6a [kernel] (inexact)
> 0x8119854b : get_swap_bio+0x25/0x6c [kernel] (inexact)
> 0x811983d0 : end_swap_bio_write+0x0/0x6a [kernel] (inexact)
> 0x811988ef : __swap_writepage+0x1a9/0x225 [kernel] (inexact)
>
> >
> > > # ~/systemtap.tmp/bin/stap -e 'global traces_bt[65536];
> > > probe begin { printf("Probe start!\n"); }
> > > function dump_if_new(mask:long) {
> > > bt = backtrace();
> > > if (traces_bt[bt]++ == 0) {
> > > printf("%s(%u) 0x%lx\n", execname(), pid(), mask);
> > > print_backtrace();
> > > printf("\n");
> > > }
> > > }
> > > probe kernel.function("get_page_from_freelist") { if ($alloc_flags & 0x4)
> > > dump_if_new($gfp_mask); }
> > > probe kernel.function("gfp_pfmemalloc_allowed").return { if ($return !=
> > > 0) dump_if_new($gfp_mask); }
> > > probe end { delete traces_bt; }'
> > ...
> > > # addr2line -i -e /usr/src/linux-4.6.2/vmlinux 0x811b9c82
> > > /usr/src/linux-4.6.2/mm/memory.c:1162
> > > /usr/src/linux-4.6.2/mm/memory.c:1241
> > > /usr/src/linux-4.6.2/mm/memory.c:1262
> > > /usr/src/linux-4.6.2/mm/memory.c:1283
> >
> > I'm attaching both the stap output and the serial console log,
> > not sure what you're looking for with addr2line. Let me know.
>
> I just meant how to find location in source code from addresses.
I meant the log is so large I wouldn't know which
addresses would be interesting to look up.
Thanks,
Johannes
Re: 4.6.2 frequent crashes under memory + IO pressure
Johannes Stezenbach wrote:
> On Sun, Jun 26, 2016 at 02:04:40AM +0900, Tetsuo Handa wrote:
> > It seems to me that somebody is using ALLOC_NO_WATERMARKS (with possibly
> > __GFP_NOWARN), but I don't know how to identify such callers. Maybe print
> > backtrace from __alloc_pages_slowpath() when ALLOC_NO_WATERMARKS is used?
>
> Wouldn't this create too much output for slow serial console?
> Or is this case supposed to be triggered rarely?
>
> This crash testing is pretty painful but I can try it tomorrow
> if there is no better idea.
>
> Johannes
>
If you can use latest SystemTap from git repository, I think you can get traces
with "uniq" using below script.
# ~/systemtap.tmp/bin/stap --version
Systemtap translator/driver (version 3.1/0.163, commit
release-3.0-133-g42b97387ed3f)
Copyright (C) 2005-2016 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
tested kernel versions: 2.6.18 ... 4.6-rc
enabled features: JAVA NLS
# ~/systemtap.tmp/bin/stap -e 'global traces_bt[65536];
probe begin { printf("Probe start!\n"); }
function dump_if_new(mask:long) {
bt = backtrace();
if (traces_bt[bt]++ == 0) {
printf("%s(%u) 0x%lx\n", execname(), pid(), mask);
print_backtrace();
printf("\n");
}
}
probe kernel.function("get_page_from_freelist") { if ($alloc_flags & 0x4)
dump_if_new($gfp_mask); }
probe kernel.function("gfp_pfmemalloc_allowed").return { if ($return != 0)
dump_if_new($gfp_mask); }
probe end { delete traces_bt; }'
--
Probe start!
oom-torture(15957) 0x342004a
0x81188e40 : get_page_from_freelist+0x0/0xcf0 [kernel]
0x8118a146 : __alloc_pages_nodemask+0x616/0xcd0 [kernel]
0x811dfc22 : alloc_pages_current+0x92/0x190 [kernel]
0x8117cf56 : __page_cache_alloc+0x146/0x180 [kernel]
0x8117e961 : pagecache_get_page+0x51/0x280 [kernel]
0x8117ef14 : grab_cache_page_write_begin+0x24/0x40 [kernel]
0x812fadbf : xfs_vm_write_begin+0x2f/0x100 [kernel]
0x8117cd1d : generic_perform_write+0xcd/0x1c0 [kernel]
0x8130ffdd : xfs_file_buffered_aio_write+0x15d/0x3d0 [kernel]
0x813102d6 : xfs_file_write_iter+0x86/0x140 [kernel]
0x812168a7 : __vfs_write+0xc7/0x100 [kernel]
0x8121773d : vfs_write+0x9d/0x190 [kernel]
0x81218b63 : sys_write+0x53/0xc0 [kernel]
0x81002dbc : do_syscall_64+0x5c/0x170 [kernel]
0x81724ada : return_from_SYSCALL_64+0x0/0x7a [kernel]
oom-torture(15957) 0x2000200
0x81188e40 : get_page_from_freelist+0x0/0xcf0 [kernel]
0x8118a146 : __alloc_pages_nodemask+0x616/0xcd0 [kernel]
0x811dfc22 : alloc_pages_current+0x92/0x190 [kernel]
0x811841ff : __get_free_pages+0xf/0x40 [kernel]
0x811b8622 : __tlb_remove_page+0x62/0xa0 [kernel]
0x811b9c82 : unmap_page_range+0x692/0x8f0 [kernel]
0x811b9f34 : unmap_single_vma+0x54/0xd0 [kernel]
0x811ba25c : unmap_vmas+0x3c/0x50 [kernel]
0x811c2ad6 : exit_mmap+0xc6/0x140 [kernel]
0x81068a6d : mmput+0x4d/0xe0 [kernel]
0x81070f60 : do_exit+0x280/0xd20 [kernel]
0x81071a87 : do_group_exit+0x47/0xc0 [kernel]
0x8107ffbb : get_signal+0x33b/0x9b0 [kernel]
0x8101d312 : do_signal+0x32/0x6c0 [kernel]
0x81065fc6 : exit_to_usermode_loop+0x46/0x84 [kernel]
0x81002e6d : do_syscall_64+0x10d/0x170 [kernel]
0x81724ada : return_from_SYSCALL_64+0x0/0x7a [kernel]
--
# addr2line -i -e /usr/src/linux-4.6.2/vmlinux 0x811b9c82
/usr/src/linux-4.6.2/mm/memory.c:1162
/usr/src/linux-4.6.2/mm/memory.c:1241
/usr/src/linux-4.6.2/mm/memory.c:1262
/usr/src/linux-4.6.2/mm/memory.c:1283
Re: 4.6.2 frequent crashes under memory + IO pressure
Johannes Stezenbach wrote:
> On Sun, Jun 26, 2016 at 02:04:40AM +0900, Tetsuo Handa wrote:
> > It seems to me that somebody is using ALLOC_NO_WATERMARKS (with possibly
> > __GFP_NOWARN), but I don't know how to identify such callers. Maybe print
> > backtrace from __alloc_pages_slowpath() when ALLOC_NO_WATERMARKS is used?
>
> Wouldn't this create too much output for slow serial console?
> Or is this case supposed to be triggered rarely?
>
> This crash testing is pretty painful but I can try it tomorrow
> if there is no better idea.
>
> Johannes
>
If you can use latest SystemTap from git repository, I think you can get traces
with "uniq" using below script.
# ~/systemtap.tmp/bin/stap --version
Systemtap translator/driver (version 3.1/0.163, commit
release-3.0-133-g42b97387ed3f)
Copyright (C) 2005-2016 Red Hat, Inc. and others
This is free software; see the source for copying conditions.
tested kernel versions: 2.6.18 ... 4.6-rc
enabled features: JAVA NLS
# ~/systemtap.tmp/bin/stap -e 'global traces_bt[65536];
probe begin { printf("Probe start!\n"); }
function dump_if_new(mask:long) {
bt = backtrace();
if (traces_bt[bt]++ == 0) {
printf("%s(%u) 0x%lx\n", execname(), pid(), mask);
print_backtrace();
printf("\n");
}
}
probe kernel.function("get_page_from_freelist") { if ($alloc_flags & 0x4)
dump_if_new($gfp_mask); }
probe kernel.function("gfp_pfmemalloc_allowed").return { if ($return != 0)
dump_if_new($gfp_mask); }
probe end { delete traces_bt; }'
--
Probe start!
oom-torture(15957) 0x342004a
0x81188e40 : get_page_from_freelist+0x0/0xcf0 [kernel]
0x8118a146 : __alloc_pages_nodemask+0x616/0xcd0 [kernel]
0x811dfc22 : alloc_pages_current+0x92/0x190 [kernel]
0x8117cf56 : __page_cache_alloc+0x146/0x180 [kernel]
0x8117e961 : pagecache_get_page+0x51/0x280 [kernel]
0x8117ef14 : grab_cache_page_write_begin+0x24/0x40 [kernel]
0x812fadbf : xfs_vm_write_begin+0x2f/0x100 [kernel]
0x8117cd1d : generic_perform_write+0xcd/0x1c0 [kernel]
0x8130ffdd : xfs_file_buffered_aio_write+0x15d/0x3d0 [kernel]
0x813102d6 : xfs_file_write_iter+0x86/0x140 [kernel]
0x812168a7 : __vfs_write+0xc7/0x100 [kernel]
0x8121773d : vfs_write+0x9d/0x190 [kernel]
0x81218b63 : sys_write+0x53/0xc0 [kernel]
0x81002dbc : do_syscall_64+0x5c/0x170 [kernel]
0x81724ada : return_from_SYSCALL_64+0x0/0x7a [kernel]
oom-torture(15957) 0x2000200
0x81188e40 : get_page_from_freelist+0x0/0xcf0 [kernel]
0x8118a146 : __alloc_pages_nodemask+0x616/0xcd0 [kernel]
0x811dfc22 : alloc_pages_current+0x92/0x190 [kernel]
0x811841ff : __get_free_pages+0xf/0x40 [kernel]
0x811b8622 : __tlb_remove_page+0x62/0xa0 [kernel]
0x811b9c82 : unmap_page_range+0x692/0x8f0 [kernel]
0x811b9f34 : unmap_single_vma+0x54/0xd0 [kernel]
0x811ba25c : unmap_vmas+0x3c/0x50 [kernel]
0x811c2ad6 : exit_mmap+0xc6/0x140 [kernel]
0x81068a6d : mmput+0x4d/0xe0 [kernel]
0x81070f60 : do_exit+0x280/0xd20 [kernel]
0x81071a87 : do_group_exit+0x47/0xc0 [kernel]
0x8107ffbb : get_signal+0x33b/0x9b0 [kernel]
0x8101d312 : do_signal+0x32/0x6c0 [kernel]
0x81065fc6 : exit_to_usermode_loop+0x46/0x84 [kernel]
0x81002e6d : do_syscall_64+0x10d/0x170 [kernel]
0x81724ada : return_from_SYSCALL_64+0x0/0x7a [kernel]
--
# addr2line -i -e /usr/src/linux-4.6.2/vmlinux 0x811b9c82
/usr/src/linux-4.6.2/mm/memory.c:1162
/usr/src/linux-4.6.2/mm/memory.c:1241
/usr/src/linux-4.6.2/mm/memory.c:1262
/usr/src/linux-4.6.2/mm/memory.c:1283
Re: 4.6.2 frequent crashes under memory + IO pressure
On Sun, Jun 26, 2016 at 02:04:40AM +0900, Tetsuo Handa wrote: > It seems to me that somebody is using ALLOC_NO_WATERMARKS (with possibly > __GFP_NOWARN), but I don't know how to identify such callers. Maybe print > backtrace from __alloc_pages_slowpath() when ALLOC_NO_WATERMARKS is used? Wouldn't this create too much output for slow serial console? Or is this case supposed to be triggered rarely? This crash testing is pretty painful but I can try it tomorrow if there is no better idea. Johannes
Re: 4.6.2 frequent crashes under memory + IO pressure
On Sun, Jun 26, 2016 at 02:04:40AM +0900, Tetsuo Handa wrote: > It seems to me that somebody is using ALLOC_NO_WATERMARKS (with possibly > __GFP_NOWARN), but I don't know how to identify such callers. Maybe print > backtrace from __alloc_pages_slowpath() when ALLOC_NO_WATERMARKS is used? Wouldn't this create too much output for slow serial console? Or is this case supposed to be triggered rarely? This crash testing is pretty painful but I can try it tomorrow if there is no better idea. Johannes
Re: 4.6.2 frequent crashes under memory + IO pressure
Johannes Stezenbach wrote: > On Thu, Jun 23, 2016 at 08:26:35PM +0900, Tetsuo Handa wrote: > > > > Since you think you saw OOM messages with the older kernels, I assume that > > the OOM > > killer was invoked on your 4.6.2 kernel. The OOM reaper in Linux 4.6 and > > Linux 4.7 > > will not help if the OOM killed process was between > > down_write(>mmap_sem) and > > up_write(>mmap_sem). > > > > I was not able to confirm whether the OOM killed process (I guess it was > > java) > > was holding mm->mmap_sem for write, for /proc/sys/kernel/hung_task_warnings > > dropped to 0 before traces of java threads are printed or console became > > unusable due to the "delayed: kcryptd_crypt, ..." line. Anyway, I think that > > kmallocwd will report it. > > > > > > It is sad that we haven't merged kmallocwd which will report > > > > which memory allocations are stalling > > > > ( > > > > http://lkml.kernel.org/r/1462630604-23410-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp > > > > ). > > > > > > Would you like me to try it? It wouldn't prevent the hang, though, > > > just print better debug ouptut to serial console, right? > > > Or would it OOM kill some process? > > > > Yes, but for bisection purpose, please try commit 78ebc2f7146156f4 without > > applying kmallocwd. If that commit helps avoiding flood of the allocation > > failure warnings, we can consider backporting it. If that commit does not > > help, I think you are reporting a new location which we should not use > > memory reserves. > > > > kmallocwd will not OOM kill some process. kmallocwd will not prevent the > > hang. > > kmallocwd just prints information of threads which are stalling inside > > memory > > allocation request. > > First I tried today's git, linux-4.7-rc4-187-g086e3eb, and > the good news is that the oom killer seems to work very > well and reliably killed the offending task (java). > It happened a few times, the AOSP build broke and I restarted > it until it completed. E.g.: > > [ 2083.604374] Purging GPU memory, 0 pages freed, 4508 pages still pinned. > [ 2083.611000] 96 and 0 pages still available in the bound and unbound GPU > page lists. > [ 2083.618815] make invoked oom-killer: > gfp_mask=0x27000c0(GFP_KERNEL_ACCOUNT|__GFP_NOTRACK), order=2, oom_score_adj=0 > [ 2083.629257] make cpuset=/ mems_allowed=0 > ... > [ 2084.688753] Out of memory: Kill process 10431 (java) score 378 or > sacrifice child > [ 2084.696593] Killed process 10431 (java) total-vm:5200964kB, > anon-rss:2521764kB, file-rss:0kB, shmem-rss:0kB > [ 2084.938058] oom_reaper: reaped process 10431 (java), now anon-rss:0kB, > file-rss:8kB, shmem-rss:0kB > Good. Your problem does not exist in Linux 4.7 kernels. > Next I tried 4.6.2 with 78ebc2f7146156f4, then with kmallocwd (needed one > manual fixup), > then both patches. It still livelocked in all cases, the log spew looked > a bit different with 78ebc2f7146156f4 applied but still continued > endlessly. kmallocwd alone didn't trigger, with both patches > applied kmallocwd triggered but: > > [ 363.815595] MemAlloc-Info: stalling=33 dying=0 exiting=42 victim=0 > oom_count=0 > [ 363.815601] MemAlloc: kworker/0:0(4) flags=0x4208860 switches=212 seq=1 > gfp=0x26012c0(GFP_KERNEL|__GFP_NOWARN|__GFP_NORETRY|__GFP_NOTRACK) order=0 > delay=17984 > ** 1402 printk messages dropped ** [ 363.818816] [] > __do_page_cache_readahead+0x144/0x29d > ** 501 printk messages dropped ** > > I'll zip up the logs and send them off-list. Thank you for testing it. I found that your 4.6.2 kernel is depleting memory reserves before invoking the OOM killer. (oom_count=0 in MemAlloc-Info: line says out_of_memory() was never called). -- [ 483.832644] DMA free:0kB min:32kB low:44kB high:56kB active_anon:704kB inactive_anon:1008kB active_file:0kB inactive_file:0kB unevictable:20kB isolated(anon):0kB isolated(file):0kB present:15984kB managed:15900kB mlocked:20kB dirty:0kB writeback:248kB mapped:24kB shmem:112kB slab_reclaimable:376kB slab_unreclaimable:13456kB kernel_stack:0kB pagetables:52kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:11096 all_unreclaimable? yes [ 483.875261] lowmem_reserve[]: 0 3154 3154 3154 [ 483.879818] DMA32 free:0kB min:7168kB low:10396kB high:13624kB active_anon:2427064kB inactive_anon:615444kB active_file:1120kB inactive_file:1152kB unevictable:4532kB isolated(anon):844kB isolated(file):0kB present:3334492kB managed:3241464kB mlocked:4532kB dirty:16kB writeback:139208kB mapped:11328kB shmem:17300kB slab_reclaimable:46672kB slab_unreclaimable:97072kB kernel_stack:5264kB pagetables:16048kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:7533108 all_unreclaimable? no [ 483.926816] lowmem_reserve[]: 0 0 0 0 [ 483.930596] DMA: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 0kB [ 483.940528] DMA32: 0*4kB 0*8kB 0*16kB 0*32kB
Re: 4.6.2 frequent crashes under memory + IO pressure
Johannes Stezenbach wrote: > On Thu, Jun 23, 2016 at 08:26:35PM +0900, Tetsuo Handa wrote: > > > > Since you think you saw OOM messages with the older kernels, I assume that > > the OOM > > killer was invoked on your 4.6.2 kernel. The OOM reaper in Linux 4.6 and > > Linux 4.7 > > will not help if the OOM killed process was between > > down_write(>mmap_sem) and > > up_write(>mmap_sem). > > > > I was not able to confirm whether the OOM killed process (I guess it was > > java) > > was holding mm->mmap_sem for write, for /proc/sys/kernel/hung_task_warnings > > dropped to 0 before traces of java threads are printed or console became > > unusable due to the "delayed: kcryptd_crypt, ..." line. Anyway, I think that > > kmallocwd will report it. > > > > > > It is sad that we haven't merged kmallocwd which will report > > > > which memory allocations are stalling > > > > ( > > > > http://lkml.kernel.org/r/1462630604-23410-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp > > > > ). > > > > > > Would you like me to try it? It wouldn't prevent the hang, though, > > > just print better debug ouptut to serial console, right? > > > Or would it OOM kill some process? > > > > Yes, but for bisection purpose, please try commit 78ebc2f7146156f4 without > > applying kmallocwd. If that commit helps avoiding flood of the allocation > > failure warnings, we can consider backporting it. If that commit does not > > help, I think you are reporting a new location which we should not use > > memory reserves. > > > > kmallocwd will not OOM kill some process. kmallocwd will not prevent the > > hang. > > kmallocwd just prints information of threads which are stalling inside > > memory > > allocation request. > > First I tried today's git, linux-4.7-rc4-187-g086e3eb, and > the good news is that the oom killer seems to work very > well and reliably killed the offending task (java). > It happened a few times, the AOSP build broke and I restarted > it until it completed. E.g.: > > [ 2083.604374] Purging GPU memory, 0 pages freed, 4508 pages still pinned. > [ 2083.611000] 96 and 0 pages still available in the bound and unbound GPU > page lists. > [ 2083.618815] make invoked oom-killer: > gfp_mask=0x27000c0(GFP_KERNEL_ACCOUNT|__GFP_NOTRACK), order=2, oom_score_adj=0 > [ 2083.629257] make cpuset=/ mems_allowed=0 > ... > [ 2084.688753] Out of memory: Kill process 10431 (java) score 378 or > sacrifice child > [ 2084.696593] Killed process 10431 (java) total-vm:5200964kB, > anon-rss:2521764kB, file-rss:0kB, shmem-rss:0kB > [ 2084.938058] oom_reaper: reaped process 10431 (java), now anon-rss:0kB, > file-rss:8kB, shmem-rss:0kB > Good. Your problem does not exist in Linux 4.7 kernels. > Next I tried 4.6.2 with 78ebc2f7146156f4, then with kmallocwd (needed one > manual fixup), > then both patches. It still livelocked in all cases, the log spew looked > a bit different with 78ebc2f7146156f4 applied but still continued > endlessly. kmallocwd alone didn't trigger, with both patches > applied kmallocwd triggered but: > > [ 363.815595] MemAlloc-Info: stalling=33 dying=0 exiting=42 victim=0 > oom_count=0 > [ 363.815601] MemAlloc: kworker/0:0(4) flags=0x4208860 switches=212 seq=1 > gfp=0x26012c0(GFP_KERNEL|__GFP_NOWARN|__GFP_NORETRY|__GFP_NOTRACK) order=0 > delay=17984 > ** 1402 printk messages dropped ** [ 363.818816] [] > __do_page_cache_readahead+0x144/0x29d > ** 501 printk messages dropped ** > > I'll zip up the logs and send them off-list. Thank you for testing it. I found that your 4.6.2 kernel is depleting memory reserves before invoking the OOM killer. (oom_count=0 in MemAlloc-Info: line says out_of_memory() was never called). -- [ 483.832644] DMA free:0kB min:32kB low:44kB high:56kB active_anon:704kB inactive_anon:1008kB active_file:0kB inactive_file:0kB unevictable:20kB isolated(anon):0kB isolated(file):0kB present:15984kB managed:15900kB mlocked:20kB dirty:0kB writeback:248kB mapped:24kB shmem:112kB slab_reclaimable:376kB slab_unreclaimable:13456kB kernel_stack:0kB pagetables:52kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:11096 all_unreclaimable? yes [ 483.875261] lowmem_reserve[]: 0 3154 3154 3154 [ 483.879818] DMA32 free:0kB min:7168kB low:10396kB high:13624kB active_anon:2427064kB inactive_anon:615444kB active_file:1120kB inactive_file:1152kB unevictable:4532kB isolated(anon):844kB isolated(file):0kB present:3334492kB managed:3241464kB mlocked:4532kB dirty:16kB writeback:139208kB mapped:11328kB shmem:17300kB slab_reclaimable:46672kB slab_unreclaimable:97072kB kernel_stack:5264kB pagetables:16048kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:7533108 all_unreclaimable? no [ 483.926816] lowmem_reserve[]: 0 0 0 0 [ 483.930596] DMA: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 0kB [ 483.940528] DMA32: 0*4kB 0*8kB 0*16kB 0*32kB
Re: 4.6.2 frequent crashes under memory + IO pressure
On Thu, Jun 23, 2016 at 08:26:35PM +0900, Tetsuo Handa wrote: > > Since you think you saw OOM messages with the older kernels, I assume that > the OOM > killer was invoked on your 4.6.2 kernel. The OOM reaper in Linux 4.6 and > Linux 4.7 > will not help if the OOM killed process was between down_write(>mmap_sem) > and > up_write(>mmap_sem). > > I was not able to confirm whether the OOM killed process (I guess it was java) > was holding mm->mmap_sem for write, for /proc/sys/kernel/hung_task_warnings > dropped to 0 before traces of java threads are printed or console became > unusable due to the "delayed: kcryptd_crypt, ..." line. Anyway, I think that > kmallocwd will report it. > > > > It is sad that we haven't merged kmallocwd which will report > > > which memory allocations are stalling > > > ( > > > http://lkml.kernel.org/r/1462630604-23410-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp > > > ). > > > > Would you like me to try it? It wouldn't prevent the hang, though, > > just print better debug ouptut to serial console, right? > > Or would it OOM kill some process? > > Yes, but for bisection purpose, please try commit 78ebc2f7146156f4 without > applying kmallocwd. If that commit helps avoiding flood of the allocation > failure warnings, we can consider backporting it. If that commit does not > help, I think you are reporting a new location which we should not use > memory reserves. > > kmallocwd will not OOM kill some process. kmallocwd will not prevent the hang. > kmallocwd just prints information of threads which are stalling inside memory > allocation request. First I tried today's git, linux-4.7-rc4-187-g086e3eb, and the good news is that the oom killer seems to work very well and reliably killed the offending task (java). It happened a few times, the AOSP build broke and I restarted it until it completed. E.g.: [ 2083.604374] Purging GPU memory, 0 pages freed, 4508 pages still pinned. [ 2083.611000] 96 and 0 pages still available in the bound and unbound GPU page lists. [ 2083.618815] make invoked oom-killer: gfp_mask=0x27000c0(GFP_KERNEL_ACCOUNT|__GFP_NOTRACK), order=2, oom_score_adj=0 [ 2083.629257] make cpuset=/ mems_allowed=0 ... [ 2084.688753] Out of memory: Kill process 10431 (java) score 378 or sacrifice child [ 2084.696593] Killed process 10431 (java) total-vm:5200964kB, anon-rss:2521764kB, file-rss:0kB, shmem-rss:0kB [ 2084.938058] oom_reaper: reaped process 10431 (java), now anon-rss:0kB, file-rss:8kB, shmem-rss:0kB Next I tried 4.6.2 with 78ebc2f7146156f4, then with kmallocwd (needed one manual fixup), then both patches. It still livelocked in all cases, the log spew looked a bit different with 78ebc2f7146156f4 applied but still continued endlessly. kmallocwd alone didn't trigger, with both patches applied kmallocwd triggered but: [ 363.815595] MemAlloc-Info: stalling=33 dying=0 exiting=42 victim=0 oom_count=0 [ 363.815601] MemAlloc: kworker/0:0(4) flags=0x4208860 switches=212 seq=1 gfp=0x26012c0(GFP_KERNEL|__GFP_NOWARN|__GFP_NORETRY|__GFP_NOTRACK) order=0 delay=17984 ** 1402 printk messages dropped ** [ 363.818816] [] __do_page_cache_readahead+0x144/0x29d ** 501 printk messages dropped ** I'll zip up the logs and send them off-list. Thanks, Johannes
Re: 4.6.2 frequent crashes under memory + IO pressure
On Thu, Jun 23, 2016 at 08:26:35PM +0900, Tetsuo Handa wrote: > > Since you think you saw OOM messages with the older kernels, I assume that > the OOM > killer was invoked on your 4.6.2 kernel. The OOM reaper in Linux 4.6 and > Linux 4.7 > will not help if the OOM killed process was between down_write(>mmap_sem) > and > up_write(>mmap_sem). > > I was not able to confirm whether the OOM killed process (I guess it was java) > was holding mm->mmap_sem for write, for /proc/sys/kernel/hung_task_warnings > dropped to 0 before traces of java threads are printed or console became > unusable due to the "delayed: kcryptd_crypt, ..." line. Anyway, I think that > kmallocwd will report it. > > > > It is sad that we haven't merged kmallocwd which will report > > > which memory allocations are stalling > > > ( > > > http://lkml.kernel.org/r/1462630604-23410-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp > > > ). > > > > Would you like me to try it? It wouldn't prevent the hang, though, > > just print better debug ouptut to serial console, right? > > Or would it OOM kill some process? > > Yes, but for bisection purpose, please try commit 78ebc2f7146156f4 without > applying kmallocwd. If that commit helps avoiding flood of the allocation > failure warnings, we can consider backporting it. If that commit does not > help, I think you are reporting a new location which we should not use > memory reserves. > > kmallocwd will not OOM kill some process. kmallocwd will not prevent the hang. > kmallocwd just prints information of threads which are stalling inside memory > allocation request. First I tried today's git, linux-4.7-rc4-187-g086e3eb, and the good news is that the oom killer seems to work very well and reliably killed the offending task (java). It happened a few times, the AOSP build broke and I restarted it until it completed. E.g.: [ 2083.604374] Purging GPU memory, 0 pages freed, 4508 pages still pinned. [ 2083.611000] 96 and 0 pages still available in the bound and unbound GPU page lists. [ 2083.618815] make invoked oom-killer: gfp_mask=0x27000c0(GFP_KERNEL_ACCOUNT|__GFP_NOTRACK), order=2, oom_score_adj=0 [ 2083.629257] make cpuset=/ mems_allowed=0 ... [ 2084.688753] Out of memory: Kill process 10431 (java) score 378 or sacrifice child [ 2084.696593] Killed process 10431 (java) total-vm:5200964kB, anon-rss:2521764kB, file-rss:0kB, shmem-rss:0kB [ 2084.938058] oom_reaper: reaped process 10431 (java), now anon-rss:0kB, file-rss:8kB, shmem-rss:0kB Next I tried 4.6.2 with 78ebc2f7146156f4, then with kmallocwd (needed one manual fixup), then both patches. It still livelocked in all cases, the log spew looked a bit different with 78ebc2f7146156f4 applied but still continued endlessly. kmallocwd alone didn't trigger, with both patches applied kmallocwd triggered but: [ 363.815595] MemAlloc-Info: stalling=33 dying=0 exiting=42 victim=0 oom_count=0 [ 363.815601] MemAlloc: kworker/0:0(4) flags=0x4208860 switches=212 seq=1 gfp=0x26012c0(GFP_KERNEL|__GFP_NOWARN|__GFP_NORETRY|__GFP_NOTRACK) order=0 delay=17984 ** 1402 printk messages dropped ** [ 363.818816] [] __do_page_cache_readahead+0x144/0x29d ** 501 printk messages dropped ** I'll zip up the logs and send them off-list. Thanks, Johannes
Re: 4.6.2 frequent crashes under memory + IO pressure
Johannes Stezenbach wrote:
> What is your opinion about older kernels (4.4, 4.5) working?
> I think I've seen some OOM messages with the older kernels,
> Jill was killed and I restarted the build to complete it.
> A full bisect would take more than a day, I don't think
> I have the time for it.
> Since I use dm-crypt + lvm, should we add more Cc or do
> you think it is an mm issue?
I have no idea.
> > > Below I'm pasting some log snippets, let me know if you like
> > > it so much you want more of it ;-/ The total log is about 1.7MB.
> >
> > Yes, I'd like to browse it. Could you send it to me?
>
> Did you get any additional insights from it?
I found
[ 2245.660712] DMA free:4kB min:32kB
[ 2245.707031] DMA32 free:0kB min:6724kB
[ 2245.757597] Normal free:24kB min:928kB
[ 2245.806515] DMA: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 0kB
[ 2245.816359] DMA32: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 0kB
[ 2245.826378] Normal: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 0kB
[ 2317.853951] DMA free:0kB min:32kB
[ 2317.900460] DMA32 free:0kB min:6724kB
[ 2317.951574] Normal free:0kB min:928kB
[ 2318.000808] DMA: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 0kB
[ 2318.010713] DMA32: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 0kB
[ 2318.020767] Normal: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 0kB
which completely depleted memory reserves. So, please try commit
78ebc2f7146156f4
("mm,writeback: don't use memory reserves for wb_start_writeback") on your 4.6.2
kernel. As far as I know, passing mem=4G option will do equivalent thing.
Since you think you saw OOM messages with the older kernels, I assume that the
OOM
killer was invoked on your 4.6.2 kernel. The OOM reaper in Linux 4.6 and Linux
4.7
will not help if the OOM killed process was between down_write(>mmap_sem)
and
up_write(>mmap_sem).
I was not able to confirm whether the OOM killed process (I guess it was java)
was holding mm->mmap_sem for write, for /proc/sys/kernel/hung_task_warnings
dropped to 0 before traces of java threads are printed or console became
unusable due to the "delayed: kcryptd_crypt, ..." line. Anyway, I think that
kmallocwd will report it.
> > It is sad that we haven't merged kmallocwd which will report
> > which memory allocations are stalling
> > (
> > http://lkml.kernel.org/r/1462630604-23410-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp
> > ).
>
> Would you like me to try it? It wouldn't prevent the hang, though,
> just print better debug ouptut to serial console, right?
> Or would it OOM kill some process?
Yes, but for bisection purpose, please try commit 78ebc2f7146156f4 without
applying kmallocwd. If that commit helps avoiding flood of the allocation
failure warnings, we can consider backporting it. If that commit does not
help, I think you are reporting a new location which we should not use
memory reserves.
kmallocwd will not OOM kill some process. kmallocwd will not prevent the hang.
kmallocwd just prints information of threads which are stalling inside memory
allocation request.
Re: 4.6.2 frequent crashes under memory + IO pressure
Johannes Stezenbach wrote:
> What is your opinion about older kernels (4.4, 4.5) working?
> I think I've seen some OOM messages with the older kernels,
> Jill was killed and I restarted the build to complete it.
> A full bisect would take more than a day, I don't think
> I have the time for it.
> Since I use dm-crypt + lvm, should we add more Cc or do
> you think it is an mm issue?
I have no idea.
> > > Below I'm pasting some log snippets, let me know if you like
> > > it so much you want more of it ;-/ The total log is about 1.7MB.
> >
> > Yes, I'd like to browse it. Could you send it to me?
>
> Did you get any additional insights from it?
I found
[ 2245.660712] DMA free:4kB min:32kB
[ 2245.707031] DMA32 free:0kB min:6724kB
[ 2245.757597] Normal free:24kB min:928kB
[ 2245.806515] DMA: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 0kB
[ 2245.816359] DMA32: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 0kB
[ 2245.826378] Normal: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 0kB
[ 2317.853951] DMA free:0kB min:32kB
[ 2317.900460] DMA32 free:0kB min:6724kB
[ 2317.951574] Normal free:0kB min:928kB
[ 2318.000808] DMA: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 0kB
[ 2318.010713] DMA32: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 0kB
[ 2318.020767] Normal: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 0*2048kB 0*4096kB = 0kB
which completely depleted memory reserves. So, please try commit
78ebc2f7146156f4
("mm,writeback: don't use memory reserves for wb_start_writeback") on your 4.6.2
kernel. As far as I know, passing mem=4G option will do equivalent thing.
Since you think you saw OOM messages with the older kernels, I assume that the
OOM
killer was invoked on your 4.6.2 kernel. The OOM reaper in Linux 4.6 and Linux
4.7
will not help if the OOM killed process was between down_write(>mmap_sem)
and
up_write(>mmap_sem).
I was not able to confirm whether the OOM killed process (I guess it was java)
was holding mm->mmap_sem for write, for /proc/sys/kernel/hung_task_warnings
dropped to 0 before traces of java threads are printed or console became
unusable due to the "delayed: kcryptd_crypt, ..." line. Anyway, I think that
kmallocwd will report it.
> > It is sad that we haven't merged kmallocwd which will report
> > which memory allocations are stalling
> > (
> > http://lkml.kernel.org/r/1462630604-23410-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp
> > ).
>
> Would you like me to try it? It wouldn't prevent the hang, though,
> just print better debug ouptut to serial console, right?
> Or would it OOM kill some process?
Yes, but for bisection purpose, please try commit 78ebc2f7146156f4 without
applying kmallocwd. If that commit helps avoiding flood of the allocation
failure warnings, we can consider backporting it. If that commit does not
help, I think you are reporting a new location which we should not use
memory reserves.
kmallocwd will not OOM kill some process. kmallocwd will not prevent the hang.
kmallocwd just prints information of threads which are stalling inside memory
allocation request.
Re: 4.6.2 frequent crashes under memory + IO pressure
On Tue, Jun 21, 2016 at 08:47:51PM +0900, Tetsuo Handa wrote:
> Johannes Stezenbach wrote:
> >
> > a man's got to have a hobby, thus I'm running Android AOSP
> > builds on my home PC which has 4GB of RAM, 4GB swap.
> > Apparently it is not really adequate for the job but used to
> > work with a 4.4.10 kernel. Now I upgraded to 4.6.2
> > and it crashes usually within 30mins during compilation.
>
> Such reproducer is welcomed.
> You might be hitting OOM livelock using innocent workload.
>
> > The crash is a hard hang, mouse doesn't move, no reaction
> > to keyboard, nothing in logs (systemd journal) after reboot.
>
> Yes, it seems to me that your system is OOM livelocked.
I got from my crash log that X is hanging in
i915_gem_object_get_pages_gtt, and network is dead
due to order 0 allocation errors causing a series of
"ath9k_htc: RX memory allocation error", which is
what makes the issue so unpleasant.
The particular command which triggers it seems to be
Jill from the Android Java toolchain
(http://tools.android.com/tech-docs/jackandjill),
which runs as "java -Xmx3500m -jar $(JILL_JAR)", i.e.
potentially eating all my available RAM when linking
the Android framework.
Meanwhile I found some RAM and linux-4.6.2 runs stable
with 8GB for this workload. The build time (for the
partial AOSP rebuild that fairly reliably triggered the hangup)
dropped from ~20min to ~17min (so it wasn't trashing too
badly), swap usage dropped from ~50% (of 4GB) to <5%.
> It is sad that we haven't merged kmallocwd which will report
> which memory allocations are stalling
> (
> http://lkml.kernel.org/r/1462630604-23410-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp
> ).
Would you like me to try it? It wouldn't prevent the hang, though,
just print better debug ouptut to serial console, right?
Or would it OOM kill some process?
> > Then I tried 4.5.7, it seems to be stable so far.
> >
> > I'm using dm-crypt + lvm + ext4 (swap also in lvm).
> >
> > Now I hooked up a laptop to the serial port and captured
> > some logs of the crash which seems to be repeating
> >
> > [ 2240.842567] swapper/3: page allocation failure: order:0,
> > mode:0x2200020(GFP_NOWAIT|__GFP_HIGH|__GFP_NOTRACK)
> > or
> > [ 2241.167986] SLUB: Unable to allocate memory on node -1,
> > gfp=0x2080020(GFP_ATOMIC)
> >
> > over and over. Based on the backtraces in the log I decided
> > to hot-unplug USB devices, and twice the kernel came
> > back to live, but on the 3rd crash it was dead for good.
>
> The values
>
> DMA free:12kB min:32kB
> DMA32 free:2268kB min:6724kB
> Normal free:84kB min:928kB
>
> suggest that memory reserves are spent for pointless purpose. Maybe your
> system is
> falling into situation which was mitigated by commit 78ebc2f7146156f4
> ("mm,writeback:
> don't use memory reserves for wb_start_writeback"). Thus, applying that
> commit to
> your 4.6.2 kernel might help avoiding flood of these allocation failure
> messages.
I could try. Could you let me know if booting with mem=4G
is equivalent, or do I need to use memmap= or physically remove
the RAM (which is not so easy since the CPU fan is in the way).
> > Before I pressed the reset button I used SysRq-W. At the bottom
> > is a "BUG: workqueue lockup", it could be the result of
> > the log spew on serial console taking so long but it looks
> > like some IO is never completing.
>
> But even after you apply that commit, I guess you will still see silent hang
> up
> because the page allocator would think there is still reclaimable memory. So,
> is
> it possible to also try current linux.git kernels? I'd like to know whether
> "OOM detection rework" (which went to 4.7) helps giving up reclaiming and
> invoking the OOM killer with your workload.
>
> Maybe __GFP_FS allocations start invoking the OOM killer. But maybe __GFP_FS
> allocations still remain stuck waiting for !__GFP_FS allocations whereas
> !__GFP_FS
> allocations gives up without invoking the OOM killer (i.e. effectively no
> "give up").
I could also try. Same question about mem= though.
What is your opinion about older kernels (4.4, 4.5) working?
I think I've seen some OOM messages with the older kernels,
Jill was killed and I restarted the build to complete it.
A full bisect would take more than a day, I don't think
I have the time for it.
Since I use dm-crypt + lvm, should we add more Cc or do
you think it is an mm issue?
> > Below I'm pasting some log snippets, let me know if you like
> > it so much you want more of it ;-/ The total log is about 1.7MB.
>
> Yes, I'd like to browse it. Could you send it to me?
Did you get any additional insights from it?
Thanks,
Johannes
Re: 4.6.2 frequent crashes under memory + IO pressure
On Tue, Jun 21, 2016 at 08:47:51PM +0900, Tetsuo Handa wrote:
> Johannes Stezenbach wrote:
> >
> > a man's got to have a hobby, thus I'm running Android AOSP
> > builds on my home PC which has 4GB of RAM, 4GB swap.
> > Apparently it is not really adequate for the job but used to
> > work with a 4.4.10 kernel. Now I upgraded to 4.6.2
> > and it crashes usually within 30mins during compilation.
>
> Such reproducer is welcomed.
> You might be hitting OOM livelock using innocent workload.
>
> > The crash is a hard hang, mouse doesn't move, no reaction
> > to keyboard, nothing in logs (systemd journal) after reboot.
>
> Yes, it seems to me that your system is OOM livelocked.
I got from my crash log that X is hanging in
i915_gem_object_get_pages_gtt, and network is dead
due to order 0 allocation errors causing a series of
"ath9k_htc: RX memory allocation error", which is
what makes the issue so unpleasant.
The particular command which triggers it seems to be
Jill from the Android Java toolchain
(http://tools.android.com/tech-docs/jackandjill),
which runs as "java -Xmx3500m -jar $(JILL_JAR)", i.e.
potentially eating all my available RAM when linking
the Android framework.
Meanwhile I found some RAM and linux-4.6.2 runs stable
with 8GB for this workload. The build time (for the
partial AOSP rebuild that fairly reliably triggered the hangup)
dropped from ~20min to ~17min (so it wasn't trashing too
badly), swap usage dropped from ~50% (of 4GB) to <5%.
> It is sad that we haven't merged kmallocwd which will report
> which memory allocations are stalling
> (
> http://lkml.kernel.org/r/1462630604-23410-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp
> ).
Would you like me to try it? It wouldn't prevent the hang, though,
just print better debug ouptut to serial console, right?
Or would it OOM kill some process?
> > Then I tried 4.5.7, it seems to be stable so far.
> >
> > I'm using dm-crypt + lvm + ext4 (swap also in lvm).
> >
> > Now I hooked up a laptop to the serial port and captured
> > some logs of the crash which seems to be repeating
> >
> > [ 2240.842567] swapper/3: page allocation failure: order:0,
> > mode:0x2200020(GFP_NOWAIT|__GFP_HIGH|__GFP_NOTRACK)
> > or
> > [ 2241.167986] SLUB: Unable to allocate memory on node -1,
> > gfp=0x2080020(GFP_ATOMIC)
> >
> > over and over. Based on the backtraces in the log I decided
> > to hot-unplug USB devices, and twice the kernel came
> > back to live, but on the 3rd crash it was dead for good.
>
> The values
>
> DMA free:12kB min:32kB
> DMA32 free:2268kB min:6724kB
> Normal free:84kB min:928kB
>
> suggest that memory reserves are spent for pointless purpose. Maybe your
> system is
> falling into situation which was mitigated by commit 78ebc2f7146156f4
> ("mm,writeback:
> don't use memory reserves for wb_start_writeback"). Thus, applying that
> commit to
> your 4.6.2 kernel might help avoiding flood of these allocation failure
> messages.
I could try. Could you let me know if booting with mem=4G
is equivalent, or do I need to use memmap= or physically remove
the RAM (which is not so easy since the CPU fan is in the way).
> > Before I pressed the reset button I used SysRq-W. At the bottom
> > is a "BUG: workqueue lockup", it could be the result of
> > the log spew on serial console taking so long but it looks
> > like some IO is never completing.
>
> But even after you apply that commit, I guess you will still see silent hang
> up
> because the page allocator would think there is still reclaimable memory. So,
> is
> it possible to also try current linux.git kernels? I'd like to know whether
> "OOM detection rework" (which went to 4.7) helps giving up reclaiming and
> invoking the OOM killer with your workload.
>
> Maybe __GFP_FS allocations start invoking the OOM killer. But maybe __GFP_FS
> allocations still remain stuck waiting for !__GFP_FS allocations whereas
> !__GFP_FS
> allocations gives up without invoking the OOM killer (i.e. effectively no
> "give up").
I could also try. Same question about mem= though.
What is your opinion about older kernels (4.4, 4.5) working?
I think I've seen some OOM messages with the older kernels,
Jill was killed and I restarted the build to complete it.
A full bisect would take more than a day, I don't think
I have the time for it.
Since I use dm-crypt + lvm, should we add more Cc or do
you think it is an mm issue?
> > Below I'm pasting some log snippets, let me know if you like
> > it so much you want more of it ;-/ The total log is about 1.7MB.
>
> Yes, I'd like to browse it. Could you send it to me?
Did you get any additional insights from it?
Thanks,
Johannes
Re: 4.6.2 frequent crashes under memory + IO pressure
Johannes Stezenbach wrote:
> Hi,
>
> a man's got to have a hobby, thus I'm running Android AOSP
> builds on my home PC which has 4GB of RAM, 4GB swap.
> Apparently it is not really adequate for the job but used to
> work with a 4.4.10 kernel. Now I upgraded to 4.6.2
> and it crashes usually within 30mins during compilation.
Such reproducer is welcomed.
You might be hitting OOM livelock using innocent workload.
> The crash is a hard hang, mouse doesn't move, no reaction
> to keyboard, nothing in logs (systemd journal) after reboot.
Yes, it seems to me that your system is OOM livelocked.
It is sad that we haven't merged kmallocwd which will report
which memory allocations are stalling
(
http://lkml.kernel.org/r/1462630604-23410-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp
).
>
> Then I tried 4.5.7, it seems to be stable so far.
>
> I'm using dm-crypt + lvm + ext4 (swap also in lvm).
>
> Now I hooked up a laptop to the serial port and captured
> some logs of the crash which seems to be repeating
>
> [ 2240.842567] swapper/3: page allocation failure: order:0,
> mode:0x2200020(GFP_NOWAIT|__GFP_HIGH|__GFP_NOTRACK)
> or
> [ 2241.167986] SLUB: Unable to allocate memory on node -1,
> gfp=0x2080020(GFP_ATOMIC)
>
> over and over. Based on the backtraces in the log I decided
> to hot-unplug USB devices, and twice the kernel came
> back to live, but on the 3rd crash it was dead for good.
The values
DMA free:12kB min:32kB
DMA32 free:2268kB min:6724kB
Normal free:84kB min:928kB
suggest that memory reserves are spent for pointless purpose. Maybe your system
is
falling into situation which was mitigated by commit 78ebc2f7146156f4
("mm,writeback:
don't use memory reserves for wb_start_writeback"). Thus, applying that commit
to
your 4.6.2 kernel might help avoiding flood of these allocation failure
messages.
> Before I pressed the reset button I used SysRq-W. At the bottom
> is a "BUG: workqueue lockup", it could be the result of
> the log spew on serial console taking so long but it looks
> like some IO is never completing.
But even after you apply that commit, I guess you will still see silent hang up
because the page allocator would think there is still reclaimable memory. So, is
it possible to also try current linux.git kernels? I'd like to know whether
"OOM detection rework" (which went to 4.7) helps giving up reclaiming and
invoking the OOM killer with your workload.
Maybe __GFP_FS allocations start invoking the OOM killer. But maybe __GFP_FS
allocations still remain stuck waiting for !__GFP_FS allocations whereas
!__GFP_FS
allocations gives up without invoking the OOM killer (i.e. effectively no "give
up").
>
> Below I'm pasting some log snippets, let me know if you like
> it so much you want more of it ;-/ The total log is about 1.7MB.
Yes, I'd like to browse it. Could you send it to me?
> [ 2378.279029] kswapd0 D 88003744f538 0 766 2
> 0x
> [ 2378.286167] 88003744f538 00ff88011b5ccd80 88011b5d62d8
> 88011ae58000
> [ 2378.293628] 88003745 88003745 0001000984f2
> 88003744f570
> [ 2378.301168] 88011b5ccd80 88003745 88003744f550
> 81845cec
> [ 2378.308674] Call Trace:
> [ 2378.311154] [] schedule+0x8b/0xa3
> [ 2378.316153] [] schedule_timeout+0x20b/0x285
> [ 2378.322028] [] ? init_timer_key+0x112/0x112
> [ 2378.327931] [] io_schedule_timeout+0xa0/0x102
> [ 2378.333960] [] ? io_schedule_timeout+0xa0/0x102
> [ 2378.340166] [] mempool_alloc+0x123/0x154
> [ 2378.345781] [] ? wait_woken+0x72/0x72
> [ 2378.351148] [] bio_alloc_bioset+0xe8/0x1d7
> [ 2378.356910] [] alloc_tio+0x2d/0x47
> [ 2378.361996] [] __split_and_process_bio+0x310/0x3a3
> [ 2378.368470] [] dm_make_request+0xb5/0xe2
> [ 2378.374078] [] generic_make_request+0xcc/0x180
> [ 2378.380206] [] submit_bio+0xfd/0x145
> [ 2378.385482] [] __swap_writepage+0x202/0x225
> [ 2378.391349] [] ? preempt_count_sub+0xf0/0x100
> [ 2378.397398] [] ? _raw_spin_unlock+0x31/0x44
> [ 2378.403273] [] ? page_swapcount+0x45/0x4c
> [ 2378.408984] [] swap_writepage+0x3a/0x3e
> [ 2378.414530] [] pageout.isra.16+0x160/0x2a7
> [ 2378.420320] [] shrink_page_list+0x5a0/0x8c4
> [ 2378.426197] [] shrink_inactive_list+0x29e/0x4a1
> [ 2378.432434] [] shrink_zone_memcg+0x4c1/0x661
> [ 2378.438406] [] shrink_zone+0xdc/0x1e5
> [ 2378.443742] [] ? shrink_zone+0xdc/0x1e5
> [ 2378.449238] [] kswapd+0x6df/0x814
> [ 2378.454222] [] ? mem_cgroup_shrink_node_zone+0x209/0x209
> [ 2378.461196] [] kthread+0xff/0x107
> [ 2378.466182] [] ret_from_fork+0x22/0x50
> [ 2378.471631] [] ? kthread_create_on_node+0x1ea/0x1ea
Unfortunately, kswapd which attempted to swap out some page to
swap partition cannot make forward progress because memory allocation
for storage I/O is stalling.
> [ 2418.938946] Showing busy workqueues and worker pools:
> [ 2418.944034] workqueue events: flags=0x0
> [ 2418.947898] pwq 0: cpus=0 node=0 flags=0x0 nice=0
Re: 4.6.2 frequent crashes under memory + IO pressure
Johannes Stezenbach wrote:
> Hi,
>
> a man's got to have a hobby, thus I'm running Android AOSP
> builds on my home PC which has 4GB of RAM, 4GB swap.
> Apparently it is not really adequate for the job but used to
> work with a 4.4.10 kernel. Now I upgraded to 4.6.2
> and it crashes usually within 30mins during compilation.
Such reproducer is welcomed.
You might be hitting OOM livelock using innocent workload.
> The crash is a hard hang, mouse doesn't move, no reaction
> to keyboard, nothing in logs (systemd journal) after reboot.
Yes, it seems to me that your system is OOM livelocked.
It is sad that we haven't merged kmallocwd which will report
which memory allocations are stalling
(
http://lkml.kernel.org/r/1462630604-23410-1-git-send-email-penguin-ker...@i-love.sakura.ne.jp
).
>
> Then I tried 4.5.7, it seems to be stable so far.
>
> I'm using dm-crypt + lvm + ext4 (swap also in lvm).
>
> Now I hooked up a laptop to the serial port and captured
> some logs of the crash which seems to be repeating
>
> [ 2240.842567] swapper/3: page allocation failure: order:0,
> mode:0x2200020(GFP_NOWAIT|__GFP_HIGH|__GFP_NOTRACK)
> or
> [ 2241.167986] SLUB: Unable to allocate memory on node -1,
> gfp=0x2080020(GFP_ATOMIC)
>
> over and over. Based on the backtraces in the log I decided
> to hot-unplug USB devices, and twice the kernel came
> back to live, but on the 3rd crash it was dead for good.
The values
DMA free:12kB min:32kB
DMA32 free:2268kB min:6724kB
Normal free:84kB min:928kB
suggest that memory reserves are spent for pointless purpose. Maybe your system
is
falling into situation which was mitigated by commit 78ebc2f7146156f4
("mm,writeback:
don't use memory reserves for wb_start_writeback"). Thus, applying that commit
to
your 4.6.2 kernel might help avoiding flood of these allocation failure
messages.
> Before I pressed the reset button I used SysRq-W. At the bottom
> is a "BUG: workqueue lockup", it could be the result of
> the log spew on serial console taking so long but it looks
> like some IO is never completing.
But even after you apply that commit, I guess you will still see silent hang up
because the page allocator would think there is still reclaimable memory. So, is
it possible to also try current linux.git kernels? I'd like to know whether
"OOM detection rework" (which went to 4.7) helps giving up reclaiming and
invoking the OOM killer with your workload.
Maybe __GFP_FS allocations start invoking the OOM killer. But maybe __GFP_FS
allocations still remain stuck waiting for !__GFP_FS allocations whereas
!__GFP_FS
allocations gives up without invoking the OOM killer (i.e. effectively no "give
up").
>
> Below I'm pasting some log snippets, let me know if you like
> it so much you want more of it ;-/ The total log is about 1.7MB.
Yes, I'd like to browse it. Could you send it to me?
> [ 2378.279029] kswapd0 D 88003744f538 0 766 2
> 0x
> [ 2378.286167] 88003744f538 00ff88011b5ccd80 88011b5d62d8
> 88011ae58000
> [ 2378.293628] 88003745 88003745 0001000984f2
> 88003744f570
> [ 2378.301168] 88011b5ccd80 88003745 88003744f550
> 81845cec
> [ 2378.308674] Call Trace:
> [ 2378.311154] [] schedule+0x8b/0xa3
> [ 2378.316153] [] schedule_timeout+0x20b/0x285
> [ 2378.322028] [] ? init_timer_key+0x112/0x112
> [ 2378.327931] [] io_schedule_timeout+0xa0/0x102
> [ 2378.333960] [] ? io_schedule_timeout+0xa0/0x102
> [ 2378.340166] [] mempool_alloc+0x123/0x154
> [ 2378.345781] [] ? wait_woken+0x72/0x72
> [ 2378.351148] [] bio_alloc_bioset+0xe8/0x1d7
> [ 2378.356910] [] alloc_tio+0x2d/0x47
> [ 2378.361996] [] __split_and_process_bio+0x310/0x3a3
> [ 2378.368470] [] dm_make_request+0xb5/0xe2
> [ 2378.374078] [] generic_make_request+0xcc/0x180
> [ 2378.380206] [] submit_bio+0xfd/0x145
> [ 2378.385482] [] __swap_writepage+0x202/0x225
> [ 2378.391349] [] ? preempt_count_sub+0xf0/0x100
> [ 2378.397398] [] ? _raw_spin_unlock+0x31/0x44
> [ 2378.403273] [] ? page_swapcount+0x45/0x4c
> [ 2378.408984] [] swap_writepage+0x3a/0x3e
> [ 2378.414530] [] pageout.isra.16+0x160/0x2a7
> [ 2378.420320] [] shrink_page_list+0x5a0/0x8c4
> [ 2378.426197] [] shrink_inactive_list+0x29e/0x4a1
> [ 2378.432434] [] shrink_zone_memcg+0x4c1/0x661
> [ 2378.438406] [] shrink_zone+0xdc/0x1e5
> [ 2378.443742] [] ? shrink_zone+0xdc/0x1e5
> [ 2378.449238] [] kswapd+0x6df/0x814
> [ 2378.454222] [] ? mem_cgroup_shrink_node_zone+0x209/0x209
> [ 2378.461196] [] kthread+0xff/0x107
> [ 2378.466182] [] ret_from_fork+0x22/0x50
> [ 2378.471631] [] ? kthread_create_on_node+0x1ea/0x1ea
Unfortunately, kswapd which attempted to swap out some page to
swap partition cannot make forward progress because memory allocation
for storage I/O is stalling.
> [ 2418.938946] Showing busy workqueues and worker pools:
> [ 2418.944034] workqueue events: flags=0x0
> [ 2418.947898] pwq 0: cpus=0 node=0 flags=0x0 nice=0
4.6.2 frequent crashes under memory + IO pressure
Hi, a man's got to have a hobby, thus I'm running Android AOSP builds on my home PC which has 4GB of RAM, 4GB swap. Apparently it is not really adequate for the job but used to work with a 4.4.10 kernel. Now I upgraded to 4.6.2 and it crashes usually within 30mins during compilation. The crash is a hard hang, mouse doesn't move, no reaction to keyboard, nothing in logs (systemd journal) after reboot. Then I tried 4.5.7, it seems to be stable so far. I'm using dm-crypt + lvm + ext4 (swap also in lvm). Now I hooked up a laptop to the serial port and captured some logs of the crash which seems to be repeating [ 2240.842567] swapper/3: page allocation failure: order:0, mode:0x2200020(GFP_NOWAIT|__GFP_HIGH|__GFP_NOTRACK) or [ 2241.167986] SLUB: Unable to allocate memory on node -1, gfp=0x2080020(GFP_ATOMIC) over and over. Based on the backtraces in the log I decided to hot-unplug USB devices, and twice the kernel came back to live, but on the 3rd crash it was dead for good. Before I pressed the reset button I used SysRq-W. At the bottom is a "BUG: workqueue lockup", it could be the result of the log spew on serial console taking so long but it looks like some IO is never completing. Below I'm pasting some log snippets, let me know if you like it so much you want more of it ;-/ The total log is about 1.7MB. Thanks, Johannes [ 2240.837431] warn_alloc_failed: 13 callbacks suppressed [ 2240.842567] swapper/3: page allocation failure: order:0, mode:0x2200020(GFP_NOWAIT|__GFP_HIGH|__GFP_NOTRACK) [ 2240.852384] CPU: 3 PID: 0 Comm: swapper/3 Not tainted 4.6.2 #2 [ 2240.858215] Hardware name: System manufacturer System Product Name/P8H77-V, BIOS 1905 10/27/2014 [ 2240.866985] 0086 8d325b5c895ad90b 88011b603a90 81368f0c [ 2240.874437] 88011b603b30 811659de [ 2240.881907] 88011b603b40 02200021 88011b603b18 81f58240 [ 2240.889396] Call Trace: [ 2240.891839][] dump_stack+0x85/0xbe [ 2240.897611] [] warn_alloc_failed+0x134/0x15c [ 2240.903531] [] __alloc_pages_nodemask+0x7bd/0x978 [ 2240.909884] [] new_slab+0x129/0x3bb [ 2240.915030] [] ___slab_alloc.constprop.22+0x2fb/0x37b [ 2240.921730] [] ? __alloc_skb+0x55/0x1b4 [ 2240.927224] [] ? skb_release_data+0xc0/0xd0 [ 2240.933046] [] ? kfree+0x1c0/0x216 [ 2240.938089] [] __slab_alloc.isra.17.constprop.21+0x57/0x8b [ 2240.945214] [] ? __slab_alloc.isra.17.constprop.21+0x57/0x8b [ 2240.952520] [] ? __alloc_skb+0x55/0x1b4 [ 2240.957997] [] kmem_cache_alloc+0xa0/0x1d6 [ 2240.963734] [] ? __alloc_skb+0x55/0x1b4 [ 2240.969210] [] __alloc_skb+0x55/0x1b4 [ 2240.974524] [] ath9k_hif_usb_reg_in_cb+0xd4/0x181 [ath9k_htc] [ 2240.981925] [] __usb_hcd_giveback_urb+0xa6/0x10b [ 2240.988215] [] usb_giveback_urb_bh+0x9a/0xe4 [ 2240.994134] [] tasklet_hi_action+0x10c/0x11b [ 2241.63] [] __do_softirq+0x182/0x377 [ 2241.005548] [] irq_exit+0x54/0xa8 [ 2241.010521] [] do_IRQ+0xc7/0xdf [ 2241.015321] [] common_interrupt+0x8c/0x8c [ 2241.020981][] ? cpuidle_enter_state+0x1ae/0x251 [ 2241.027888] [] cpuidle_enter+0x17/0x19 [ 2241.033280] [] call_cpuidle+0x44/0x46 [ 2241.038600] [] cpu_startup_entry+0x2a7/0x378 [ 2241.044524] [] start_secondary+0x17c/0x192 [ 2241.050265] Mem-Info: [ 2241.052543] active_anon:654174 inactive_anon:208849 isolated_anon:64 [ 2241.052543] active_file:4782 inactive_file:3878 isolated_file:0 [ 2241.052543] unevictable:1156 dirty:8 writeback:28052 unstable:0 [ 2241.052543] slab_reclaimable:13827 slab_unreclaimable:25768 [ 2241.052543] mapped:6794 shmem:3939 pagetables:5299 bounce:0 [ 2241.052543] free:424 free_pcp:39 free_cma:0 [ 2241.086414] DMA free:12kB min:32kB low:44kB high:56kB active_anon:28kB inactive_anon:84kB active_file:68kB inactive_file:40kB unevictable:124kB isolated(anon):0kB isolated(file):0kB present:15984kB managed:15900kB mlocked:124kB dirty:0kB writeback:0kB mapped:228kB shmem:36kB slab_reclaimable:552kB slab_unreclaimable:14656kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no [ 2241.128265] lowmem_reserve[]: 0 3156 3592 3592 [ 2241.132792] DMA32 free:2120kB min:6724kB low:9956kB high:13188kB active_anon:2414116kB inactive_anon:629228kB active_file:15184kB inactive_file:13336kB unevictable:3624kB isolated(anon):256kB isolated(file):0kB present:3334492kB managed:3243420kB mlocked:3624kB dirty:24kB writeback:104760kB mapped:21988kB shmem:13936kB slab_reclaimable:46356kB slab_unreclaimable:74196kB kernel_stack:4144kB pagetables:17708kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:92 all_unreclaimable? no [ 2241.167769] kworker/u8:3: page allocation failure: order:0, mode:0x2200020(GFP_NOWAIT|__GFP_HIGH|__GFP_NOTRACK) [ 2241.167771] CPU: 2 PID: 1470 Comm: kworker/u8:3 Not tainted 4.6.2 #2 [ 2241.167772] Hardware name: System
4.6.2 frequent crashes under memory + IO pressure
Hi, a man's got to have a hobby, thus I'm running Android AOSP builds on my home PC which has 4GB of RAM, 4GB swap. Apparently it is not really adequate for the job but used to work with a 4.4.10 kernel. Now I upgraded to 4.6.2 and it crashes usually within 30mins during compilation. The crash is a hard hang, mouse doesn't move, no reaction to keyboard, nothing in logs (systemd journal) after reboot. Then I tried 4.5.7, it seems to be stable so far. I'm using dm-crypt + lvm + ext4 (swap also in lvm). Now I hooked up a laptop to the serial port and captured some logs of the crash which seems to be repeating [ 2240.842567] swapper/3: page allocation failure: order:0, mode:0x2200020(GFP_NOWAIT|__GFP_HIGH|__GFP_NOTRACK) or [ 2241.167986] SLUB: Unable to allocate memory on node -1, gfp=0x2080020(GFP_ATOMIC) over and over. Based on the backtraces in the log I decided to hot-unplug USB devices, and twice the kernel came back to live, but on the 3rd crash it was dead for good. Before I pressed the reset button I used SysRq-W. At the bottom is a "BUG: workqueue lockup", it could be the result of the log spew on serial console taking so long but it looks like some IO is never completing. Below I'm pasting some log snippets, let me know if you like it so much you want more of it ;-/ The total log is about 1.7MB. Thanks, Johannes [ 2240.837431] warn_alloc_failed: 13 callbacks suppressed [ 2240.842567] swapper/3: page allocation failure: order:0, mode:0x2200020(GFP_NOWAIT|__GFP_HIGH|__GFP_NOTRACK) [ 2240.852384] CPU: 3 PID: 0 Comm: swapper/3 Not tainted 4.6.2 #2 [ 2240.858215] Hardware name: System manufacturer System Product Name/P8H77-V, BIOS 1905 10/27/2014 [ 2240.866985] 0086 8d325b5c895ad90b 88011b603a90 81368f0c [ 2240.874437] 88011b603b30 811659de [ 2240.881907] 88011b603b40 02200021 88011b603b18 81f58240 [ 2240.889396] Call Trace: [ 2240.891839][] dump_stack+0x85/0xbe [ 2240.897611] [] warn_alloc_failed+0x134/0x15c [ 2240.903531] [] __alloc_pages_nodemask+0x7bd/0x978 [ 2240.909884] [] new_slab+0x129/0x3bb [ 2240.915030] [] ___slab_alloc.constprop.22+0x2fb/0x37b [ 2240.921730] [] ? __alloc_skb+0x55/0x1b4 [ 2240.927224] [] ? skb_release_data+0xc0/0xd0 [ 2240.933046] [] ? kfree+0x1c0/0x216 [ 2240.938089] [] __slab_alloc.isra.17.constprop.21+0x57/0x8b [ 2240.945214] [] ? __slab_alloc.isra.17.constprop.21+0x57/0x8b [ 2240.952520] [] ? __alloc_skb+0x55/0x1b4 [ 2240.957997] [] kmem_cache_alloc+0xa0/0x1d6 [ 2240.963734] [] ? __alloc_skb+0x55/0x1b4 [ 2240.969210] [] __alloc_skb+0x55/0x1b4 [ 2240.974524] [] ath9k_hif_usb_reg_in_cb+0xd4/0x181 [ath9k_htc] [ 2240.981925] [] __usb_hcd_giveback_urb+0xa6/0x10b [ 2240.988215] [] usb_giveback_urb_bh+0x9a/0xe4 [ 2240.994134] [] tasklet_hi_action+0x10c/0x11b [ 2241.63] [] __do_softirq+0x182/0x377 [ 2241.005548] [] irq_exit+0x54/0xa8 [ 2241.010521] [] do_IRQ+0xc7/0xdf [ 2241.015321] [] common_interrupt+0x8c/0x8c [ 2241.020981][] ? cpuidle_enter_state+0x1ae/0x251 [ 2241.027888] [] cpuidle_enter+0x17/0x19 [ 2241.033280] [] call_cpuidle+0x44/0x46 [ 2241.038600] [] cpu_startup_entry+0x2a7/0x378 [ 2241.044524] [] start_secondary+0x17c/0x192 [ 2241.050265] Mem-Info: [ 2241.052543] active_anon:654174 inactive_anon:208849 isolated_anon:64 [ 2241.052543] active_file:4782 inactive_file:3878 isolated_file:0 [ 2241.052543] unevictable:1156 dirty:8 writeback:28052 unstable:0 [ 2241.052543] slab_reclaimable:13827 slab_unreclaimable:25768 [ 2241.052543] mapped:6794 shmem:3939 pagetables:5299 bounce:0 [ 2241.052543] free:424 free_pcp:39 free_cma:0 [ 2241.086414] DMA free:12kB min:32kB low:44kB high:56kB active_anon:28kB inactive_anon:84kB active_file:68kB inactive_file:40kB unevictable:124kB isolated(anon):0kB isolated(file):0kB present:15984kB managed:15900kB mlocked:124kB dirty:0kB writeback:0kB mapped:228kB shmem:36kB slab_reclaimable:552kB slab_unreclaimable:14656kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no [ 2241.128265] lowmem_reserve[]: 0 3156 3592 3592 [ 2241.132792] DMA32 free:2120kB min:6724kB low:9956kB high:13188kB active_anon:2414116kB inactive_anon:629228kB active_file:15184kB inactive_file:13336kB unevictable:3624kB isolated(anon):256kB isolated(file):0kB present:3334492kB managed:3243420kB mlocked:3624kB dirty:24kB writeback:104760kB mapped:21988kB shmem:13936kB slab_reclaimable:46356kB slab_unreclaimable:74196kB kernel_stack:4144kB pagetables:17708kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:92 all_unreclaimable? no [ 2241.167769] kworker/u8:3: page allocation failure: order:0, mode:0x2200020(GFP_NOWAIT|__GFP_HIGH|__GFP_NOTRACK) [ 2241.167771] CPU: 2 PID: 1470 Comm: kworker/u8:3 Not tainted 4.6.2 #2 [ 2241.167772] Hardware name: System
