From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
	id S1753037AbcHONc2 (ORCPT <rfc822;w@1wt.eu>);
	Mon, 15 Aug 2016 09:32:28 -0400
Received: from parrot.pmhahn.de ([88.198.50.102]:55421 "EHLO parrot.pmhahn.de"
	rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP
	id S1752783AbcHONc1 (ORCPT <rfc822;linux-kernel@vger.kernel.org>);
	Mon, 15 Aug 2016 09:32:27 -0400
X-Greylist: delayed 358 seconds by postgrey-1.27 at vger.kernel.org; Mon, 15 Aug 2016 09:32:26 EDT
To: "linux-kernel@vger.kernel.org" <linux-kernel@vger.kernel.org>,
        Rusty Russell <rusty@rustcorp.com.au>,
        qemu-devel <qemu-devel@nongnu.org>
From: Philipp Hahn <pmhahn@pmhahn.de>
X-Enigmail-Draft-Status: N1110
Subject: virnet: page allocation failure: order:0
Message-ID: <8838f4e4-cb93-9c78-f446-7b1e2cb639fa@pmhahn.de>
Date: Mon, 15 Aug 2016 15:26:25 +0200
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101
 Icedove/45.2.0
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

Hello,

this Sunday one of our virtual servers running linux-4.1.16 inside
OpenStack using qemu "crashed" while doing a backup using rsync to a
slow NFS server.
Crash here means that the server became unresponsive to network traffic:
- it was no longer able to contact the two LDAP servers
- no ssh login was possible
- the backup got stuck
- crond was still running and added process after process, leading to
~1.5k processes running after one day.

What I don't know is if the network problem was the cause or the
consequence. Because of that I want to understand why the follwoing
order=0 allocation failed:

> swapper/0: page allocation failure: order:0, mode:0x120

 4KiB
src/extern/linux/include/linux/gfp.h:
  18 #define ___GFP_HIGH»»···0x20u
  21 #define ___GFP_COLD»»···0x100u
  72 #define __GFP_HIGH»·((__force gfp_t)___GFP_HIGH)»···/* Should
access emergency pools? */


  75 #define __GFP_COLD»·((__force gfp_t)___GFP_COLD)»···/* Cache-cold
page required */



> CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.1.0-ucs190-amd64 #1 Debian
4.1.6-1.190.201604142226

The kernel is 4.1.16 with some patches from Debian and some others.

> Hardware name: OpenStack Foundation OpenStack Nova, BIOS Bochs 01/01/2011
>  0000000000000000 0000000000000000 ffffffff81597807 0000000000000120
>  ffffffff8116b6e9 0000000000018200 ffff88021fffbb00 0000000000000000
>  ffff88021fffbb08 0000000000000000 ffff88021fffab50 ffffffff818164e0
> Call Trace:
>  <IRQ>  [<ffffffff81597807>] ? dump_stack+0x40/0x50
>  [<ffffffff8116b6e9>] ? warn_alloc_failed+0xf9/0x150
>  [<ffffffff8116ee7a>] ? __alloc_pages_nodemask+0x65a/0x9d0
>  [<ffffffff811b3024>] ? alloc_pages_current+0xa4/0x120
>  [<ffffffff81481d77>] ? skb_page_frag_refill+0xb7/0xe0
>  [<ffffffffa005614b>] ? try_fill_recv+0x31b/0x610 [virtio_net]
>  [<ffffffffa0056b10>] ? virtnet_receive+0x580/0x890 [virtio_net]

Received network packet, but failed to copy from VirtIO to local kernel
memory.

>  [<ffffffffa0056e46>] ? virtnet_poll+0x26/0x90 [virtio_net]
>  [<ffffffff81499629>] ? net_rx_action+0x159/0x330
>  [<ffffffff8107aace>] ? __do_softirq+0xde/0x260
>  [<ffffffff8107ae95>] ? irq_exit+0x95/0xa0
>  [<ffffffff815a0b74>] ? do_IRQ+0x64/0x110
>  [<ffffffff8159e9ee>] ? common_interrupt+0x6e/0x6e
>  <EOI>  [<ffffffff81020a70>] ? mwait_idle+0x150/0x150
>  [<ffffffff8105e192>] ? native_safe_halt+0x2/0x10
>  [<ffffffff81020a8c>] ? default_idle+0x1c/0xb0
>  [<ffffffff810b67f4>] ? cpu_startup_entry+0x314/0x3e0
>  [<ffffffff8191b093>] ? start_kernel+0x48d/0x498
>  [<ffffffff8191a95d>] ? set_init_arg+0x50/0x50
>  [<ffffffff8191a117>] ? early_idt_handler_array+0x117/0x120
>  [<ffffffff8191a117>] ? early_idt_handler_array+0x117/0x120
>  [<ffffffff8191a720>] ? x86_64_start_kernel+0x14a/0x159
> Mem-Info:
> active_anon:34861 inactive_anon:3120 isolated_anon:0
>  active_file:941577 inactive_file:946489 isolated_file:0
>  unevictable:974 dirty:2953 writeback:282206 unstable:1277
>  slab_reclaimable:55077 slab_unreclaimable:31365
>  mapped:3979 shmem:3986 pagetables:3163 bounce:0
>  free:9437 free_pcp:740 free_cma:0

Looks like enough memory is free

> Node 0 DMA free:15908kB min:20kB low:24kB high:28kB active_anon:0kB
inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB
isolated(anon):0kB isolated(file):0kB present:15992kB managed:15908kB
mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB
slab_reclaimable:0kB slab_unreclaimable:0kB 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? yes
> lowmem_reserve[]: 0 3492 7971 7971
> Node 0 DMA32 free:19532kB min:4968kB low:6208kB high:7452kB
active_anon:62328kB inactive_anon:5336kB active_file:1659704kB
inactive_file:1671236kB unevictable:2056kB isolated(anon):0kB
isolated(file):0kB present:3653624kB managed:3578476kB mlocked:2056kB
dirty:10472kB writeback:479692kB mapped:11892kB shmem:7132kB
slab_reclaimable:79832kB slab_unreclaimable:46784kB kernel_stack:2000kB
pagetables:4660kB unstable:2596kB bounce:0kB free_pcp:1080kB
local_pcp:120kB free_cma:0kB writeback_tmp:0kB pages_scanned:0
all_unreclaimable? no
> lowmem_reserve[]: 0 0 4478 4478
> Node 0 Normal free:2308kB min:6372kB low:7964kB high:9556kB
active_anon:77116kB inactive_anon:7144kB active_file:2106604kB
inactive_file:2114720kB unevictable:1840kB isolated(anon):0kB
isolated(file):0kB present:4718592kB managed:4586204kB mlocked:1840kB
dirty:1340kB writeback:649132kB mapped:4024kB shmem:8812kB
slab_reclaimable:140476kB slab_unreclaimable:78676kB kernel_stack:1888kB
pagetables:7992kB unstable:2512kB bounce:0kB free_pcp:1880kB
local_pcp:164kB free_cma:0kB writeback_tmp:0kB pages_scanned:768
all_unreclaimable? no
> lowmem_reserve[]: 0 0 0 0

Show also enough pages being available

> Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 2*64kB (U) 1*128kB (U)
1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (R) 3*4096kB (EM) = 15908kB
> Node 0 DMA32: 4632*4kB (UEM) 81*8kB (UMR) 4*16kB (R) 1*32kB (R) 0*64kB
1*128kB (R) 1*256kB (R) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 19656kB
> Node 0 Normal: 315*4kB (UM) 1*8kB (R) 1*16kB (R) 1*32kB (R) 1*64kB (R)
1*128kB (R) 2*256kB (R) 1*512kB (R) 0*1024kB 0*2048kB 0*4096kB = 2532kB
> Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0
hugepages_size=2048kB

Here too.

> 1892811 total pagecache pages
> 0 pages in swap cache
> Swap cache stats: add 0, delete 0, find 0/0
> Free swap  = 0kB
> Total swap = 0kB

Okay, no swap for defragmentation, but should be no problem for order=0

> 2097052 pages RAM
> 0 pages HighMem/MovableOnly
> 51905 pages reserved
> 0 pages hwpoisoned

Any explanation?

Thank you in advance

Philipp

From mboxrd@z Thu Jan  1 00:00:00 1970
Received: from eggs.gnu.org ([2001:4830:134:3::10]:53008)
	by lists.gnu.org with esmtp (Exim 4.71)
	(envelope-from <pmhahn@pmhahn.de>) id 1bZHuW-0002gQ-ET
	for qemu-devel@nongnu.org; Mon, 15 Aug 2016 09:26:37 -0400
Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71)
	(envelope-from <pmhahn@pmhahn.de>) id 1bZHuR-0006WD-In
	for qemu-devel@nongnu.org; Mon, 15 Aug 2016 09:26:36 -0400
