From mboxrd@z Thu Jan 1 00:00:00 1970 From: Jiri Slaby Subject: Re: PM: cannot hibernate -- BUG at kernel/workqueue.c:3659 Date: Tue, 24 Jan 2012 17:24:33 +0100 Message-ID: <4F1EDB41.2070303@suse.cz> References: <4F1EC8D5.5040102@suse.cz> <4F1ED9C4.9020503@linux.vnet.ibm.com> Mime-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Return-path: In-Reply-To: <4F1ED9C4.9020503@linux.vnet.ibm.com> List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: linux-pm-bounces@lists.linux-foundation.org Errors-To: linux-pm-bounces@lists.linux-foundation.org To: "Srivatsa S. Bhat" Cc: Linux-pm mailing list , LKML , Jiri Slaby List-Id: linux-pm@vger.kernel.org On 01/24/2012 05:18 PM, Srivatsa S. Bhat wrote: > Hi Jiri, > > On 01/24/2012 08:35 PM, Jiri Slaby wrote: > >> Hi, >> >> this is a freshly booted system. When I do s2dsk, I see: >> ... >> Freezing remaining freezable tasks ... BUG: 'workqueue_freezing' is true! >> ------------[ cut here ]------------ >> kernel BUG at /l/latest/linux/kernel/workqueue.c:3659! >> invalid opcode: 0000 [#1] SMP >> CPU 0 >> Modules linked in: >> >> Pid: 2669, comm: s2disk Not tainted 3.3.0-rc1-next-20120124_64+ #1627 >> Bochs Bochs >> RIP: 0010:[] [] >> freeze_workqueues_begin+0x195/0x1a0 >> RSP: 0018:ffff880046f01d68 EFLAGS: 00010292 >> RAX: 0000000000000023 RBX: 0000000000000001 RCX: 00000000000000c9 >> RDX: 0000000000000077 RSI: 0000000000000046 RDI: ffffffff81b51f7c >> RBP: ffff880046f01d98 R08: ffffffff81a9d760 R09: 0000000000000000 >> R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000 >> R13: 00007fff579464dc R14: ffffffffffffffff R15: 0000000000000004 >> FS: 00007f3c65d54700(0000) GS:ffff880049600000(0000) knlGS:0000000000000000 >> CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b >> CR2: 00007f3c64f58c20 CR3: 0000000045b64000 CR4: 00000000000006f0 >> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 >> DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 >> Process s2disk (pid: 2669, threadinfo ffff880046f00000, task >> ffff880047251980) >> Stack: >> ffff880046f01d98 0000000000000001 0000000000000000 00007fff579464dc >> ffffffffffffffff 0000000000000004 ffff880046f01e18 ffffffff81096cb9 >> 00000000ffff0124 0000000000000004 ffff880046f01e18 000000004f1ec7d1 >> Call Trace: >> [] try_to_freeze_tasks+0x1b9/0x2d0 >> [] freeze_kernel_threads+0x25/0x90 >> [] hibernation_snapshot+0x75/0x2e0 >> [] snapshot_ioctl+0x314/0x4e0 >> [] do_vfs_ioctl+0x96/0x550 >> [] ? vfs_write+0x10b/0x180 >> [] sys_ioctl+0x4a/0x80 >> [] system_call_fastpath+0x16/0x1b >> Code: c7 c6 0a a4 92 81 48 c7 c7 16 65 92 81 31 c0 e8 19 94 5a 00 0f 0b >> 48 c7 c6 27 a4 92 81 48 c7 c7 16 65 92 81 31 c0 e8 02 94 5a 00 <0f> 0b >> 66 0f 1f 84 00 00 00 00 00 55 48 c7 c7 82 4b b9 81 48 89 >> RIP [] freeze_workqueues_begin+0x195/0x1a0 >> RSP >> ---[ end trace 632574abdc098963 ]--- >> > > > I couldn't find any obvious root-cause from a quick check. Is this completely > reproducible upon a fresh boot? True. The cause is that the function is called twice: # s2disk PM: Marking nosave pages: 000000000009f000 - 0000000000100000 PM: Basic memory bitmaps created Syncing filesystems ... done. Freezing user space processes ... (elapsed 0.01 seconds) done. PM: Preallocating image memory... done (allocated 264170 pages) PM: Allocated 1056680 kbytes in 0.45 seconds (2348.17 MB/s) Freezing remaining freezable tasks ... Pid: 2650, comm: s2disk Not tainted 3.3.0-rc1-next-20120124_64+ #1628 Call Trace: [] ? getnstimeofday+0x52/0xf0 [] freeze_workqueues_begin+0x36/0x1b0 [] try_to_freeze_tasks+0x1b9/0x2d0 [] freeze_kernel_threads+0x25/0x90 [] hibernation_snapshot+0x75/0x2e0 [] snapshot_ioctl+0x314/0x4e0 [] do_vfs_ioctl+0x96/0x550 [] ? vfs_write+0x10b/0x180 [] sys_ioctl+0x4a/0x80 [] system_call_fastpath+0x16/0x1b (elapsed 0.03 seconds) done. PM: freeze of devices complete after 57.216 msecs PM: late freeze of devices complete after 0.720 msecs ACPI: Preparing to enter system sleep state S4 PM: Saving platform NVS memory Disabling non-boot CPUs ... CPU 1 is now offline PM: Creating hibernation image: PM: Need to copy 24112 pages PM: Normal pages needed: 24112 + 1024, available pages: 277076 PM: Hibernation image created (24112 pages copied) Enabling non-boot CPUs ... Booting Node 0 Processor 1 APIC 0x1 smpboot cpu 1: start_ip = 9a000 Calibrating delay loop (skipped) already calibrated this CPU NMI watchdog disabled (cpu1): hardware events not enabled CPU1 is up ACPI: Waking up from system sleep state S4 PM: early thaw of devices complete after 0.093 msecs ata_piix 0000:00:01.1: setting latency timer to 64 e1000 0000:00:03.0: setting latency timer to 64 e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX ata2.01: NODEV after polling detection ata1.00: configured for MWDMA2 ata2.00: configured for MWDMA2 ata1.01: configured for MWDMA2 sd 0:0:1:0: [sdb] Starting disk sd 0:0:0:0: [sda] Starting disk PM: thaw of devices complete after 192.317 msecs PM: Preallocating image memory... done (allocated 264295 pages) PM: Allocated 1057180 kbytes in 0.12 seconds (8809.83 MB/s) Freezing remaining freezable tasks ... BUG: 'workqueue_freezing' is true! ------------[ cut here ]------------ kernel BUG at /l/latest/linux/kernel/workqueue.c:3659! invalid opcode: 0000 [#1] SMP CPU 1 Modules linked in: Pid: 2650, comm: s2disk Not tainted 3.3.0-rc1-next-20120124_64+ #1628 Bochs Bochs RIP: 0010:[] [] freeze_workqueues_begin+0x1a1/0x1b0 RSP: 0018:ffff8800456d7d68 EFLAGS: 00010292 RAX: 0000000000000023 RBX: 0000000000000001 RCX: 0000000000000073 RDX: 00000000000000ea RSI: 0000000000000046 RDI: ffffffff81b51f7c RBP: ffff8800456d7d98 R08: ffffffff81a9d760 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000 R13: 00007fff11d8709c R14: ffffffffffffffff R15: 0000000000000004 FS: 00007f4744397700(0000) GS:ffff880049700000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b CR2: 0000000001f46bc0 CR3: 000000004483b000 CR4: 00000000000006e0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 Process s2disk (pid: 2650, threadinfo ffff8800456d6000, task ffff880046c93300) Stack: ffff8800456d7d98 0000000000000001 0000000000000000 00007fff11d8709c ffffffffffffffff 0000000000000004 ffff8800456d7e18 ffffffff81096cc9 00000000ffff008f 0000000000000004 ffff8800456d7e18 000000004f1edaaf Call Trace: [] try_to_freeze_tasks+0x1b9/0x2d0 [] freeze_kernel_threads+0x25/0x90 [] hibernation_snapshot+0x75/0x2e0 [] snapshot_ioctl+0x314/0x4e0 [] do_vfs_ioctl+0x96/0x550 [] ? vfs_write+0x10b/0x180 [] sys_ioctl+0x4a/0x80 [] system_call_fastpath+0x16/0x1b Code: c7 c6 0a a4 92 81 48 c7 c7 16 65 92 81 31 c0 e8 1d 94 5a 00 0f 0b 48 c7 c6 27 a4 92 81 48 c7 c7 16 65 92 81 31 c0 e8 06 94 5a 00 <0f> 0b 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 55 48 c7 c7 82 4b RIP [] freeze_workqueues_begin+0x1a1/0x1b0 RSP ---[ end trace 696a23a038efce41 ]--- > > Regards, > Srivatsa S. Bhat > IBM Linux Technology Center > -- js suse labs From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755312Ab2AXQYk (ORCPT ); Tue, 24 Jan 2012 11:24:40 -0500 Received: from mail-ey0-f174.google.com ([209.85.215.174]:42443 "EHLO mail-ey0-f174.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753404Ab2AXQYh (ORCPT ); Tue, 24 Jan 2012 11:24:37 -0500 Message-ID: <4F1EDB41.2070303@suse.cz> Date: Tue, 24 Jan 2012 17:24:33 +0100 From: Jiri Slaby User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:10.0) Gecko/20120118 Thunderbird/10.0 MIME-Version: 1.0 To: "Srivatsa S. Bhat" CC: "Rafael J. Wysocki" , Linux-pm mailing list , LKML , Jiri Slaby Subject: Re: [linux-pm] PM: cannot hibernate -- BUG at kernel/workqueue.c:3659 References: <4F1EC8D5.5040102@suse.cz> <4F1ED9C4.9020503@linux.vnet.ibm.com> In-Reply-To: <4F1ED9C4.9020503@linux.vnet.ibm.com> X-Enigmail-Version: 1.3.4 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On 01/24/2012 05:18 PM, Srivatsa S. Bhat wrote: > Hi Jiri, > > On 01/24/2012 08:35 PM, Jiri Slaby wrote: > >> Hi, >> >> this is a freshly booted system. When I do s2dsk, I see: >> ... >> Freezing remaining freezable tasks ... BUG: 'workqueue_freezing' is true! >> ------------[ cut here ]------------ >> kernel BUG at /l/latest/linux/kernel/workqueue.c:3659! >> invalid opcode: 0000 [#1] SMP >> CPU 0 >> Modules linked in: >> >> Pid: 2669, comm: s2disk Not tainted 3.3.0-rc1-next-20120124_64+ #1627 >> Bochs Bochs >> RIP: 0010:[] [] >> freeze_workqueues_begin+0x195/0x1a0 >> RSP: 0018:ffff880046f01d68 EFLAGS: 00010292 >> RAX: 0000000000000023 RBX: 0000000000000001 RCX: 00000000000000c9 >> RDX: 0000000000000077 RSI: 0000000000000046 RDI: ffffffff81b51f7c >> RBP: ffff880046f01d98 R08: ffffffff81a9d760 R09: 0000000000000000 >> R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000 >> R13: 00007fff579464dc R14: ffffffffffffffff R15: 0000000000000004 >> FS: 00007f3c65d54700(0000) GS:ffff880049600000(0000) knlGS:0000000000000000 >> CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b >> CR2: 00007f3c64f58c20 CR3: 0000000045b64000 CR4: 00000000000006f0 >> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 >> DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 >> Process s2disk (pid: 2669, threadinfo ffff880046f00000, task >> ffff880047251980) >> Stack: >> ffff880046f01d98 0000000000000001 0000000000000000 00007fff579464dc >> ffffffffffffffff 0000000000000004 ffff880046f01e18 ffffffff81096cb9 >> 00000000ffff0124 0000000000000004 ffff880046f01e18 000000004f1ec7d1 >> Call Trace: >> [] try_to_freeze_tasks+0x1b9/0x2d0 >> [] freeze_kernel_threads+0x25/0x90 >> [] hibernation_snapshot+0x75/0x2e0 >> [] snapshot_ioctl+0x314/0x4e0 >> [] do_vfs_ioctl+0x96/0x550 >> [] ? vfs_write+0x10b/0x180 >> [] sys_ioctl+0x4a/0x80 >> [] system_call_fastpath+0x16/0x1b >> Code: c7 c6 0a a4 92 81 48 c7 c7 16 65 92 81 31 c0 e8 19 94 5a 00 0f 0b >> 48 c7 c6 27 a4 92 81 48 c7 c7 16 65 92 81 31 c0 e8 02 94 5a 00 <0f> 0b >> 66 0f 1f 84 00 00 00 00 00 55 48 c7 c7 82 4b b9 81 48 89 >> RIP [] freeze_workqueues_begin+0x195/0x1a0 >> RSP >> ---[ end trace 632574abdc098963 ]--- >> > > > I couldn't find any obvious root-cause from a quick check. Is this completely > reproducible upon a fresh boot? True. The cause is that the function is called twice: # s2disk PM: Marking nosave pages: 000000000009f000 - 0000000000100000 PM: Basic memory bitmaps created Syncing filesystems ... done. Freezing user space processes ... (elapsed 0.01 seconds) done. PM: Preallocating image memory... done (allocated 264170 pages) PM: Allocated 1056680 kbytes in 0.45 seconds (2348.17 MB/s) Freezing remaining freezable tasks ... Pid: 2650, comm: s2disk Not tainted 3.3.0-rc1-next-20120124_64+ #1628 Call Trace: [] ? getnstimeofday+0x52/0xf0 [] freeze_workqueues_begin+0x36/0x1b0 [] try_to_freeze_tasks+0x1b9/0x2d0 [] freeze_kernel_threads+0x25/0x90 [] hibernation_snapshot+0x75/0x2e0 [] snapshot_ioctl+0x314/0x4e0 [] do_vfs_ioctl+0x96/0x550 [] ? vfs_write+0x10b/0x180 [] sys_ioctl+0x4a/0x80 [] system_call_fastpath+0x16/0x1b (elapsed 0.03 seconds) done. PM: freeze of devices complete after 57.216 msecs PM: late freeze of devices complete after 0.720 msecs ACPI: Preparing to enter system sleep state S4 PM: Saving platform NVS memory Disabling non-boot CPUs ... CPU 1 is now offline PM: Creating hibernation image: PM: Need to copy 24112 pages PM: Normal pages needed: 24112 + 1024, available pages: 277076 PM: Hibernation image created (24112 pages copied) Enabling non-boot CPUs ... Booting Node 0 Processor 1 APIC 0x1 smpboot cpu 1: start_ip = 9a000 Calibrating delay loop (skipped) already calibrated this CPU NMI watchdog disabled (cpu1): hardware events not enabled CPU1 is up ACPI: Waking up from system sleep state S4 PM: early thaw of devices complete after 0.093 msecs ata_piix 0000:00:01.1: setting latency timer to 64 e1000 0000:00:03.0: setting latency timer to 64 e1000: eth0 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX ata2.01: NODEV after polling detection ata1.00: configured for MWDMA2 ata2.00: configured for MWDMA2 ata1.01: configured for MWDMA2 sd 0:0:1:0: [sdb] Starting disk sd 0:0:0:0: [sda] Starting disk PM: thaw of devices complete after 192.317 msecs PM: Preallocating image memory... done (allocated 264295 pages) PM: Allocated 1057180 kbytes in 0.12 seconds (8809.83 MB/s) Freezing remaining freezable tasks ... BUG: 'workqueue_freezing' is true! ------------[ cut here ]------------ kernel BUG at /l/latest/linux/kernel/workqueue.c:3659! invalid opcode: 0000 [#1] SMP CPU 1 Modules linked in: Pid: 2650, comm: s2disk Not tainted 3.3.0-rc1-next-20120124_64+ #1628 Bochs Bochs RIP: 0010:[] [] freeze_workqueues_begin+0x1a1/0x1b0 RSP: 0018:ffff8800456d7d68 EFLAGS: 00010292 RAX: 0000000000000023 RBX: 0000000000000001 RCX: 0000000000000073 RDX: 00000000000000ea RSI: 0000000000000046 RDI: ffffffff81b51f7c RBP: ffff8800456d7d98 R08: ffffffff81a9d760 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000 R13: 00007fff11d8709c R14: ffffffffffffffff R15: 0000000000000004 FS: 00007f4744397700(0000) GS:ffff880049700000(0000) knlGS:0000000000000000 CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b CR2: 0000000001f46bc0 CR3: 000000004483b000 CR4: 00000000000006e0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 Process s2disk (pid: 2650, threadinfo ffff8800456d6000, task ffff880046c93300) Stack: ffff8800456d7d98 0000000000000001 0000000000000000 00007fff11d8709c ffffffffffffffff 0000000000000004 ffff8800456d7e18 ffffffff81096cc9 00000000ffff008f 0000000000000004 ffff8800456d7e18 000000004f1edaaf Call Trace: [] try_to_freeze_tasks+0x1b9/0x2d0 [] freeze_kernel_threads+0x25/0x90 [] hibernation_snapshot+0x75/0x2e0 [] snapshot_ioctl+0x314/0x4e0 [] do_vfs_ioctl+0x96/0x550 [] ? vfs_write+0x10b/0x180 [] sys_ioctl+0x4a/0x80 [] system_call_fastpath+0x16/0x1b Code: c7 c6 0a a4 92 81 48 c7 c7 16 65 92 81 31 c0 e8 1d 94 5a 00 0f 0b 48 c7 c6 27 a4 92 81 48 c7 c7 16 65 92 81 31 c0 e8 06 94 5a 00 <0f> 0b 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 55 48 c7 c7 82 4b RIP [] freeze_workqueues_begin+0x1a1/0x1b0 RSP ---[ end trace 696a23a038efce41 ]--- > > Regards, > Srivatsa S. Bhat > IBM Linux Technology Center > -- js suse labs