Bug 23182

Summary:	Endless and reasonless kernel complain at __pm_runtime_resume()
Product:	Power Management	Reporter:	Ivan Baidakou (the.dmol)
Component:	Other	Assignee:	Rafael J. Wysocki (rjw)
Status:	CLOSED CODE_FIX
Severity:	normal	CC:	Drumm3R, florian, jason.vas.dias, rjw
Priority:	P1
Hardware:	All
OS:	Linux
Kernel Version:	2.6.36	Subsystem:
Regression:	No	Bisected commit-id:
Bug Depends on:
Bug Blocks:	7216
Attachments:	config patch against v2.6.36.2 drivers/base/power/runtime.c

Description Ivan Baidakou 2010-11-18 10:32:37 UTC

I do boot up my linux box (please note, I do not resume) and I see the following:

Nov 18 11:53:51 localhost kernel: ehci_hcd 0000:00:13.2: EHCI Host Controller
Nov 18 11:53:51 localhost kernel: ehci_hcd 0000:00:13.2: new USB bus registered, assigned bus number 2
Nov 18 11:53:51 localhost kernel: ehci_hcd 0000:00:13.2: debug port 1
Nov 18 11:53:51 localhost kernel: ehci_hcd 0000:00:13.2: irq 17, io mem 0xdc606400
Nov 18 11:53:51 localhost kernel: ehci_hcd 0000:00:13.2: USB 2.0 started, EHCI 1.00
Nov 18 11:53:51 localhost kernel: PM: Adding info for usb:usb2
Nov 18 11:53:51 localhost kernel: PM: Adding info for usb:2-0:1.0
Nov 18 11:53:51 localhost kernel: hub 2-0:1.0: USB hub found
Nov 18 11:53:51 localhost kernel: hub 2-0:1.0: 5 ports detected
Nov 18 11:53:51 localhost kernel: PM: Adding info for No Bus:ep_81
Nov 18 11:53:51 localhost kernel: PM: Adding info for No Bus:usbdev2.1
Nov 18 11:53:51 localhost kernel: PM: Adding info for No Bus:ep_00
Nov 18 11:53:51 localhost kernel: ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
Nov 18 11:53:51 localhost kernel: ohci_hcd 0000:00:12.0: PCI INT A -> GSI 18 (level, low) -> IRQ 18
Nov 18 11:53:51 localhost kernel: ohci_hcd 0000:00:12.0: OHCI Host Controller
Nov 18 11:53:51 localhost kernel: ohci_hcd 0000:00:12.0: new USB bus registered, assigned bus number 3
Nov 18 11:53:51 localhost kernel: ohci_hcd 0000:00:12.0: irq 18, io mem 0xdc404000
Nov 18 11:53:51 localhost kernel: PM: Adding info for usb:usb3
Nov 18 11:53:51 localhost kernel: PM: Adding info for usb:3-0:1.0
Nov 18 11:53:51 localhost kernel: hub 3-0:1.0: USB hub found
Nov 18 11:53:51 localhost kernel: hub 3-0:1.0: 5 ports detected
Nov 18 11:53:51 localhost kernel: PM: Adding info for No Bus:ep_81
Nov 18 11:53:51 localhost kernel: PM: Adding info for No Bus:usbdev3.1
Nov 18 11:53:51 localhost kernel: PM: Adding info for No Bus:ep_00
Nov 18 11:53:51 localhost kernel: ohci_hcd 0000:00:13.0: PCI INT A -> GSI 18 (level, low) -> IRQ 18
Nov 18 11:53:51 localhost kernel: ohci_hcd 0000:00:13.0: OHCI Host Controller
Nov 18 11:53:51 localhost kernel: scsi host3: __pm_runtime_suspend()!
Nov 18 11:53:51 localhost kernel: scsi host3: __pm_runtime_suspend() returns 0!
Nov 18 11:53:51 localhost kernel: scsi host2: __pm_runtime_suspend()!
Nov 18 11:53:51 localhost kernel: scsi host2: __pm_runtime_suspend() returns 0!

