WARNING: at kernel/power/main.c:176 suspend_test_finish+0x70/0x80()

WARNING: at kernel/power/main.c:176 suspend_test_finish+0x70/0x80()

[Parag Warudkar]

2.6.27 seems to be taking long time to resume, it hits this WARN_ON in
kernel/power/main.c:176 suspend_test_finish -
Never seen earlier.

[  295.600086] PM: resume devices took 10.180 seconds
[  295.600091] ------------[ cut here ]------------
[  295.600092] WARNING: at kernel/power/main.c:176
suspend_test_finish+0x70/0x80()
[  295.600094] Modules linked in: i2c_i801 i2c_core nls_iso8859_1
nls_cp437 vfat fat isofs udf af_packet binfmt_misc ipv6 sco bnep
rfcomm l2cap bluetooth ipt_MASQUERADE iptable_nat nf_nat
nf_conntrack_ipv4 xt_state nf_conntrack ipt_REJECT xt_tcpudp bridge
stp llc kvm_intel kvm ppdev acpi_cpufreq cpufreq_conservative
cpufreq_ondemand cpufreq_stats freq_table cpufreq_userspace
cpufreq_powersave wmi video output pci_slot container battery
iptable_filter ip_tables x_tables ac firewire_sbp2 lp snd_hda_intel
snd_pcm_oss snd_mixer_oss snd_pcm snd_seq_dummy snd_seq_oss
snd_seq_midi serio_raw snd_rawmidi evdev dm_multipath psmouse pcspkr
scsi_dh snd_seq_midi_event snd_seq snd_timer snd_seq_device
appledisplay snd parport_serial parport_pc soundcore parport shpchp
snd_page_alloc pci_hotplug button iTCO_wdt iTCO_vendor_support
intel_agp sd_mod sr_mod crc_t10dif cdrom usb_storage usbhid libusual
hid sg firewire_ohci firewire_core crc_itu_t ahci libata scsi_mod dock
ehci_hcd uhci_hcd usbcore e1000e dm_mirror dm_log dm_snapshot dm_mod
thermal processor fan fuse
[  295.600141] Pid: 7470, comm: pm-suspend Not tainted 2.6.27 #2
[  295.600142]
[  295.600142] Call Trace:
[  295.600147]  [<ffffffff802471ff>] warn_on_slowpath+0x5f/0x90
[  295.600150]  [<ffffffff804be7de>] ? printk+0x67/0x69
[  295.600164]  [<ffffffffa006fc10>] ? usb_autopm_do_device+0xc0/0x110 [usbcore]
[  295.600166]  [<ffffffff80377307>] ? kobject_put+0x27/0x60
[  295.600169]  [<ffffffff803f95c5>] ? put_device+0x15/0x20
[  295.600172]  [<ffffffff804017ba>] ? device_resume+0x39a/0x460
[  295.600174]  [<ffffffff802742e0>] suspend_test_finish+0x70/0x80
[  295.600176]  [<ffffffff802743d4>] suspend_devices_and_enter+0xe4/0x200
[  295.600178]  [<ffffffff80274666>] enter_state+0x146/0x1d0
[  295.600180]  [<ffffffff802747aa>] state_store+0xba/0x100
[  295.600181]  [<ffffffff803771c7>] kobj_attr_store+0x17/0x20
[  295.600184]  [<ffffffff80326475>] sysfs_write_file+0xc5/0x140
[  295.600186]  [<ffffffff802cd14b>] vfs_write+0xcb/0x190
[  295.600188]  [<ffffffff802cd300>] sys_write+0x50/0x90
[  295.600191]  [<ffffffff8021168a>] system_call_fastpath+0x16/0x1b
[  295.600192]
[  295.600193] ---[ end trace 8a154931a4b75ee4 ]---
[  295.600333] PM: Finishing wakeup.

Re: WARNING: at kernel/power/main.c:176 suspend_test_finish+0x70/0x80()

[Rafael J. Wysocki]

On Friday, 10 of October 2008, Parag Warudkar wrote:
> 2.6.27 seems to be taking long time to resume, it hits this WARN_ON in
> kernel/power/main.c:176 suspend_test_finish -
> Never seen earlier.

Resuming devices takes too much time (more than 5 sec. actually)
and the stack trace indicates USB.

Can you test with the USB modules unloaded?


