20110531 i386 server ISO: order 5 allocation failure during install

[C de-Avillez]

WORKAROUND:
Allocate enough memory to the VM.

This is via Jenkins. This install received the following:

May 31 09:47:23 kernel: [ 3719.426587] swapper: page allocation failure. order:5, mode:0x4020
May 31 09:47:23 kernel: [ 3719.426591] Pid: 0, comm: swapper Not tainted 2.6.39-3-generic #9-Ubuntu
May 31 09:47:23 kernel: [ 3719.426593] Call Trace:
May 31 09:47:23 kernel: [ 3719.426600] [<c15135b0>] ? printk+0x2d/0x2f
May 31 09:47:23 kernel: [ 3719.426605] [<c10e68b3>] __alloc_pages_nodemask+0x5b3/0x790
May 31 09:47:23 kernel: [ 3719.426608] [<c10e6b0c>] __get_free_pages+0x1c/0x30
May 31 09:47:23 kernel: [ 3719.426611] [<c1117127>] kmalloc_order_trace+0x27/0xa0
May 31 09:47:23 kernel: [ 3719.426613] [<c10e8c4d>] ? __put_compound_page+0x1d/0x30
May 31 09:47:23 kernel: [ 3719.426620] [<dc0a313a>] ? vring_add_indirect+0x2a/0x170 [virtio_ring]
May 31 09:47:23 kernel: [ 3719.426622] [<c1117991>] __kmalloc+0x1c1/0x1e0
May 31 09:47:23 kernel: [ 3719.426625] [<dc0a3587>] ? virtqueue_add_buf_gfp+0x1a7/0x1f0 [virtio_ring]
May 31 09:47:23 kernel: [ 3719.426629] [<c142bdc8>] pskb_expand_head+0x78/0x250
May 31 09:47:23 kernel: [ 3719.426631] [<c142c036>] __pskb_pull_tail+0x46/0x330
May 31 09:47:23 kernel: [ 3719.426634] [<c1437b1a>] dev_hard_start_xmit+0x1da/0x4c0
May 31 09:47:23 kernel: [ 3719.426639] [<c144f161>] sch_direct_xmit+0xb1/0x180
May 31 09:47:23 kernel: [ 3719.426641] [<c1437ef6>] dev_queue_xmit+0xf6/0x370
May 31 09:47:23 kernel: [ 3719.426645] [<c1465add>] ip_finish_output+0x12d/0x300
May 31 09:47:23 kernel: [ 3719.426647] [<c14665c7>] ip_output+0xc7/0xe0
May 31 09:47:23 kernel: [ 3719.426651] [<c102acd8>] ? pvclock_clocksource_read+0xa8/0x120
May 31 09:47:23 kernel: [ 3719.426684] [<c1465d80>] ip_local_out+0x20/0x30
May 31 09:47:23 kernel: [ 3719.426686] [<c1465eaf>] ip_queue_xmit+0x11f/0x380
May 31 09:47:23 kernel: [ 3719.426688] [<c1029de4>] ? kvm_clock_read+0x14/0x20
May 31 09:47:23 kernel: [ 3719.426691] [<c1029df8>] ? kvm_clock_get_cycles+0x8/0x10
May 31 09:47:23 kernel: [ 3719.426694] [<c147b9a1>] tcp_transmit_skb+0x2d1/0x4b0
May 31 09:47:23 kernel: [ 3719.426696] [<c147c366>] tcp_write_xmit+0x146/0x370
May 31 09:47:23 kernel: [ 3719.426699] [<c147c5fc>] __tcp_push_pending_frames+0x2c/0x90
May 31 09:47:23 kernel: [ 3719.426702] [<c1479075>] tcp_rcv_established+0x235/0x710
May 31 09:47:23 kernel: [ 3719.426704] [<c14805ce>] tcp_v4_do_rcv+0x8e/0x170
May 31 09:47:23 kernel: [ 3719.426706] [<c1482217>] tcp_v4_rcv+0x4f7/0x760
May 31 09:47:23 kernel: [ 3719.426709] [<c1461687>] ip_local_deliver_finish+0xa7/0x290
May 31 09:47:23 kernel: [ 3719.426712] [<c1516ff5>] ? get_partial_node+0x52/0x79
May 31 09:47:23 kernel: [ 3719.426714] [<c145f7a7>] ? ip_route_input_common+0x217/0x220
May 31 09:47:23 kernel: [ 3719.426717] [<c14619ff>] ip_local_deliver+0x7f/0x90
May 31 09:47:23 kernel: [ 3719.426719] [<c1461373>] ip_rcv_finish+0x113/0x380
May 31 09:47:23 kernel: [ 3719.426721] [<c1461c53>] ip_rcv+0x243/0x310
May 31 09:47:23 kernel: [ 3719.426724] [<c143699b>] __netif_receive_skb+0x40b/0x4c0
May 31 09:47:23 kernel: [ 3719.426726] [<c1436d1f>] netif_receive_skb+0x6f/0x80
May 31 09:47:23 kernel: [ 3719.426730] [<dc0e0465>] receive_buf+0x145/0x260 [virtio_net]
May 31 09:47:23 kernel: [ 3719.426738] [<c15263bd>] ? _raw_spin_lock+0xd/0x10
May 31 09:47:23 kernel: [ 3719.426742] [<dc0e0bdf>] virtnet_poll+0x7f/0xd0 [virtio_net]
May 31 09:47:23 kernel: [ 3719.426744] [<c143747d>] net_rx_action+0x10d/0x220
May 31 09:47:23 kernel: [ 3719.426747] [<c10b0383>] ? rcu_check_quiescent_state+0x23/0xa0
May 31 09:47:23 kernel: [ 3719.426751] [<c10529c0>] ? local_bh_enable_ip+0x90/0x90
May 31 09:47:23 kernel: [ 3719.426753] [<c10529c0>] ? local_bh_enable_ip+0x90/0x90
May 31 09:47:23 kernel: [ 3719.426756] [<c1052a41>] __do_softirq+0x81/0x1a0
May 31 09:47:23 kernel: [ 3719.426758] [<c10529c0>] ? local_bh_enable_ip+0x90/0x90
May 31 09:47:23 kernel: [ 3719.426760] <IRQ> [<c1052d86>] ? irq_exit+0x76/0x90
May 31 09:47:23 kernel: [ 3719.426764] [<c152db7b>] ? do_IRQ+0x4b/0xc0
May 31 09:47:23 kernel: [ 3719.426767] [<c152dab0>] ? common_interrupt+0x30/0x38
May 31 09:47:23 kernel: [ 3719.426769] [<c1029eba>] ? native_safe_halt+0xa/0x10
May 31 09:47:23 kernel: [ 3719.426773] [<c100953c>] ? default_idle.part.5+0x3c/0xf0
May 31 09:47:23 kernel: [ 3719.426775] [<c100960f>] ? default_idle+0x1f/0x40
May 31 09:47:23 kernel: [ 3719.426777] [<c100177a>] ? cpu_idle+0x8a/0xc0
May 31 09:47:23 kernel: [ 3719.426781] [<c14f81d5>] ? rest_init+0x5d/0x68
May 31 09:47:23 kernel: [ 3719.426785] [<c17b2767>] ? start_kernel+0x34c/0x352
May 31 09:47:23 kernel: [ 3719.426787] [<c17b23ac>] ? pass_bootoption.constprop.1+0xe2/0xe2
May 31 09:47:23 kernel: [ 3719.426790] [<c17b20b3>] ? i386_start_kernel+0xb3/0xb9
May 31 09:47:23 kernel: [ 3719.426791] Mem-Info:
May 31 09:47:23 kernel: [ 3719.426793] DMA per-cpu:
May 31 09:47:23 kernel: [ 3719.426794] CPU 0: hi: 0, btch: 1 usd: 0
May 31 09:47:23 kernel: [ 3719.426796] Normal per-cpu:
May 31 09:47:23 kernel: [ 3719.426797] CPU 0: hi: 186, btch: 31 usd: 119
May 31 09:47:23 kernel: [ 3719.426801] active_anon:1976 inactive_anon:5985 isolated_anon:0
May 31 09:47:23 kernel: [ 3719.426801] active_file:34871 inactive_file:32798 isolated_file:0
May 31 09:47:23 kernel: [ 3719.426802] unevictable:11393 dirty:196 writeback:0 unstable:0
May 31 09:47:23 kernel: [ 3719.426803] free:12174 slab_reclaimable:6310 slab_unreclaimable:1055
May 31 09:47:23 kernel: [ 3719.426804] mapped:5448 shmem:35 pagetables:209 bounce:0
May 31 09:47:23 kernel: [ 3719.426809] DMA free:4424kB min:92kB low:112kB high:136kB active_anon:0kB inactive_anon:12kB active_file:6152kB inactive_file:4332kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15796kB mlocked:0kB dirty:4kB
May 31 09:47:23 kernel: [ 3719.426812] lowmem_reserve[]: 0 420 420 420
May 31 09:47:23 kernel: [ 3719.426818] Normal free:44272kB min:2576kB low:3220kB high:3864kB active_anon:7904kB inactive_anon:23928kB active_file:133332kB inactive_file:126860kB unevictable:45572kB isolated(anon):0kB isolated(file):0kB present:430772k
May 31 09:47:23 kernel: [ 3719.426822] lowmem_reserve[]: 0 0 0 0
May 31 09:47:23 kernel: [ 3719.426825] DMA: 201*4kB 103*8kB 61*16kB 29*32kB 12*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 4428kB
May 31 09:47:23 kernel: [ 3719.426831] Normal: 2762*4kB 1607*8kB 713*16kB 234*32kB 21*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 44272kB
May 31 09:47:23 kernel: [ 3719.426848] 79105 total pagecache pages
May 31 09:47:23 kernel: [ 3719.426849] 0 pages in swap cache
May 31 09:47:23 kernel: [ 3719.426851] Swap cache stats: add 0, delete 0, find 0/0
May 31 09:47:23 kernel: [ 3719.426852] Free swap = 447484kB
May 31 09:47:23 kernel: [ 3719.426853] Total swap = 447484kB
May 31 09:47:23 kernel: [ 3719.427828] 112621 pages RAM
May 31 09:47:23 kernel: [ 3719.427830] 0 pages HighMem
May 31 09:47:23 kernel: [ 3719.427831] 3734 pages reserved
May 31 09:47:23 kernel: [ 3719.427832] 47602 pages shared
May 31 09:47:23 kernel: [ 3719.427833] 56945 pages non-shared
May 31 09:47:23 kernel: [ 3719.427869] swapper: page allocation failure. order:5, mode:0x4020
May 31 09:47:23 kernel: [ 3719.427873] Pid: 0, comm: swapper Not tainted 2.6.39-3-generic #9-Ubuntu
May 31 09:47:23 kernel: [ 3719.427875] Call Trace:
May 31 09:47:23 kernel: [ 3719.427880] [<c15135b0>] ? printk+0x2d/0x2f
May 31 09:47:23 kernel: [ 3719.427885] [<c10e68b3>] __alloc_pages_nodemask+0x5b3/0x790
May 31 09:47:23 kernel: [ 3719.427888] [<c10e6b0c>] __get_free_pages+0x1c/0x30
May 31 09:47:23 kernel: [ 3719.427891] [<c1117127>] kmalloc_order_trace+0x27/0xa0
May 31 09:47:23 kernel: [ 3719.427893] [<c10e8c4d>] ? __put_compound_page+0x1d/0x30
May 31 09:47:23 kernel: [ 3719.427895] [<c1117991>] ? __kmalloc+0x1c1/0x1e0
May 31 09:47:23 kernel: [ 3719.427898] [<c1117991>] __kmalloc+0x1c1/0x1e0
May 31 09:47:23 kernel: [ 3719.427904] [<dc0a3587>] ? virtqueue_add_buf_gfp+0x1a7/0x1f0 [virtio_ring]
May 31 09:47:23 kernel: [ 3719.427907] [<c142bdc8>] pskb_expand_head+0x78/0x250
May 31 09:47:23 kernel: [ 3719.427909] [<c142c036>] __pskb_pull_tail+0x46/0x330
May 31 09:47:23 kernel: [ 3719.427912] [<c1437b1a>] dev_hard_start_xmit+0x1da/0x4c0
May 31 09:47:23 kernel: [ 3719.427916] [<c144f161>] sch_direct_xmit+0xb1/0x180
May 31 09:47:23 kernel: [ 3719.427918] [<c1437ef6>] dev_queue_xmit+0xf6/0x370
May 31 09:47:23 kernel: [ 3719.427921] [<c1465add>] ip_finish_output+0x12d/0x300
May 31 09:47:23 kernel: [ 3719.427923] [<c14665c7>] ip_output+0xc7/0xe0
May 31 09:47:23 kernel: [ 3719.427927] [<c102acd8>] ? pvclock_clocksource_read+0xa8/0x120
May 31 09:47:23 kernel: [ 3719.427929] [<c1465d80>] ip_local_out+0x20/0x30
May 31 09:47:23 kernel: [ 3719.427931] [<c1465eaf>] ip_queue_xmit+0x11f/0x380
May 31 09:47:23 kernel: [ 3719.427934] [<c1029de4>] ? kvm_clock_read+0x14/0x20
May 31 09:47:23 kernel: [ 3719.427936] [<c1029df8>] ? kvm_clock_get_cycles+0x8/0x10
May 31 09:47:23 kernel: [ 3719.427939] [<c147b9a1>] tcp_transmit_skb+0x2d1/0x4b0
May 31 09:47:23 kernel: [ 3719.427941] [<c147c366>] tcp_write_xmit+0x146/0x370
May 31 09:47:23 kernel: [ 3719.427944] [<c147c5fc>] __tcp_push_pending_frames+0x2c/0x90
May 31 09:47:23 kernel: [ 3719.427946] [<c1479075>] tcp_rcv_established+0x235/0x710
May 31 09:47:23 kernel: [ 3719.427949] [<c14805ce>] tcp_v4_do_rcv+0x8e/0x170
May 31 09:47:23 kernel: [ 3719.427951] [<c1482217>] tcp_v4_rcv+0x4f7/0x760
May 31 09:47:23 kernel: [ 3719.427954] [<c1461687>] ip_local_deliver_finish+0xa7/0x290
May 31 09:47:23 kernel: [ 3719.427956] [<c1516ff5>] ? get_partial_node+0x52/0x79
May 31 09:47:23 kernel: [ 3719.427959] [<c145f7a7>] ? ip_route_input_common+0x217/0x220
May 31 09:47:23 kernel: [ 3719.427961] [<c14619ff>] ip_local_deliver+0x7f/0x90
May 31 09:47:23 kernel: [ 3719.427964] [<c1461373>] ip_rcv_finish+0x113/0x380
May 31 09:47:23 kernel: [ 3719.427966] [<c1461c53>] ip_rcv+0x243/0x310
May 31 09:47:23 kernel: [ 3719.427968] [<c143699b>] __netif_receive_skb+0x40b/0x4c0
May 31 09:47:23 kernel: [ 3719.427971] [<c1436d1f>] netif_receive_skb+0x6f/0x80
May 31 09:47:23 kernel: [ 3719.427974] [<dc0e0465>] receive_buf+0x145/0x260 [virtio_net]
May 31 09:47:23 kernel: [ 3719.427977] [<c15263bd>] ? _raw_spin_lock+0xd/0x10
May 31 09:47:23 kernel: [ 3719.427980] [<dc0e0bdf>] virtnet_poll+0x7f/0xd0 [virtio_net]
May 31 09:47:23 kernel: [ 3719.427982] [<c143747d>] net_rx_action+0x10d/0x220
May 31 09:47:23 kernel: [ 3719.427985] [<c10b0383>] ? rcu_check_quiescent_state+0x23/0xa0
May 31 09:47:23 kernel: [ 3719.427989] [<c10529c0>] ? local_bh_enable_ip+0x90/0x90
May 31 09:47:23 kernel: [ 3719.427991] [<c10529c0>] ? local_bh_enable_ip+0x90/0x90
May 31 09:47:23 kernel: [ 3719.427994] [<c1052a41>] __do_softirq+0x81/0x1a0
May 31 09:47:23 kernel: [ 3719.427996] [<c10529c0>] ? local_bh_enable_ip+0x90/0x90
May 31 09:47:23 kernel: [ 3719.427998] <IRQ> [<c1052d86>] ? irq_exit+0x76/0x90
May 31 09:47:23 kernel: [ 3719.428037] [<c152db7b>] ? do_IRQ+0x4b/0xc0
May 31 09:47:23 kernel: [ 3719.428039] [<c152dab0>] ? common_interrupt+0x30/0x38
May 31 09:47:23 kernel: [ 3719.428042] [<c1029eba>] ? native_safe_halt+0xa/0x10
May 31 09:47:23 kernel: [ 3719.428045] [<c100953c>] ? default_idle.part.5+0x3c/0xf0
May 31 09:47:23 kernel: [ 3719.428048] [<c100960f>] ? default_idle+0x1f/0x40
May 31 09:47:23 kernel: [ 3719.428050] [<c100177a>] ? cpu_idle+0x8a/0xc0
May 31 09:47:23 kernel: [ 3719.428053] [<c14f81d5>] ? rest_init+0x5d/0x68
May 31 09:47:23 kernel: [ 3719.428057] [<c17b2767>] ? start_kernel+0x34c/0x352
May 31 09:47:23 kernel: [ 3719.428059] [<c17b23ac>] ? pass_bootoption.constprop.1+0xe2/0xe2
May 31 09:47:23 kernel: [ 3719.428062] [<c17b20b3>] ? i386_start_kernel+0xb3/0xb9
May 31 09:47:23 kernel: [ 3719.428063] Mem-Info:
May 31 09:47:23 kernel: [ 3719.428064] DMA per-cpu:
May 31 09:47:23 kernel: [ 3719.428066] CPU 0: hi: 0, btch: 1 usd: 0
May 31 09:47:23 kernel: [ 3719.428067] Normal per-cpu:
May 31 09:47:23 kernel: [ 3719.428094] CPU 0: hi: 186, btch: 31 usd: 134
May 31 09:47:23 kernel: [ 3719.428098] active_anon:1976 inactive_anon:5985 isolated_anon:0
May 31 09:47:23 kernel: [ 3719.428099] active_file:34871 inactive_file:32798 isolated_file:0
May 31 09:47:23 kernel: [ 3719.428099] unevictable:11393 dirty:196 writeback:0 unstable:0
May 31 09:47:23 kernel: [ 3719.428100] free:12174 slab_reclaimable:6310 slab_unreclaimable:1055
May 31 09:47:23 kernel: [ 3719.428101] mapped:5448 shmem:35 pagetables:209 bounce:0
May 31 09:47:23 kernel: [ 3719.428106] DMA free:4424kB min:92kB low:112kB high:136kB active_anon:0kB inactive_anon:12kB active_file:6152kB inactive_file:4332kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15796kB mlocked:0kB dirty:4kB
May 31 09:47:23 kernel: [ 3719.428109] lowmem_reserve[]: 0 420 420 420
May 31 09:47:23 kernel: [ 3719.428115] Normal free:44272kB min:2576kB low:3220kB high:3864kB active_anon:7904kB inactive_anon:23928kB active_file:133332kB inactive_file:126860kB unevictable:45572kB isolated(anon):0kB isolated(file):0kB present:430772k
May 31 09:47:23 kernel: [ 3719.428119] lowmem_reserve[]: 0 0 0 0
May 31 09:47:23 kernel: [ 3719.428122] DMA: 201*4kB 103*8kB 61*16kB 29*32kB 12*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 4428kB
May 31 09:47:23 kernel: [ 3719.428128] Normal: 2762*4kB 1607*8kB 713*16kB 234*32kB 21*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 44272kB
May 31 09:47:23 kernel: [ 3719.428134] 79105 total pagecache pages
May 31 09:47:23 kernel: [ 3719.428135] 0 pages in swap cache
May 31 09:47:23 kernel: [ 3719.428137] Swap cache stats: add 0, delete 0, find 0/0
May 31 09:47:23 kernel: [ 3719.428138] Free swap = 447484kB
May 31 09:47:23 kernel: [ 3719.428139] Total swap = 447484kB
May 31 09:47:23 kernel: [ 3719.429090] 112621 pages RAM
May 31 09:47:23 kernel: [ 3719.429092] 0 pages HighMem
May 31 09:47:23 kernel: [ 3719.429093] 3734 pages reserved
May 31 09:47:23 kernel: [ 3719.429094] 47601 pages shared
May 31 09:47:23 kernel: [ 3719.429095] 56931 pages non-shared
May 31 09:47:23 in-target: debconf (developer): <-- STOP

