Re: [Update][PATCH] PCI / ACPI: Always resume devices on ACPI wakeup notifications

[Martin Mokrejs <mmokrejs@fold.natur.cuni.cz>]

Hi,
  I applied this patches over 3.8.3 hoping it will fix my issue under
thread: "Re: 3.8.2: xhci port is dead until pcieport PME# goes to disabled"
but unfortunately, it is even worse! Now, although lsusb -v nor lsusb -vv do
wakeup the XHCI port but it falls asleep immediately, more quickly than I am
able to plug a device into the socket. To get a device working in the USB3 socket
I need to plug it in, run lsusb -vv and then it is recognized.

Without the patch, the 'lsusb -vv' woke up the port (PME# disabled happened
on both 1c.4 and 0b:00.0) and I had unlimited time to find some USB device
around and to plug it into the slot.


  I noticed this message some while after a bootup (no external USB devices were
connected to the laptop, neither into USB2 socket nor into USB3.0 sockets) before
I started to do the tests:

[   36.594171] xhci_hcd 0000:0b:00.0: xhci_suspend: stopping port polling.
[   36.594202] xhci_hcd 0000:0b:00.0: // Setting command ring address to 0xd6007001
[   36.594247] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_suspend: 0
[   36.594349] xhci_hcd 0000:0b:00.0: PME# enabled
[   36.703695] r8169 0000:05:00.0 eth0: link down
[   37.098299] microcode: CPU0 updated to revision 0x28, date = 2012-04-24
[   37.098941] microcode: CPU1 updated to revision 0x28, date = 2012-04-24
[   37.098944] perf_event_intel: PEBS enabled due to microcode update
[   38.343029] r8169 0000:05:00.0 eth0: link up
[   39.094944] r8169 0000:05:00.0 eth0: link down
[   41.492768] r8169 0000:05:00.0 eth0: link up
[   62.782910] xhci_hcd 0000:0b:00.0: Poll event ring: 4294943584
[   62.782938] xhci_hcd 0000:0b:00.0: op reg status = 0xffffffff
[   62.782939] xhci_hcd 0000:0b:00.0: HW died, polling stopped.
[   88.754183] pcieport 0000:00:1c.0: PME# enabled
[   88.764182] xhci_hcd 0000:0b:00.0: PME# disabled
[   88.764192] xhci_hcd 0000:0b:00.0: enabling bus mastering
[   88.764206] xhci_hcd 0000:0b:00.0: // Setting command ring address to 0xd6007001
[   88.764242] xhci_hcd 0000:0b:00.0: Port Status Change Event for port 2
[   88.764246] xhci_hcd 0000:0b:00.0: resume root hub
[   88.764259] xhci_hcd 0000:0b:00.0: handle_port_status: starting port polling.
[   88.764276] xhci_hcd 0000:0b:00.0: xhci_resume: starting port polling.
[   88.764281] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_resume: 0


What "HW died? Why 1c.0 is here? What is this device actually doing?

