2.6.37-rc5, pata_atiixp, DVD-ROM: kernel log flooded with "rpm_resume flags 0x4", "rpm_resume returns 1"

DISCUSSION Stefan Richter 3 participants 19 messages Dec 11, 2010 – Dec 18, 2010 libata

Share & tools

Stefan Richter

author

2010-12-11 16:32 UTC #0 lore raw

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
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:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume returns 1

Why is rpm_resume performed 6 times every two seconds?

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

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

Signature · 3 lines

Stefan Richter
-=====-==-=- ==-- -=-==
http://arcgraph.de/sr/

Rafael J. Wysocki

2010-12-11 19:29 UTC #1 lore raw

Quoted 5 lines · Stefan Richter

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?

Rafael

Quoted 72 lines

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
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:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume returns 1

Why is rpm_resume performed 6 times every two seconds?

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

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

Rafael J. Wysocki

2010-12-11 19:29 UTC #2 lore raw

In reply to Stefan Richter

Quoted 5 lines · Stefan Richter

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?

Rafael

Quoted 72 lines

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
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:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:33 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:35 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume returns 1
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume flags 0x4
Dec 11 17:11:37 stein kernel: scsi host6: rpm_resume returns 1

Why is rpm_resume performed 6 times every two seconds?

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

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

Alan Stern

2010-12-11 19:38 UTC #3 lore raw

In reply to Stefan Richter

Quoted 10 lines · Stefan Richter

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

...

Quoted 1 line

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.

Quoted 5 lines

host6 is pata_atiixp with an:
00:14.1 IDE interface: ATI Technologies Inc SB700/SB800 IDE Controller (prog-if 8a [Master SecP PriP])

Quoted 10 lines

# 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.

Quoted 6 lines

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

Quoted 10 lines

# 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

Stefan Richter

author

2010-12-17 20:15 UTC #4 lore raw

Quoted 14 lines · On Dec 11 Alan Stern wrote:

Quoted 10 lines · Stefan Richter
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
...

Quoted 7 lines

Quoted 1 line
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.

Quoted 16 lines

Quoted 5 lines

host6 is pata_atiixp with an:
00:14.1 IDE interface: ATI Technologies Inc SB700/SB800 IDE Controller (prog-if 8a [Master SecP PriP])

Quoted 10 lines

# 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

Quoted 3 lines

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.

Quoted 1 line

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

--------

Quoted 10 lines · On Dec 11 Rafael J. Wysocki wrote:

Quoted 5 lines · Stefan Richter
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).

Signature · 3 lines

Stefan Richter
-=====-==-=- ==-- =---=
http://arcgraph.de/sr/

Stefan Richter

author

2010-12-17 20:17 UTC #5 lore raw

In reply to Alan Stern

Quoted 14 lines · On Dec 11 Alan Stern wrote:

Quoted 10 lines · Stefan Richter
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
...

Quoted 7 lines

Quoted 1 line
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.

Quoted 16 lines

Quoted 5 lines

host6 is pata_atiixp with an:
00:14.1 IDE interface: ATI Technologies Inc SB700/SB800 IDE Controller (prog-if 8a [Master SecP PriP])

Quoted 10 lines

# 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

Quoted 3 lines

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:

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):

The parent device 0000:00:14.1 is bound to the mentioned pata_atiixp, if this is of any importance at all.

Quoted 1 line

From the child device:

--------

Quoted 10 lines · On Dec 11 Rafael J. Wysocki wrote:

Quoted 5 lines · Stefan Richter
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).

Signature · 3 lines

Stefan Richter
-=====-==-=- ==-- =---=
http://arcgraph.de/sr/

Stefan Richter

author

2010-12-17 20:30 UTC #6 lore raw

Quoted 10 lines · On Dec 17 Stefan Richter wrote:

Quoted 5 lines · 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.

[...]

Quoted 33 lines

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

Quoted 4 lines

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.

Signature · 3 lines

Stefan Richter
-=====-==-=- ==-- =---=
http://arcgraph.de/sr/

Stefan Richter

author

2010-12-17 20:30 UTC #7 lore raw

In reply to Stefan Richter

Quoted 10 lines · On Dec 17 Stefan Richter wrote:

Quoted 5 lines · 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.

[...]

Quoted 33 lines

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

Quoted 4 lines

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?

Signature · 3 lines

Stefan Richter
-=====-==-=- ==-- =---=
http://arcgraph.de/sr/

Stefan Richter

author

2010-12-17 20:32 UTC #8 lore raw