Nov 18 11:53:51 localhost kernel: scsi 0:0:0:0: Direct-Access     ATA      TOSHIBA MK1665GS GJ00 PQ: 0 ANSI: 5
Nov 18 11:53:51 localhost kernel: PM: Adding info for scsi:target0:0:0
Nov 18 11:53:51 localhost kernel: scsi target0:0:0: __pm_runtime_resume()!
Nov 18 11:53:51 localhost kernel: scsi target0:0:0: __pm_runtime_resume() returns 1!
Nov 18 11:53:51 localhost kernel: scsi 0:0:0:0: __pm_runtime_resume()!
Nov 18 11:53:51 localhost kernel: scsi 0:0:0:0: __pm_runtime_resume() returns 1!
Nov 18 11:53:51 localhost kernel: scsi 0:0:0:0: __pm_runtime_resume()!
Nov 18 11:53:51 localhost kernel: scsi 0:0:0:0: __pm_runtime_resume() returns 1!
Nov 18 11:53:51 localhost kernel: PM: Adding info for scsi:0:0:0:0
Nov 18 11:53:51 localhost kernel: PM: Adding info for No Bus:0:0:0:0
Nov 18 11:53:51 localhost kernel: PM: Adding info for No Bus:0:0:0:0
Nov 18 11:53:51 localhost kernel: sd 0:0:0:0: [sda] 312581808 512-byte logical blocks: (160 GB/149 GiB)
Nov 18 11:53:51 localhost kernel: sd 0:0:0:0: [sda] Write Protect is off
Nov 18 11:53:51 localhost kernel: PM: Adding info for No Bus:0:0:0:0
Nov 18 11:53:51 localhost kernel: sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Nov 18 11:53:51 localhost kernel: sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Nov 18 11:53:51 localhost kernel: scsi target1:0:0: __pm_runtime_resume()!
Nov 18 11:53:51 localhost kernel: scsi target1:0:0: __pm_runtime_resume() returns -11!



Nov 18 11:53:54 localhost kernel: sd 0:0:0:0: __pm_runtime_resume()!
Nov 18 11:53:54 localhost kernel: sd 0:0:0:0: __pm_runtime_resume() returns 1!
Nov 18 11:53:54 localhost kernel: sd 0:0:0:0: __pm_runtime_resume()!
Nov 18 11:53:54 localhost kernel: sd 0:0:0:0: __pm_runtime_resume() returns 1!
Nov 18 11:53:54 localhost kernel: scsi host1: __pm_runtime_resume()!
Nov 18 11:53:54 localhost kernel: scsi host1: __pm_runtime_resume() returns 1!
Nov 18 11:53:54 localhost kernel: scsi host1: __pm_runtime_resume()!
Nov 18 11:53:54 localhost kernel: scsi host1: __pm_runtime_resume() returns 1!
Nov 18 11:53:54 localhost kernel: scsi host1: __pm_runtime_resume()!
Nov 18 11:53:54 localhost kernel: scsi host1: __pm_runtime_resume() returns 1!
Nov 18 11:53:54 localhost kernel: scsi host1: __pm_runtime_resume()!
Nov 18 11:53:54 localhost kernel: scsi host1: __pm_runtime_resume() returns 1!
Nov 18 11:53:54 localhost kernel: scsi host1: __pm_runtime_resume()!
Nov 18 11:53:54 localhost kernel: scsi host1: __pm_runtime_resume() returns 1!


the last message repeats endlessly!

# uname -a
Linux logos 2.6.36 #1 PREEMPT Thu Nov 18 11:52:17 EET 2010 x86_64 AMD V120 Processor AuthenticAMD GNU/Linux

Comment 1 Rafael J. Wysocki 2010-11-18 12:36:39 UTC

Apparently, you have CONFIG_PM_VERBOSE set.  It does what it says, so please
turn it off and these messages will go away.

Comment 2 Alexandr Kuznetsov 2010-11-18 13:48:04 UTC

Created attachment 37452 [details]
config

(In reply to comment #1)
> Apparently, you have CONFIG_PM_VERBOSE set.  It does what it says, so please
> turn it off and these messages will go away.
Nope :). Have the same problem with PM_DEBUG disabled. PM_VERBOSE depends on it.

Comment 3 Ivan Baidakou 2010-11-18 19:32:06 UTC

