Bug#592187: Bug#576838: virtio network crashes again
So, testing begins.
First conclusion: not all traffic patterns produce the page allocation
failure. rdiff-backup only writing to an nfs-share does no harm;
rdiff-backup reading and writing (incremental backup) leads to (nearly
immediate) error.
The nfs-share is always mounted with proto=tcp and nfsv3; /proc/mount says:
fileserver.backup...:/export/backup/lbork /.cbackup-mp nfs rw,relatime,vers=3,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,port=65535,timeo=600,retrans=2,sec=sys,mountport=65535,addr=x.x.x.x 0 0
This is the result of 2.6.32-18 with virtio:
(/proc/meminfo within ten seconds of the page allocation failure, if
that helps)
MemTotal: 509072 kB
MemFree: 10356 kB
Buffers: 4244 kB
Cached: 419996 kB
SwapCached: 0 kB
Active: 50856 kB
Inactive: 422424 kB
Active(anon): 24948 kB
Inactive(anon): 25084 kB
Active(file): 25908 kB
Inactive(file): 397340 kB
Unevictable: 0 kB
Mlocked: 0 kB
SwapTotal: 4194296 kB
SwapFree: 4194296 kB
Dirty: 5056 kB
Writeback: 0 kB
AnonPages: 49080 kB
Mapped: 7868 kB
Shmem: 952 kB
Slab: 11736 kB
SReclaimable: 5604 kB
SUnreclaim: 6132 kB
KernelStack: 1920 kB
PageTables: 3728 kB
NFS_Unstable: 0 kB
Bounce: 0 kB
WritebackTmp: 0 kB
CommitLimit: 4448832 kB
Committed_AS: 1419384 kB
VmallocTotal: 34359738367 kB
VmallocUsed: 5536 kB
VmallocChunk: 34359728048 kB
HardwareCorrupted: 0 kB
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
HugePages_Surp: 0
Hugepagesize: 2048 kB
DirectMap4k: 8180 kB
DirectMap2M: 516096 kB
[ 170.625928] rdiff-backup.bi: page allocation failure. order:0, mode:0x20
[ 170.625934] Pid: 2398, comm: rdiff-backup.bi Not tainted 2.6.32-5-amd64 #1
[ 170.625935] Call Trace:
[ 170.625937] <IRQ> [<ffffffff810b8b7f>] ? __alloc_pages_nodemask+0x55b/0x5d0
[ 170.625993] [<ffffffff81245a6c>] ? __alloc_skb+0x69/0x15a
[ 170.626002] [<ffffffffa01aee52>] ? try_fill_recv+0x8b/0x18b [virtio_net]
[ 170.626004] [<ffffffffa01af8c6>] ? virtnet_poll+0x543/0x5c9 [virtio_net]
[ 170.626010] [<ffffffff8124cb8b>] ? net_rx_action+0xae/0x1c9
[ 170.626032] [<ffffffff81052735>] ? __do_softirq+0xdd/0x1a0
[ 170.626035] [<ffffffffa01ae153>] ? skb_recv_done+0x28/0x34 [virtio_net]
[ 170.626044] [<ffffffff81011cac>] ? call_softirq+0x1c/0x30
[ 170.626049] [<ffffffff81013207>] ? do_softirq+0x3f/0x7c
[ 170.626051] [<ffffffff810525a4>] ? irq_exit+0x36/0x76
[ 170.626053] [<ffffffff810128fe>] ? do_IRQ+0xa0/0xb6
[ 170.626061] [<ffffffff810114d3>] ? ret_from_intr+0x0/0x11
[ 170.626062] <EOI>
[ 170.626063] Mem-Info:
[ 170.626065] Node 0 DMA per-cpu:
[ 170.626072] CPU 0: hi: 0, btch: 1 usd: 0
[ 170.626073] CPU 1: hi: 0, btch: 1 usd: 0
[ 170.626074] Node 0 DMA32 per-cpu:
[ 170.626076] CPU 0: hi: 186, btch: 31 usd: 30
[ 170.626078] CPU 1: hi: 186, btch: 31 usd: 181
[ 170.626082] active_anon:6237 inactive_anon:6271 isolated_anon:0
[ 170.626083] active_file:6476 inactive_file:100535 isolated_file:32
[ 170.626084] unevictable:0 dirty:1008 writeback:0 unstable:2050
[ 170.626084] free:729 slab_reclaimable:1401 slab_unreclaimable:1762
[ 170.626085] mapped:1967 shmem:238 pagetables:932 bounce:0
[ 170.626087] Node 0 DMA free:1980kB min:84kB low:104kB high:124kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:13856kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15372kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:32kB slab_unreclaimable:8kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 170.626099] lowmem_reserve[]: 0 489 489 489
[ 170.626101] Node 0 DMA32 free:936kB min:2784kB low:3480kB high:4176kB active_anon:24948kB inactive_anon:25084kB active_file:25904kB inactive_file:388284kB unevictable:0kB isolated(anon):0kB isolated(file):128kB present:500948kB mlocked:0kB dirty:4032kB writeback:0kB mapped:7868kB shmem:952kB slab_reclaimable:5572kB slab_unreclaimable:7040kB kernel_stack:1912kB pagetables:3728kB unstable:8200kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 170.626110] lowmem_reserve[]: 0 0 0 0
[ 170.626112] Node 0 DMA: 0*4kB 1*8kB 1*16kB 1*32kB 0*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 1976kB
[ 170.626118] Node 0 DMA32: 0*4kB 1*8kB 0*16kB 1*32kB 0*64kB 1*128kB 1*256kB 1*512kB 0*1024kB 0*2048kB 0*4096kB = 936kB
[ 170.626125] 107278 total pagecache pages
[ 170.626126] 0 pages in swap cache
[ 170.626127] Swap cache stats: add 0, delete 0, find 0/0
[ 170.626128] Free swap = 4194296kB
[ 170.626130] Total swap = 4194296kB
[ 170.631675] 131069 pages RAM
[ 170.631677] 3801 pages reserved
[ 170.631678] 23548 pages shared
[ 170.631679] 113310 pages non-shared
And later on another test run, this time the network went down with it
and the system didn't shut down properly anymore, /proc/meminfo again
within ten seconds of the page allocation failure:
MemTotal: 509072 kB
MemFree: 4932 kB
Buffers: 18940 kB
Cached: 410220 kB
SwapCached: 0 kB
Active: 88440 kB
Inactive: 384704 kB
Active(anon): 22448 kB
Inactive(anon): 22620 kB
Active(file): 65992 kB
Inactive(file): 362084 kB
Unevictable: 0 kB
Mlocked: 0 kB
SwapTotal: 4194296 kB
SwapFree: 4194296 kB
Dirty: 32668 kB
Writeback: 20480 kB
AnonPages: 44192 kB
Mapped: 7956 kB
Shmem: 952 kB
Slab: 17184 kB
SReclaimable: 8200 kB
SUnreclaim: 8984 kB
KernelStack: 1928 kB
PageTables: 3768 kB
NFS_Unstable: 14340 kB
Bounce: 0 kB
WritebackTmp: 0 kB
CommitLimit: 4448832 kB
Committed_AS: 1414712 kB
VmallocTotal: 34359738367 kB
VmallocUsed: 5536 kB
VmallocChunk: 34359728052 kB
HardwareCorrupted: 0 kB
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
HugePages_Surp: 0
Hugepagesize: 2048 kB
DirectMap4k: 8180 kB
DirectMap2M: 516096 kB
[ 137.866382] flush-254:0: page allocation failure. order:0, mode:0x20
[ 137.866387] Pid: 1234, comm: flush-254:0 Not tainted 2.6.32-5-amd64 #1
[ 137.866389] Call Trace:
[ 137.866391] <IRQ> [<ffffffff810b8b7f>] ? __alloc_pages_nodemask+0x55b/0x5d0
[ 137.866449] [<ffffffff81245a6c>] ? __alloc_skb+0x69/0x15a
[ 137.866457] [<ffffffffa01b6e52>] ? try_fill_recv+0x8b/0x18b [virtio_net]
[ 137.866460] [<ffffffffa01b78c6>] ? virtnet_poll+0x543/0x5c9 [virtio_net]
[ 137.866466] [<ffffffff8124cb8b>] ? net_rx_action+0xae/0x1c9
[ 137.866484] [<ffffffff81052735>] ? __do_softirq+0xdd/0x1a0
[ 137.866486] [<ffffffffa01b6153>] ? skb_recv_done+0x28/0x34 [virtio_net]
[ 137.866495] [<ffffffff81011cac>] ? call_softirq+0x1c/0x30
[ 137.866500] [<ffffffff81013207>] ? do_softirq+0x3f/0x7c
[ 137.866503] [<ffffffff810525a4>] ? irq_exit+0x36/0x76
[ 137.866505] [<ffffffff810128fe>] ? do_IRQ+0xa0/0xb6
[ 137.866507] [<ffffffff810114d3>] ? ret_from_intr+0x0/0x11
[ 137.866509] <EOI> [<ffffffff810b8f56>] ? clear_page_dirty_for_io+0x9f/0xb8
[ 137.866513] [<ffffffff810b9272>] ? write_cache_pages+0x1f8/0x327
[ 137.866515] [<ffffffff810b8bf4>] ? __writepage+0x0/0x25
[ 137.866527] [<ffffffff81105ff6>] ? writeback_single_inode+0xe7/0x2da
[ 137.866535] [<ffffffff81106cfc>] ? writeback_inodes_wb+0x424/0x4ff
[ 137.866538] [<ffffffff81106f03>] ? wb_writeback+0x12c/0x1ab
[ 137.866551] [<ffffffff81059294>] ? try_to_del_timer_sync+0x63/0x6c
[ 137.866554] [<ffffffff81107179>] ? wb_do_writeback+0x14f/0x165
[ 137.866556] [<ffffffff811071c0>] ? bdi_writeback_task+0x31/0xaa
[ 137.866565] [<ffffffff810c742a>] ? bdi_start_fn+0x0/0xd2
[ 137.866567] [<ffffffff810c749a>] ? bdi_start_fn+0x70/0xd2
[ 137.866573] [<ffffffff810c742a>] ? bdi_start_fn+0x0/0xd2
[ 137.866582] [<ffffffff81063589>] ? kthread+0x79/0x81
[ 137.866585] [<ffffffff81011baa>] ? child_rip+0xa/0x20
[ 137.866600] [<ffffffff811510da>] ? cap_task_wait+0x0/0x3
[ 137.866603] [<ffffffff81063510>] ? kthread+0x0/0x81
[ 137.866605] [<ffffffff81011ba0>] ? child_rip+0x0/0x20
[ 137.866606] Mem-Info:
[ 137.866608] No[ 155.950000] serial8250: too much work for irq4
de 0 DMA per-cpu:
[ 137.866610] CPU 0: hi: 0, btch: 1 usd: 0
[ 137.866611] CPU 1: hi: 0, btch: 1 usd: 0
[ 137.866612] Node 0 DMA32 per-cpu:
[ 137.866614] CPU 0: hi: 186, btch: 31 usd: 159
[ 137.866616] CPU 1: hi: 186, btch: 31 usd: 164
[ 137.866620] active_anon:5631 inactive_anon:5655 isolated_anon:0
[ 137.866621] active_file:16488 inactive_file:88419 isolated_file:35
[ 137.866621] unevictable:0 dirty:6953 writeback:3079 unstable:3833
[ 137.866622] free:787 slab_reclaimable:2032 slab_unreclaimable:1897
[ 137.866623] mapped:1989 shmem:238 pagetables:942 bounce:0
[ 137.866625] Node 0 DMA free:1980kB min:84kB low:104kB high:124kB active_anon:0kB inactive_anon:0kB active_file:4kB inactive_file:13684kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15372kB mlocked:0kB dirty:20kB writeback:232kB mapped:0kB shmem:0kB slab_reclaimable:32kB slab_unreclaimable:24kB kernel_stack:0kB pagetables:0kB unstable:212kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 137.866633] lowmem_reserve[]: 0 489 489 489
[ 137.866636] Node 0 DMA32 free:1168kB min:2784kB low:3480kB high:4176kB active_anon:22524kB inactive_anon:22620kB active_file:65948kB inactive_file:339992kB unevictable:0kB isolated(anon):0kB isolated(file):140kB present:500948kB mlocked:0kB dirty:27792kB writeback:12084kB mapped:7956kB shmem:952kB slab_reclaimable:8096kB slab_unreclaimable:7564kB kernel_stack:1928kB pagetables:3768kB unstable:15120kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 137.866644] lowmem_reserve[]: 0 0 0 0
[ 137.866646] Node 0 DMA: 1*4kB 1*8kB 1*16kB 1*32kB 0*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 1980kB
[ 137.866653] Node 0 DMA32: 40*4kB 0*8kB 2*16kB 1*32kB 1*64kB 1*128kB 1*256kB 1*512kB 0*1024kB 0*2048kB 0*4096kB = 1184kB
[ 137.866659] 105185 total pagecache pages
[ 137.866661] 0 pages in swap cache
[ 137.866662] Swap cache stats: add 0, delete 0, find 0/0
[ 137.866663] Free swap = 4194296kB
[ 137.866664] Total swap = 4194296kB
[ 137.872177] 131069 pages RAM
[ 137.872179] 3801 pages reserved
[ 137.872180] 37643 pages shared
[ 137.872181] 99163 pages non-shared
[ 138.854983] swapper: page allocation failure. order:0, mode:0x20
[ 138.854988] Pid: 0, comm: swapper Not tainted 2.6.32-5-amd64 #1
[ 138.854990] Call Trace:
[ 138.854992] <IRQ> [<ffffffff810b8b7f>] ? __alloc_pages_nodemask+0x55b/0x5d0
[ 138.855010] [<ffffffff81245a6c>] ? __alloc_skb+0x69/0x15a
[ 138.855018] [<ffffffffa01b6e52>] ? try_fill_recv+0x8b/0x18b [virtio_net]
[ 138.855021] [<ffffffffa01b78c6>] ? virtnet_poll+0x543/0x5c9 [virtio_net]
[ 138.855027] [<ffffffff8124cb8b>] ? net_rx_action+0xae/0x1c9
[ 138.855034] [<ffffffff81052735>] ? __do_softirq+0xdd/0x1a0
[ 138.855037] [<ffffffffa01b6153>] ? skb_recv_done+0x28/0x34 [virtio_net]
[ 138.855042] [<ffffffff81011cac>] ? call_softirq+0x1c/0x30
[ 138.855044] [<ffffffff81013207>] ? do_softirq+0x3f/0x7c
[ 138.855047] [<ffffffff810525a4>] ? irq_exit+0x36/0x76
[ 138.855049] [<ffffffff810128fe>] ? do_IRQ+0xa0/0xb6
[ 138.855051] [<ffffffff810114d3>] ? ret_from_intr+0x0/0x11
[ 138.855052] <EOI> [<ffffffff8102b574>] ? native_safe_halt+0x2/0x3
[ 138.855077] [<ffffffff81017121>] ? default_idle+0x34/0x51
[ 138.855083] [<ffffffff8100feb1>] ? cpu_idle+0xa2/0xda
[ 138.855103] [<ffffffff814eb140>] ? early_idt_handler+0x0/0x71
[ 138.855108] [<ffffffff814ebcd1>] ? start_kernel+0x3dc/0x3e8
[ 138.855111] [<ffffffff814eb3b7>] ? x86_64_start_kernel+0xf9/0x106
[ 138.855116] Mem-Info:
[ 138.855117] Node 0 DMA per-cpu:
[ 138.855119] CPU 0: hi: 0, btch: 1 usd: 0
[ 138.855121] CPU 1: hi: 0, btch: 1 usd: 0
[ 138.855122] Node 0 DMA32 per-cpu:
[ 138.855124] CPU 0: hi: 186, btch: 31 usd: 30
[ 138.855126] CPU 1: hi: 186, btch: 31 usd: 156
[ 138.855130] active_anon:5631 inactive_anon:5655 isolated_anon:0
[ 138.855131] active_file:16488 inactive_file:90455 isolated_file:32
[ 138.855131] unevictable:0 dirty:11465 writeback:256 unstable:3329
[ 138.855132] free:786 slab_reclaimable:2050 slab_unreclaimable:2336
[ 138.855133] mapped:1989 shmem:238 pagetables:942 bounce:0
[ 138.855135] Node 0 DMA free:1976kB min:84kB low:104kB high:124kB active_anon:0kB inactive_anon:0kB active_file:4kB inactive_file:13724kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15372kB mlocked:0kB dirty:784kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:32kB slab_unreclaimable:52kB kernel_stack:0kB pagetables:0kB unstable:224kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaim[ 155.995914] serial8250: too much work for irq4
able? no
[ 138.855143] lowmem_reserve[]: 0 489 489 489
[ 138.855146] Node 0 DMA32 free:1168kB min:2784kB low:3480kB high:4176kB active_anon:22524kB inactive_anon:22620kB active_file:65948kB inactive_file:348096kB unevictable:0kB isolated(anon):0kB isolated(file):128kB present:500948kB mlocked:0kB dirty:45076kB writeback:1024kB mapped:7956kB shmem:952kB slab_reclaimable:8168kB slab_unreclaimable:9292kB kernel_stack:1928kB pagetables:3768kB unstable:13092kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 138.855156] lowmem_reserve[]: 0 0 0 0
[ 138.855158] Node 0 DMA: 0*4kB 1*8kB 1*16kB 1*32kB 0*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 1976kB
[ 138.855164] Node 0 DMA32: 32*4kB 0*8kB 1*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 1168kB
[ 138.855171] 107214 total pagecache pages
[ 138.855172] 0 pages in swap cache
[ 138.855174] Swap cache stats: add 0, delete 0, find 0/0
[ 138.855175] Free swap = 4194296kB
[ 138.855176] Total swap = 4194296kB
[ 138.860829] 131069 pages RAM
[ 138.860832] 3801 pages reserved
[ 138.860833] 52211 pages shared
[ 138.860834] 84789 pages non-shared
[ 138.864543] flush-0:18: page allocation failure. order:0, mode:0x20
[ 138.864546] Pid: 2577, comm: flush-0:18 Not tainted 2.6.32-5-amd64 #1
[ 138.864548] Call Trace:
[ 138.864550] <IRQ> [<ffffffff810b8b7f>] ? __alloc_pages_nodemask+0x55b/0x5d0
[ 138.864566] [<ffffffff81245a6c>] ? __alloc_skb+0x69/0x15a
[ 138.864574] [<ffffffffa01b6e52>] ? try_fill_recv+0x8b/0x18b [virtio_net]
[ 138.864577] [<ffffffffa01b78c6>] ? virtnet_poll+0x543/0x5c9 [virtio_net]
[ 138.864582] [<ffffffff8124cb8b>] ? net_rx_action+0xae/0x1c9
[ 138.864590] [<ffffffff81052735>] ? __do_softirq+0xdd/0x1a0
[ 138.864592] [<ffffffffa01b6153>] ? skb_recv_done+0x28/0x34 [virtio_net]
[ 138.864596] [<ffffffff81011cac>] ? call_softirq+0x1c/0x30
[ 138.864599] [<ffffffff81013207>] ? do_softirq+0x3f/0x7c
[ 138.864601] [<ffffffff810525a4>] ? irq_exit+0x36/0x76
[ 138.864603] [<ffffffff810128fe>] ? do_IRQ+0xa0/0xb6
[ 138.864606] [<ffffffff810114d3>] ? ret_from_intr+0x0/0x11
[ 138.864607] <EOI> [<ffffffffa02badd3>] ? nfs_set_page_tag_locked+0xd/0x47 [nfs]
[ 138.864659] [<ffffffffa02bd885>] ? nfs_find_and_lock_request+0x44/0x7e [nfs]
[ 138.864666] [<ffffffffa02bdeb7>] ? nfs_do_writepage+0x82/0x122 [nfs]
[ 138.864671] [<ffffffffa02be44e>] ? nfs_writepages_callback+0xf/0x21 [nfs]
[ 138.864674] [<ffffffff810b9285>] ? write_cache_pages+0x20b/0x327
[ 138.864680] [<ffffffffa02be43f>] ? nfs_writepages_callback+0x0/0x21 [nfs]
[ 138.864686] [<ffffffffa02be3fe>] ? nfs_writepages+0xef/0x130 [nfs]
[ 138.864692] [<ffffffffa02bf625>] ? nfs_flush_one+0x0/0xce [nfs]
[ 138.864698] [<ffffffff81105ff6>] ? writeback_single_inode+0xe7/0x2da
[ 138.864705] [<ffffffff81106cfc>] ? writeback_inodes_wb+0x424/0x4ff
[ 138.864708] [<ffffffff81106f03>] ? wb_writeback+0x12c/0x1ab
[ 138.864711] [<ffffffff8110709d>] ? wb_do_writeback+0x73/0x165
[ 138.864713] [<ffffffff811071c0>] ? bdi_writeback_task+0x31/0xaa
[ 138.864719] [<ffffffff810c742a>] ? bdi_start_fn+0x0/0xd2
[ 138.864721] [<ffffffff810c749a>] ? bdi_start_fn+0x70/0xd2
[ 138.864724] [<ffffffff810c742a>] ? bdi_start_fn+0x0/0xd2
[ 138.864731] [<ffffffff81063589>] ? kthread+0x79/0x81
[ 138.864733] [<ffffffff81011baa>] ? child_rip+0xa/0x20
[ 138.864735] [<ffffffff81063510>] ? kthread+0x0/0x81
[ 138.864737] [<ffffffff81011ba0>] ? child_rip+0x0/0x20
[ 138.864739] Mem-Info:
[ 138.864740] Node 0 DMA per-cpu:
[ 138.864742] CPU 0: hi: 0, btch: 1 usd: 0
[ 138.864744] CPU 1: hi: 0, btch: 1 usd: 0
[ 138.864745] Node 0 DMA32 per-cpu:
[ 138.864747] CPU 0: hi: 186, btch: 31 usd: 134
[ 138.864748] CPU 1: hi: 186, btch: 31 usd: 158
[ 138.864752] active_anon:5631 inactive_anon:5655 isolated_anon:0
[ 138.864753] active_file:16488 inactive_file:90533 isolated_file:32
[ 138.864758] unevictable:0 dirty:11712 writeback:218 unstable:3576
[ 138.864759] free:755 slab_reclaimable:2050 slab_unreclaimable:2289
[ 138.864760] mapped:1989 shmem:238 pagetables:942 bounce:0
[ 138.864761] Node 0 DMA free:1988kB min:84kB low:104kB high:124kB active_anon:0kB inactive_anon:0kB active_file:4kB inactive_file:13724kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15372kB mlocked:0kB dirty:784kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:32kB slab_unreclaimable:84kB kernel_stack:0kB pagetables:0kB unstable:224kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 138.864774] lo[ 156.043149] serial8250: too much work for irq4
wmem_reserve[]: 0 489 489 489
[ 138.864777] Node 0 DMA32 free:1032kB min:2784kB low:3480kB high:4176kB active_anon:22524kB inactive_anon:22620kB active_file:65948kB inactive_file:348408kB unevictable:0kB isolated(anon):0kB isolated(file):128kB present:500948kB mlocked:0kB dirty:46064kB writeback:872kB mapped:7956kB shmem:952kB slab_reclaimable:8168kB slab_unreclaimable:9072kB kernel_stack:1928kB pagetables:3768kB unstable:14080kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 138.864790] lowmem_reserve[]: 0 0 0 0
[ 138.864792] Node 0 DMA: 7*4kB 3*8kB 0*16kB 1*32kB 0*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 2004kB
[ 138.864800] Node 0 DMA32: 0*4kB 1*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 1032kB
[ 138.864806] 107290 total pagecache pages
[ 138.864808] 0 pages in swap cache
[ 138.864809] Swap cache stats: add 0, delete 0, find 0/0
[ 138.864810] Free swap = 4194296kB
[ 138.864811] Total swap = 4194296kB
[ 138.870003] 131069 pages RAM
[ 138.870005] 3801 pages reserved
[ 138.870007] 52198 pages shared
[ 138.870008] 84820 pages non-shared
[ 138.884250] flush-0:18: page allocation failure. order:0, mode:0x20
[ 138.884254] Pid: 2577, comm: flush-0:18 Not tainted 2.6.32-5-amd64 #1
[ 138.884256] Call Trace:
[ 138.884258] <IRQ> [<ffffffff810b8b7f>] ? __alloc_pages_nodemask+0x55b/0x5d0
[ 138.884275] [<ffffffff81245a6c>] ? __alloc_skb+0x69/0x15a
[ 138.884283] [<ffffffffa01b6e52>] ? try_fill_recv+0x8b/0x18b [virtio_net]
[ 138.884297] [<ffffffff8126ff1f>] ? ip_rcv_finish+0x373/0x38d
[ 138.884300] [<ffffffffa01b78c6>] ? virtnet_poll+0x543/0x5c9 [virtio_net]
[ 138.884306] [<ffffffff8124cb8b>] ? net_rx_action+0xae/0x1c9
[ 138.884313] [<ffffffff81052735>] ? __do_softirq+0xdd/0x1a0
[ 138.884316] [<ffffffffa01b6153>] ? skb_recv_done+0x28/0x34 [virtio_net]
[ 138.884320] [<ffffffff81011cac>] ? call_softirq+0x1c/0x30
[ 138.884323] [<ffffffff81013207>] ? do_softirq+0x3f/0x7c
[ 138.884325] [<ffffffff810525a4>] ? irq_exit+0x36/0x76
[ 138.884327] [<ffffffff810128fe>] ? do_IRQ+0xa0/0xb6
[ 138.884329] [<ffffffff810114d3>] ? ret_from_intr+0x0/0x11
[ 138.884334] <EOI> [<ffffffff8118e587>] ? kref_get+0x1f/0x20
[ 138.884366] [<ffffffffa02bd87d>] ? nfs_find_and_lock_request+0x3c/0x7e [nfs]
[ 138.884372] [<ffffffffa02bdeb7>] ? nfs_do_writepage+0x82/0x122 [nfs]
[ 138.884378] [<ffffffffa02be44e>] ? nfs_writepages_callback+0xf/0x21 [nfs]
[ 138.884381] [<ffffffff810b9285>] ? write_cache_pages+0x20b/0x327
[ 138.884386] [<ffffffffa02be43f>] ? nfs_writepages_callback+0x0/0x21 [nfs]
[ 138.884392] [<ffffffffa02be3fe>] ? nfs_writepages+0xef/0x130 [nfs]
[ 138.884398] [<ffffffffa02bf625>] ? nfs_flush_one+0x0/0xce [nfs]
[ 138.884405] [<ffffffff81105ff6>] ? writeback_single_inode+0xe7/0x2da
[ 138.884408] [<ffffffff81106cfc>] ? writeback_inodes_wb+0x424/0x4ff
[ 138.884410] [<ffffffff81106f03>] ? wb_writeback+0x12c/0x1ab
[ 138.884413] [<ffffffff8110709d>] ? wb_do_writeback+0x73/0x165
[ 138.884415] [<ffffffff811071c0>] ? bdi_writeback_task+0x31/0xaa
[ 138.884422] [<ffffffff810c742a>] ? bdi_start_fn+0x0/0xd2
[ 138.884424] [<ffffffff810c749a>] ? bdi_start_fn+0x70/0xd2
[ 138.884426] [<ffffffff810c742a>] ? bdi_start_fn+0x0/0xd2
[ 138.884433] [<ffffffff81063589>] ? kthread+0x79/0x81
[ 138.884436] [<ffffffff81011baa>] ? child_rip+0xa/0x20
[ 138.884438] [<ffffffff81063510>] ? kthread+0x0/0x81
[ 138.884440] [<ffffffff81011ba0>] ? child_rip+0x0/0x20
[ 138.884441] Mem-Info:
[ 138.884443] Node 0 DMA per-cpu:
[ 138.884445] CPU 0: hi: 0, btch: 1 usd: 0
[ 138.884446] CPU 1: hi: 0, btch: 1 usd: 0
[ 138.884448] Node 0 DMA32 per-cpu:
[ 138.884449] CPU 0: hi: 186, btch: 31 usd: 29
[ 138.884451] CPU 1: hi: 186, btch: 31 usd: 109
[ 138.884455] active_anon:5631 inactive_anon:5655 isolated_anon:0
[ 138.884456] active_file:16488 inactive_file:90476 isolated_file:32
[ 138.884457] unevictable:0 dirty:11111 writeback:807 unstable:3576
[ 138.884457] free:743 slab_reclaimable:2050 slab_unreclaimable:2326
[ 138.884458] mapped:1989 shmem:238 pagetables:942 bounce:0
[ 138.884460] Node 0 DMA free:1992kB min:84kB low:104kB high:124kB active_anon:0kB inactive_anon:0kB active_file:4kB inactive_file:13752kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15372kB mlocked:0kB dirty:812kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:32kB slab_unreclaimable:84kB kernel_stack:0kB pagetables:0kB unstable:224kB bounce:0kB writeback_tmp:0kB pages_scann[ 156.089824] serial8250: too much work for irq4
ed:0 all_unreclaimable? no
[ 138.884468] lowmem_reserve[]: 0 489 489 489
[ 138.884471] Node 0 DMA32 free:980kB min:2784kB low:3480kB high:4176kB active_anon:22524kB inactive_anon:22620kB active_file:65948kB inactive_file:348152kB unevictable:0kB isolated(anon):0kB isolated(file):128kB present:500948kB mlocked:0kB dirty:43632kB writeback:3228kB mapped:7956kB shmem:952kB slab_reclaimable:8168kB slab_unreclaimable:9220kB kernel_stack:1928kB pagetables:3768kB unstable:14080kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 138.884479] lowmem_reserve[]: 0 0 0 0
[ 138.884481] Node 0 DMA: 1*4kB 1*8kB 0*16kB 0*32kB 1*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 1996kB
[ 138.884488] Node 0 DMA32: 1*4kB 0*8kB 1*16kB 0*32kB 1*64kB 1*128kB 1*256kB 1*512kB 0*1024kB 0*2048kB 0*4096kB = 980kB
[ 138.884494] 107240 total pagecache pages
[ 138.884495] 0 pages in swap cache
[ 138.884496] Swap cache stats: add 0, delete 0, find 0/0
[ 138.884497] Free swap = 4194296kB
[ 138.884498] Total swap = 4194296kB
[ 138.890045] 131069 pages RAM
[ 138.890047] 3801 pages reserved
[ 138.890048] 51696 pages shared
[ 138.890049] 85300 pages non-shared
[ 138.907466] flush-0:18: page allocation failure. order:0, mode:0x20
[ 138.907471] Pid: 2577, comm: flush-0:18 Not tainted 2.6.32-5-amd64 #1
[ 138.907472] Call Trace:
[ 138.907474] <IRQ> [<ffffffff810b8b7f>] ? __alloc_pages_nodemask+0x55b/0x5d0
[ 138.907493] [<ffffffff81245a6c>] ? __alloc_skb+0x69/0x15a
[ 138.907502] [<ffffffffa01b6e52>] ? try_fill_recv+0x8b/0x18b [virtio_net]
[ 138.907514] [<ffffffffa01b78c6>] ? virtnet_poll+0x543/0x5c9 [virtio_net]
[ 138.907525] [<ffffffff8124cb8b>] ? net_rx_action+0xae/0x1c9
[ 138.907532] [<ffffffff81052735>] ? __do_softirq+0xdd/0x1a0
[ 138.907535] [<ffffffffa01b6153>] ? skb_recv_done+0x28/0x34 [virtio_net]
[ 138.907539] [<ffffffff81011cac>] ? call_softirq+0x1c/0x30
[ 138.907542] [<ffffffff81013207>] ? do_softirq+0x3f/0x7c
[ 138.907544] [<ffffffff810525a4>] ? irq_exit+0x36/0x76
[ 138.907546] [<ffffffff810128fe>] ? do_IRQ+0xa0/0xb6
[ 138.907549] [<ffffffff810114d3>] ? ret_from_intr+0x0/0x11
[ 138.907550] <EOI> [<ffffffff810b925e>] ? write_cache_pages+0x1e4/0x327
[ 138.907572] [<ffffffffa02be43f>] ? nfs_writepages_callback+0x0/0x21 [nfs]
[ 138.907578] [<ffffffffa02be3fe>] ? nfs_writepages+0xef/0x130 [nfs]
[ 138.907584] [<ffffffffa02bf625>] ? nfs_flush_one+0x0/0xce [nfs]
[ 138.907587] [<ffffffff81063777>] ? bit_waitqueue+0x10/0xa0
[ 138.907593] [<ffffffff81105ff6>] ? writeback_single_inode+0xe7/0x2da
[ 138.907596] [<ffffffff81106cfc>] ? writeback_inodes_wb+0x424/0x4ff
[ 138.907599] [<ffffffff81106f03>] ? wb_writeback+0x12c/0x1ab
[ 138.907601] [<ffffffff8110709d>] ? wb_do_writeback+0x73/0x165
[ 138.907604] [<ffffffff811071c0>] ? bdi_writeback_task+0x31/0xaa
[ 138.907610] [<ffffffff810c742a>] ? bdi_start_fn+0x0/0xd2
[ 138.907612] [<ffffffff810c749a>] ? bdi_start_fn+0x70/0xd2
[ 138.907614] [<ffffffff810c742a>] ? bdi_start_fn+0x0/0xd2
[ 138.907621] [<ffffffff81063589>] ? kthread+0x79/0x81
[ 138.907623] [<ffffffff81011baa>] ? child_rip+0xa/0x20
[ 138.907625] [<ffffffff81063510>] ? kthread+0x0/0x81
[ 138.907627] [<ffffffff81011ba0>] ? child_rip+0x0/0x20
[ 138.907628] Mem-Info:
[ 138.907630] Node 0 DMA per-cpu:
[ 138.907632] CPU 0: hi: 0, btch: 1 usd: 0
[ 138.907633] CPU 1: hi: 0, btch: 1 usd: 0
[ 138.907635] Node 0 DMA32 per-cpu:
[ 138.907636] CPU 0: hi: 186, btch: 31 usd: 128
[ 138.907638] CPU 1: hi: 186, btch: 31 usd: 38
[ 138.907642] active_anon:5631 inactive_anon:5655 isolated_anon:0
[ 138.907643] active_file:16488 inactive_file:90533 isolated_file:32
[ 138.907644] unevictable:0 dirty:10202 writeback:1773 unstable:3576
[ 138.907644] free:755 slab_reclaimable:2050 slab_unreclaimable:2304
[ 138.907645] mapped:1989 shmem:238 pagetables:942 bounce:0
[ 138.907647] Node 0 DMA free:1992kB min:84kB low:104kB high:124kB active_anon:0kB inactive_anon:0kB active_file:4kB inactive_file:13752kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15372kB mlocked:0kB dirty:672kB writeback:140kB mapped:0kB shmem:0kB slab_reclaimable:32kB slab_unreclaimable:84kB kernel_stack:0kB pagetables:0kB unstable:224kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 138.907655] lowmem_reserve[]: 0 489 489 489
[ 138.907657] Node 0 DMA32 free:1028kB min:2784kB low:3480kB high:4176kB active_anon:22524kB inactive_anon:22620kB active_file:65948kB inactive_file:348380kB unevictable:0kB isolated(anon):0kB isolated(file):128kB pre[ 156.134643] serial8250: too much work for irq4
sent:500948kB mlocked:0kB dirty:40136kB writeback:6952kB mapped:7956kB shmem:952kB slab_reclaimable:8168kB slab_unreclaimable:9132kB kernel_stack:1928kB pagetables:3768kB unstable:14080kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 138.907666] lowmem_reserve[]: 0 0 0 0
[ 138.907668] Node 0 DMA: 0*4kB 1*8kB 1*16kB 1*32kB 0*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 0*2048kB 0*4096kB = 1976kB
[ 138.907675] Node 0 DMA32: 1*4kB 0*8kB 0*16kB 8*32kB 4*64kB 0*128kB 2*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1028kB
[ 138.907681] 107297 total pagecache pages
[ 138.907682] 0 pages in swap cache
[ 138.907683] Swap cache stats: add 0, delete 0, find 0/0
[ 138.907685] Free swap = 4194296kB
[ 138.907686] Total swap = 4194296kB
[ 138.913104] 131069 pages RAM
[ 138.913106] 3801 pages reserved
[ 138.913107] 51216 pages shared
[ 138.913119] 85878 pages non-shared
And of course the inevitable:
[ 360.336049] INFO: task kswapd0:31 blocked for more than 120 seconds.
[ 360.336947] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
This is the result of 2.6.32-18 with e1000:
I wasn't able to trigger this with the e1000 model so far.
e1000 was able to saturate the gbit-link of the server - I didn't expect
that, btw.
Stay tuned for the next episode: 2.6.32-19 with virtio and e1000.
Kind regards,
Lukas
Reply to: