Bug 29482

Summary:	Warning at suspend_test_finish
Product:	Drivers	Reporter:	Seth Arnold (seth.arnold+kernelbugzilla)
Component:	Other	Assignee:	drivers_other
Status:	RESOLVED INVALID
Severity:	normal	CC:	rjw
Priority:	P1
Hardware:	x86-64
OS:	Linux
Kernel Version:	2.6.38-rc5	Subsystem:
Regression:	Yes	Bisected commit-id:
Bug Depends on:
Bug Blocks:	7216
Attachments:	initial dmesg output dmesg with initcall_debug

Description Seth Arnold 2011-02-19 23:10:18 UTC

Created attachment 48442 [details]
initial dmesg output

When resuming from suspend-to-ram, I get a single blinking cursor in the upper left corner of my monitor for roughly a minute (it looks like a framebuffer console, not 80x25 console). After the minute is up, X11 returns and I have this warning in dmesg. I have attached the dmesg during suspend/resume.

[43422.427702] PM: resume of devices complete after 60806.888 msecs
[43422.427826] PM: resume devices took 60.810 seconds
[43422.427827] ------------[ cut here ]------------
[43422.427831] WARNING: at /home/kernel-ppa/COD/linux/kernel/power/suspend_test.c:53 suspend_test_finish+0x89/0x90()
[43422.427833] Hardware name: EX58-UD5
[43422.427833] Component: resume devices, time: 60810
[43422.427834] Modules linked in: ip6table_filter ip6_tables ipt_MASQUERADE binfmt_misc iptable_nat nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack ipt_REJECT xt_tcpudp iptable_filter ip_tables x_tables bridge stp kvm_intel kvm parport_pc ppdev radeon snd_hda_codec_hdmi snd_hda_codec_realtek ttm drm_kms_helper drm snd_hda_intel snd_hda_codec i2c_algo_bit snd_hwdep snd_pcm snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq snd_timer snd_seq_device snd i7core_edac edac_core soundcore snd_page_alloc serio_raw lp parport hid_apple usbhid firewire_ohci firewire_core ahci hid r8169 libahci crc_itu_t pata_jmicron
[43422.427855] Pid: 4408, comm: pm-suspend Not tainted 2.6.38-020638rc4-generic #201102081010
[43422.427857] Call Trace:
[43422.427859]  [<ffffffff810a41c9>] ? suspend_test_finish+0x89/0x90
[43422.427862]  [<ffffffff810a41c9>] ? suspend_test_finish+0x89/0x90
[43422.427865]  [<ffffffff810642a0>] ? warn_slowpath_common+0x90/0xc0
[43422.427867]  [<ffffffff810643ce>] ? warn_slowpath_fmt+0x6e/0x70
[43422.427870]  [<ffffffff81037d59>] ? default_spin_lock_flags+0x9/0x10
[43422.427873]  [<ffffffff812cc837>] ? kobject_put+0x27/0x60
[43422.427875]  [<ffffffff813a0687>] ? put_device+0x17/0x20
[43422.427878]  [<ffffffff813aa262>] ? dpm_complete+0x112/0x120
[43422.427880]  [<ffffffff810a41c9>] ? suspend_test_finish+0x89/0x90
[43422.427883]  [<ffffffff810a3f51>] ? suspend_devices_and_enter+0xb1/0x160
[43422.427885]  [<ffffffff810a40e1>] ? enter_state+0xe1/0xf0
[43422.427887]  [<ffffffff810a34a4>] ? state_store+0xb4/0xf0
[43422.427889]  [<ffffffff812cc597>] ? kobj_attr_store+0x17/0x20
[43422.427891]  [<ffffffff811cc26f>] ? flush_write_buffer+0x5f/0x90
[43422.427893]  [<ffffffff811cc6a6>] ? sysfs_write_file+0x66/0xa0
[43422.427896]  [<ffffffff8115ea6c>] ? vfs_write+0xcc/0x180
[43422.427897]  [<ffffffff8115f0c5>] ? sys_write+0x55/0x90
[43422.427899]  [<ffffffff8100c002>] ? system_call_fastpath+0x16/0x1b
[43422.427901] ---[ end trace d273af22dde85b81 ]---
[43422.427929] PM: Finishing wakeup.

I did not see this problem when running Ubuntu 9.04, 10.04, or 10.10 kernels. It only started after moving to mainline kernels for other debugging. I used pre-compiled packages: http://kernel.ubuntu.com/~kernel-ppa/mainline/v2.6.38-rc4-natty/

I run x86-64.

Thanks!

Comment 1 Rafael J. Wysocki 2011-02-20 00:12:17 UTC

The warning only means that resume takes more time than it probably
should.  If you want it to go away, please unset
CONFIG_PM_TEST_SUSPEND in your kernel .config.

However, it shows that the resume of devices on your system took about
1 minute, which is really too much (should be about 5 sec.).

Probably one of the device drivers takes much time to resume and you can
figure out which one by booting with initcall_debug in the kernel command
line and checking dmesg output after a suspend/resume cycle.

Comment 2 Seth Arnold 2011-02-20 01:23:30 UTC

Created attachment 48472 [details]
dmesg with initcall_debug

Comment 3 Seth Arnold 2011-02-20 01:29:40 UTC

Thanks Rafael!

Yes, five seconds is about how long it used to take to resume before upgrading. (Still takes around sixty seconds with -rc5 as well, so version number updated.)

Comment 4 Seth Arnold 2011-02-20 02:31:16 UTC

Rafael, thanks to your suggestion, I found that the problem was due to missing RTL8169 firmware: http://kerneltrap.org/mailarchive/linux-netdev/2011/1/4/6292795

Simply copying the correct firmware from dwmw2's linux-firmware git repository into /lib/firmware/ fixed the problem!

dwmw2's repository information: http://lwn.net/Articles/294308/

I'm closing this with INVALID just because it appears all the code is there, it just needed firmware files. Reasonable enough.

Thanks!