Received: from parrot.pmhahn.de ([88.198.50.102]:44741)
	by eggs.gnu.org with esmtp (Exim 4.71)
	(envelope-from <pmhahn@pmhahn.de>) id 1bZHuR-0006Vx-5U
	for qemu-devel@nongnu.org; Mon, 15 Aug 2016 09:26:31 -0400
From: Philipp Hahn <pmhahn@pmhahn.de>
Message-ID: <8838f4e4-cb93-9c78-f446-7b1e2cb639fa@pmhahn.de>
Date: Mon, 15 Aug 2016 15:26:25 +0200
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: quoted-printable
Subject: [Qemu-devel] virnet: page allocation failure: order:0
List-Id: <qemu-devel.nongnu.org>
List-Unsubscribe: <https://lists.nongnu.org/mailman/options/qemu-devel>,
	<mailto:qemu-devel-request@nongnu.org?subject=unsubscribe>
List-Archive: <http://lists.nongnu.org/archive/html/qemu-devel/>
List-Post: <mailto:qemu-devel@nongnu.org>
List-Help: <mailto:qemu-devel-request@nongnu.org?subject=help>
List-Subscribe: <https://lists.nongnu.org/mailman/listinfo/qemu-devel>,
	<mailto:qemu-devel-request@nongnu.org?subject=subscribe>
