kernel false positive warning while suspending (took more than 5secs)

[Philipp Dreimann]

linux-image-2.6.27-7-generic 2.6.27-7.12
fglrx 2:8.543-0ubuntu3

[...]
[ 1788.756273] PM: suspend devices took 5.420 seconds
[ 1788.756284] ------------[ cut here ]------------
[ 1788.756288] WARNING: at /build/buildd/linux-2.6.27/kernel/power/main.c:176 suspend_test_finish+0x75/0x80()
[ 1788.756292] Modules linked in: aes_x86_64 aes_generic af_packet sco bridge stp rfcomm bnep l2cap ppdev ipv6 acpi_cpufreq cpufreq_ondemand cpufreq_userspace cpufreq_conservative cpufreq_stats cpufreq_powersave freq_table wmi sbs container pci_slot sbshc iptable_filter ip_tables x_tables input_polldev tp_smapi thinkpad_ec uinput parport_pc lp parport btusb bluetooth arc4 ecb crypto_blkcipher pcmcia snd_hda_intel iwl3945 thinkpad_acpi snd_pcm_oss snd_mixer_oss iTCO_wdt rfkill psmouse mac80211 yenta_socket snd_pcm battery led_class iTCO_vendor_support serio_raw evdev pcspkr nvram rsrc_nonstatic pcmcia_core cfg80211 ac fglrx(P) snd_seq_dummy video output snd_seq_oss snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq snd_timer snd_seq_device snd soundcore button intel_agp snd_page_alloc shpchp pci_hotplug ext3 jbd mbcache sd_mod crc_t10dif sr_mod cdrom sg ata_generic pata_acpi ahci ata_piix libata uhci_hcd ehci_hcd scsi_mod usbcore dock thermal processor fan fbcon tileblit font bitblit softcursor fuse
[ 1788.756393] Pid: 9384, comm: pm-suspend Tainted: P W 2.6.27-7-generic #1
[ 1788.756395]
[ 1788.756396] Call Trace:
[ 1788.756401] [<ffffffff8024e9b4>] warn_on_slowpath+0x64/0x90
[ 1788.756406] [<ffffffff804fffb6>] ? printk+0x6c/0x6e
[ 1788.756410] [<ffffffff803a3fb7>] ? kobject_put+0x27/0x60
[ 1788.756412] [<ffffffff80501059>] ? mutex_unlock+0x9/0x20
[ 1788.756416] [<ffffffff80434c86>] ? dpm_suspend+0x136/0x150
[ 1788.756419] [<ffffffff8027e1a5>] suspend_test_finish+0x75/0x80
[ 1788.756421] [<ffffffff8027e23c>] suspend_devices_and_enter+0x8c/0x1b0
[ 1788.756423] [<ffffffff8027e571>] enter_state+0xe1/0x110
[ 1788.756425] [<ffffffff8027e65a>] state_store+0xba/0x100
[ 1788.756427] [<ffffffff803a3e57>] kobj_attr_store+0x17/0x20
[ 1788.756431] [<ffffffff803495fa>] sysfs_write_file+0xca/0x140
[ 1788.756434] [<ffffffff802e9e9b>] vfs_write+0xcb/0x130
[ 1788.756436] [<ffffffff802e9ff5>] sys_write+0x55/0x90
[ 1788.756441] [<ffffffff8021285a>] system_call_fastpath+0x16/0x1b
[ 1788.756442]
[ 1788.756443] ---[ end trace b1910bf5ce790e97 ]---
[...]

[Leann Ogasawara (leannogasawara)]

Hi Philipp,

I just want to ask a few additional questions. Are you able to resume from suspend successfully? Does this warning appear every time you attempt to suspend? Thanks.

[Philipp Dreimann (philipp-dreimann-deactivatedaccount)]

The warning seems to appear every time I resume my computer. I had no unsuccessful attempt where I saw this warning.

[Leann Ogasawara (leannogasawara)]

Thanks Philipp,

Just so I can gather some additional information about your system, per the kernel team's bug policy, can you please attach the following information. Please be sure to attach each file as a separate attachment.

* cat /proc/version_signature > version.log
* dmesg > dmesg.log
* sudo lspci -vvnn > lspci-vvnn.log

