Bug 14504

Summary: intermittent hibernation problem again
Product: Power Management Reporter: Ferenc Wágner (wferi)
Component: Hibernation/SuspendAssignee: power-management_other
Status: CLOSED CODE_FIX    
Severity: normal CC: bugs-kernel.8eaf7cd8e5128d8191fe, lenb, pterjan, rjw, wferi
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 2.6.32-rc5 Subsystem:
Regression: Yes Bisected commit-id:
Bug Depends on:    
Bug Blocks: 7216, 14230    
Attachments: e100 NAPI freeze during hibernation under 2.6.32-rc8

Description Ferenc Wágner 2009-10-28 23:49:10 UTC
Something similar to http://bugzilla.kernel.org/show_bug.cgi?id=13894
raised its ugly head again, please see my last comments on that bug.
2.6.32-rc5 feels particularly bad, with frequent failures to switch
off the machine after "S|" or freezes after "Snapshotting system".
The former does not cause much trouble in itself, as the machine can
be switched off and resumed all right, but the latter is nasty.
Suspend to RAM works all the time.  The issue is not reproducible,
unfortunately, and the kernel change happened almost together with a
BIOS upgrade.  Yesterday I switched back to 2.6.31 to see whether it
still works stably with the new BIOS.  I'll report back my findings in
a couple of days.
Comment 1 Ferenc Wágner 2009-11-10 00:34:13 UTC
2.6.31 seemed unaffected, so I went back to 2.6.32-rc5 and tried playing with the shutdown mode parameter, as Rafael suggested.  I also switched to the latest (git) s2disk utility.  After several suspend/resume cycles with the "platform" method, suddenly the machine didn't power off after S|.  After a manual reset and a successful resume I switched to "shutdown" mode, but that failed with the exact same symptoms.  After a second "manual" resume I swithed to reboot mode, which worked fine, and after this I managed 7 successful suspend/resume cycles.  The 8th stalled after "Snapshotting sysmtem", but the system wan't completely dead: pressing Enter advanced the cursor, and Ctrl-C even printed ^C.  But that was its last action, even SysRq did'nt work after this.
Comment 2 Ferenc Wágner 2009-11-21 16:59:33 UTC
I'm upgrading to 2.6.32-rc8 now and keeping on poking around.
AFAIK no change is expected with respect to this bug.
Comment 3 Ferenc Wágner 2009-11-28 16:13:15 UTC
Well, 2.6.32-rc8 is affected as well. The freeze definitely happens during dpm_suspend_start(PMSG_HIBERNATE). I'm trying to find the guilty device.
Comment 4 Pascal Terjan 2009-12-16 11:13:44 UTC
I have the same issue on my Thinkpad T40

It often hangs on S| when hibernating, but I did not yet bother looking as powering it off does not break the hibernation :)
Comment 5 Ferenc Wágner 2009-12-20 14:00:26 UTC
I've been running with 2.6.32 since its release, and the problem hasn't appeared since then.  Either it was fixed or something else changed and hid it.  Unsettling.  I'm considering going back to rc8 to be sure...  Meanwhile, you (Pascal) may want to test 2.6.32 if you didn't already.
Comment 6 bugs-kernel@spamgourmet.com 2009-12-27 22:14:02 UTC
On kernel 2.6.32.2, I see the same problems as described in comment #0.  I have hibernated four times:

- Try #1: hung after S|
- Try #2: worked normally
- Try #3: hung after S|
- Try #4: froze at "Snapshotting system"

As in comment #0, hangs after S| seem harmless, and the system resumes normally.  I previously ran 2.6.31.6, which always hibernated successfully.  I jumped straight from 2.6.31.6 to 2.6.32.2, without running any -rc kernels or the .0 or .1 releases of 2.6.32.  Since I am new here, a few system details:

- User distribution is a fairly current Gentoo "stable" amd64, though with "testing" sys-power/suspend-0.8-r1.
- No 3D or KMS.
- Kernel is pulled directly from git tags, in this case v2.6.32.2 and v2.6.31.6, respectively.  No distribution patches or out of tree modules.  The kernel is purpose-built, so the only module at all is kvm-intel.  Guests are sometimes open while hibernating.  Unfortunately, I did not keep good track of whether I always had a guest open when hibernating, so I am not sure that this is a deciding factor.  Full kernel .config is available if you want it.
- Hibernation is triggered via acpid reaction to power button, while the system is running X using xf86-video-radeonhd-1.3.0 on a single screen.
- Hibernation image is written to a swap partition.
- Hardware is a 3 month old desktop machine.  No wireless.  Hardware details available if you want them.