00:1c.0 PCI bridge: Intel Corporation 6 Series/C200 Series Chipset Family PCI Express Root Port 1 (rev b5) (prog-if 00 [Normal decode])
        Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
        Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
        Latency: 0, Cache Line Size: 64 bytes
        Bus: primary=00, secondary=03, subordinate=04, sec-latency=0
        I/O behind bridge: 0000f000-00000fff
        Memory behind bridge: fff00000-000fffff
        Prefetchable memory behind bridge: 00000000fff00000-00000000000fffff
        Secondary status: 66MHz- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort+ <SERR- <PERR-
        BridgeCtl: Parity- SERR- NoISA- VGA- MAbort- >Reset- FastB2B-
                PriDiscTmr- SecDiscTmr- DiscTmrStat- DiscTmrSERREn-
        Capabilities: [40] Express (v2) Root Port (Slot+), MSI 00
                DevCap: MaxPayload 128 bytes, PhantFunc 0, Latency L0s <64ns, L1 <1us
                        ExtTag- RBE+ FLReset-
                DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
                        RlxdOrd- ExtTag- PhantFunc- AuxPwr- NoSnoop-
                        MaxPayload 128 bytes, MaxReadReq 128 bytes
                DevSta: CorrErr- UncorrErr- FatalErr- UnsuppReq- AuxPwr+ TransPend-
                LnkCap: Port #1, Speed 5GT/s, Width x1, ASPM L0s L1, Latency L0 <1us, L1 <16us
                        ClockPM- Surprise- LLActRep+ BwNot-
                LnkCtl: ASPM L1 Enabled; RCB 64 bytes Disabled- Retrain- CommClk-
                        ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
                LnkSta: Speed 2.5GT/s, Width x0, TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
                SltCap: AttnBtn- PwrCtrl- MRL- AttnInd- PwrInd- HotPlug- Surprise-
                        Slot #0, PowerLimit 10.000W; Interlock- NoCompl+
                SltCtl: Enable: AttnBtn- PwrFlt- MRL- PresDet- CmdCplt- HPIrq- LinkChg-
                        Control: AttnInd Unknown, PwrInd Unknown, Power- Interlock-
                SltSta: Status: AttnBtn- PowerFlt- MRL- CmdCplt- PresDet- Interlock-
                        Changed: MRL- PresDet- LinkState-
                RootCtl: ErrCorrectable- ErrNon-Fatal- ErrFatal- PMEIntEna- CRSVisible-
                RootCap: CRSVisible-
                RootSta: PME ReqID 0000, PMEStatus- PMEPending-
                DevCap2: Completion Timeout: Range BC, TimeoutDis+, LTR-, OBFF Not Supported ARIFwd-
                DevCtl2: Completion Timeout: 50us to 50ms, TimeoutDis-, LTR-, OBFF Disabled ARIFwd-
                LnkCtl2: Target Link Speed: 2.5GT/s, EnterCompliance- SpeedDis-
                         Transmit Margin: Normal Operating Range, EnterModifiedCompliance- ComplianceSOS-
                         Compliance De-emphasis: -6dB
                LnkSta2: Current De-emphasis Level: -3.5dB, EqualizationComplete-, EqualizationPhase1-
                         EqualizationPhase2-, EqualizationPhase3-, LinkEqualizationRequest-
        Capabilities: [80] MSI: Enable- Count=1/1 Maskable- 64bit-
                Address: 00000000  Data: 0000
        Capabilities: [90] Subsystem: Dell Device 04b3
        Capabilities: [a0] Power Management version 2
                Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0+,D1-,D2-,D3hot+,D3cold+)
                Status: D3 NoSoftRst- PME-Enable+ DSel=0 DScale=0 PME-
        Kernel driver in use: pcieport





Nevertheless, I went to check if if the USB3 socket dies after first unplug of device
or not anymore thanks to the patch being tested:

I plugged into the USB3.0 socket a mouse, it worked. Around its unplug I got:

[   94.954779] hub 3-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x100
[   94.954795] hub 3-0:1.0: hub_suspend
[   94.954802] usb usb3: bus auto-suspend, wakeup 1
[   94.954817] xhci_hcd 0000:0b:00.0: xhci_hub_status_data: stopping port polling.
[   94.954835] xhci_hcd 0000:0b:00.0: xhci_suspend: stopping port polling.
[   94.954857] xhci_hcd 0000:0b:00.0: // Setting command ring address to 0xd6007001
[   94.954898] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_suspend: 0
[   94.954983] xhci_hcd 0000:0b:00.0: PME# enabled
[  169.622513] hub 2-1:1.0: state 7 ports 8 chg 0000 evt 0004
[  169.623057] hub 2-1:1.0: port 2, status 0101, change 0001, 12 Mb/s
[  169.777012] hub 2-1:1.0: debounce: port 2: total 100ms stable 100ms status 0x101
[  169.856992] usb 2-1.2: new low-speed USB device number 4 using ehci-pci

and the port was dead, no matter what "lsusb -v or -vv" options I tried. At about
[  169.622513] I plugged the mouse into a USB2.0 socket (do not know if that is 1a.0 or 1d.0).

# lspci -tv
-[0000:00]-+-00.0  Intel Corporation 2nd Generation Core Processor Family DRAM Controller
           +-02.0  Intel Corporation 2nd Generation Core Processor Family Integrated Graphics Controller
           +-16.0  Intel Corporation 6 Series/C200 Series Chipset Family MEI Controller #1
           +-1a.0  Intel Corporation 6 Series/C200 Series Chipset Family USB Enhanced Host Controller #2
           +-1b.0  Intel Corporation 6 Series/C200 Series Chipset Family High Definition Audio Controller
           +-1c.0-[03-04]--
           +-1c.1-[05-06]----00.0  Realtek Semiconductor Co., Ltd. RTL8111/8168 PCI Express Gigabit Ethernet controller
           +-1c.3-[09-0a]----00.0  Intel Corporation Centrino Wireless-N 1030 [Rainbow Peak]
           +-1c.4-[0b-0c]----00.0  Texas Instruments TUSB73x0 SuperSpeed USB 3.0 xHCI Host Controller
           +-1c.7-[11-16]----00.0  Silicon Image, Inc. SiI 3132 Serial ATA Raid II Controller
           +-1d.0  Intel Corporation 6 Series/C200 Series Chipset Family USB Enhanced Host Controller #1
           +-1f.0  Intel Corporation HM67 Express Chipset Family LPC Controller
           +-1f.2  Intel Corporation 6 Series/C200 Series Chipset Family 6 port SATA AHCI Controller
           \-1f.3  Intel Corporation 6 Series/C200 Series Chipset Family SMBus Controller
#


 Why isn't the PME# enabled/disabled reported for the USB2.0 port of the
same laptop? There I can plugin a device many times in and out and not a single PME# line is
spitted by dmesg.
# grep . /sys/bus/pci/devices/*/power/control
/sys/bus/pci/devices/0000:00:00.0/power/control:auto
/sys/bus/pci/devices/0000:00:02.0/power/control:auto
/sys/bus/pci/devices/0000:00:16.0/power/control:auto
/sys/bus/pci/devices/0000:00:1a.0/power/control:auto
/sys/bus/pci/devices/0000:00:1b.0/power/control:auto
/sys/bus/pci/devices/0000:00:1c.0/power/control:auto
/sys/bus/pci/devices/0000:00:1c.1/power/control:auto
/sys/bus/pci/devices/0000:00:1c.3/power/control:auto
/sys/bus/pci/devices/0000:00:1c.4/power/control:auto
/sys/bus/pci/devices/0000:00:1c.7/power/control:auto
/sys/bus/pci/devices/0000:00:1d.0/power/control:auto
/sys/bus/pci/devices/0000:00:1f.0/power/control:auto
/sys/bus/pci/devices/0000:00:1f.2/power/control:auto
/sys/bus/pci/devices/0000:00:1f.3/power/control:auto
/sys/bus/pci/devices/0000:05:00.0/power/control:auto
/sys/bus/pci/devices/0000:09:00.0/power/control:auto
/sys/bus/pci/devices/0000:0b:00.0/power/control:auto
/sys/bus/pci/devices/0000:11:00.0/power/control:auto
# grep . /sys/bus/pci/devices/*/power/runtime_status
/sys/bus/pci/devices/0000:00:00.0/power/runtime_status:suspended
/sys/bus/pci/devices/0000:00:02.0/power/runtime_status:active
/sys/bus/pci/devices/0000:00:16.0/power/runtime_status:suspended
/sys/bus/pci/devices/0000:00:1a.0/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1b.0/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1c.0/power/runtime_status:suspended
/sys/bus/pci/devices/0000:00:1c.1/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1c.3/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1c.4/power/runtime_status:suspended
/sys/bus/pci/devices/0000:00:1c.7/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1d.0/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1f.0/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1f.2/power/runtime_status:active
/sys/bus/pci/devices/0000:00:1f.3/power/runtime_status:suspended
/sys/bus/pci/devices/0000:05:00.0/power/runtime_status:active
/sys/bus/pci/devices/0000:09:00.0/power/runtime_status:active
/sys/bus/pci/devices/0000:0b:00.0/power/runtime_status:suspended
/sys/bus/pci/devices/0000:11:00.0/power/runtime_status:active
#

If I run lsusb -vv it does (with the problematic patch):