It would be best if you could capture the dmesg output after you resume from suspend. For more information regarding the kernel team bug policy, please refer to https://wiki.ubuntu.com/KernelTeamBugPolicies . Thanks again and we appreciate your help and feedback.

[Thomas Novin (thomasn80)]

I got the same bug. After resuming from suspend system worked for maybe 20-30 seconds, then it froze completely. Not even REISUB worked, had to kill power.

[Thomas Novin (thomasn80)]

There is also bug #286672 but they got this problem after installing kerneloops. Same error message though..

[Leann Ogasawara (leannogasawara)]

Hi Thomas,

I think you actually have a different bug than Philipp and should open a new report. The reason I say this is the warning you see is just that, a warning. It's indicating that it took longer to resume the devices than anticipated. Philipp mentioned he sees no other ill effects whereas you mention your system freezes so I suspect even though you may be seeing the same warning you likely have separate issues. I'd assume when Philipp posts the above requested information that it will show he has different hardware than you (via the lspci output). So for now if you can open a separate bug report that would be great. We can always mark bugs as duplicates later on if necessary. Thanks.

[Mark Grandi (markgrandi)]

I get the same warming when i try to suspend. Everything works fine when i suspend/resume, EXCEPT my wireless card. That refuses to work when i resume my computer

[moose (snyderra)]

I am getting something similar. suspend/resume works every time so far. just the warnings pop up saying it failed. different call trace than Philipp.

Nov 22 07:33:50 redyns kernel: [41996.449490] ------------[ cut here ]------------
Nov 22 07:33:50 redyns kernel: [41996.449492] WARNING: at /build/buildd/linux-2.6.27/kernel/power/main.c:176 suspend_test_finish+0x74/0x80()
Nov 22 07:33:50 redyns kernel: [41996.449494] Modules linked in: nls_iso8859_1 nls_cp437 vfat fat usblp usb_storage libusual ipv6 af_packet binfmt_misc sco bridge stp rfcomm bnep l2cap bluetooth vboxdrv ppdev powernow_k8 cpufreq_ondemand cpufreq_conservative cpufreq_userspace cpufreq_powersave cpufreq_stats freq_table video output container sbs sbshc wmi pci_slot battery iptable_filter ip_tables x_tables dm_crypt crypto_blkcipher dm_mod ac parport_pc lp parport snd_hda_intel snd_pcm_oss snd_mixer_oss snd_pcm snd_seq_dummy snd_seq_oss snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq snd_timer snd_seq_device psmouse evdev snd nvidia(P) soundcore i2c_nforce2 serio_raw snd_page_alloc pcspkr agpgart button k8temp i2c_core ext3 jbd mbcache sr_mod cdrom sd_mod crc_t10dif sg usbhid hid pata_amd ata_generic pata_acpi sata_nv libata scsi_mod dock ehci_hcd ohci_hcd usbcore thermal processor fan fbcon tileblit font bitblit softcursor fuse [last unloaded: forcedeth]
Nov 22 07:33:50 redyns kernel: [41996.449538] Pid: 18946, comm: pm-suspend Tainted: P W 2.6.27-7-generic #1
Nov 22 07:33:50 redyns kernel: [41996.449541] [<c037c406>] ? printk+0x1d/0x1f
Nov 22 07:33:50 redyns kernel: [41996.449546] [<c0131de9>] warn_on_slowpath+0x59/0x90
Nov 22 07:33:50 redyns kernel: [41996.449550] [<c014d255>] ? sched_clock_cpu+0xd5/0x170
Nov 22 07:33:50 redyns kernel: [41996.449554] [<c014c0af>] ? down_trylock+0x2f/0x40
Nov 22 07:33:50 redyns kernel: [41996.449557] [<c01324c2>] ? try_acquire_console_sem+0x12/0x40
Nov 22 07:33:50 redyns kernel: [41996.449561] [<c0105003>] ? common_interrupt+0x23/0x30
Nov 22 07:33:50 redyns kernel: [41996.449564] [<c024e580>] ? kobject_put+0x20/0x50
Nov 22 07:33:50 redyns kernel: [41996.449568] [<c015d204>] suspend_test_finish+0x74/0x80
Nov 22 07:33:50 redyns kernel: [41996.449570] [<c015d2f6>] suspend_devices_and_enter+0xe6/0x190
Nov 22 07:33:50 redyns kernel: [41996.449574] [<c015d571>] enter_state+0xd1/0x100
Nov 22 07:33:50 redyns kernel: [41996.449576] [<c015d625>] state_store+0x85/0xd0
Nov 22 07:33:50 redyns kernel: [41996.449577] [<c015d5a0>] ? state_store+0x0/0xd0
Nov 22 07:33:50 redyns kernel: [41996.449580] [<c024e444>] kobj_attr_store+0x24/0x30
Nov 22 07:33:50 redyns kernel: [41996.449582] [<c01ff4c7>] sysfs_write_file+0x97/0x100
Nov 22 07:33:50 redyns kernel: [41996.449585] [<c01b24c0>] vfs_write+0xa0/0x110
Nov 22 07:33:50 redyns kernel: [41996.449588] [<c01ff430>] ? sysfs_write_file+0x0/0x100
Nov 22 07:33:50 redyns kernel: [41996.449590] [<c01b2602>] sys_write+0x42/0x70
Nov 22 07:33:50 redyns kernel: [41996.449593] [<c0103f7b>] sysenter_do_call+0x12/0x2f
Nov 22 07:33:50 redyns kernel: [41996.449595] =======================
Nov 22 07:33:50 redyns kernel: [41996.449597] ---[ end trace b56c53bce9ccb7db ]---

