Bug 60636

Summary:	dmesg/kernel log polluted with power state changed by ACPI to D0/D3
Product:	Drivers	Reporter:	Oleksii Shevchuk (alxchk)
Component:	USB	Assignee:	Alan Stern (stern)
Status:	CLOSED OBSOLETE
Severity:	normal	CC:	leho, stern, tianyu.lan
Priority:	P1
Hardware:	All
OS:	Linux
Kernel Version:	3.10.1	Subsystem:
Regression:	No	Bisected commit-id:

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.