Quoted 5 lines · 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.

Signature · 3 lines

Stefan Richter
-=====-==-=- ==-- =---=
http://arcgraph.de/sr/

Stefan Richter

author

2010-12-17 20:32 UTC #9 lore raw

In reply to Stefan Richter

Quoted 5 lines · 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.

Signature · 3 lines

Stefan Richter
-=====-==-=- ==-- =---=
http://arcgraph.de/sr/

Alan Stern

2010-12-18 18:14 UTC #10 lore raw

In reply to Stefan Richter

Quoted 7 lines · Stefan Richter

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".

Quoted 5 lines

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

Stefan Richter

author

2010-12-18 19:12 UTC #11 lore raw

Quoted 10 lines · On Dec 18 Alan Stern wrote:

Quoted 7 lines · Stefan Richter
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?

Quoted 3 lines

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.

Quoted 8 lines

Quoted 5 lines
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.

Signature · 3 lines

Stefan Richter
-=====-==-=- ==-- =--=-
http://arcgraph.de/sr/

Stefan Richter

author

2010-12-18 19:13 UTC #12 lore raw

In reply to Alan Stern

Quoted 10 lines · On Dec 18 Alan Stern wrote:

Quoted 7 lines · Stefan Richter
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?

Quoted 3 lines

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.

Quoted 8 lines

Quoted 5 lines
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.

Signature · 3 lines

Stefan Richter
-=====-==-=- ==-- =--=-
http://arcgraph.de/sr/

Alan Stern

2010-12-18 18:11 UTC #13 lore raw

In reply to Stefan Richter

Quoted 59 lines · Stefan Richter

Quoted 14 lines · On Dec 11 Alan Stern wrote:
Quoted 10 lines · Stefan Richter
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
...
Quoted 7 lines
Quoted 1 line
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.
Quoted 16 lines
Quoted 5 lines
host6 is pata_atiixp with an:
00:14.1 IDE interface: ATI Technologies Inc SB700/SB800 IDE Controller (prog-if 8a [Master SecP PriP])
Quoted 10 lines
# 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
Quoted 3 lines
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

...

Quoted 35 lines

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:

Quoted 8 lines

/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.

Quoted 10 lines

--------
Quoted 7 lines · On Dec 11 Rafael J. Wysocki wrote:
Quoted 5 lines · Stefan Richter
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:

Quoted 7 lines

Quoted 3 lines
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

Stefan Richter

author

2010-12-18 19:08 UTC #14 lore raw

Quoted 6 lines · On Dec 18 Alan Stern wrote:

Quoted 5 lines · Stefan Richter
Quoted 3 lines · 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?

Quoted 8 lines

Quoted 3 lines
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.

Signature · 3 lines

Stefan Richter
-=====-==-=- ==-- =--=-
http://arcgraph.de/sr/

Rafael J. Wysocki

2010-12-18 22:41 UTC #15 lore raw

Quoted 11 lines · Stefan Richter

Quoted 10 lines · On Dec 18 Alan Stern wrote:
Quoted 8 lines · Stefan Richter
Quoted 3 lines · 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).

Quoted 7 lines

Quoted 4 lines
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

Rafael J. Wysocki

2010-12-18 22:42 UTC #16 lore raw

In reply to Stefan Richter

Quoted 11 lines · Stefan Richter

Quoted 10 lines · On Dec 18 Alan Stern wrote:
Quoted 8 lines · Stefan Richter
Quoted 3 lines · 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).

Quoted 7 lines

Quoted 4 lines
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

Stefan Richter

author

2010-12-18 19:08 UTC #17 lore raw

In reply to Alan Stern

Quoted 6 lines · On Dec 18 Alan Stern wrote:

Quoted 5 lines · Stefan Richter
Quoted 3 lines · 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?

Quoted 8 lines

Quoted 3 lines
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.

Signature · 3 lines

Stefan Richter
-=====-==-=- ==-- =--=-
http://arcgraph.de/sr/

Alan Stern

2010-12-11 19:38 UTC #18 lore raw

In reply to Stefan Richter

Quoted 10 lines · Stefan Richter

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

...

Quoted 1 line

Why is rpm_resume performed 6 times every two seconds?

Quoted 5 lines

host6 is pata_atiixp with an:
00:14.1 IDE interface: ATI Technologies Inc SB700/SB800 IDE Controller (prog-if 8a [Master SecP PriP])

Quoted 10 lines

# 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

Quoted 6 lines

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

Quoted 10 lines

# 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