[Jonas Petersson (catellie)]

As reported in bug #298541 I experience the same problem and also find it relatively harmless except for that the battery and network applets get more and duplicate entries as a keep suspending/resuming (but not every time).

I noticed something interesting: When the latest kernel was installed (through synaptics) the install process somehow removed all the dups. Does this indicate that this is a HAL problem?

BTW: After the upgrade to 2.6.27-10-generic yesterday I have been though 2 cycles and neither of them produced dups (proves nothing really since it only happens sometimes) nor the above message (which is more promising, but could still just be luck).

Best / Jonas

[DaveAbrahams (boostpro)]

I'm getting the same warning. Why is this bug still marked INCOMPLETE?

[Leann Ogasawara (leannogasawara)]

Hi Guys,

Can you test the most recent pre-release of Jaunty 9.04 (currently Alpha3) - http://cdimage.ubuntu.com/releases/jaunty/ . You should be able to test suspend via a LiveCD. Jaunty contains a newer 2.6.28 based kernel. It would be good to know if you still see this warning. Thanks.

[Jonas Petersson (catellie)]

Followup from my earlier comment: 2.6.27-10-generic continued being OK for me and
2.6.27-11-generic has been OK too. Not tried Jaunty yet, but it sure looks hopeful.

Best / Jonas

[TJ (tj)]

This appears to be caused by bug #331415 "request_firmware() fails on resume from suspend" but I need to know what device drivers might be requesting firmware.

Please attach /var/log/kern.log that contains the Oops message - it should also contain clues as to which driver was delayed.

If the logs confirm it I'll mark this as a duplicate of that bug.

[Mark Grandi (markgrandi)]

Im actually not running ubuntu at the moment, rather arch (on the laptop that i had this problem on originally)....i tried recreating the error message but its not coming up, im not sure if its been fixed or its just a different kernel....since intrepid doesn't even work on this laptop (video drivers dont work so X doesn't start, and jaunty doesnt install cause the installer crashes) so it would be nice if someone else could provide the logs...

[Jacob Torrey (ranok)]

I have this problem, but a few seconds later I get a kernel oops. I'm not sure where exactly where to make this comment, but I've attached the relevant portions of my kernel log, and output of lspci and cpuinfo

[Jacob Torrey (ranok)]

Uname -a: Linux catty 2.6.27-11-generic #1 SMP Thu Jan 29 19:28:32 UTC 2009 x86_64 GNU/Linux

Attached is my cpuinfo

[Jacob Torrey (ranok)]

And lspci

[TJ (tj)]

Jacob, your problem looks unrelated to this bug and more serious.

