On Sat, 11 Dec 2010, Stefan Richter wrote:
> Hi,
>
> I just booted from 2.6.36 (without PM debugging configured) into
> 2.6.37-rc5 (with PM debugging enabled). There is endless log spam like
> this:
>
> Dec 11 17:11:31 stein kernel: scsi host6: rpm_resume flags 0x4
> Dec 11 17:11:31 stein kernel: scsi host6: rpm_resume returns 1
> Dec 11 17:11:31 stein kernel: scsi host6: rpm_resume flags 0x4
> Dec 11 17:11:31 stein kernel: scsi host6: rpm_resume returns 1
...
> Why is rpm_resume performed 6 times every two seconds?
This is probably because hal probes the DVD drive every two seconds
looking for media changes. However that's not supposed to cause
rpm_resume to be called for the host unless runtime PM is allowed for
the DVD drive, which it isn't according to your listings below. So
there's a bug somewhere.
> host6 is pata_atiixp with an:
>
> 00:14.1 IDE interface: ATI Technologies Inc SB700/SB800 IDE Controller
> (prog-if 8a [Master SecP PriP])
>
> # grep . /sys/class/scsi_host/host6/power/*
> /sys/class/scsi_host/host6/power/async:enabled
> grep: /sys/class/scsi_host/host6/power/autosuspend_delay_ms: Input/output error
> /sys/class/scsi_host/host6/power/control:auto
> /sys/class/scsi_host/host6/power/runtime_active_kids:0
> /sys/class/scsi_host/host6/power/runtime_active_time:0
> /sys/class/scsi_host/host6/power/runtime_enabled:disabled
> /sys/class/scsi_host/host6/power/runtime_status:unsupported
> /sys/class/scsi_host/host6/power/runtime_suspended_time:0
> /sys/class/scsi_host/host6/power/runtime_usage:0
This is the wrong directory (the class device, not the device itself).
You should look at /sys/class/scsi_host/host6/device/power instead.
And also /sys/class/scsi_host/host6/device/target6:0:0/power.
> Attached to it is one device:
>
> Host: scsi6 Channel: 00 Id: 00 Lun: 00
> Vendor: PLEXTOR Model: DVD-ROM PX-130A Rev: 1.01
> Type: CD-ROM ANSI SCSI revision: 05
>
> # grep . /sys/class/scsi_host/host6/device/target6\:0\:0/6\:0\:0\:0/power/*
> /sys/class/scsi_host/host6/device/target6:0:0/6:0:0:0/power/async:enabled
> grep: /sys/class/scsi_host/host6/device/target6:0:0/6:0:0:0/power/autosuspend_delay_ms: Input/output error
> /sys/class/scsi_host/host6/device/target6:0:0/6:0:0:0/power/control:on
> /sys/class/scsi_host/host6/device/target6:0:0/6:0:0:0/power/runtime_active_kids:0
> /sys/class/scsi_host/host6/device/target6:0:0/6:0:0:0/power/runtime_active_time:2689146
> /sys/class/scsi_host/host6/device/target6:0:0/6:0:0:0/power/runtime_enabled:forbidden
> /sys/class/scsi_host/host6/device/target6:0:0/6:0:0:0/power/runtime_status:active
> /sys/class/scsi_host/host6/device/target6:0:0/6:0:0:0/power/runtime_suspended_time:0
> /sys/class/scsi_host/host6/device/target6:0:0/6:0:0:0/power/runtime_usage:2
These values are correct; they show that the DVD drive is forbidden
from doing a runtime suspend.
Alan Stern
On Dec 11 Alan Stern wrote:
> On Sat, 11 Dec 2010, Stefan Richter wrote:
>
> > Hi,
> >
> > I just booted from 2.6.36 (without PM debugging configured) into
> > 2.6.37-rc5 (with PM debugging enabled). There is endless log spam like
> > this:
> >
> > Dec 11 17:11:31 stein kernel: scsi host6: rpm_resume flags 0x4
> > Dec 11 17:11:31 stein kernel: scsi host6: rpm_resume returns 1
> > Dec 11 17:11:31 stein kernel: scsi host6: rpm_resume flags 0x4
> > Dec 11 17:11:31 stein kernel: scsi host6: rpm_resume returns 1
> ...
>
> > Why is rpm_resume performed 6 times every two seconds?
>
> This is probably because hal probes the DVD drive every two seconds
> looking for media changes. However that's not supposed to cause
> rpm_resume to be called for the host unless runtime PM is allowed for
> the DVD drive, which it isn't according to your listings below. So
> there's a bug somewhere.
I had 2.6.36 running since then and have now booted into 2.6.37-rc6.
Yes, it is hal indeed. Shutting hal down avoids this logging activity.
> > host6 is pata_atiixp with an:
> >
> > 00:14.1 IDE interface: ATI Technologies Inc SB700/SB800 IDE Controller
> > (prog-if 8a [Master SecP PriP])
> >
> > # grep . /sys/class/scsi_host/host6/power/*
> > /sys/class/scsi_host/host6/power/async:enabled
> > grep: /sys/class/scsi_host/host6/power/autosuspend_delay_ms: Input/output error
> > /sys/class/scsi_host/host6/power/control:auto
> > /sys/class/scsi_host/host6/power/runtime_active_kids:0
> > /sys/class/scsi_host/host6/power/runtime_active_time:0
> > /sys/class/scsi_host/host6/power/runtime_enabled:disabled
> > /sys/class/scsi_host/host6/power/runtime_status:unsupported
> > /sys/class/scsi_host/host6/power/runtime_suspended_time:0
> > /sys/class/scsi_host/host6/power/runtime_usage:0
>
> This is the wrong directory (the class device, not the device itself).
> You should look at /sys/class/scsi_host/host6/device/power instead.
> And also /sys/class/scsi_host/host6/device/target6:0:0/power.
OK, correct directory follows below.
Actually, this time I see once every two seconds a message about
logical unit 6:0:0:0 and 6 times every two seconds a message about
host7:
Dec 17 20:22:08 stein kernel: sd 6:0:0:0: rpm_resume flags 0x4
Dec 17 20:22:08 stein kernel: sd 6:0:0:0: rpm_resume returns 1
Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
Dec 17 20:22:10 stein kernel: sd 6:0:0:0: rpm_resume flags 0x4
Dec 17 20:22:10 stein kernel: sd 6:0:0:0: rpm_resume returns 1
Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume flags 0x4
Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume returns 1
Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume flags 0x4
Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume returns 1
Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume flags 0x4
Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume returns 1
Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume flags 0x4
Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume returns 1
Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume flags 0x4
Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume returns 1
Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume flags 0x4
Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume returns 1
sd 6:0:0:0 is a USB card reader built into a monitor:
Host: scsi6 Channel: 00 Id: 00 Lun: 00
Vendor: Generic Model: Ultra HS-SD/MMC Rev: 1.88
Type: Direct-Access ANSI SCSI revision: 00
This is from the power/ directory of the "6:0:0:0" device which is
bound to driver sd:
/sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/async:enabled
/sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/control:on
/sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/runtime_active_kids:0
/sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/runtime_active_time:1650131
/sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/runtime_enabled:forbidden
/sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/runtime_status:active
/sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/runtime_suspended_time:0
/sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/runtime_usage:1
host7 is the mentioned ATI SB700/SB800 IDE controller. Here is the
power/ directory of the scsi_host device (rather than scsi_host class
device):
/sys/devices/pci0000:00/0000:00:14.1/host7/power/async:enabled
/sys/devices/pci0000:00/0000:00:14.1/host7/power/control:auto
/sys/devices/pci0000:00/0000:00:14.1/host7/power/runtime_active_kids:1
/sys/devices/pci0000:00/0000:00:14.1/host7/power/runtime_active_time:1935478
/sys/devices/pci0000:00/0000:00:14.1/host7/power/runtime_enabled:enabled
/sys/devices/pci0000:00/0000:00:14.1/host7/power/runtime_status:active
/sys/devices/pci0000:00/0000:00:14.1/host7/power/runtime_suspended_time:0
/sys/devices/pci0000:00/0000:00:14.1/host7/power/runtime_usage:0
The parent device 0000:00:14.1 is bound to the mentioned pata_atiixp,
if this is of any importance at all.
>From the child device:
/sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/async:enabled
/sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/control:auto
/sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/runtime_active_kids:1
/sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/runtime_active_time:2402125
/sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/runtime_enabled:enabled
/sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/runtime_status:active
/sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/runtime_suspended_time:0
/sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/runtime_usage:0
--------
On Dec 11 Rafael J. Wysocki wrote:
> On Saturday, December 11, 2010, Stefan Richter wrote:
> > Hi,
> >
> > I just booted from 2.6.36 (without PM debugging configured) into
> > 2.6.37-rc5 (with PM debugging enabled). There is endless log spam like
> > this:
>
> I guess you have either CONFIG_PM_VERBOSE set or CONFIG_PM_DEBUG unset.
>
> Which is the case?
I have both options off on 2.6.36 and older kernels. I have both
options on on 2.6.37-rc5/-rc6 (because I wanted to check something
unrelated on 2.6.37).
--
Stefan Richter
-=====-==-=- ==-- =---=
http://arcgraph.de/sr/
On Dec 17 Stefan Richter wrote:
> On Dec 11 Alan Stern wrote:
> > This is probably because hal probes the DVD drive every two seconds
> > looking for media changes. However that's not supposed to cause
> > rpm_resume to be called for the host unless runtime PM is allowed for
> > the DVD drive, which it isn't according to your listings below. So
> > there's a bug somewhere.
>
> I had 2.6.36 running since then and have now booted into 2.6.37-rc6.
>
> Yes, it is hal indeed. Shutting hal down avoids this logging activity.
[...]
> Actually, this time I see once every two seconds a message about
> logical unit 6:0:0:0 and 6 times every two seconds a message about
> host7:
>
> Dec 17 20:22:08 stein kernel: sd 6:0:0:0: rpm_resume flags 0x4
> Dec 17 20:22:08 stein kernel: sd 6:0:0:0: rpm_resume returns 1
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
> Dec 17 20:22:10 stein kernel: sd 6:0:0:0: rpm_resume flags 0x4
> Dec 17 20:22:10 stein kernel: sd 6:0:0:0: rpm_resume returns 1
> Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume returns 1
> Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume returns 1
> Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume returns 1
> Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume returns 1
> Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume returns 1
> Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:10 stein kernel: scsi host7: rpm_resume returns 1
>
> sd 6:0:0:0 is a USB card reader built into a monitor:
> Host: scsi6 Channel: 00 Id: 00 Lun: 00
> Vendor: Generic Model: Ultra HS-SD/MMC Rev: 1.88
> Type: Direct-Access ANSI SCSI revision: 00
Well right --- hald polls the card reader for media change too.
I now noticed that the two lines
sd *:0:0:0: rpm_resume flags 0x4
sd *:0:0:0: rpm_resume returns 1
are logged once for each sd device (i.e. those with fixed media too)
at the startup of hald. Is this expected?
Note, I have not seen anything of the sort on another PC which runs
2.3.37-rc6 with the same PM debug options. The differences are that
the other PC is an Intel 945GM based one with x86-32 kernel and 32bit
Gentoo userland, whereas the PC with log spam is an AMD RS780 based one
with x86-64 kernel and 64bit Gentoo userland. Both got hal 0.5.14-r2.
--
Stefan Richter
-=====-==-=- ==-- =---=
http://arcgraph.de/sr/
On Dec 17 Stefan Richter wrote:
> Note, I have not seen anything of the sort on another PC which runs
> 2.3.37-rc6 with the same PM debug options. The differences are that
> the other PC is an Intel 945GM based one with x86-32 kernel and 32bit
> Gentoo userland, whereas the PC with log spam is an AMD RS780 based one
> with x86-64 kernel and 64bit Gentoo userland. Both got hal 0.5.14-r2.
Sorry, I forgot:
Both kernel are configured with the same _PM_ kernel config options.
--
Stefan Richter
-=====-==-=- ==-- =---=
http://arcgraph.de/sr/
On Fri, 17 Dec 2010, Stefan Richter wrote:
> On Dec 11 Alan Stern wrote:
> > On Sat, 11 Dec 2010, Stefan Richter wrote:
> >
> > > Hi,
> > >
> > > I just booted from 2.6.36 (without PM debugging configured) into
> > > 2.6.37-rc5 (with PM debugging enabled). There is endless log spam like
> > > this:
> > >
> > > Dec 11 17:11:31 stein kernel: scsi host6: rpm_resume flags 0x4
> > > Dec 11 17:11:31 stein kernel: scsi host6: rpm_resume returns 1
> > > Dec 11 17:11:31 stein kernel: scsi host6: rpm_resume flags 0x4
> > > Dec 11 17:11:31 stein kernel: scsi host6: rpm_resume returns 1
> > ...
> >
> > > Why is rpm_resume performed 6 times every two seconds?
> >
> > This is probably because hal probes the DVD drive every two seconds
> > looking for media changes. However that's not supposed to cause
> > rpm_resume to be called for the host unless runtime PM is allowed for
> > the DVD drive, which it isn't according to your listings below. So
> > there's a bug somewhere.
>
> I had 2.6.36 running since then and have now booted into 2.6.37-rc6.
>
> Yes, it is hal indeed. Shutting hal down avoids this logging activity.
>
> > > host6 is pata_atiixp with an:
> > >
> > > 00:14.1 IDE interface: ATI Technologies Inc SB700/SB800 IDE Controller
> > > (prog-if 8a [Master SecP PriP])
> > >
> > > # grep . /sys/class/scsi_host/host6/power/*
> > > /sys/class/scsi_host/host6/power/async:enabled
> > > grep: /sys/class/scsi_host/host6/power/autosuspend_delay_ms: Input/output error
> > > /sys/class/scsi_host/host6/power/control:auto
> > > /sys/class/scsi_host/host6/power/runtime_active_kids:0
> > > /sys/class/scsi_host/host6/power/runtime_active_time:0
> > > /sys/class/scsi_host/host6/power/runtime_enabled:disabled
> > > /sys/class/scsi_host/host6/power/runtime_status:unsupported
> > > /sys/class/scsi_host/host6/power/runtime_suspended_time:0
> > > /sys/class/scsi_host/host6/power/runtime_usage:0
> >
> > This is the wrong directory (the class device, not the device itself).
> > You should look at /sys/class/scsi_host/host6/device/power instead.
> > And also /sys/class/scsi_host/host6/device/target6:0:0/power.
>
> OK, correct directory follows below.
>
> Actually, this time I see once every two seconds a message about
> logical unit 6:0:0:0 and 6 times every two seconds a message about
> host7:
>
> Dec 17 20:22:08 stein kernel: sd 6:0:0:0: rpm_resume flags 0x4
> Dec 17 20:22:08 stein kernel: sd 6:0:0:0: rpm_resume returns 1
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume flags 0x4
> Dec 17 20:22:08 stein kernel: scsi host7: rpm_resume returns 1
...
> sd 6:0:0:0 is a USB card reader built into a monitor:
> Host: scsi6 Channel: 00 Id: 00 Lun: 00
> Vendor: Generic Model: Ultra HS-SD/MMC Rev: 1.88
> Type: Direct-Access ANSI SCSI revision: 00
>
> This is from the power/ directory of the "6:0:0:0" device which is
> bound to driver sd:
>
> /sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/async:enabled
> /sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/control:on
> /sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/runtime_active_kids:0
> /sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/runtime_active_time:1650131
> /sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/runtime_enabled:forbidden
> /sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/runtime_status:active
> /sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/runtime_suspended_time:0
> /sys/devices/pci0000:00/0000:00:12.2/usb1/1-1/1-1.1/1-1.1.1/1-1.1.1:1.0/host6/target6:0:0/6:0:0:0/power/runtime_usage:1
>
> host7 is the mentioned ATI SB700/SB800 IDE controller. Here is the
> power/ directory of the scsi_host device (rather than scsi_host class
> device):
>
> /sys/devices/pci0000:00/0000:00:14.1/host7/power/async:enabled
> /sys/devices/pci0000:00/0000:00:14.1/host7/power/control:auto
> /sys/devices/pci0000:00/0000:00:14.1/host7/power/runtime_active_kids:1
> /sys/devices/pci0000:00/0000:00:14.1/host7/power/runtime_active_time:1935478
> /sys/devices/pci0000:00/0000:00:14.1/host7/power/runtime_enabled:enabled
> /sys/devices/pci0000:00/0000:00:14.1/host7/power/runtime_status:active
> /sys/devices/pci0000:00/0000:00:14.1/host7/power/runtime_suspended_time:0
> /sys/devices/pci0000:00/0000:00:14.1/host7/power/runtime_usage:0
>
> The parent device 0000:00:14.1 is bound to the mentioned pata_atiixp,
> if this is of any importance at all.
>
> From the child device:
>
> /sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/async:enabled
> /sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/control:auto
> /sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/runtime_active_kids:1
> /sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/runtime_active_time:2402125
> /sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/runtime_enabled:enabled
> /sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/runtime_status:active
> /sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/runtime_suspended_time:0
> /sys/devices/pci0000:00/0000:00:14.1/host7/target7:0:0/power/runtime_usage:0
Okay. These messages appear because during each probe, something is
requesting a runtime-PM resume. In the case of sd 6:0:0:0, the resume
happens each time the device file is opened; I don't know why you're
getting a resume request for the scsi7 host (probably something strange
going on in the ATA stack). If you really want to know, you could add a
dump_stack() to one of the debugging messages in rpm_resume().
The "flags 0x4" means the actual call is pm_runtime_get_sync(). The
"returns 1" means that the call didn't do anything to the hardware because
the device in question was already at full power.
> --------
>
> On Dec 11 Rafael J. Wysocki wrote:
> > On Saturday, December 11, 2010, Stefan Richter wrote:
> > > Hi,
> > >
> > > I just booted from 2.6.36 (without PM debugging configured) into
> > > 2.6.37-rc5 (with PM debugging enabled). There is endless log spam like
> > > this:
> >
> > I guess you have either CONFIG_PM_VERBOSE set or CONFIG_PM_DEBUG unset.
> >
> > Which is the case?
>
> I have both options off on 2.6.36 and older kernels. I have both
> options on on 2.6.37-rc5/-rc6 (because I wanted to check something
> unrelated on 2.6.37).
These messages are produced by dev_dbg() calls. The debug output is
enabled by either CONFIG_PM_VERBOSE or CONFIG_DEBUG_DRIVER. Since you say
CONFIG_PM_VERBOSE is off, the other must be on -- unless maybe you have
CONFIG_DYNAMIC_DEBUG enabled.
Alan Stern
On Fri, 17 Dec 2010, Stefan Richter wrote:
> Well right --- hald polls the card reader for media change too.
>
> I now noticed that the two lines
> sd *:0:0:0: rpm_resume flags 0x4
> sd *:0:0:0: rpm_resume returns 1
> are logged once for each sd device (i.e. those with fixed media too)
> at the startup of hald. Is this expected?
I don't know anything about the details of hal. But I do know that you
can tell hal not to poll certain devices. Look at "man
hal-disable-polling".
> Note, I have not seen anything of the sort on another PC which runs
> 2.3.37-rc6 with the same PM debug options. The differences are that
> the other PC is an Intel 945GM based one with x86-32 kernel and 32bit
> Gentoo userland, whereas the PC with log spam is an AMD RS780 based one
> with x86-64 kernel and 64bit Gentoo userland. Both got hal 0.5.14-r2.
Maybe CONFIG_DYNAMIC_DEBUG is set differently, or userspace enables
dynamic debugging of different subsystems.
Alan Stern
On Dec 18 Alan Stern wrote:
> On Fri, 17 Dec 2010, Stefan Richter wrote:
> > On Dec 11 Rafael J. Wysocki wrote:
> > > I guess you have either CONFIG_PM_VERBOSE set or CONFIG_PM_DEBUG unset.
> > >
> > > Which is the case?
> >
> > I have both options off on 2.6.36 and older kernels. I have both
> > options on on 2.6.37-rc5/-rc6 (because I wanted to check something
> > unrelated on 2.6.37).
>
> These messages are produced by dev_dbg() calls. The debug output is
> enabled by either CONFIG_PM_VERBOSE or CONFIG_DEBUG_DRIVER. Since you say
> CONFIG_PM_VERBOSE is off, the other must be on -- unless maybe you have
> CONFIG_DYNAMIC_DEBUG enabled.
No, CONFIG_PM_VERBOSE is of course _on_ in the kernel that spams the
log. It is off in the older kernel that does not spam the log.
--
Stefan Richter
-=====-==-=- ==-- =--=-
http://arcgraph.de/sr/
On Dec 18 Alan Stern wrote:
> On Fri, 17 Dec 2010, Stefan Richter wrote:
>
> > Well right --- hald polls the card reader for media change too.
> >
> > I now noticed that the two lines
> > sd *:0:0:0: rpm_resume flags 0x4
> > sd *:0:0:0: rpm_resume returns 1
> > are logged once for each sd device (i.e. those with fixed media too)
> > at the startup of hald. Is this expected?
>
> I don't know anything about the details of hal. But I do know that you
> can tell hal not to poll certain devices. Look at "man
> hal-disable-polling".
I wouldn't use hal at all if it weren't for some weak userland
programs that require it.
> > Note, I have not seen anything of the sort on another PC which runs
> > 2.3.37-rc6 with the same PM debug options. The differences are that
> > the other PC is an Intel 945GM based one with x86-32 kernel and 32bit
> > Gentoo userland, whereas the PC with log spam is an AMD RS780 based one
> > with x86-64 kernel and 64bit Gentoo userland. Both got hal 0.5.14-r2.
>
> Maybe CONFIG_DYNAMIC_DEBUG is set differently, or userspace enables
> dynamic debugging of different subsystems.
Simpler: I am now noticing that CONFIG_PM_RUNTIME is off on the silent
PC. It is only on on the PC which produces the log spam.
Good. Then the solution for me is simply to disable CONFIG_PM_RUNTIME,
which I had switched on for no apparent reason.
--
Stefan Richter
-=====-==-=- ==-- =--=-
http://arcgraph.de/sr/
On Saturday, December 18, 2010, Stefan Richter wrote:
> On Dec 18 Alan Stern wrote:
> > On Fri, 17 Dec 2010, Stefan Richter wrote:
> > > On Dec 11 Rafael J. Wysocki wrote:
> > > > I guess you have either CONFIG_PM_VERBOSE set or CONFIG_PM_DEBUG unset.
> > > >
> > > > Which is the case?
> > >
> > > I have both options off on 2.6.36 and older kernels. I have both
> > > options on on 2.6.37-rc5/-rc6 (because I wanted to check something
> > > unrelated on 2.6.37).
> >
> > These messages are produced by dev_dbg() calls. The debug output is
> > enabled by either CONFIG_PM_VERBOSE or CONFIG_DEBUG_DRIVER. Since you say
> > CONFIG_PM_VERBOSE is off, the other must be on -- unless maybe you have
> > CONFIG_DYNAMIC_DEBUG enabled.
>
> No, CONFIG_PM_VERBOSE is of course _on_ in the kernel that spams the
> log.
Please turn if off, then. Most likely you don't need it anyway.
Thanks,
Rafael