[ 1760.414086] pcieport 0000:00:1c.4: PME# disabled
[ 1760.434314] xhci_hcd 0000:0b:00.0: PME# disabled
[ 1760.434327] xhci_hcd 0000:0b:00.0: enabling bus mastering
[ 1760.434338] xhci_hcd 0000:0b:00.0: // Setting command ring address to 0xd6007001
[ 1760.434360] xhci_hcd 0000:0b:00.0: Port Status Change Event for port 2
[ 1760.434363] xhci_hcd 0000:0b:00.0: resume root hub
[ 1760.434367] xhci_hcd 0000:0b:00.0: handle_port_status: starting port polling.
[ 1760.434378] xhci_hcd 0000:0b:00.0: xhci_resume: starting port polling.
[ 1760.434383] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_resume: 0
[ 1760.434388] usb usb3: usb auto-resume
[ 1760.434407] hub 3-0:1.0: hub_resume
[ 1760.434439] xhci_hcd 0000:0b:00.0: get port status, actual port 0 status  = 0x2a0
[ 1760.434440] xhci_hcd 0000:0b:00.0: Get port status returned 0x100
[ 1760.434464] xhci_hcd 0000:0b:00.0: get port status, actual port 1 status  = 0x202a0
[ 1760.434465] xhci_hcd 0000:0b:00.0: Get port status returned 0x10100
[ 1760.434492] xhci_hcd 0000:0b:00.0: clear port connect change, actual port 1 status  = 0x2a0
[ 1760.434642] usb usb4: usb wakeup-resume
[ 1760.434646] usb usb4: usb auto-resume
[ 1760.434661] hub 4-0:1.0: hub_resume
[ 1760.434683] xhci_hcd 0000:0b:00.0: get port status, actual port 0 status  = 0x2a0
[ 1760.434684] xhci_hcd 0000:0b:00.0: Get port status returned 0x2a0
[ 1760.434710] xhci_hcd 0000:0b:00.0: get port status, actual port 1 status  = 0x2a0
[ 1760.434711] xhci_hcd 0000:0b:00.0: Get port status returned 0x2a0
[ 1760.434727] hub 4-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1760.434757] xhci_hcd 0000:0b:00.0: set port remote wake mask, actual port 0 status  = 0xe0002a0
[ 1760.434784] xhci_hcd 0000:0b:00.0: set port remote wake mask, actual port 1 status  = 0xe0002a0
[ 1760.434791] hub 4-0:1.0: hub_suspend
[ 1760.434796] usb usb4: bus auto-suspend, wakeup 1
[ 1760.434807] xhci_hcd 0000:0b:00.0: xhci_hub_status_data: stopping port polling.
[ 1760.553734] xhci_hcd 0000:0b:00.0: xhci_hub_status_data: stopping port polling.
[ 1760.553751] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1760.574793] xhci_hcd 0000:0b:00.0: get port status, actual port 0 status  = 0x2a0
[ 1760.574794] xhci_hcd 0000:0b:00.0: Get port status returned 0x100
[ 1760.575300] xhci_hcd 0000:0b:00.0: get port status, actual port 1 status  = 0x2a0
[ 1760.575301] xhci_hcd 0000:0b:00.0: Get port status returned 0x100
[ 1760.576768] hub 3-0:1.0: hub_suspend
[ 1760.576774] usb usb3: bus auto-suspend, wakeup 1
[ 1760.576789] xhci_hcd 0000:0b:00.0: xhci_hub_status_data: stopping port polling.
[ 1760.576802] xhci_hcd 0000:0b:00.0: xhci_suspend: stopping port polling.
[ 1760.576817] xhci_hcd 0000:0b:00.0: // Setting command ring address to 0xd6007001
[ 1760.576851] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_suspend: 0
[ 1760.576938] xhci_hcd 0000:0b:00.0: PME# enabled
[ 1760.613874] xhci_hcd 0000:0b:00.0: PME# disabled
[ 1760.613884] xhci_hcd 0000:0b:00.0: enabling bus mastering
[ 1760.613895] xhci_hcd 0000:0b:00.0: // Setting command ring address to 0xd6007001
[ 1760.613914] xhci_hcd 0000:0b:00.0: xhci_resume: starting port polling.
[ 1760.613922] xhci_hcd 0000:0b:00.0: xhci_hub_status_data: stopping port polling.
[ 1760.613924] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_resume: 0
[ 1760.613929] usb usb4: usb auto-resume
[ 1760.613945] hub 4-0:1.0: hub_resume
[ 1760.613981] xhci_hcd 0000:0b:00.0: get port status, actual port 0 status  = 0x2a0
[ 1760.613982] xhci_hcd 0000:0b:00.0: Get port status returned 0x2a0
[ 1760.614010] xhci_hcd 0000:0b:00.0: get port status, actual port 1 status  = 0x2a0
[ 1760.614012] xhci_hcd 0000:0b:00.0: Get port status returned 0x2a0
[ 1760.614038] usb usb3: usb wakeup-resume
[ 1760.614040] usb usb3: usb auto-resume
[ 1760.614059] hub 3-0:1.0: hub_resume
[ 1760.614080] xhci_hcd 0000:0b:00.0: get port status, actual port 0 status  = 0x2a0
[ 1760.614081] xhci_hcd 0000:0b:00.0: Get port status returned 0x100
[ 1760.614104] xhci_hcd 0000:0b:00.0: get port status, actual port 1 status  = 0x2a0
[ 1760.614105] xhci_hcd 0000:0b:00.0: Get port status returned 0x100
[ 1760.614122] hub 4-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1760.614126] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1760.614134] hub 3-0:1.0: hub_suspend
[ 1760.614139] usb usb3: bus auto-suspend, wakeup 1
[ 1760.614152] xhci_hcd 0000:0b:00.0: xhci_hub_status_data: stopping port polling.
[ 1760.623621] xhci_hcd 0000:0b:00.0: xhci_hub_status_data: stopping port polling.
[ 1760.646744] xhci_hcd 0000:0b:00.0: get port status, actual port 0 status  = 0x2a0
[ 1760.646746] xhci_hcd 0000:0b:00.0: Get port status returned 0x2a0
[ 1760.647281] xhci_hcd 0000:0b:00.0: get port status, actual port 1 status  = 0x2a0
[ 1760.647283] xhci_hcd 0000:0b:00.0: Get port status returned 0x2a0
[ 1760.657965] xhci_hcd 0000:0b:00.0: set port remote wake mask, actual port 0 status  = 0xe0002a0
[ 1760.657992] xhci_hcd 0000:0b:00.0: set port remote wake mask, actual port 1 status  = 0xe0002a0
[ 1760.658000] hub 4-0:1.0: hub_suspend
[ 1760.658004] usb usb4: bus auto-suspend, wakeup 1
[ 1760.658015] xhci_hcd 0000:0b:00.0: xhci_hub_status_data: stopping port polling.
[ 1760.658027] xhci_hcd 0000:0b:00.0: xhci_suspend: stopping port polling.
[ 1760.658042] xhci_hcd 0000:0b:00.0: // Setting command ring address to 0xd6007001
[ 1760.658074] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_suspend: 0
[ 1760.658159] xhci_hcd 0000:0b:00.0: PME# enabled
[ 1760.683743] pcieport 0000:00:1c.4: PME# enabled



