Re: [QUERY] Cold plugged USB device to Inateck PCIE USB card is not detected

[Kishon Vijay Abraham I <kishon@ti.com>]

Hi Mathias,

On 19/08/21 6:48 pm, Mathias Nyman wrote:
> On 19.8.2021 10.54, Kishon Vijay Abraham I wrote:
>> Hi All,
>>
>> I was trying to test PCIe USB card (Inateck) connected to AM64 EVM and
>> J7200 EVM. Inateck uses Renesas uPD720201 USB3 host controller.
>>
>> So if I connect USB pendrive and then boot the board (cold plug), I
>> don't see the pendrive getting detected. But if I remove and plug it
>> again, it gets detected.
>>
>> For the cold plug case, I see this message
>> 	"usb usb1-port3: couldn't allocate usb_device"
>>
>> It actually fails in
>> xhci_alloc_dev()->xhci_queue_slot_control()->queue_command()->XHCI_STATE_HALTED
>>
>> I'm not familiar with xhci but it looks like port event is invoked
>> before the controller is fully initialized (?).
> 
> Maybe this controller is capable of generating interrupts before it's running?

I don't see any MSI interrupts being raised actually..

512:          0          0   ITS-MSI 524288 Edge      xhci_hcd
513:          0          0   ITS-MSI 524289 Edge      xhci_hcd
514:          0          0   ITS-MSI 524290 Edge      xhci_hcd
>  
>>
>> I tried the following hack which kind of changes the sequence where
>> xhci_start() and xhci_run_finished() is invoked before port_event() and
>> with that I could see the pendrive enumerate successfully in cold plug case.
>>
>> diff --git a/drivers/usb/core/hub.c b/drivers/usb/core/hub.c
>> index 228e3d4e1a9f..d19f27c46c6f 100644
>> --- a/drivers/usb/core/hub.c
>> +++ b/drivers/usb/core/hub.c
>> @@ -1077,7 +1077,7 @@ static void hub_activate(struct usb_hub *hub, enum
>> hub_activation_type type)
>>                         INIT_DELAYED_WORK(&hub->init_work, hub_init_func2);
>>                         queue_delayed_work(system_power_efficient_wq,
>>                                         &hub->init_work,
>> -                                       msecs_to_jiffies(delay));
>> +                                       msecs_to_jiffies(150));
>>
>>                         /* Suppress autosuspend until init is done */
>>                         usb_autopm_get_interface_no_resume(
>>
>> Irrespective of the delay the port status looks correct and the modified
>> delay only helps to change the flow.
>>
>> Adding other prints and delays also change the sequence and seems to
>> detect the connected pendrive.
>>
>> Can someone provide hints on how to fix this properly?
> 
> Either keep xHC interrupts disabled until second (usb3) hcd is added, and
> host is running. (haven't thought about side effects yet)
> Or make sure we don't start polling the usb2 roothub until host is running.
> 
> Below code should return before port event handler starts roothub polling if 
> any xhci->xhc_state flag is set. 
> Untested, does it work for you?

I still see the issue. When root hub is polled again in your code
snippet, PORT_CSC is not set and xhci_hub_status_data() returns 0.

I've printed port status in xhci_hub_status_data() below

[    7.422124] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    7.482282] xhci_hcd 0000:01:00.0: new USB bus registered, assigned
bus number 1
[    7.596587] xhci_hcd 0000:01:00.0: hcc params 0x014051cf hci version
0x100 quirks 0x0000001100000410
[    7.679626] usb usb1: New USB device found, idVendor=1d6b,
idProduct=0002, bcdDevice= 5.14
[    7.747969] usb usb1: New USB device strings: Mfr=3, Product=2,
SerialNumber=1
[    7.885643] usb usb1: Product: xHCI Host Controller
[    7.974816] usb usb1: Manufacturer: Linux
5.14.0-rc4-80127-gf061ccba1dcc-dirty xhci-hcd
[    8.004951] usb usb1: SerialNumber: 0000:01:00.0
[    8.016014] hub 1-0:1.0: USB hub found
[    8.020047] hub 1-0:1.0: 4 ports detected
[    8.068702] xhci_hcd 0000:01:00.0: xHCI Host Controller
[    8.142741] xhci_hcd 0000:01:00.0: new USB bus registered, assigned
bus number 2
[    8.196053] usb usb1-port3: couldn't allocate usb_device
[    8.201665] xhci_hub_status_data port=0 status=a0002a0
[    8.206832] xhci_hub_status_data port=1 status=a0002a0
[    8.211977] xhci_hub_status_data port=2 status=c0002e1
[    8.217117] xhci_hub_status_data port=3 status=a0002a0
[    8.259972] xhci_hcd 0000:01:00.0: Host supports USB 3.0 SuperSpeed
[    8.344124] xhci_hub_status_data port=0 status=a0002a0
[    8.349296] xhci_hub_status_data port=1 status=a0002a0
[    8.354439] xhci_hub_status_data port=2 status=c0002e1
[    8.359582] xhci_hub_status_data port=3 status=a0002a0
[    8.458489] usb usb2: We don't know the algorithms for LPM for this
host, disabling LPM.
[    8.531363] usb usb2: New USB device found, idVendor=1d6b,
idProduct=0003, bcdDevice= 5.14
[    8.559934] usb usb2: New USB device strings: Mfr=3, Product=2,
SerialNumber=1
[    8.613931] usb usb2: Product: xHCI Host Controller
[    8.695966] usb usb2: Manufacturer: Linux
5.14.0-rc4-80127-gf061ccba1dcc-dirty xhci-hcd
[    8.805694] usb usb2: SerialNumber: 0000:01:00.0
[    8.848261] hub 2-0:1.0: USB hub found
[    8.905741] hub 2-0:1.0: 4 ports detected
[    8.986168] xhci_hub_status_data port=0 status=a0002a0
[    8.991334] xhci_hub_status_data port=1 status=a0002a0
[    8.996477] xhci_hub_status_data port=2 status=a0002a0
[    9.001616] xhci_hub_status_data port=3 status=a0002a0


I'm unable to get the initial port status in the same run, but on a
different run, the initial port status value looks okay

[    9.603444] xhci_hcd 0000:01:00.0: Get port status 1-1 read: 0x2a0,
return 0x100
[    9.611144] xhci_hcd 0000:01:00.0: Get port status 1-2 read: 0x2a0,
return 0x100
[    9.618832] xhci_hcd 0000:01:00.0: Get port status 1-3 read: 0x202e1,
return 0x10101
[    9.626851] xhci_hcd 0000:01:00.0: Get port status 1-4 read: 0x2a0,
return 0x100

Sometime later the port status changes to c0002e1 (not sure what leads
to it).

As an experiment I added PORT_CONNECT to "mask" in
xhci_hub_status_data() and the device seem to get detected after
multiple "usb usb1-port3: couldn't allocate usb_device". But haven't
tested this extensively and also not sure if there are any side effects.

Thanks
Kishon
> 
> diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
> index e676749f543b..9f4cc5c87b27 100644
> --- a/drivers/usb/host/xhci-ring.c
> +++ b/drivers/usb/host/xhci-ring.c
> @@ -2024,6 +2024,8 @@ static void handle_port_status(struct xhci_hcd *xhci,
>         if (bogus_port_status)
>                 return;
>  
> +       if (xhci->xhc_state != 0)
> +               return;
>         /*
>          * xHCI port-status-change events occur when the "or" of all the
>          * status-change bits in the portsc register changes from 0 to 1.
> diff --git a/drivers/usb/host/xhci.c b/drivers/usb/host/xhci.c
> index f3dabd02382c..b171558956dd 100644
> --- a/drivers/usb/host/xhci.c
> +++ b/drivers/usb/host/xhci.c
> @@ -646,9 +646,15 @@ int xhci_run(struct usb_hcd *hcd)
>          */
>  
>         hcd->uses_new_polling = 1;
> -       if (!usb_hcd_is_primary_hcd(hcd))
> -               return xhci_run_finished(xhci);
> -
> +       if (!usb_hcd_is_primary_hcd(hcd)) {
> +               ret = xhci_run_finished(xhci);
> +               if (ret)
> +                       return ret;
> +               /* start polling usb2 roothub */
> +               set_bit(HCD_FLAG_POLL_RH, &xhci->main_hcd->flags);
> +               usb_hcd_poll_rh_status(xhci->main_hcd);
> +               return ret;
> +       }
>         xhci_dbg_trace(xhci, trace_xhci_dbg_init, "xhci_run");
>  
>         ret = xhci_try_enable_msi(hcd);
> 
> Thanks
> -Mathias
> 
>