For now, I have gone back to 2.6.31.x to get reliable hibernation.  My usage pattern is essentially unchanged between kernels, as is my system state.  Despite running Gentoo, I do not update that frequently.  In particular, none of the hibernation-related packages (hibernate-script, sys-power/suspend) have changed since late October.  This is a personal machine, so I can reboot to test proposed fixes or add debug instrumentation.  I would prefer not to bisect into changes that appeared during the merge window.
Comment 7 Ferenc Wágner 2010-01-02 19:08:16 UTC
Interestingly, I still haven't experienced a single hibernation failure with 2.6.32 (.0), but noticed that sometimes unusual console output is produced during hibernation. I'm running with "suspend loglevel = 8" in uswsusp config and "CONFIG_PM_VERBOSE=y" in the kernel, so there's plenty of messages flashing away on my screen, but the shape of it reminds me of oom-killer messages (several of that). There's no trace of it in dmesg after resume, though the system always switches off and resumes correctly. The messages always appear after "Preparing the hibernation image" and before "saving the image" to disk. I'm contemplating adding some memory metrics logging to the pm-utils infrastructure, what kind would be most useful?

Meanwhile, might be useful if the previous commenter configured uswsusp with "suspend loglevel = 8" in case something emerges (in non-Gentoo speak). (Or some analogue feature of the used hibernation framework).
Comment 8 Rafael J. Wysocki 2010-01-02 20:03:03 UTC
First off, hanging after the S| may be a result of quite a few things, (1) failure to "suspend" devices in the poweroff phase, (2) failure to offline non-boot CPUs (my candidate), (3) failure to "suspend" one of the sysdevs (not likely), and (4) failure to execute one of the ACPI control methods.

If the problem is visible in the "shutdown" mode of hibernation, (4) may be ruled out, but the other possibilities are still to consider.

Second, the kernel messages printed after the system has been snapshotted are obviously not available after the resume, because they are not in the image.  To save them, you'd have to use netconsole or firescope (or something similar).

Dear author of comment #6, I suggest you try the current Linus' tree.

Ferenc, please try to increase PAGES_FOR_IO from 4 MB to 8 MB or 16 MB and see if that helps.
Comment 9 Ferenc Wágner 2010-01-06 21:02:47 UTC
As for (1): I'm suspicious of e100. I've got a screenshot with PM_VERBOSE, where hibernation stopped right after "e100: 0000:02:08.0: hibernate, may wakeup".
Is (2) really applicable to my single-core non-HT Celeron?

I've not no firewire either, but netconsole and ttyUSB will be possible as soon as I get proper control of my access point again.

I can increase PAGES_FOR_IO, but it'll be hard to tell whether it helps, as with the current setup I haven't got a single freeze yet! I'll go back to my previous kernel to see if it happens again.
Comment 10 bugs-kernel@spamgourmet.com 2010-01-12 03:48:43 UTC
To clarify, I use uswsusp for hibernation.  The machine is a quad core CPU, so SMP issues could apply.  For a NIC, I use a Realtek Semiconductor Co., Ltd. RTL8111/8168B PCI Express Gigabit Ethernet controller driven by r8169.

I added "suspend loglevel = 8" to /etc/suspend.conf, and have been running with it for a few days.  One hang after S| produced no useful output, because the console was suspended at the time of the hang.  I added no_console_suspend, and will continue trying to capture a hang.

In response to the request to try Linus' tree: are you asking that on general principle because his tree might have picked up a fix during the merge window, or is there some particular change or set of changes there that you think have a good chance of fixing the problem?
Comment 11 bugs-kernel@spamgourmet.com 2010-01-25 06:04:17 UTC
I caught another hang, and this time have some output that may be useful.  The system hung before it began writing the snapshot.  I saw several occurrences of the message "ACPI handle has no context!", then a long hang after it printed "PM: Saving platform NVS memory".  It stopped for a few minutes, then generated a backtrace.  Due to limited scrollback, I was not able to capture register contents, but I do have the callstack:

? _spin_unlock_irq+0x11/0x2a
schedule_timeout+0x35/0x1f1 [kernel/timer.c:1368]
? resched_task+0x4b/0x6b
wait_for_common+0xc2/0x12c
? default_wake_function+0x0/0xf
wait_for_completion+0x18/0x1a
kthread_create+0xa9/0x150
? worker_thread+0x0/0x1e6
? mutex_unlock+0x9/0xb
? __mutex_lock_slowpath+0x26d/0x293
create_workqueue_thread+0x47/0x7d [kernel/workqueue.c:796]
? _spin_lock+0x16/0x2e
__create_workqueue_key+0x17c/0x1d8 [kernel/workqueue.c:880]
stop_machine_create+0x34/0x95
disable_nonboot_cpus+0x16/0x11e
hibernation_snapshot+0x94/0x1b4
snapshot_ioctl+0x211/0x487
vfs_ioctl+0x2a/0x78
do_vfs_ioctl+0x42a/0x467
sys_ioctl+0x42/0x65

I tagged a few of the functions with the corresponding source file and line in v2.6.32.2.  I can look up others if there are any that are ambiguous.  The callstack had three additional lines after sys_ioctl that I did not record.

After a longer period, perhaps 10 minutes, the screen blanked.  I think this was the normal Linux behavior of blanking an idle console, which suggests the kernel was not completely hung.
Comment 12 Rafael J. Wysocki 2010-02-07 22:08:46 UTC
It looks like the patch from

http://patchwork.kernel.org/patch/77180/

may help here.  Can you test it, please?
Comment 13 Ferenc Wágner 2010-02-08 10:49:31 UTC
Despite the growing memory pressure (I haven't rebooted in a month or so and Firefox is leaking continuously) I'm yet to see even memory stats flying away on my screen during hibernation. So 2.6.32.0 is rock stable for me.  However, I'll switch back (today, really!) to my previous kernel, which exhibited the problem, and test it with and without your patch. It would be very useful if you could provide some hints how to trigger the error path your patch is supposed to fix.
Comment 14 Rafael J. Wysocki 2010-02-08 11:11:30 UTC
I personally was unable to trigger the issue, so I can't tell you any specific scenario.  For some people it was sufficient to hibernate-resume many (about 40) times in a row, though.
Comment 15 bugs-kernel@spamgourmet.com 2010-02-10 04:42:04 UTC
I have built a 2.6.32.7 kernel with the proposed patch included and switched to it.  I normally only hibernate once or twice a day, so if repetition is a factor, it could take a while before we have definitive results from my end.
Comment 16 Ferenc Wágner 2010-02-15 10:05:35 UTC
As soon as I switched back to 2.6.32-rc8, the freeze appeared, several times already in the last couple of days. 2.6.32.0 NEVER exhibited the freeze during more then a month. 2.6.32-rc8 always froze after printing "e100: 0000:02:08.0: hibernate, may wakeup". I'll apply your patch now, and at the same time instrument the e100 suspend routine (I'm in the dark here, so hints welcome).
The memory statistics sometimes appear with both kernels, but they seem disconnected with the freezes. I haven't changed PAGES_FOR_IO yet, should I add it to tonight's mix?

I tried provoking the freeze by locking large percentages of my RAM before hibernating, but didn't succeed. I'm open to ideas on this front as well.
Comment 17 bugs-kernel@spamgourmet.com 2010-02-16 04:08:17 UTC
I saw one hang with the proposed patch included, but unfortunately the console was suspended at the time, so no useful data was produced.  I am now on a 2.6.32.8 with the proposed patch, and no_console_suspend has been added to the Grub line to ensure that it is present in every boot.
Comment 18 Ferenc Wágner 2010-02-18 00:59:41 UTC
I managed to reproduce the issue a couple of times, and the e100 instrumentation pointed to napi_disable() in include/linux/netdevice.h. My freeze appears to be napi_disable() waiting "till any outstanding processing completes", which seemingly never happens (after all, we're in the middle of the final device hibernation round).

I hope this is something PM and netdev can start investigating. I'll see how reliably I can reproduce the freeze, but upping eth0 and locking 180 MB of memory before hibernation seemed to do it (there's 512 MB in this laptop).

Besides, it happened quite often between 2.6.32-rc5 and -rc8, but never with 2.6.32 final. If it turns out fairly reproducible under -rc8, I'll also try with newer kernels.
Comment 19 Rafael J. Wysocki 2010-02-18 19:14:50 UTC
If it's not reproducible with anything later than 2.6.32, I'd rather not spend time on debugging it.
Comment 20 Ferenc Wágner 2010-02-19 13:24:42 UTC
No, it isn't for me. I can reliably trigger it under 2.6.32-rc8, but it never happened under 2.6.32.0. So it isn't a problem for me anymore. But the other reporter had similar issues under 2.6.32.7, and r8169 may use napi_disable() similarly to e100, so it may be the same thing. To check this, I'd recommend:

--- a/include/linux/netdevice.h
+++ b/include/linux/netdevice.h
@@ -454,8 +454,11 @@ extern void napi_complete(struct napi_struct *n);
 static inline void napi_disable(struct napi_struct *n)
 {
        set_bit(NAPI_STATE_DISABLE, &n->state);
-       while (test_and_set_bit(NAPI_STATE_SCHED, &n->state))
+       while (test_and_set_bit(NAPI_STATE_SCHED, &n->state)) {
+               if (printk_ratelimit())
+                       printk(KERN_INFO "looping in napi_disable\n");
                msleep(1);
+       }
        clear_bit(NAPI_STATE_DISABLE, &n->state);
 }
 
By the way, after testing hibernation with something like the above patch, I triggered a freeze by Ctrl-Alt-Del as well: the messages started appearing when an init script stopped NetworkManager, and later the sendsigs init script got stuck fatally. I guess NetworkManager was trapped in an unkillable state and refused to die, but I couldn't check this.

I attach the program I used to reproduce the freeze, maybe it's usable for the other victims as well.  The recipe is (with 512 MB of memory):
1. sudo ip link set eth0 up
2. sudo press 8 256
This results in 6 successful hibernation cycles and a freeze on the 7th. I'm not sure whether sudo press 1 192 is capable of doing it in one shot.
Comment 21 Ferenc Wágner 2010-02-19 13:27:37 UTC
Created attachment 25114 [details]
e100 NAPI freeze during hibernation under 2.6.32-rc8
Comment 22 bugs-kernel@spamgourmet.com 2010-02-21 22:25:41 UTC
In reply to comment #19:

For me, it is intermittently reproducible with 2.6.32.2, 2.6.32.7, and 2.6.32.8.  I have not tried any other 2.6.32.* kernels.

Rafael, is the suggestion to try the current tip of Linus' tree based on work done for v2.6.33 that touches an affected code path or on the general hope that it is already fixed?
Comment 23 Rafael J. Wysocki 2010-02-21 22:29:44 UTC
Since I'm not sure if you both are seeing the same issue (probably not) and I have no idea which code path actually causes this thing to happen in your case, I'd like to know if the issue is present in 2.6.33-rc that contains a number of suspend/hibernate fixes.
Comment 24 bugs-kernel@spamgourmet.com 2010-02-26 03:19:43 UTC
In reply to comment #23:

I will switch to 2.6.33 as soon as possible and report back.
Comment 25 Rafael J. Wysocki 2010-02-26 20:13:17 UTC
Please try this patch too:

http://patchwork.kernel.org/patch/81830/
Comment 26 Ferenc Wágner 2010-03-02 14:36:06 UTC
(In reply to comment #23)
> Since I'm not sure if you both are seeing the same issue (probably not) [...]

I agree. Now that I found a way to reproduce my (past) issue, I bisected the commit which fixed it between 2.6.32-rc8 and 2.6.32.0: it's

commit 98468efddb101f8a29af974101c17ba513b07be1
Author: Roger Oksanen <roger.oksanen@cs.helsinki.fi>
Date:   Sun Nov 29 17:17:29 2009 -0800

    e100: Use pci pool to work around GFP_ATOMIC order 5 memory allocation failure
    
    pci_alloc_consistent uses GFP_ATOMIC allocation that may fail on some systems
    with limited memory (Bug #14265). pci_pool_alloc allows waiting with
    GFP_KERNEL.

I've read through the corresponding thread at http://thread.gmane.org/gmane.linux.drivers.e1000.devel/6070/focus=6093 , but it still isn't clear to me whether that patch fixes my issue (causing looping in napi_disable) for good or just hides it accidentally.  If the former, could you please spare a couple of minutes to educate me on the mechanism?  Thanks.
Comment 27 bugs-kernel@spamgourmet.com 2010-03-23 23:03:07 UTC
I have seen no failures on v2.6.33.1.  Though we never found the root cause for my failures, I am comfortable saying that it is fixed in v2.6.33.1.  I never tested v2.6.33, so it may have been fixed before the patch release.
Comment 28 Rafael J. Wysocki 2010-03-23 23:19:56 UTC
Thanks, closing.