> [  295.600086] PM: resume devices took 10.180 seconds
> [  295.600091] ------------[ cut here ]------------
> [  295.600092] WARNING: at kernel/power/main.c:176
> suspend_test_finish+0x70/0x80()
> [  295.600094] Modules linked in: i2c_i801 i2c_core nls_iso8859_1
> nls_cp437 vfat fat isofs udf af_packet binfmt_misc ipv6 sco bnep
> rfcomm l2cap bluetooth ipt_MASQUERADE iptable_nat nf_nat
> nf_conntrack_ipv4 xt_state nf_conntrack ipt_REJECT xt_tcpudp bridge
> stp llc kvm_intel kvm ppdev acpi_cpufreq cpufreq_conservative
> cpufreq_ondemand cpufreq_stats freq_table cpufreq_userspace
> cpufreq_powersave wmi video output pci_slot container battery
> iptable_filter ip_tables x_tables ac firewire_sbp2 lp snd_hda_intel
> snd_pcm_oss snd_mixer_oss snd_pcm snd_seq_dummy snd_seq_oss
> snd_seq_midi serio_raw snd_rawmidi evdev dm_multipath psmouse pcspkr
> scsi_dh snd_seq_midi_event snd_seq snd_timer snd_seq_device
> appledisplay snd parport_serial parport_pc soundcore parport shpchp
> snd_page_alloc pci_hotplug button iTCO_wdt iTCO_vendor_support
> intel_agp sd_mod sr_mod crc_t10dif cdrom usb_storage usbhid libusual
> hid sg firewire_ohci firewire_core crc_itu_t ahci libata scsi_mod dock
> ehci_hcd uhci_hcd usbcore e1000e dm_mirror dm_log dm_snapshot dm_mod
> thermal processor fan fuse
> [  295.600141] Pid: 7470, comm: pm-suspend Not tainted 2.6.27 #2
> [  295.600142]
> [  295.600142] Call Trace:
> [  295.600147]  [<ffffffff802471ff>] warn_on_slowpath+0x5f/0x90
> [  295.600150]  [<ffffffff804be7de>] ? printk+0x67/0x69
> [  295.600164]  [<ffffffffa006fc10>] ? usb_autopm_do_device+0xc0/0x110 [usbcore]
> [  295.600166]  [<ffffffff80377307>] ? kobject_put+0x27/0x60
> [  295.600169]  [<ffffffff803f95c5>] ? put_device+0x15/0x20
> [  295.600172]  [<ffffffff804017ba>] ? device_resume+0x39a/0x460
> [  295.600174]  [<ffffffff802742e0>] suspend_test_finish+0x70/0x80
> [  295.600176]  [<ffffffff802743d4>] suspend_devices_and_enter+0xe4/0x200
> [  295.600178]  [<ffffffff80274666>] enter_state+0x146/0x1d0
> [  295.600180]  [<ffffffff802747aa>] state_store+0xba/0x100
> [  295.600181]  [<ffffffff803771c7>] kobj_attr_store+0x17/0x20
> [  295.600184]  [<ffffffff80326475>] sysfs_write_file+0xc5/0x140
> [  295.600186]  [<ffffffff802cd14b>] vfs_write+0xcb/0x190
> [  295.600188]  [<ffffffff802cd300>] sys_write+0x50/0x90
> [  295.600191]  [<ffffffff8021168a>] system_call_fastpath+0x16/0x1b
> [  295.600192]
> [  295.600193] ---[ end trace 8a154931a4b75ee4 ]---
> [  295.600333] PM: Finishing wakeup.
> 
> 

Re: [linux-pm] WARNING: at kernel/power/main.c:176 suspend_test_finish+0x70/0x80()

[Alan Stern]

On Fri, 10 Oct 2008, Rafael J. Wysocki wrote:

> On Friday, 10 of October 2008, Parag Warudkar wrote:
> > 2.6.27 seems to be taking long time to resume, it hits this WARN_ON in
> > kernel/power/main.c:176 suspend_test_finish -
> > Never seen earlier.
> 
> Resuming devices takes too much time (more than 5 sec. actually)
> and the stack trace indicates USB.
> 
> Can you test with the USB modules unloaded?

There's a bug that affects USB power management: commmit 
f9dd45ce10a014bdfd5432828c44630ea7fefedd needs to be reverted.  Greg KH
has been asked to do this a few times but he hasn't gotten around to it 
yet.

Alan Stern

Re: [linux-pm] WARNING: at kernel/power/main.c:176 suspend_test_finish+0x70/0x80()

[Parag Warudkar]

On Fri, Oct 10, 2008 at 10:31 AM, Alan Stern <stern@rowland.harvard.edu> wrote:

> There's a bug that affects USB power management: commmit
> f9dd45ce10a014bdfd5432828c44630ea7fefedd needs to be reverted.  Greg KH
> has been asked to do this a few times but he hasn't gotten around to it
> yet.

Hi Alan,

Thanks for the info.

I can't seem to find that commit in mainline. If you have pointer to
the patch I will submit a revert.

Parag

Re: [linux-pm] WARNING: at kernel/power/main.c:176 suspend_test_finish+0x70/0x80()

[Alan Stern]

On Fri, 10 Oct 2008, Parag Warudkar wrote:

> On Fri, Oct 10, 2008 at 10:31 AM, Alan Stern <stern@rowland.harvard.edu> wrote:
> 
> > There's a bug that affects USB power management: commmit
> > f9dd45ce10a014bdfd5432828c44630ea7fefedd needs to be reverted.  Greg KH
> > has been asked to do this a few times but he hasn't gotten around to it
> > yet.
> 
> Hi Alan,
> 
> Thanks for the info.
> 
> I can't seem to find that commit in mainline. If you have pointer to
> the patch I will submit a revert.