To: "linux-kernel@vger.kernel.org" <linux-kernel@vger.kernel.org>, Rusty Russell <rusty@rustcorp.com.au>, qemu-devel <qemu-devel@nongnu.org>

Hello,

this Sunday one of our virtual servers running linux-4.1.16 inside
OpenStack using qemu "crashed" while doing a backup using rsync to a
slow NFS server.
Crash here means that the server became unresponsive to network traffic:
- it was no longer able to contact the two LDAP servers
- no ssh login was possible
- the backup got stuck
- crond was still running and added process after process, leading to
~1.5k processes running after one day.

What I don't know is if the network problem was the cause or the
consequence. Because of that I want to understand why the follwoing
order=3D0 allocation failed:

> swapper/0: page allocation failure: order:0, mode:0x120

 4KiB
src/extern/linux/include/linux/gfp.h:
  18 #define ___GFP_HIGH=C2=BB=C2=BB=C2=B7=C2=B7=C2=B70x20u
  21 #define ___GFP_COLD=C2=BB=C2=BB=C2=B7=C2=B7=C2=B70x100u
  72 #define __GFP_HIGH=C2=BB=C2=B7((__force gfp_t)___GFP_HIGH)=C2=BB=C2=B7=
=C2=B7=C2=B7/* Should
access emergency pools? */


  75 #define __GFP_COLD=C2=BB=C2=B7((__force gfp_t)___GFP_COLD)=C2=BB=C2=B7=
=C2=B7=C2=B7/* Cache-cold
page required */



> CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.1.0-ucs190-amd64 #1 Debian
4.1.6-1.190.201604142226

The kernel is 4.1.16 with some patches from Debian and some others.

> Hardware name: OpenStack Foundation OpenStack Nova, BIOS Bochs 01/01/20=
11
>  0000000000000000 0000000000000000 ffffffff81597807 0000000000000120
>  ffffffff8116b6e9 0000000000018200 ffff88021fffbb00 0000000000000000
>  ffff88021fffbb08 0000000000000000 ffff88021fffab50 ffffffff818164e0
> Call Trace:
>  <IRQ>  [<ffffffff81597807>] ? dump_stack+0x40/0x50
>  [<ffffffff8116b6e9>] ? warn_alloc_failed+0xf9/0x150
>  [<ffffffff8116ee7a>] ? __alloc_pages_nodemask+0x65a/0x9d0
>  [<ffffffff811b3024>] ? alloc_pages_current+0xa4/0x120
>  [<ffffffff81481d77>] ? skb_page_frag_refill+0xb7/0xe0
>  [<ffffffffa005614b>] ? try_fill_recv+0x31b/0x610 [virtio_net]
>  [<ffffffffa0056b10>] ? virtnet_receive+0x580/0x890 [virtio_net]

Received network packet, but failed to copy from VirtIO to local kernel
memory.

