Bug 60636 - dmesg/kernel log polluted with power state changed by ACPI to D0/D3
Summary: dmesg/kernel log polluted with power state changed by ACPI to D0/D3
Status: CLOSED OBSOLETE
Alias: None
Product: Drivers
Classification: Unclassified
Component: USB (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Alan Stern
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2013-07-27 06:01 UTC by Oleksii Shevchuk
Modified: 2019-07-19 04:55 UTC (History)
3 users (show)

See Also:
Kernel Version: 3.10.1
Subsystem:
Regression: No
Bisected commit-id:


Attachments

Description Oleksii Shevchuk 2013-07-27 06:01:39 UTC
When inactive, every second added next records:

[51284.737296] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
[51285.716215] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
[51285.816681] ehci-pci 0000:00:1d.0: setting latency timer to 64
[51285.889551] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
[51286.868397] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
[51286.969021] ehci-pci 0000:00:1d.0: setting latency timer to 64
[51287.041889] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
[51288.020679] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
[51288.121429] ehci-pci 0000:00:1d.0: setting latency timer to 64
[51288.194200] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
[51289.172993] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
[51289.273611] ehci-pci 0000:00:1d.0: setting latency timer to 64
[51289.346567] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
[51290.325315] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
[51290.425883] ehci-pci 0000:00:1d.0: setting latency timer to 64
[51290.498838] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
[51291.477532] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
[51291.578245] ehci-pci 0000:00:1d.0: setting latency timer to 64
[51291.651137] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
[51292.629887] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
[51292.730600] ehci-pci 0000:00:1d.0: setting latency timer to 64
[51292.803443] ehci-pci 0000:00:1d.0: power state changed by ACPI to D3cold
[51293.782279] ehci-pci 0000:00:1d.0: power state changed by ACPI to D0
....

 # lspci -vvv -s 00:1d.0
00:1d.0 USB controller: Intel Corporation 7 Series/C210 Series Chipset Family USB Enhanced Host Controller #1 (rev 04) (prog-if 20 [EHCI])
	Subsystem: Lenovo Device 21fa
	Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
	Status: Cap+ 66MHz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
	Latency: 0
	Interrupt: pin A routed to IRQ 23
	Region 0: Memory at f2539000 (32-bit, non-prefetchable) [size=1K]
	Capabilities: [50] Power Management version 2
		Flags: PMEClk- DSI- D1- D2- AuxCurrent=375mA PME(D0+,D1-,D2-,D3hot+,D3cold+)
		Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
	Capabilities: [58] Debug port: BAR=1 offset=00a0
	Capabilities: [98] PCI Advanced Features
		AFCap: TP+ FLR+
		AFCtrl: FLR-
		AFStatus: TP-
	Kernel driver in use: ehci-pci
	Kernel modules: ehci_pci

# lsusb
Bus 001 Device 009: ID 1199:9013 Sierra Wireless, Inc. 
Bus 003 Device 002: ID 8087:0024 Intel Corp. Integrated Rate Matching Hub
Bus 004 Device 002: ID 8087:0024 Intel Corp. Integrated Rate Matching Hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 003 Device 003: ID 147e:2020 Upek TouchChip Fingerprint Coprocessor (WBF advanced mode)
Bus 003 Device 005: ID 5986:02d2 Acer, Inc 

All devices (looks like) inactive. I.e. b.t. off, fp reader inactive, camera off, modem in rfkill
Comment 1 Lan Tianyu 2013-07-27 06:58:57 UTC
Hi,
    This seems EHCI fluctuates between D0 and D3. Please try to disabe EHCI runtime PM via powertop.
Comment 2 Alan Stern 2013-07-27 14:57:14 UTC
It looks like the dev_info line in drivers/pci/pci-acpi.c:acpi_pci_set_power_state() should be changed to dev_dbg.  The "latency timer" message in pci.c:pcibios_set_master() already uses KERN_DEBUG.

This will prevent the kernel log from being spammed.  The dmesg log is a different matter.  I don't know what causes those constant suspends and resumes.  You could get more information by enabled CONFIG_USB_DEBUG.
Comment 3 Lan Tianyu 2013-07-29 01:39:34 UTC
(In reply to Alan Stern from comment #2)
> It looks like the dev_info line in
> drivers/pci/pci-acpi.c:acpi_pci_set_power_state() should be changed to
> dev_dbg.  The "latency timer" message in pci.c:pcibios_set_master() already
> uses KERN_DEBUG.

Yes, dev_dbg makes more sense. I will send a patch to change it.

> 
> This will prevent the kernel log from being spammed.  The dmesg log is a
> different matter.  I don't know what causes those constant suspends and
> resumes.  You could get more information by enabled CONFIG_USB_DEBUG.

From the logs, this should be a EHCI issue and so reassign to USB component.
Comment 4 Alan Stern 2013-10-10 14:18:26 UTC
Oleksii, if you want to find out what causes the continuing suspends and resumes, you should capture a usbmon trace of the USB bus corresponding to the 1d.0 controller, and attach it to this bug report.

Note You need to log in before you can comment on or make changes to this bug.