It isn't in mainline; it's in linux-next.  Sorry, I wasn't sure which 
kernel you were using.

Alan Stern

Re: [linux-pm] WARNING: at kernel/power/main.c:176 suspend_test_finish+0x70/0x80()

[Rafael J. Wysocki]

On Friday, 10 of October 2008, Alan Stern wrote:
> On Fri, 10 Oct 2008, Parag Warudkar wrote:
> 
> > On Fri, Oct 10, 2008 at 10:31 AM, Alan Stern <stern@rowland.harvard.edu> wrote:
> > 
> > > There's a bug that affects USB power management: commmit
> > > f9dd45ce10a014bdfd5432828c44630ea7fefedd needs to be reverted.  Greg KH
> > > has been asked to do this a few times but he hasn't gotten around to it
> > > yet.
> > 
> > Hi Alan,
> > 
> > Thanks for the info.
> > 
> > I can't seem to find that commit in mainline. If you have pointer to
> > the patch I will submit a revert.
> 
> It isn't in mainline; it's in linux-next.  Sorry, I wasn't sure which 
> kernel you were using.

I understood it was the mainline from the report.

Parag, could you please try to suspend without the USB drivers and see if the
delay is still there?

Thanks,
Rafael

Re: [linux-pm] WARNING: at kernel/power/main.c:176 suspend_test_finish+0x70/0x80()

[Alan Stern]

On Fri, 10 Oct 2008, Rafael J. Wysocki wrote:

> I understood it was the mainline from the report.
> 
> Parag, could you please try to suspend without the USB drivers and see if the
> delay is still there?

Or even better, suspend with the USB drivers present, and with
CONFIG_USB_DEBUG, CONFIG_PM_SLEEP, and CONFIG_PRINTK_TIME all enabled.  
The resulting detailed timing information should pinpoint the problem.

Alan Stern

Re: [linux-pm] WARNING: at kernel/power/main.c:176 suspend_test_finish+0x70/0x80()

[Parag Warudkar]

On Fri, Oct 10, 2008 at 3:34 PM, Rafael J. Wysocki <rjw@sisk.pl> wrote:

>> It isn't in mainline; it's in linux-next.  Sorry, I wasn't sure which
>> kernel you were using.
>
> I understood it was the mainline from the report.
>
> Parag, could you please try to suspend without the USB drivers and see if the
> delay is still there?
>
Hi Rafael,

I did and it still does it of course with different stack trace -

[ 3929.502328] Pid: 8069, comm: pm-suspend Not tainted 2.6.27 #3
[ 3929.502329] Call Trace:
[ 3929.502334]  [<ffffffff8024721f>] warn_on_slowpath+0x5f/0x90
[ 3929.502337]  [<ffffffff804beb2e>] ? printk+0x67/0x69
[ 3929.502340]  [<ffffffff80377437>] ? kobject_put+0x27/0x60
[ 3929.502343]  [<ffffffff803f9905>] ? put_device+0x15/0x20
[ 3929.502345]  [<ffffffff80401afa>] ? device_resume+0x39a/0x460
[ 3929.502347]  [<ffffffff80274300>] suspend_test_finish+0x70/0x80
[ 3929.502349]  [<ffffffff802743f4>] suspend_devices_and_enter+0xe4/0x200
[ 3929.502351]  [<ffffffff80274686>] enter_state+0x146/0x1d0
[ 3929.502353]  [<ffffffff802747ca>] state_store+0xba/0x100
[ 3929.502354]  [<ffffffff803772f7>] kobj_attr_store+0x17/0x20
[ 3929.502357]  [<ffffffff803265a5>] sysfs_write_file+0xc5/0x140
[ 3929.502360]  [<ffffffff802cd18b>] vfs_write+0xcb/0x190
[ 3929.502362]  [<ffffffff802cd340>] sys_write+0x50/0x90
[ 3929.502365]  [<ffffffff8021163a>] system_call_fastpath+0x16/0x1b
[ 3929.502366] ---[ end trace 16538c71b37f9061 ]---
[ 3929.502557] PM: Finishing wakeup.
[ 3929.502558] Restarting tasks ... done.

Thanks
Parag

Re: [linux-pm] WARNING: at kernel/power/main.c:176 suspend_test_finish+0x70/0x80()

[Parag Warudkar]

On Fri, Oct 10, 2008 at 3:44 PM, Alan Stern <stern@rowland.harvard.edu> wrote:

> Or even better, suspend with the USB drivers present, and with
> CONFIG_USB_DEBUG, CONFIG_PM_SLEEP, and CONFIG_PRINTK_TIME all enabled.
> The resulting detailed timing information should pinpoint the problem.

As of now it is reproducible without USB modules loaded. But any way
will try this over weekend.

Parag