Please create a new bug report "BUG: scheduling while atomic: notification-da/10006/0x10000001" against the "linux" package, attach the same logs you've attached here (maybe delete the attachments from this report to save confusion) and subscribe me directly to the new bug report. Please describe the scenario that causes it and whether it makes the system unstable.

Make sure to report the kernel version affected using "uname -a" and "lsb_release -a".

[Jacob Torrey (ranok)]

Ok, I created a new bug #335429, but I'm not sure how to delete comments/attachments. Thanks for the advice.

[TJ (tj)]

If you are experiencing this issue (kernel reporting a slow resume - more than 5 seconds) there are several potential causes, at least two of which are expected (1 & 2) and the warning is something of a false positive.

1. Several devices pushing the resume time slightly beyond the arbitrary 5-second boundary
2. Hard disks taking some time to become ready - see bug #318978
3. Device(s) requesting a firmware file to be loaded whilst user-space is still frozen (the delay will be around 60 seconds in this case) - see bug #331415
4. Some device or driver suffering specific problems with resume.

To determine if the warnings you see are 'real' problems please run this small shell script and copy the results to a comment here.

for log in /var/log/kern.log*; do CMD="cat "; echo $log; [ ! ${log##*.gz} ] && CMD="zcat "; $CMD $log | grep -n 'PM: suspend devices took'; done

Example output:

/var/log/kern.log
/var/log/kern.log.0
3678:Feb 19 06:06:56 hephaestion kernel: [60285.296215] PM: suspend devices took 3.752 seconds
3948:Feb 19 10:19:23 hephaestion kernel: [75478.752211] PM: suspend devices took 3.752 seconds
/var/log/kern.log.1.gz
/var/log/kern.log.2.gz
/var/log/kern.log.3.gz

Basically, if you see a resume time close to but just over 5 seconds, it is likely there is no real problem - it's just the kernel taking a lets-be-cautious approach, e.g.:

PM: resume devices took 5.148 seconds

If there are no other kernel Oops messages besides the suspend_test_finish() then you can safely ignore the warning.

[TJ (tj)]

Trust me to provide an incorrect shell script! I omitted to test for the "resume" as well as "suspend" action!

Please use this shell script instead:

for log in /var/log/kern.log*; do CMD="cat "; echo $log; [ ! ${log##*.gz} ] && CMD="zcat "; $CMD $log | grep -n 'PM: \(suspend\|resume\) devices took'; done

Example output:

var/log/kern.log
/var/log/kern.log.0
3678:Feb 19 06:06:56 hephaestion kernel: [60285.296215] PM: suspend devices took 3.752 seconds
3830:Feb 19 06:06:57 hephaestion kernel: [60354.780958] PM: resume devices took 69.072 seconds
3948:Feb 19 10:19:23 hephaestion kernel: [75478.752211] PM: suspend devices took 3.752 seconds
4102:Feb 19 10:19:23 hephaestion kernel: [75488.172580] PM: resume devices took 9.024 seconds
/var/log/kern.log.1.gz
/var/log/kern.log.2.gz
/var/log/kern.log.3.gz

The resume of 69 seconds shows this system is affected by bug #331415

[TJ (tj)]

Philipp's original report says:

PM: suspend devices took 5.420 seconds

This means that the arbitrary 5-second boundary set in TEST_SUSPEND_SECONDS is triggering what looks to be a false positive report.

We're discussing increasing this value to avoid many of these false positives.

[Andres Mujica (andres.mujica)]

added some dupes from this bug report here.

[Anton Samets (bock-bynets)]

I just compiled by myself new kernel
Linux wax 2.6.29.3-wax-1 #1 SMP Sun May 10 00:19:48 EEST 2009 x86_64 GNU/Linux

I my case was: after suspend computer wake-uped immediately and no working sound on my Multimedia audio controller: Creative Labs CA0106 Soundblaster

Log of old dmesg (then wake-up always after suspend): http://paste.org.ru/?bpa652
and new: http://paste.org.ru/?mtsutp

[Anton Samets (bock-bynets)]

Ouch, forgot: bad case was in kernels:
Ubuntu 9.04, kernel 2.6.28-12-generic
Ubuntu 9.04, kernel 2.6.28-11-generic