[Date Prev][Date Next] [Thread Prev][Thread Next] [Date Index] [Thread Index]

Bug#638631: Crash following repeated 'page allocation failure' & 'BUG: soft lockup'

Package: linux-image-3.0.0-1-686-pae
Version: 3.0.0-1
My sid KVM guest crashed yesterday. The emulated screen was blank and did not respond to any input. The kernel log is full of messages as shown below. They almost all name the same executable, apache_accesses (from package munin-node) and have the same backtraces, but are different PIDs (it is not a long-running process).
The exception is a "BUG: soft lockup - CPU#0 stuck for 35s!" message, also below.
The guest is a news server, with around a kilobyte/second of network traffic going into it at all times.
The guest has 512MB RAM assigned. It has a gigabyte of swap available and doesn't seem to have been using much of it. The host is running 64-bit squeeze. 

ttfn/rjk
Aug 18 14:30:00 deodand kernel: [1547640.899450] apache_accesses: page allocation failure: order:1, mode:0x20 Aug 18 14:30:00 deodand kernel: [1547640.899456] Pid: 456, comm: apache_accesses Not tainted 3.0.0-1-686-pae #1 
Aug 18 14:30:00 deodand kernel: [1547640.899458] Call Trace:
Aug 18 14:30:00 deodand kernel: [1547640.899469] [<c109713f>] ? warn_alloc_failed+0xb4/0xc2 Aug 18 14:30:00 deodand kernel: [1547640.899472] [<c1099353>] ? __alloc_pages_nodemask+0x57e/0x5e0 Aug 18 14:30:00 deodand kernel: [1547640.899478] [<c10be9b5>] ? ____cache_alloc+0x281/0x44f Aug 18 14:30:00 deodand kernel: [1547640.899481] [<c10bf18b>] ? kmem_cache_alloc+0x2b/0x93 Aug 18 14:30:00 deodand kernel: [1547640.899486] [<c1206445>] ? sk_prot_alloc+0x23/0xf7 Aug 18 14:30:00 deodand kernel: [1547640.899488] [<c12065c0>] ? sk_clone+0x15/0x273 Aug 18 14:30:00 deodand kernel: [1547640.899492] [<c1238a83>] ? inet_csk_clone+0xc/0x81 Aug 18 14:30:00 deodand kernel: [1547640.899496] [<c124a454>] ? tcp_create_openreq_child+0x19/0x3da Aug 18 14:30:00 deodand kernel: [1547640.899499] [<c1247fc8>] ? tcp_v4_syn_recv_sock+0x31/0x1bb Aug 18 14:30:00 deodand kernel: [1547640.899503] [<c128c3bc>] ? tcp_v6_syn_recv_sock+0x33/0x3fb Aug 18 14:30:00 deodand kernel: [1547640.899506] [<c123e99d>] ? tcp_parse_options+0x187/0x21c Aug 18 14:30:00 deodand kernel: [1547640.899509] [<c124acfe>] ? tcp_check_req+0x1e1/0x297 Aug 18 14:30:00 deodand kernel: [1547640.899512] [<c123886d>] ? inet_csk_search_req+0x21/0x77 Aug 18 14:30:00 deodand kernel: [1547640.899514] [<c1249057>] ? tcp_v4_do_rcv+0x19e/0x289 Aug 18 14:30:00 deodand kernel: [1547640.899517] [<c124a062>] ? tcp_v4_rcv+0x389/0x571 Aug 18 14:30:00 deodand kernel: [1547640.899521] [<c1021b55>] ? pvclock_clocksource_read+0xc4/0xf6 Aug 18 14:30:00 deodand kernel: [1547640.899525] [<c12316d9>] ? ip_local_deliver_finish+0x104/0x1a0 Aug 18 14:30:00 deodand kernel: [1547640.899529] [<c12315d5>] ? xfrm4_policy_check.clone.10+0x45/0x45 Aug 18 14:30:00 deodand kernel: [1547640.899531] [<c12317ab>] ? NF_HOOK.clone.11+0x36/0x39 Aug 18 14:30:00 deodand kernel: [1547640.899534] [<c12318a4>] ? ip_local_deliver+0x39/0x3c Aug 18 14:30:00 deodand kernel: [1547640.899537] [<c12315d5>] ? xfrm4_policy_check.clone.10+0x45/0x45 Aug 18 14:30:00 deodand kernel: [1547640.899540] [<c1231571>] ? ip_rcv_finish+0x2cb/0x2ea Aug 18 14:30:00 deodand kernel: [1547640.899543] [<c12312a6>] ? pskb_may_pull+0x2c/0x2c Aug 18 14:30:00 deodand kernel: [1547640.899545] [<c12317ab>] ? NF_HOOK.clone.11+0x36/0x39 Aug 18 14:30:00 deodand kernel: [1547640.899548] [<c1210880>] ? __netif_receive_skb+0x338/0x362 Aug 18 14:30:00 deodand kernel: [1547640.899551] [<c12312a6>] ? pskb_may_pull+0x2c/0x2c Aug 18 14:30:00 deodand kernel: [1547640.899554] [<c1210905>] ? process_backlog+0x5b/0x109 Aug 18 14:30:00 deodand kernel: [1547640.899557] [<c103ae67>] ? local_bh_enable+0x2/0x2 Aug 18 14:30:00 deodand kernel: [1547640.899560] [<c1211630>] ? net_rx_action+0x94/0x17e Aug 18 14:30:00 deodand kernel: [1547640.899563] [<c103ae67>] ? local_bh_enable+0x2/0x2 Aug 18 14:30:00 deodand kernel: [1547640.899565] [<c103aefb>] ? __do_softirq+0x94/0x130 Aug 18 14:30:00 deodand kernel: [1547640.899568] [<c103ae67>] ? local_bh_enable+0x2/0x2 Aug 18 14:30:00 deodand kernel: [1547640.899570] <IRQ> [<c103ae58>] ? _local_bh_enable_ip.clone.6+0x62/0x6d Aug 18 14:30:00 deodand kernel: [1547640.899575] [<c12125ee>] ? dev_queue_xmit+0x37b/0x388 Aug 18 14:30:00 deodand kernel: [1547640.899577] [<c1234dff>] ? ip_queue_xmit+0x1e6/0x302 Aug 18 14:30:00 deodand kernel: [1547640.899580] [<c123430a>] ? ip_finish_output2+0x1ab/0x1e6 Aug 18 14:30:00 deodand kernel: [1547640.899583] [<c1233774>] ? dst_output+0x9/0xa Aug 18 14:30:00 deodand kernel: [1547640.899585] [<c1244d60>] ? tcp_transmit_skb+0x694/0x6bb Aug 18 14:30:00 deodand kernel: [1547640.899588] [<c12457dd>] ? tcp_write_xmit+0x6c8/0x7b2 Aug 18 14:30:00 deodand kernel: [1547640.899591] [<c1245902>] ? __tcp_push_pending_frames+0x15/0x42 Aug 18 14:30:00 deodand kernel: [1547640.899595] [<c123baa9>] ? tcp_sendmsg+0x576/0x643 Aug 18 14:30:00 deodand kernel: [1547640.899598] [<c12545d5>] ? inet_sendmsg+0x47/0x4d Aug 18 14:30:00 deodand kernel: [1547640.899602] [<c1202dbf>] ? __sock_sendmsg+0x4e/0x57 Aug 18 14:30:00 deodand kernel: [1547640.899605] [<c1202ea0>] ? sock_aio_write+0xd8/0xe1 Aug 18 14:30:00 deodand kernel: [1547640.899609] [<c10ab3be>] ? handle_pte_fault+0x30f/0x8c7 Aug 18 14:30:00 deodand kernel: [1547640.899612] [<c10c9ab7>] ? do_sync_write+0x9e/0xd3 Aug 18 14:30:00 deodand kernel: [1547640.899617] [<c12b0824>] ? do_page_fault+0x2f6/0x312 Aug 18 14:30:00 deodand kernel: [1547640.899620] [<c10c9e85>] ? rw_verify_area+0xc8/0xe9 Aug 18 14:30:00 deodand kernel: [1547640.899624] [<c1029cfe>] ? need_resched+0x11/0x1a Aug 18 14:30:00 deodand kernel: [1547640.899627] [<c10ca130>] ? vfs_write+0x8d/0xd6 Aug 18 14:30:00 deodand kernel: [1547640.899629] [<c10ca2e8>] ? sys_write+0x3c/0x60 Aug 18 14:30:00 deodand kernel: [1547640.899633] [<c12adac4>] ? syscall_call+0x7/0xb 
Aug 18 14:30:00 deodand kernel: [1547640.899635] Mem-Info:
Aug 18 14:30:00 deodand kernel: [1547640.899636] DMA per-cpu:
Aug 18 14:30:00 deodand kernel: [1547640.899638] CPU 0: hi: 0, btch: 1 usd: 0 
Aug 18 14:30:00 deodand kernel: [1547640.899640] Normal per-cpu:
Aug 18 14:30:00 deodand kernel: [1547640.899642] CPU 0: hi: 186, btch: 31 usd: 67 Aug 18 14:30:00 deodand kernel: [1547640.899646] active_anon:3647 inactive_anon:2236 isolated_anon:0 Aug 18 14:30:00 deodand kernel: [1547640.899648] active_file:57886 inactive_file:51690 isolated_file:0 Aug 18 14:30:00 deodand kernel: [1547640.899649] unevictable:1107 dirty:59 writeback:0 unstable:0 Aug 18 14:30:00 deodand kernel: [1547640.899650] free:1403 slab_reclaimable:6031 slab_unreclaimable:1251 Aug 18 14:30:00 deodand kernel: [1547640.899651] mapped:4647 shmem:60 pagetables:278 bounce:0 Aug 18 14:30:00 deodand kernel: [1547640.899658] DMA free:2188kB min:84kB low:104kB high:124kB active_anon:4772kB inactive_anon:256kB active_file:1192kB inactive_file:1568kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15804kB mlocked:0kB dirty:48kB writeback:0kB mapped:92kB shmem:0kB slab_reclaimable:1984kB slab_unreclaimable:108kB kernel_stack:64kB pagetables:48kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:32 all_unreclaimable? no Aug 18 14:30:00 deodand kernel: [1547640.899663] lowmem_reserve[]: 0 492 492 492 Aug 18 14:30:00 deodand kernel: [1547640.899671] Normal free:3424kB min:2792kB low:3488kB high:4188kB active_anon:9816kB inactive_anon:8688kB active_file:230352kB inactive_file:205192kB unevictable:4428kB isolated(anon):0kB isolated(file):0kB present:503916kB mlocked:4428kB dirty:188kB writeback:0kB mapped:18496kB shmem:240kB slab_reclaimable:22140kB slab_unreclaimable:4896kB kernel_stack:1520kB pagetables:1064kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:26 all_unreclaimable? no 
Aug 18 14:30:00 deodand kernel: [1547640.899676] lowmem_reserve[]: 0 0 0 0
Aug 18 14:30:00 deodand kernel: [1547640.899679] DMA: 545*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2180kB Aug 18 14:30:00 deodand kernel: [1547640.899687] Normal: 856*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3424kB Aug 18 14:30:00 deodand kernel: [1547640.899694] 113922 total pagecache pages 
Aug 18 14:30:00 deodand kernel: [1547640.899695] 3314 pages in swap cache
Aug 18 14:30:00 deodand kernel: [1547640.899698] Swap cache stats: add 4323882, delete 4320568, find 31078896/31754505 
Aug 18 14:30:00 deodand kernel: [1547640.899700] Free swap  = 961376kB
Aug 18 14:30:00 deodand kernel: [1547640.899701] Total swap = 996024kB
Aug 18 14:30:00 deodand kernel: [1547640.900028] 131051 pages RAM
Aug 18 14:30:00 deodand kernel: [1547640.900028] 0 pages HighMem
Aug 18 14:30:00 deodand kernel: [1547640.900028] 2455 pages reserved
Aug 18 14:30:00 deodand kernel: [1547640.900028] 93111 pages shared
Aug 18 14:30:00 deodand kernel: [1547640.900028] 40200 pages non-shared
Aug 16 04:44:12 deodand kernel: [1339687.107786] BUG: soft lockup - CPU#0 stuck for 35s! [flush-254:0:776] Aug 16 04:44:12 deodand kernel: [1339687.111748] Modules linked in: btrfs zlib_deflate crc32c libcrc32c ufs qnx4 hfsplus hfs minix ntfs vfat msdos fat jfs xfs reiserfs ext4 jbd2 crc16 ext2 dm_mod tun binfmt_misc fuse nfsd nf s lockd fscache auth_rpcgss nfs_acl sunrpc snd_intel8x0 snd_ac97_codec ac97_bus snd_pcm snd_timer snd soundcore evdev i2c_piix4 psmouse i2c_core processor button virtio_balloon snd_page_alloc pcspkr serio_raw thermal_sys ext 3 jbd mbcache sg sr_mod cdrom ata_generic virtio_net virtio_blk floppy ata_piix uhci_hcd ehci_hcd usbcore libata 
 scsi_mod virtio_pci [last unloaded: scsi_wait_scan]
Aug 16 04:44:12 deodand kernel: [1339687.111748] Modules linked in: btrfs zlib_deflate crc32c libcrc32c ufs qnx4 hfsplus hfs minix ntfs vfat msdos fat jfs xfs reiserfs ext4 jbd2 crc16 ext2 dm_mod tun binfmt_misc fuse nfsd nf s lockd fscache auth_rpcgss nfs_acl sunrpc snd_intel8x0 snd_ac97_codec ac97_bus snd_pcm snd_timer snd soundcore evdev i2c_piix4 psmouse i2c_core processor button virtio_balloon snd_page_alloc pcspkr serio_raw thermal_sys ext 3 jbd mbcache sg sr_mod cdrom ata_generic virtio_net virtio_blk floppy ata_piix uhci_hcd ehci_hcd usbcore libata 
 scsi_mod virtio_pci [last unloaded: scsi_wait_scan]
Aug 16 04:44:12 deodand kernel: [1339687.111748]
Aug 16 04:44:12 deodand kernel: [1339687.111748] Pid: 776, comm: flush-254:0 Not tainted 3.0.0-1-686-pae #1 Boch 
s Bochs
Aug 16 04:44:12 deodand kernel: [1339687.111748] EIP: 0060:[<c113f721>] EFLAGS: 00000246 CPU: 0 Aug 16 04:44:12 deodand kernel: [1339687.111748] EIP is at arch_local_irq_restore+0x2/0x7 Aug 16 04:44:12 deodand kernel: [1339687.111748] EAX: 00000246 EBX: dcf3be44 ECX: 0001c910 EDX: 0000c910 Aug 16 04:44:12 deodand kernel: [1339687.111748] ESI: df5414dc EDI: 00000070 EBP: 00000246 ESP: dcf3be2c Aug 16 04:44:12 deodand kernel: [1339687.111748] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 Aug 16 04:44:12 deodand kernel: [1339687.111748] Process flush-254:0 (pid: 776, ti=dcf3a000 task=dcdb2a60 task.t 
i=dcf3a000)
Aug 16 04:44:12 deodand kernel: [1339687.111748] Stack:
Aug 16 04:44:12 deodand kernel: [1339687.111748] c114401b dcf3be44 00fed040 00000000 dcf3be3c dcf3be3c dcf3be44 
 dcf3be44
