Bug 48331

Summary: fl1000 USB3 xhci controller invisible
Product: Drivers Reporter: Jan-Simon Möller (dl9pf)
Component: USBAssignee: Greg Kroah-Hartman (greg)
Status: RESOLVED OBSOLETE    
Severity: high CC: alan, rjw, sarah
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 3.6 Subsystem:
Regression: Yes Bisected commit-id:
Attachments: kernel config used for lates/running kernel build
bzgrep xhci /var/log/messages*.bz2
dmesg from running system (kernel 3.6)
lspci -vv

Description Jan-Simon Möller 2012-10-04 11:41:06 UTC 
Hardware is a ASUS G74SX. It has one USB3 port attached to a fl1000.
OS is openSUSE 11.4 with recent kernel.

The port worked just in newer kernels and not in the stock distro kernel.

An upgrade to kernel 3.6 revealed yesterday that the port is no longer working.
The power is attached, but no device enumerates. Also lspci does no longer show the controller!

I grep'ed my /var/log/messages (attached) and saw traces of the controller in earlier logs, but since a suspend/resume cycle it seems to be vanished - also in non-linux.

A few lines from the attached file:

Oct  1 08:47:30 aragorn kernel: [18736.104027] xhci_hcd 0000:04:00.0: Refused to change power state, currently in D3
Oct  1 08:47:30 aragorn kernel: [18736.104038] xhci_hcd 0000:04:00.0: restoring config space at offset 0xf (was 0xffffffff, writing 0x105)
Oct  1 08:47:30 aragorn kernel: [18736.104043] xhci_hcd 0000:04:00.0: restoring config space at offset 0xe (was 0xffffffff, writing 0x0)
Oct  1 08:47:30 aragorn kernel: [18736.104047] xhci_hcd 0000:04:00.0: restoring config space at offset 0xd (was 0xffffffff, writing 0x50)
Oct  1 08:47:30 aragorn kernel: [18736.104051] xhci_hcd 0000:04:00.0: restoring config space at offset 0xc (was 0xffffffff, writing 0x0)
Oct  1 08:47:30 aragorn kernel: [18736.104055] xhci_hcd 0000:04:00.0: restoring config space at offset 0xb (was 0xffffffff, writing 0x10391043)
Oct  1 08:47:30 aragorn kernel: [18736.104060] xhci_hcd 0000:04:00.0: restoring config space at offset 0xa (was 0xffffffff, writing 0x0)
Oct  1 08:47:30 aragorn kernel: [18736.104064] xhci_hcd 0000:04:00.0: restoring config space at offset 0x9 (was 0xffffffff, writing 0x0)
Oct  1 08:47:30 aragorn kernel: [18736.104068] xhci_hcd 0000:04:00.0: restoring config space at offset 0x8 (was 0xffffffff, writing 0x0)
Oct  1 08:47:30 aragorn kernel: [18736.104072] xhci_hcd 0000:04:00.0: restoring config space at offset 0x7 (was 0xffffffff, writing 0x0)
Oct  1 08:47:30 aragorn kernel: [18736.104076] xhci_hcd 0000:04:00.0: restoring config space at offset 0x6 (was 0xffffffff, writing 0x0)
Oct  1 08:47:30 aragorn kernel: [18736.104080] xhci_hcd 0000:04:00.0: restoring config space at offset 0x5 (was 0xffffffff, writing 0x0)
Oct  1 08:47:30 aragorn kernel: [18736.104084] xhci_hcd 0000:04:00.0: restoring config space at offset 0x4 (was 0xffffffff, writing 0xf4c00000)
Oct  1 08:47:30 aragorn kernel: [18736.104088] xhci_hcd 0000:04:00.0: restoring config space at offset 0x3 (was 0xffffffff, writing 0x10)
Oct  1 08:47:30 aragorn kernel: [18736.104092] xhci_hcd 0000:04:00.0: restoring config space at offset 0x2 (was 0xffffffff, writing 0xc033004)
Oct  1 08:47:30 aragorn kernel: [18736.104096] xhci_hcd 0000:04:00.0: restoring config space at offset 0x1 (was 0xffffffff, writing 0x100403)
Oct  1 08:47:30 aragorn kernel: [18736.104100] xhci_hcd 0000:04:00.0: restoring config space at offset 0x0 (was 0xffffffff, writing 0x10001b73)
Oct  1 08:47:30 aragorn kernel: [18736.114999] xhci_hcd 0000:04:00.0: Refused to change power state, currently in D3
Oct  1 08:47:30 aragorn kernel: [18736.125842] xhci_hcd 0000:04:00.0: Refused to change power state, currently in D3
Oct  1 08:47:30 aragorn kernel: [18736.125864] xhci_hcd 0000:04:00.0: PCI post-resume error -110!
Oct  1 08:47:30 aragorn kernel: [18736.125865] xhci_hcd 0000:04:00.0: HC died; cleaning up
Oct  2 08:19:24 aragorn kernel: [11039.812400] xhci_hcd 0000:04:00.0: wake-up capability enabled by ACPI



Oct  3 11:16:37 aragorn kernel: [49179.190249] xhci_hcd 0000:04:00.0: Refused to change power state, currently in D3
Oct  3 11:16:37 aragorn kernel: [49179.190279] xhci_hcd 0000:04:00.0: WARN: xHC restore state timeout
Oct  3 11:16:37 aragorn kernel: [49179.190280] xhci_hcd 0000:04:00.0: PCI post-resume error -110!
Oct  3 11:16:37 aragorn kernel: [49179.190282] xhci_hcd 0000:04:00.0: HC died; cleaning up
Oct  3 11:16:37 aragorn kernel: [49179.190284] xhci_hcd 0000:04:00.0: HC died; cleaning up
Oct  3 13:37:40 aragorn kernel: [57635.180424] xhci_hcd 0000:04:00.0: remove, state 4
Oct  3 13:37:40 aragorn kernel: [57635.180580] xHCI xhci_drop_endpoint called for root hub
Oct  3 13:37:40 aragorn kernel: [57635.180585] xHCI xhci_check_bandwidth called for root hub
Oct  3 13:37:40 aragorn kernel: [57635.180845] xhci_hcd 0000:04:00.0: Host not halted after 16000 microseconds.
Oct  3 13:37:40 aragorn kernel: [57635.180871] xhci_hcd 0000:04:00.0: USB bus 4 deregistered
Oct  3 13:37:40 aragorn kernel: [57635.180880] xhci_hcd 0000:04:00.0: remove, state 4
Oct  3 13:37:40 aragorn kernel: [57635.181013] xHCI xhci_drop_endpoint called for root hub
Oct  3 13:37:40 aragorn kernel: [57635.181018] xHCI xhci_check_bandwidth called for root hub
Oct  3 13:37:40 aragorn kernel: [57635.181221] xhci_hcd 0000:04:00.0: Host not halted after 16000 microseconds.
Oct  3 13:37:40 aragorn kernel: [57635.181306] xhci_hcd 0000:04:00.0: USB bus 3 deregistered
Oct  3 13:37:49 aragorn kernel: [57644.198905] xhci_hcd 0000:04:00.0: Refused to change power state, currently in D3
Oct  3 13:37:49 aragorn kernel: [57644.199115] xhci_hcd 0000:04:00.0: xHCI Host Controller
Oct  3 13:37:49 aragorn kernel: [57644.199140] xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 3
Oct  3 13:37:49 aragorn kernel: [57644.199185] xhci_hcd 0000:04:00.0: Host not halted after 16000 microseconds.
Oct  3 13:37:49 aragorn kernel: [57644.199215] xhci_hcd 0000:04:00.0: can't setup
Oct  3 13:37:49 aragorn kernel: [57644.199239] xhci_hcd 0000:04:00.0: USB bus 3 deregistered
Oct  3 13:37:49 aragorn kernel: [57644.199315] xhci_hcd 0000:04:00.0: init 0000:04:00.0 fail, -19
Oct  3 13:38:08 aragorn kernel: [57663.521682] xhci_hcd 0000:04:00.0: Refused to change power state, currently in D3
Oct  3 13:38:08 aragorn kernel: [57663.521843] xhci_hcd 0000:04:00.0: xHCI Host Controller
Oct  3 13:38:08 aragorn kernel: [57663.521863] xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 3
Oct  3 13:38:08 aragorn kernel: [57663.521907] xhci_hcd 0000:04:00.0: Host not halted after 16000 microseconds.
Oct  3 13:38:08 aragorn kernel: [57663.521928] xhci_hcd 0000:04:00.0: can't setup
Oct  3 13:38:08 aragorn kernel: [57663.521944] xhci_hcd 0000:04:00.0: USB bus 3 deregistered
Oct  3 13:38:08 aragorn kernel: [57663.522004] xhci_hcd 0000:04:00.0: init 0000:04:00.0 fail, -19
Oct  3 13:38:25 aragorn kernel: [57680.143330] xhci_hcd 0000:04:00.0: Refused to change power state, currently in D3
Oct  3 13:38:25 aragorn kernel: [57680.143496] xhci_hcd 0000:04:00.0: xHCI Host Controller
Oct  3 13:38:25 aragorn kernel: [57680.143520] xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 3
Oct  3 13:38:25 aragorn kernel: [57680.143552] xhci_hcd 0000:04:00.0: Host not halted after 16000 microseconds.
Oct  3 13:38:25 aragorn kernel: [57680.143573] xhci_hcd 0000:04:00.0: can't setup
Oct  3 13:38:25 aragorn kernel: [57680.143589] xhci_hcd 0000:04:00.0: USB bus 3 deregistered
Oct  3 13:38:25 aragorn kernel: [57680.143648] xhci_hcd 0000:04:00.0: init 0000:04:00.0 fail, -19
Oct  3 15:11:41 aragorn kernel: [63270.581231] xhci_hcd 0000:04:00.0: Refused to change power state, currently in D3
Oct  3 15:11:41 aragorn kernel: [63270.581389] xhci_hcd 0000:04:00.0: xHCI Host Controller
Oct  3 15:11:41 aragorn kernel: [63270.581409] xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 3
Oct  3 15:11:41 aragorn kernel: [63270.581445] xhci_hcd 0000:04:00.0: Host not halted after 16000 microseconds.
Oct  3 15:11:41 aragorn kernel: [63270.581466] xhci_hcd 0000:04:00.0: can't setup
Oct  3 15:11:41 aragorn kernel: [63270.581481] xhci_hcd 0000:04:00.0: USB bus 3 deregistered
Oct  3 15:11:41 aragorn kernel: [63270.581538] xhci_hcd 0000:04:00.0: init 0000:04:00.0 fail, -19
Comment 1 Jan-Simon Möller 2012-10-04 11:42:35 UTC 
Created attachment 82061 [details]
kernel config used for lates/running kernel build
Comment 2 Jan-Simon Möller 2012-10-04 11:44:54 UTC 
Created attachment 82071 [details]
bzgrep xhci /var/log/messages*.bz2
Comment 3 Jan-Simon Möller 2012-10-04 11:58:37 UTC 
Created attachment 82081 [details]
dmesg from running system (kernel 3.6)
Comment 4 Jan-Simon Möller 2012-10-04 11:58:59 UTC 
Created attachment 82091 [details]
lspci -vv
Comment 5 Jan-Simon Möller 2012-10-04 12:00:44 UTC 
Comment on attachment 82071 [details]
bzgrep xhci /var/log/messages*.bz2

fixed mime
Comment 6 Jan-Simon Möller 2012-10-04 12:01:15 UTC 
Comment on attachment 82081 [details]
dmesg from running system (kernel 3.6)

fixed mime
Comment 7 Greg Kroah-Hartman 2012-10-04 13:59:16 UTC 
On Thu, Oct 04, 2012 at 11:41:07AM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> 
>            Summary: fl1000 USB3 xhci controller invisible

Please post this to the linux-usb@vger.kernel.org mailing list.
Comment 8 Alan 2012-10-05 10:21:29 UTC 
Oct  1 08:47:30 aragorn kernel: [18736.104027] xhci_hcd 0000:04:00.0: Refused
to change power state, currently in D3

Looks like it may actually be PM related
Comment 9 Rafael J. Wysocki 2012-10-07 21:50:05 UTC 
Yes, it may be PM-related.

I wonder if reverting

commit db288c9c5f9db45610dab3940377625132b4af41
Author: Rafael J. Wysocki <rjw@sisk.pl>
Date:   Thu Jul 5 15:20:00 2012 -0600

    PCI / PM: restore the original behavior of pci_set_power_state()

helps?
Comment 10 Rafael J. Wysocki 2012-10-07 21:54:01 UTC 
And if that doesn't help, please check if reverting the following commits helps:

3d8387e PCI/PM: Fix config reg access for D3cold and bridge suspending
ea8c88f PCI/PM: Keep parent bridge active when probing device
4f9c139 PCI/PM: Enable D3/D3cold by default for most devices
448bd85 PCI/PM: add PCIe runtime D3cold support
Comment 11 Jan-Simon Möller 2012-10-23 09:09:11 UTC 
(In reply to comment #9)
> Yes, it may be PM-related.
> 
> I wonder if reverting
> 
> commit db288c9c5f9db45610dab3940377625132b4af41
> Author: Rafael J. Wysocki <rjw@sisk.pl>
> Date:   Thu Jul 5 15:20:00 2012 -0600
> 
>     PCI / PM: restore the original behavior of pci_set_power_state()
> 
> helps?


Hi all!

Back from travel here is my report:

* Good news is that the controller now enumerates when booted with 2.6.37

* I built 3.6 with db288c9c reverted
  So far the controller enumerates and is usable before/after a s2ram cycle.
  Testing more.