From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932097AbYHUWHj (ORCPT ); Thu, 21 Aug 2008 18:07:39 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1759780AbYHUWHa (ORCPT ); Thu, 21 Aug 2008 18:07:30 -0400 Received: from ogre.sisk.pl ([217.79.144.158]:40507 "EHLO ogre.sisk.pl" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1759759AbYHUWH3 (ORCPT ); Thu, 21 Aug 2008 18:07:29 -0400 From: "Rafael J. Wysocki" To: "Pekka Enberg" Subject: Re: latest -git: suspend: unable to handle kernel paging request (was Re: no_console_suspend doesn't work?) Date: Fri, 22 Aug 2008 00:10:36 +0200 User-Agent: KMail/1.9.6 (enterprise 20070904.708012) Cc: "Vegard Nossum" , "Linux Kernel Mailing List" , "Andrew Morton" , "Jens Axboe" References: <19f34abd0808211028w7889587fke523ff244339e7c5@mail.gmail.com> <19f34abd0808211308t2ee63a37kc204a5849231af45@mail.gmail.com> <84144f020808211421l643eef28p4ea2754b3f0c786a@mail.gmail.com> In-Reply-To: <84144f020808211421l643eef28p4ea2754b3f0c786a@mail.gmail.com> MIME-Version: 1.0 Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: 7bit Content-Disposition: inline Message-Id: <200808220010.37733.rjw@sisk.pl> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Thursday, 21 of August 2008, Pekka Enberg wrote: > Hi Vegard, > > On Thu, Aug 21, 2008 at 11:08 PM, Vegard Nossum wrote: > > On Thu, Aug 21, 2008 at 9:37 PM, Rafael J. Wysocki wrote: > >> Can you switch to SLAB and retest? I don't really think SLUB is the issue > >> here, but SLAB may give us additional information. > > > > Got this with SLAB: > > > > BUG: unable to handle kernel NULL pointer dereference at 00000000 > > IP: [] list_del+0xc/0x90 > > *pdpt = 0000000031480001 *pde = 0000000000000000 > > Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC > > Pid: 7, comm: events/0 Not tainted (2.6.27-rc4-00003-gef9b1bc #33) > > EIP: 0060:[] EFLAGS: 00010082 CPU: 0 > > EIP is at list_del+0xc/0x90 > > EAX: 00000000 EBX: f556afa0 ECX: f54a5380 EDX: f54e3128 > > ESI: f54f1ef0 EDI: f556afa0 EBP: f68b7ee0 ESP: f68b7ec8 > > DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 > > Process events/0 (pid: 7, ti=f68b6000 task=f689c338 task.ti=f68b6000) > > Stack: c015b62e f68b7ed4 c015b66d f68b7efc 00000046 f54f1f20 f68b7f1c c01b4054 > > 00000000 f689c338 f54e315c 00000001 f54f1f20 f54a5380 00000000 f54e3128 > > f55b3348 00000000 f54f1f20 f54f1ef0 00000001 f68b7f3c c01b41ba 00000000 > > Call Trace: > > [] ? get_lock_stats+0x1e/0x50 > > [] ? put_lock_stats+0xd/0x30 > > Looks like slabp->list is corrupted when we do list_del() in > free_block(). Why is the stack trace so unreliable, though? > > > [] ? free_block+0xa4/0x1b0 > > [] ? drain_array+0x5a/0xb0 > > [] ? cache_reap+0x72/0x230 > > [] ? run_workqueue+0x107/0x200 > > [] ? run_workqueue+0x16a/0x200 > > [] ? run_workqueue+0x107/0x200 > > [] ? cache_reap+0x0/0x230 > > [] ? worker_thread+0x7d/0xe0 > > [] ? autoremove_wake_function+0x0/0x50 > > [] ? worker_thread+0x0/0xe0 > > [] ? kthread+0x42/0x70 > > [] ? kthread+0x0/0x70 > > [] ? kernel_thread_helper+0x7/0x14 > > ======================= > > Code: e8 01 89 44 24 04 e8 d4 1d db ff 8b 55 04 b8 48 2f 7a c0 e8 47 d8 dd ff e8 > > c2 dc d7 ff eb a9 55 89 e5 53 89 c3 83 ec 14 8b 40 04 <8b> 00 39 d8 75 24 8b 13 > > 8b 42 04 39 d8 75 41 8b 43 04 89 42 04 > > EIP: [] list_del+0xc/0x90 SS:ESP 0068:f68b7ec8 > > ---[ end trace 958cea1a710a109a ]--- > > note: events/0[7] exited with preempt_count 1 > > uhci_hcd 0000:00:1d.2: setting latency timer to 64 > > uhci_hcd 0000:00:1d.3: setting latency timer to 64 > > ehci_hcd 0000:00:1d.7: setting latency timer to 64 > > pci 0000:00:1e.0: setting latency timer to 64 > > ------------[ cut here ]------------ > > WARNING: at /uio/arkimedes/s29/vegardno/git-working/linux-2.6/lib/list_debug.c:26 > > __list_add+0x61/0x90() > > list_add corruption. next->prev should be prev (f6c00490), but was > > f73ecea8. (next=f73ecea8). > > Pid: 201, comm: rcu_torture_rea Tainted: G D > > 2.6.27-rc4-00003-gef9b1bc #33 > > [] warn_slowpath+0x5e/0x80 > > [] ? trace_hardirqs_off+0xb/0x10 > > [] ? native_sched_clock+0xb5/0x110 > > [] ? kernel_map_pages+0xa6/0x130 > > This looks most interesting. The free_list in zone->free_area is corrupted. > > > [] __list_add+0x61/0x90 > > [] __free_pages_ok+0x368/0x410 > > [] __free_pages+0x22/0x40 > > [] free_pages+0x48/0x50 > > [] free_thread_info+0x19/0x20 > > [] free_task+0x19/0x30 > > [] __put_task_struct+0x51/0xa0 > > [] delayed_put_task_struct+0x27/0x30 > > [] rcu_process_callbacks+0x6c/0xb0 > > [] __do_softirq+0x83/0x100 > > [] do_softirq+0xa5/0xb0 > > [] irq_exit+0x95/0xa0 > > [] do_IRQ+0x4d/0xa0 > > [] ? trace_hardirqs_off_thunk+0xc/0x18 > > [] common_interrupt+0x28/0x30 > > [] ? schedule+0x734/0x8f0 > > [] ? start_secondary+0x19b/0x1c0 > > [] ? check_tsc_warp+0x38/0x1e0 > > [] ? _spin_unlock_irq+0x2b/0x60 > > [] schedule+0x734/0x8f0 > > [] ? restore_nocheck_notrace+0x0/ > > [] ? trace_hardirqs_on+0xb/0x10 > > [] rcu_torture_reader+0x148/0x230 > > [] ? rcu_torture_timer+0x0/0x100 > > [] ? rcu_torture_reader+0x1d9/0x230 > > [] ? rcu_torture_reader+0x0/0x230 > > [] kthread+0x42/0x70 > > [] ? kthread+0x0/0x70 > > [] kernel_thread_helper+0x7/0x14 > > ======================= > > ---[ end trace 958cea1a710a109a ]--- > > eth0: link up, 100Mbps, full-duplex, lpa 0x45E1 > > eth1: link down > > hda: host max PIO4 wanted PIO255(auto-tune) selected PIO4 > > hda: UDMA/100 mode selected > > ------------[ cut here ]------------ > > kernel BUG at /uio/arkimedes/s29/vegardno/git-working/linux-2.6/mm/slab.c:590! > > invalid opcode: 0000 [#2] PREEMPT SMP DEBUG_PAGEALLOC > > Pid: 3257, comm: S99local Tainted: G D W (2.6.27-rc4-00003-gef9b1bc #33) > > EIP: 0060:[] EFLAGS: 00210002 CPU: 0 > > EIP is at cache_free_debugcheck+0x2e0/0x310 > > EAX: 00000000 EBX: f4c1f688 ECX: c018976e EDX: f785f744 > > ESI: f6864180 EDI: f4c1f688 EBP: f25b1de8 ESP: f25b1d94 > > DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068 > > Process S99local (pid: 3257, ti=f25b0000 task=f253f338 task.ti=f25b0000) > > Stack: 00200200 f4c1f688 00000000 f25b1e20 f25b1dac c0683402 f25b1e58 c018976e > > 00000001 c036a7b0 00000002 00000000 00000000 c088c190 f253f338 f4c1f688 > > f253f338 f25b1df8 f6864180 f6960ef0 f4c1f688 f25b1e0c c01b3c9c f253f7f4 > > Call Trace: > > [] ? wait_for_completion+0x12/0x20 > > Here the block layer is passing a pointer to a non-slab page to > kmem_cache_free(). Assuming we can rely on the stack trace, of > course... > > > [] ? mempool_free_slab+0xe/0x10 > > [] ? blk_end_sync_rq+0x0/0x30 > > [] ? kmem_cache_free+0x5c/0x200 > > [] ? mempool_free_slab+0xe/0x10 > > [] ? mempool_free+0x2c/0x90 > > [] ? __blk_put_request+0x62/0x90 > > [] ? blk_put_request+0x2c/0x50 > > [] ? generic_ide_resume+0xa2/0xf0 > > [] ? device_resume+0x32e/0x380 > > [] ? hibernation_snapshot+0xa1/0x220 > > [] ? printk+0x1b/0x20 > > [] ? hibernate+0xe0/0x180 > > [] ? state_store+0x0/0xd0 > > [] ? state_store+0xbf/0xd0 > > [] ? state_store+0x0/0xd0 > > [] ? kobj_attr_store+0x24/0x30 > > [] ? sysfs_write_file+0xa2/0x100 > > [] ? vfs_write+0x96/0x130 > > [] ? sysfs_write_file+0x0/0x100 > > [] ? sys_write+0x3d/0x70 > > [] ? sysenter_do_call+0x12/0x3f > > ======================= > > Code: 00 00 75 cd c7 03 21 43 65 87 8b 5e 28 e9 78 ff ff ff 0f 0b eb fe 90 8d 74 > > 26 00 8b 52 0c e9 ca fd ff ff 0f 0b eb fe 8d 74 26 00 <0f> 0b eb fe 0f 0b eb fe > > 0f 0b eb fe 8d 74 26 00 8b 52 0c 8b 02 > > EIP: [] cache_free_debugcheck+0x2e0/0x310 SS:ESP 0068:f25b1d94 > > ---[ end trace 958cea1a710a109a ]--- > > note: S99local[3257] exited with preempt_count 1 > > > BUG: unable to handle kernel paging request at 00100104 > > IP: [] __list_add+0x15/0x90 > > *pdpt = 0000000031480001 *pde = 0000000000000000 > > Oops: 0000 [#3] PREEMPT SMP DEBUG_PAGEALLOC > > Pid: 3257, comm: S99local Tainted: G D W (2.6.27-rc4-00003-gef9b1bc #33) > > EIP: 0060:[] EFLAGS: 00210086 CPU: 0 > > EIP is at __list_add+0x15/0x90 > > EAX: f73ece6c EBX: 00100100 ECX: 00100100 EDX: f73ece6c > > ESI: f73ece6c EDI: f73ece6c EBP: f25b16dc ESP: f25b16b8 > > DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 > > Process S99local (pid: 3257, ti=f25b0000 task=f253f338 task.ti=f25b0000) > > Stack: f6814e44 f6c00400 c06860b3 00000000 00000002 00000000 f73ece3c f73ece6c > > f73ece6c f25b1704 c018b9e4 0000001f 00000000 f6c00400 f6c00444 00000001 > > f6814e44 f6814e38 00200002 f25b1778 c018d3a7 f6814e44 00000000 00000000 > > Call Trace: > > [] ? _spin_lock+0x63/0x70 > > And now we have the per-cpu page lists corrupted as well. Note that > even though we have tty showing up in the stack traces, the list has > already been corrupted by someone else. So I don't think tty is at > fault here. > > > [] ? rmqueue_bulk+0x54/0x80 > > [] ? get_page_from_freelist+0x5a7/0x720 > > [] ? __alloc_pages_internal+0xa0/0x450 > > [] ? kmem_getpages+0x62/0x110 > > [] ? cache_grow+0x39c/0x3b0 > > [] ? _raw_spin_unlock+0x46/0x80 > > [] ? cache_alloc_refill+0x1f3/0x230 > > [] ? __kmalloc+0x1a5/0x1e0 > > [] ? tty_buffer_request_room+0xe2/0x130 > > [] ? tty_buffer_request_room+0xe2/0x130 > > [] ? tty_insert_flip_string_flags+0x2d/0xa0 > > [] ? receive_chars+0x161/0x290 > > [] ? serial8250_interrupt+0x134/0x150 > > [] ? handle_IRQ_event+0x28/0x70 > > [] ? handle_edge_irq+0xaf/0x140 > > [] ? do_IRQ+0x48/0xa0 > > [] ? trace_hardirqs_off_thunk+0xc/0x18 > > [] ? common_interrupt+0x28/0x30 > > [] ? vprintk+0x151/0x3c0 > > [] ? run_timer_softirq+0x19f/0x1d0 > > [] ? run_timer_softirq+0x19f/0x1d0 > > [] ? printk+0x1b/0x20 > > [] ? __print_symbol+0x2a/0x40 > > [] ? trace_hardirqs_on_thunk+0xc/0x10 > > [] ? restore_nocheck_notrace+0x0/0xe > > [] ? vprintk+0x151/0x3c0 > > [] ? vprintk+0x2db/0x3c0 > > [] ? irq_exit+0x3a/0xa0 > > [] ? restore_nocheck_notrace+0x0/0xe > > [] ? vprintk+0x151/0x3c0 > > [] ? do_trap+0x91/0xc0 > > [] ? printk+0x1b/0x20 > > [] ? do_trap+0x91/0xc0 > > [] ? print_trace_address+0x40/0x50 > > [] ? do_trap+0x91/0xc0 > > [] ? dump_trace+0xaa/0x120 > > [] ? show_trace_log_lvl+0x26/0x40 > > [] ? show_trace+0x1a/0x20 > > [] ? dump_stack+0x72/0x80 > > [] ? __might_sleep+0xf1/0x140 > > [] ? down_read+0x19/0x80 > > [] ? tty_audit_add_data+0x1bb/0x2e0 > > [] ? exit_mm+0x2b/0x110 > > [] ? do_exit+0x184/0x890 > > [] ? printk+0x1b/0x20 > > [] ? print_oops_end_marker+0x2a/0x30 > > [] ? oops_end+0xb1/0xc0 > > [] ? die+0x50/0x70 > > [] ? do_trap+0x91/0xc0 > > [] ? do_invalid_op+0x0/0xa0 > > [] ? do_invalid_op+0x88/0xa0 > > [] ? cache_free_debugcheck+0x2e0/0x310 > > [] ? print_lock_contention_bug+0x1a/0xe0 > > [] ? rcu_irq_exit+0x17/0x90 > > [] ? error_code+0x72/0x78 > > [] ? mempool_free_slab+0xe/0x10 > > [] ? start_secondary+0x19b/0x1c0 > > [] ? check_tsc_warp+0x38/0x1e0 > > [] ? cache_free_debugcheck+0x2e0/0x310 > > [] ? wait_for_completion+0x12/0x20 > > [] ? mempool_free_slab+0xe/0x10 > > [] ? blk_end_sync_rq+0x0/0x30 > > [] ? kmem_cache_free+0x5c/0x200 > > [] ? mempool_free_slab+0xe/0x10 > > [] ? mempool_free+0x2c/0x90 > > [] ? __blk_put_request+0x62/0x90 > > [] ? blk_put_request+0x2c/0x50 > > [] ? generic_ide_resume+0xa2/0xf0 > > [] ? device_resume+0x32e/0x380 > > [] ? hibernation_snapshot+0xa1/0x220 > > [] ? printk+0x1b/0x20 > > [] ? hibernate+0xe0/0x180 > > [] ? state_store+0x0/0xd0 > > [] ? state_store+0xbf/0xd0 > > [] ? state_store+0x0/0xd0 > > [] ? kobj_attr_store+0x24/0x30 > > [] ? sysfs_write_file+0xa2/0x100 > > [] ? vfs_write+0x96/0x130 > > [] ? sysfs_write_file+0x0/0x100 > > [] ? sys_write+0x3d/0x70 > > [] ? sysenter_do_call+0x12/0x3f > > ======================= > > Code: c0 e8 10 0d db ff 8b 13 eb 97 8d b6 00 00 00 00 8d bf 00 00 00 00 55 89 e5 > > 83 ec 24 89 5d f4 89 cb 89 75 f8 89 d6 89 7d fc 89 c7 <8b> 41 04 39 d0 75 1d 8b > > 06 39 d8 75 41 89 7b 04 89 1f 8b 5d f4 > > EIP: [] __list_add+0x15/0x90 SS:ESP 0068:f25b16b8 > > I don't know the suspend code at all but the bogus pointer coming from > hibernation_snapshot() seems suspicious. Which one? > Another possibility is that the block layer is doing something strange here. > Dunno. I bet on the IDE driver. Thanks, Rafael