Aug 16 04:44:12 deodand kernel: [1339687.111748] dcf3be70 dcf3be70 00000000 de40278c c114402d de40278c c1099b27 
 de40278c
Aug 16 04:44:12 deodand kernel: [1339687.111748] dcf3bf18 91827364 dcf3be74 dcf3be74 dcf3be7c dcf3be7c 00000000 
 de4026c0
Aug 16 04:44:12 deodand kernel: [1339687.111748] Call Trace:
Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c114401b>] ? blk_flush_plug_list+0x158/0x160 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c114402d>] ? blk_finish_plug+0xa/0x25 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c1099b27>] ? generic_writepages+0x3a/0x44 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c109a4f8>] ? do_writepages+0x12/0x1b Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e1813>] ? writeback_single_inode+0x8e/0x173 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e1dd2>] ? writeback_sb_inodes+0x99/0xfb Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e22f5>] ? writeback_inodes_wb+0x109/0x119 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e24f2>] ? wb_writeback+0x1ed/0x2bd Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e26d7>] ? wb_do_writeback+0x115/0x15d Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e278a>] ? bdi_writeback_thread+0x6b/0x19d Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e271f>] ? wb_do_writeback+0x15d/0x15d Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c104b8bb>] ? kthread+0x63/0x68 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c104b858>] ? kthread_worker_fn+0x117/0x117 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c12b27be>] ? kernel_thread_helper+0x6/0x10 Aug 16 04:44:12 deodand kernel: [1339687.111748] Code: c7 fe 05 54 8e 50 c1 68 93 ef 38 c1 01 df 57 e8 c6 82 01 00 8d 04 03 83 c4 0c 5b 5e 5f 5d c3 90 90 90 9c 58 8d 74 26 00 c3 50 9d <8d> 74 26 00 c3 3e ff 00 c3 3e ff 08 c3 
 fe 00 fb 90 8d 74 26 00
Aug 16 04:44:12 deodand kernel: [1339687.111748] Call Trace:
Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c114401b>] ? blk_flush_plug_list+0x158/0x160 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c114402d>] ? blk_finish_plug+0xa/0x25 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c1099b27>] ? generic_writepages+0x3a/0x44 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c109a4f8>] ? do_writepages+0x12/0x1b Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e1813>] ? writeback_single_inode+0x8e/0x173 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e1dd2>] ? writeback_sb_inodes+0x99/0xfb Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e22f5>] ? writeback_inodes_wb+0x109/0x119 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e24f2>] ? wb_writeback+0x1ed/0x2bd Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e26d7>] ? wb_do_writeback+0x115/0x15d Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e278a>] ? bdi_writeback_thread+0x6b/0x19d Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c10e271f>] ? wb_do_writeback+0x15d/0x15d Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c104b8bb>] ? kthread+0x63/0x68 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c104b858>] ? kthread_worker_fn+0x117/0x117 Aug 16 04:44:12 deodand kernel: [1339687.111748] [<c12b27be>] ? kernel_thread_helper+0x6/0x10
Reply to: