linux-kernel - Re: 4.6.2 frequent crashes under memory + IO pressure

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [day] [month] [year] [list]
Date:	Sun, 26 Jun 2016 21:40:25 +0200
From:	Johannes Stezenbach <js@...21.net>
To:	Tetsuo Handa <penguin-kernel@...ove.SAKURA.ne.jp>
Cc:	linux-mm@...ck.org, linux-kernel@...r.kernel.org, mhocko@...nel.org
Subject: 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
>  0xffffffff81167522 : get_page_from_freelist+0x0/0x82b [kernel]
>  0xffffffff81168127 : __alloc_pages_nodemask+0x3da/0x978 [kernel]
>  0xffffffff8119fb2a : new_slab+0xbc/0x3bb [kernel]
>  0xffffffff811a1acd : ___slab_alloc.constprop.22+0x2fb/0x37b [kernel]
>  0xffffffff81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
>  0xffffffff810c502d : put_lock_stats.isra.9+0xe/0x20 [kernel] (inexact)
>  0xffffffff811a1ba4 : __slab_alloc.isra.17.constprop.21+0x57/0x8b [kernel] (inexact)
>  0xffffffff811a1ba4 : __slab_alloc.isra.17.constprop.21+0x57/0x8b [kernel] (inexact)
>  0xffffffff81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
>  0xffffffff811a1c78 : kmem_cache_alloc+0xa0/0x1d6 [kernel] (inexact)
>  0xffffffff81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
>  0xffffffff81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
>  0xffffffff81162b7a : mempool_alloc+0x72/0x154 [kernel] (inexact)
>  0xffffffff810c6438 : __lock_acquire.isra.16+0x55e/0xb4c [kernel] (inexact)
>  0xffffffff8133fdc1 : bio_alloc_bioset+0xe8/0x1d7 [kernel] (inexact)
>  0xffffffff816342ea : alloc_tio+0x2d/0x47 [kernel] (inexact)
>  0xffffffff8163587e : __split_and_process_bio+0x310/0x3a3 [kernel] (inexact)
>  0xffffffff81635e15 : dm_make_request+0xb5/0xe2 [kernel] (inexact)
>  0xffffffff81347ae7 : generic_make_request+0xcc/0x180 [kernel] (inexact)
>  0xffffffff81347c98 : submit_bio+0xfd/0x145 [kernel] (inexact)
> 
> kswapd0(766) 0x2201200
>  0xffffffff81167522 : get_page_from_freelist+0x0/0x82b [kernel]
>  0xffffffff81168127 : __alloc_pages_nodemask+0x3da/0x978 [kernel]
>  0xffffffff8119fb2a : new_slab+0xbc/0x3bb [kernel]
>  0xffffffff811a1acd : ___slab_alloc.constprop.22+0x2fb/0x37b [kernel]
>  0xffffffff81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
>  0xffffffff81640e29 : kcryptd_queue_crypt+0x63/0x68 [kernel] (inexact)
>  0xffffffff811a1ba4 : __slab_alloc.isra.17.constprop.21+0x57/0x8b [kernel] (inexact)
>  0xffffffff811a1ba4 : __slab_alloc.isra.17.constprop.21+0x57/0x8b [kernel] (inexact)
>  0xffffffff81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
>  0xffffffff811a1c78 : kmem_cache_alloc+0xa0/0x1d6 [kernel] (inexact)
>  0xffffffff81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
>  0xffffffff81162a88 : mempool_alloc_slab+0x15/0x17 [kernel] (inexact)
>  0xffffffff81162b7a : mempool_alloc+0x72/0x154 [kernel] (inexact)
>  0xffffffff8101f5ba : sched_clock+0x9/0xd [kernel] (inexact)
>  0xffffffff810ae420 : local_clock+0x20/0x22 [kernel] (inexact)
>  0xffffffff8133fdc1 : bio_alloc_bioset+0xe8/0x1d7 [kernel] (inexact)
>  0xffffffff811983d0 : end_swap_bio_write+0x0/0x6a [kernel] (inexact)
>  0xffffffff8119854b : get_swap_bio+0x25/0x6c [kernel] (inexact)
>  0xffffffff811983d0 : end_swap_bio_write+0x0/0x6a [kernel] (inexact)
>  0xffffffff811988ef : __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 0xffffffff811b9c82
> > > /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