>  [<ffffffffa0056e46>] ? virtnet_poll+0x26/0x90 [virtio_net]
>  [<ffffffff81499629>] ? net_rx_action+0x159/0x330
>  [<ffffffff8107aace>] ? __do_softirq+0xde/0x260
>  [<ffffffff8107ae95>] ? irq_exit+0x95/0xa0
>  [<ffffffff815a0b74>] ? do_IRQ+0x64/0x110
>  [<ffffffff8159e9ee>] ? common_interrupt+0x6e/0x6e
>  <EOI>  [<ffffffff81020a70>] ? mwait_idle+0x150/0x150
>  [<ffffffff8105e192>] ? native_safe_halt+0x2/0x10
>  [<ffffffff81020a8c>] ? default_idle+0x1c/0xb0
>  [<ffffffff810b67f4>] ? cpu_startup_entry+0x314/0x3e0
>  [<ffffffff8191b093>] ? start_kernel+0x48d/0x498
>  [<ffffffff8191a95d>] ? set_init_arg+0x50/0x50
>  [<ffffffff8191a117>] ? early_idt_handler_array+0x117/0x120
>  [<ffffffff8191a117>] ? early_idt_handler_array+0x117/0x120
>  [<ffffffff8191a720>] ? x86_64_start_kernel+0x14a/0x159
> Mem-Info:
> active_anon:34861 inactive_anon:3120 isolated_anon:0
>  active_file:941577 inactive_file:946489 isolated_file:0
>  unevictable:974 dirty:2953 writeback:282206 unstable:1277
>  slab_reclaimable:55077 slab_unreclaimable:31365
>  mapped:3979 shmem:3986 pagetables:3163 bounce:0
>  free:9437 free_pcp:740 free_cma:0

Looks like enough memory is free

> Node 0 DMA free:15908kB min:20kB low:24kB high:28kB active_anon:0kB
inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB
isolated(anon):0kB isolated(file):0kB present:15992kB managed:15908kB
mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB
slab_reclaimable:0kB slab_unreclaimable:0kB 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? yes
> lowmem_reserve[]: 0 3492 7971 7971
> Node 0 DMA32 free:19532kB min:4968kB low:6208kB high:7452kB
active_anon:62328kB inactive_anon:5336kB active_file:1659704kB
inactive_file:1671236kB unevictable:2056kB isolated(anon):0kB
isolated(file):0kB present:3653624kB managed:3578476kB mlocked:2056kB
dirty:10472kB writeback:479692kB mapped:11892kB shmem:7132kB
slab_reclaimable:79832kB slab_unreclaimable:46784kB kernel_stack:2000kB
pagetables:4660kB unstable:2596kB bounce:0kB free_pcp:1080kB
local_pcp:120kB free_cma:0kB writeback_tmp:0kB pages_scanned:0
all_unreclaimable? no
> lowmem_reserve[]: 0 0 4478 4478
> Node 0 Normal free:2308kB min:6372kB low:7964kB high:9556kB
active_anon:77116kB inactive_anon:7144kB active_file:2106604kB
inactive_file:2114720kB unevictable:1840kB isolated(anon):0kB
isolated(file):0kB present:4718592kB managed:4586204kB mlocked:1840kB
dirty:1340kB writeback:649132kB mapped:4024kB shmem:8812kB
slab_reclaimable:140476kB slab_unreclaimable:78676kB kernel_stack:1888kB
pagetables:7992kB unstable:2512kB bounce:0kB free_pcp:1880kB
local_pcp:164kB free_cma:0kB writeback_tmp:0kB pages_scanned:768
all_unreclaimable? no
> lowmem_reserve[]: 0 0 0 0

Show also enough pages being available

> Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 2*64kB (U) 1*128kB (U)
1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (R) 3*4096kB (EM) =3D 15908kB
> Node 0 DMA32: 4632*4kB (UEM) 81*8kB (UMR) 4*16kB (R) 1*32kB (R) 0*64kB
1*128kB (R) 1*256kB (R) 0*512kB 0*1024kB 0*2048kB 0*4096kB =3D 19656kB
> Node 0 Normal: 315*4kB (UM) 1*8kB (R) 1*16kB (R) 1*32kB (R) 1*64kB (R)
1*128kB (R) 2*256kB (R) 1*512kB (R) 0*1024kB 0*2048kB 0*4096kB =3D 2532kB
> Node 0 hugepages_total=3D0 hugepages_free=3D0 hugepages_surp=3D0
hugepages_size=3D2048kB

Here too.

> 1892811 total pagecache pages
> 0 pages in swap cache
> Swap cache stats: add 0, delete 0, find 0/0
> Free swap  =3D 0kB
> Total swap =3D 0kB

Okay, no swap for defragmentation, but should be no problem for order=3D0

> 2097052 pages RAM
> 0 pages HighMem/MovableOnly
> 51905 pages reserved
> 0 pages hwpoisoned

Any explanation?

Thank you in advance

Philipp