[C de-Avillez (hggdh2)]

full debian-installer log is at http://jenkins.qa.ubuntu-uk.org/view/oneiric-server/job/oneiric-server-i386_ltp-lite/75/artifact/75/test-results/d-i-syslog.log.gz

The installation continued, and eventually stalled. I am repeating the run, JIC.

[C de-Avillez (hggdh2)]

Another similar failure: http://jenkins.qa.ubuntu-uk.org/view/oneiric-server/job/oneiric-server-i386_lvm/144/artifact/144/test-results/d-i-syslog.log.gz

[C de-Avillez (hggdh2)]

second failure OOPS:

May 31 09:26:59 kernel: [ 2409.497553] swapper: page allocation failure. order:5, mode:0x4020
May 31 09:26:59 kernel: [ 2409.497556] Pid: 0, comm: swapper Not tainted 2.6.39-3-generic #9-Ubuntu
May 31 09:26:59 kernel: [ 2409.497558] Call Trace:
May 31 09:26:59 kernel: [ 2409.497566] [<c15135b0>] ? printk+0x2d/0x2f
May 31 09:26:59 kernel: [ 2409.497571] [<c10e68b3>] __alloc_pages_nodemask+0x5b3/0x790
May 31 09:26:59 kernel: [ 2409.497574] [<c10e6b0c>] __get_free_pages+0x1c/0x30
May 31 09:26:59 kernel: [ 2409.497577] [<c1117127>] kmalloc_order_trace+0x27/0xa0
May 31 09:26:59 kernel: [ 2409.497580] [<c10e8c4d>] ? __put_compound_page+0x1d/0x30
May 31 09:26:59 kernel: [ 2409.497601] [<dc0a313a>] ? vring_add_indirect+0x2a/0x170 [virtio_ring]
May 31 09:26:59 kernel: [ 2409.497604] [<c1117991>] __kmalloc+0x1c1/0x1e0
May 31 09:26:59 kernel: [ 2409.497607] [<dc0a3587>] ? virtqueue_add_buf_gfp+0x1a7/0x1f0 [virtio_ring]
May 31 09:26:59 kernel: [ 2409.497611] [<c142bdc8>] pskb_expand_head+0x78/0x250
May 31 09:26:59 kernel: [ 2409.497613] [<c142c036>] __pskb_pull_tail+0x46/0x330
May 31 09:26:59 kernel: [ 2409.497616] [<c1437b1a>] dev_hard_start_xmit+0x1da/0x4c0
May 31 09:26:59 kernel: [ 2409.497619] [<dc0a36c5>] ? virtqueue_kick+0x35/0x40 [virtio_ring]
May 31 09:26:59 kernel: [ 2409.497622] [<c144f161>] sch_direct_xmit+0xb1/0x180
May 31 09:26:59 kernel: [ 2409.497625] [<c1437ef6>] dev_queue_xmit+0xf6/0x370
May 31 09:26:59 kernel: [ 2409.497628] [<c1465add>] ip_finish_output+0x12d/0x300
May 31 09:26:59 kernel: [ 2409.497630] [<c14665c7>] ip_output+0xc7/0xe0
May 31 09:26:59 kernel: [ 2409.497634] [<c102acd8>] ? pvclock_clocksource_read+0xa8/0x120
May 31 09:26:59 kernel: [ 2409.497636] [<c1465d80>] ip_local_out+0x20/0x30
May 31 09:26:59 kernel: [ 2409.497658] [<c1465eaf>] ip_queue_xmit+0x11f/0x380
May 31 09:26:59 kernel: [ 2409.497660] [<c1029de4>] ? kvm_clock_read+0x14/0x20
May 31 09:26:59 kernel: [ 2409.497663] [<c1029df8>] ? kvm_clock_get_cycles+0x8/0x10
May 31 09:26:59 kernel: [ 2409.497666] [<c147b9a1>] tcp_transmit_skb+0x2d1/0x4b0
May 31 09:26:59 kernel: [ 2409.497668] [<c147c366>] tcp_write_xmit+0x146/0x370
May 31 09:26:59 kernel: [ 2409.497670] [<c147c5fc>] __tcp_push_pending_frames+0x2c/0x90
May 31 09:26:59 kernel: [ 2409.497673] [<c1479075>] tcp_rcv_established+0x235/0x710
May 31 09:26:59 kernel: [ 2409.497676] [<c102ac00>] ? pvclock_tsc_khz+0x80/0x80
May 31 09:26:59 kernel: [ 2409.497678] [<c14805ce>] tcp_v4_do_rcv+0x8e/0x170
May 31 09:26:59 kernel: [ 2409.497680] [<c1482217>] tcp_v4_rcv+0x4f7/0x760
May 31 09:26:59 kernel: [ 2409.497683] [<c102acd8>] ? pvclock_clocksource_read+0xa8/0x120
May 31 09:26:59 kernel: [ 2409.497686] [<c1461687>] ip_local_deliver_finish+0xa7/0x290
May 31 09:26:59 kernel: [ 2409.497688] [<c1516ff5>] ? get_partial_node+0x52/0x79
May 31 09:26:59 kernel: [ 2409.497691] [<c145f7a7>] ? ip_route_input_common+0x217/0x220
May 31 09:26:59 kernel: [ 2409.497693] [<c14619ff>] ip_local_deliver+0x7f/0x90
May 31 09:26:59 kernel: [ 2409.497695] [<c1461373>] ip_rcv_finish+0x113/0x380
May 31 09:26:59 kernel: [ 2409.497698] [<c1461c53>] ip_rcv+0x243/0x310
May 31 09:26:59 kernel: [ 2409...

[Stefan Bader (smb)]

I see virtio functions in those traces. So am I right to assume that those installations were done in a KVM environment? Which version of the kernel are we looking at?

[C de-Avillez (hggdh2)]

@Stefan: yes, they are run on a KVM, under libvirt/qemu Natty. ON the host, these are the versions:

ii libvirt-bin 0.8.8-1ubuntu6 the programs for the libvirt library
ii libvirt0 0.8.8-1ubuntu6 library for interfacing with different virtualization systems
ii linux-image-2.6.38-8-server 2.6.38-8.42 Linux kernel image for version 2.6.38 on x86_64
ii linux-image-server 2.6.38.8.22 Linux kernel image on Server Equipment.
ii qemu-common 0.14.0+noroms-0ubuntu4.1 qemu common functionality (bios, documentation, etc)
ii qemu-kvm 0.14.0+noroms-0ubuntu4.1 Full virtualization on i386 and amd64 hardware

For the virtual machines: they were running Oneiric and linux-image-2.6.39-3-generic-pae.

[Stefan Bader (smb)]

Ok, thanks Carlos. So what we see in the guest logs is that the virtual network interface seems to try allocating a 128K receive buffer which fails and that triggers some OOM actions resulting in bad things. If I see this right, there seems to be 439M of memory available (probably set up as 512M and the rest lacking for page tables and so on).
Generally virnet is claimed to be able to really have a hard impact on memory (especially if there is any service doing transfers between host and guest) as transport is not limited by any transmission speed. Is there something configured like that.
The system can be tweaked a bit by telling it to try having more memory in reserve (/proc/sys/vm/min_free_kbytes) but I am not sure this is easily implemented for install. Would things improve by just allocating the guests more memory (768M, 1024M)?

[Jean-Baptiste Lallement (jibel)]

I had this crash very regularly while testing i386 alternate images on VMs running on amd64 (kernel 3.0-1.2-generic 3.0.0-rc3). After increasing VM's memory it didn't happened in 4 runs.

We'll wait for tomorrows run and see if it happens when the test server is loaded.

Also, I've never seen this crash when running amd64 guest on an amd64 host on same hardware and same VM configuration. So it shouldn't happen anyway.

[Kate Stewart (kate.stewart)]

Since this is happening during the iso testing, as well as during the automated jenkins testing, this needs to be looked at. Have marked the priority high.

[Stefan Bader (smb)]

Looking at the whole thing more in depth, this turns out to be a very very very long winded way of the kernel telling us that something tried to allocate 128K of continuous memory and failed (which includes a stack trace and a dump of memory info). It does not say OOPS actually.
As far as I see this is likely triggered by virtnet_poll() which tries to pull in data from the virtual network. It does so using GFP_ATOMIC which allows for failure without waiting but does not automatically set the flag to suppress warnings like this. Probably that might be improved. The code AFAICS is prepared to handle the allocation failure and there does not seem to be an immediate crash involved.
In this report there is one statement about a hung installation. In the other confirmations I have not seen indication whether the install proceeds or not. There is not much more I can say from the posted messages. And the jenkins links seem to go to 404 for me.

[C de-Avillez (hggdh2)]

Usually -- meaning on these installs I followed on Jenkins, and on my KVM tests -- the installation stalls. On Jenkins, the test eventually times out and fails (these were the Jenkins failed tests). On personal KVM runs I can see the progress bar stopping; I would then go into another console, and start killing some installation processes, and sometimes I killed the right one, and installation proceeded; sometimes I would completely bork the install.

---
Ubuntu Bug Squad volunteer triager
http://wiki.ubuntu.com/BugSquad

[Stefan Bader (smb)]

If possible it would be good to have the syslog from such a failed installation. As said, the links above do not work and I was not able to get data any other ways. The allocation failure may just be an indication that we have some memory pressure. Would it be possible to add any debugging script(s) easily, if the syslog is not sufficiently providing data?

[C de-Avillez (hggdh2)]

Here you go. Note that this is the Debian-Installer syslog (the only syslog available on an install that I know of).

[Stefan Bader (smb)]

Thanks. So from this log I see several times that some allocations failed (order 2 to 4). I am not sure this log was from a run that went through. At least there did not seem to be any other indication of problems. And the failures first became worse (smaller allocations failing) but then recovered. So it goes with the assumption that the message itself is not fatal.
Generally it might be just of taxing the system hardly. The system has not much memory, the virtio net is performing well (better than an emulated card would), but the disk is probably not (running through an emulated IDE controller) and could be backed by a non-raw image, which would impact performance further.
Still this should not hang. Just be slow and maybe show messages about processes not getting scheduled. The problem will be to find any way to get something useful out of this...

[Stefan Bader (smb)]

Can this be confirmed with the beta release? Also, at the moment I do not see a strong hint about what the problem could be. Do we have a chance to set up those installs to write console output to a file? Then maybe add debug to the kernel command line in order to send even lower prio messages there.
I have not been able, yet, to get the same locally. Would it be possible to summarize a bit more details about the host and guest setup? What release is running on the host, beyond memory what is the exact guest configuration. How much more is running on the host in parallel (like is host memory overcommitted)?

[C de-Avillez (hggdh2)]

I have been unable to reproduce it; I will try again, with the automated server tests on Jenkins, lowering the VM's memory allocation to 512M or less.

[C de-Avillez (hggdh2)]

I am marking the Precise task FixReleased (unknown fix), and closing WONTFIX the Oneiric one. We cannot replicate it anymore; even more, we never saw this issue outside KVM.

The workaround for Oneiric is, as noted in the comments above, to increase the VM's memory allocation.