(In reply to comment #2)
> Created an attachment (id=37452) [details]
> config
> 
> (In reply to comment #1)
> > Apparently, you have CONFIG_PM_VERBOSE set.  It does what it says, so
> please
> > turn it off and these messages will go away.
> Nope :). Have the same problem with PM_DEBUG disabled. PM_VERBOSE depends on
> it.

You can try to clean all and recompile the sources. The proposed solution solved an annoying output at least in my case. But, I think that it reflects a bit buggy behaviour in PM-subsystem.

Comment 4 Rafael J. Wysocki 2010-11-18 21:53:10 UTC

(In reply to comment #2)
> Created an attachment (id=37452) [details]
> config
> 
> (In reply to comment #1)
> > Apparently, you have CONFIG_PM_VERBOSE set.  It does what it says, so
> please
> > turn it off and these messages will go away.
> Nope :). Have the same problem with PM_DEBUG disabled. PM_VERBOSE depends on
> it.

Hmm.  Can ypu check _with_ PM_DEBUG and without PM_VERBOSE?

Comment 5 Alexandr Kuznetsov 2010-11-18 23:09:29 UTC

(In reply to comment #4)
> (In reply to comment #2)
> > Created an attachment (id=37452) [details] [details]
> > config
> > 
> > (In reply to comment #1)
> > > Apparently, you have CONFIG_PM_VERBOSE set.  It does what it says, so
> please
> > > turn it off and these messages will go away.
> > Nope :). Have the same problem with PM_DEBUG disabled. PM_VERBOSE depends
> on
> > it.
> 
> Hmm.  Can ypu check _with_ PM_DEBUG and without PM_VERBOSE?

I disabled PM_RUNTIME and it's gone.

Comment 6 Jason Vas Dias 2011-01-03 15:29:45 UTC

Created attachment 42262 [details]
patch against v2.6.36.2 drivers/base/power/runtime.c

This fixes the issue for me - but should pm_runtime_resume be being 
entered more than 10 times per second?

Comment 7 Jason Vas Dias 2011-01-03 15:34:27 UTC

( sorry, this should have been in Comment #6 ) 

I too saw this problem, with pm_runtime_resume logging @10 messages per second,
regardless of whether PM_DEBUG or PM_VERBOSE were set - this is because 
pm_runtime_resume calls dev_dbg directly, and I do enable device driver
debugging.

The attached patch makes the pm_runtime_resume debug messages dependant 
on PM_VERBOSE, and fixes the message logging problem for me - BUT :
Question : should pm_runtime_resume() really be entered more than 10 times
per second ?

[  273.022954] scsi host4: __pm_runtime_resume()!                        
[  273.022960] scsi host4: __pm_runtime_resume() returns 1!              
[  273.029395] scsi host4: __pm_runtime_resume()!                        
[  273.029400] scsi host4: __pm_runtime_resume() returns 1!              
[  273.035697] scsi host4: __pm_runtime_resume()!                        
[  273.035701] scsi host4: __pm_runtime_resume() returns 1!              
[  273.042126] scsi host4: __pm_runtime_resume()!                        
[  273.042130] scsi host4: __pm_runtime_resume() returns 1!              
[  273.048511] scsi host4: __pm_runtime_resume()!                        
[  273.048514] scsi host4: __pm_runtime_resume() returns 1!              
[  273.054822] scsi host4: __pm_runtime_resume()!                        
[  273.054825] scsi host4: __pm_runtime_resume() returns 1!              
[  273.062123] scsi host4: __pm_runtime_resume()!                        
[  273.062126] scsi host4: __pm_runtime_resume() returns 1!              
[  273.068508] scsi host4: __pm_runtime_resume()!                        
[  273.068512] scsi host4: __pm_runtime_resume() returns 1!              
[  273.074789] scsi host4: __pm_runtime_resume()!                        
[  273.074792] scsi host4: __pm_runtime_resume() returns 1!              
[  273.081173] scsi host4: __pm_runtime_resume()!                        
[  273.081176] scsi host4: __pm_runtime_resume() returns 1!              
[  273.087553] scsi host4: __pm_runtime_resume()!                        
[  273.087557] scsi host4: __pm_runtime_resume() returns 1!              
[  273.093867] scsi host4: __pm_runtime_resume()!                        
[  273.093871] scsi host4: __pm_runtime_resume() returns 1!              
[  275.022994] scsi host4: __pm_runtime_resume()!                        
[  275.023000] scsi host4: __pm_runtime_resume() returns 1!              
[  275.029442] scsi host4: __pm_runtime_resume()!                        
[  275.029446] scsi host4: __pm_runtime_resume() returns 1!
[  275.035811] scsi host4: __pm_runtime_resume()!
[  275.035815] scsi host4: __pm_runtime_resume() returns 1!
[  275.042164] scsi host4: __pm_runtime_resume()!
[  275.042168] scsi host4: __pm_runtime_resume() returns 1!
[  275.048535] scsi host4: __pm_runtime_resume()!
[  275.048538] scsi host4: __pm_runtime_resume() returns 1!
[  275.054889] scsi host4: __pm_runtime_resume()!
[  275.054892] scsi host4: __pm_runtime_resume() returns 1!
[  275.062115] scsi host4: __pm_runtime_resume()!
[  275.062120] scsi host4: __pm_runtime_resume() returns 1!
[  275.068505] scsi host4: __pm_runtime_resume()!
[  275.068509] scsi host4: __pm_runtime_resume() returns 1!
[  275.074889] scsi host4: __pm_runtime_resume()!
[  275.074893] scsi host4: __pm_runtime_resume() returns 1!
[  275.081222] scsi host4: __pm_runtime_resume()!
[  275.081225] scsi host4: __pm_runtime_resume() returns 1!
[  275.087614] scsi host4: __pm_runtime_resume()!
[  275.087618] scsi host4: __pm_runtime_resume() returns 1!
[  275.093927] scsi host4: __pm_runtime_resume()!
[  275.093931] scsi host4: __pm_runtime_resume() returns 1!
[  277.023094] scsi host4: __pm_runtime_resume()!
[  277.023100] scsi host4: __pm_runtime_resume() returns 1!
[  277.029477] scsi host4: __pm_runtime_resume()!
[  277.029481] scsi host4: __pm_runtime_resume() returns 1!
[  277.035845] scsi host4: __pm_runtime_resume()!
[  277.035848] scsi host4: __pm_runtime_resume() returns 1!
[  277.042198] scsi host4: __pm_runtime_resume()!
[  277.042202] scsi host4: __pm_runtime_resume() returns 1!
[  277.048551] scsi host4: __pm_runtime_resume()!
[  277.048554] scsi host4: __pm_runtime_resume() returns 1!
[  277.054928] scsi host4: __pm_runtime_resume()!
[  277.054932] scsi host4: __pm_runtime_resume() returns 1!
[  277.062170] scsi host4: __pm_runtime_resume()!
[  277.062173] scsi host4: __pm_runtime_resume() returns 1!
[  277.068552] scsi host4: __pm_runtime_resume()!
[  277.068556] scsi host4: __pm_runtime_resume() returns 1!
[  277.074909] scsi host4: __pm_runtime_resume()!
[  277.074912] scsi host4: __pm_runtime_resume() returns 1!
[  277.081240] scsi host4: __pm_runtime_resume()!
[  277.081244] scsi host4: __pm_runtime_resume() returns 1!
[  277.087596] scsi host4: __pm_runtime_resume()!
[  277.087600] scsi host4: __pm_runtime_resume() returns 1!
[  277.093979] scsi host4: __pm_runtime_resume()!
[  277.093983] scsi host4: __pm_runtime_resume() returns 1!

Comment 8 Florian Mickler 2011-05-30 07:55:25 UTC

A patch referencing this bug report has been merged in v3.0-rc1:

commit c650da23d59d2c82307380414606774c6d49b8bd
Author: Rafael J. Wysocki <rjw@sisk.pl>
Date:   Tue May 17 23:25:10 2011 +0200

    PM: Remove CONFIG_PM_VERBOSE

Comment 9 Jason Vas Dias 2011-05-30 10:55:07 UTC

Well, I've observed major progress with this bug necessitating the withdrawal of
my patch anyway -

Now, with 2.6.38.2,  I only see the messages when I am actually attempting to
resume from disk, whereas before (2.6.37.2) I saw them ALL the time :

$ grep resume /var/log/messages | tail -10
2011-05-28T16:46:31.895648+01:00 (none) kernel: [   62.325128] sd 0:0:0:0: rpm_resume flags 0x4
2011-05-28T16:46:31.895666+01:00 (none) kernel: [   62.326013] sd 0:0:0:0: rpm_resume returns 1
2011-05-28T16:46:31.925050+01:00 (none) kernel: [   62.354539] sd 0:0:0:0: rpm_resume flags 0x4
2011-05-28T16:46:31.925067+01:00 (none) kernel: [   62.355308] sd 0:0:0:0: rpm_resume returns 1
2011-05-28T16:46:31.955957+01:00 (none) kernel: [   62.385504] sd 0:0:0:0: rpm_resume flags 0x4
2011-05-28T16:46:31.955997+01:00 (none) kernel: [   62.386275] sd 0:0:0:0: rpm_resume returns 1
2011-05-28T16:46:31.977063+01:00 (none) kernel: [   62.406664] sd 0:0:0:0: rpm_resume flags 0x4
2011-05-28T16:46:31.977080+01:00 (none) kernel: [   62.407359] sd 0:0:0:0: rpm_resume returns 1
2011-05-28T16:46:32.091121+01:00 (none) kernel: [   62.520838] sd 0:0:0:0: rpm_resume flags 0x4
2011-05-28T16:46:32.091141+01:00 (none) kernel: [   62.521589] sd 0:0:0:0: rpm_resume returns 1


But since resume from disk has stopped working on my HP 6715b laptop since 2.6.38+ 
( it now appears to resume from 'suspend to disk' into 'suspend to ram' ,
  after initial bootup messages are displayed -
  and no wakeup keyboard sequence I've ever been able to discover,
  including that obtained by raising a support issue with HP, has
  ever been able to wakeup my box out of 'suspend to ram' -
) - this specific bug is no longer a problem for me since I can't use freeze .

But my earlier question remains - why log these messages @ 10 times per second?
Can't we give them some kind of throttle ?