Hope this helps,
Martin




Rafael J. Wysocki wrote:
> From: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
> Subject: PCI / ACPI: Always resume devices on ACPI wakeup notifications
> 
> It turns out that the _Lxx control methods provided by some BIOSes
> clear the PME Status bit of PCI devices they handle, which means that
> pci_acpi_wake_dev() cannot really use that bit to check whether or
> not the device has signalled wakeup.
> 
> One symptom of the problem is, for example, that when an affected PCI
> USB controller is runtime-suspended, then plugging in a new USB device
> into one of the controller's ports will not wake up the controller,
> which should happen.
> 
> For this reason, make pci_acpi_wake_dev() always attempt to resume
> the device it is called for regardless of the device's PME Status bit
> value (that bit still has to be cleared if set at this point,
> though).
> 
> Reported-by: Sarah Sharp <sarah.a.sharp@linux.intel.com>
> Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
> Acked-by: Matthew Garrett <mjg59@srcf.ucam.org>
> Cc: 3.7+ <stable@vger.kernel.org>
> ---
> 
> The changelog in this version is slightly better than in the previous one, IMHO.
> 
> Thanks,
> Rafael
> 
> ---
>  drivers/pci/pci-acpi.c |   15 ++++++++-------
>  1 file changed, 8 insertions(+), 7 deletions(-)
> 
> Index: linux-pm/drivers/pci/pci-acpi.c
> ===================================================================
> --- linux-pm.orig/drivers/pci/pci-acpi.c
> +++ linux-pm/drivers/pci/pci-acpi.c
> @@ -53,14 +53,15 @@ static void pci_acpi_wake_dev(acpi_handl
>  		return;
>  	}
>  
> -	if (!pci_dev->pm_cap || !pci_dev->pme_support
> -	     || pci_check_pme_status(pci_dev)) {
> -		if (pci_dev->pme_poll)
> -			pci_dev->pme_poll = false;
> +	/* Clear PME Status if set. */
> +	if (pci_dev->pme_support)
> +		pci_check_pme_status(pci_dev);
>  
> -		pci_wakeup_event(pci_dev);
> -		pm_runtime_resume(&pci_dev->dev);
> -	}
> +	if (pci_dev->pme_poll)
> +		pci_dev->pme_poll = false;
> +
> +	pci_wakeup_event(pci_dev);
> +	pm_runtime_resume(&pci_dev->dev);
>  
>  	if (pci_dev->subordinate)
>  		pci_pme_wakeup_bus(pci_dev->subordinate);
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-acpi" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
>