Message-ID: <410670D7E743164D87FA6160E7907A56FD9FB8D3@am04wembxb.internal.synopsys.com>
Date:   Fri, 7 Apr 2017 12:52:46 +0000
From:   Minas Harutyunyan <Minas.Harutyunyan@...opsys.com>
To:     Felipe Balbi <felipe.balbi@...ux.intel.com>,
        John Stultz <john.stultz@...aro.org>,
        Minas Harutyunyan <Minas.Harutyunyan@...opsys.com>
CC:     John Youn <John.Youn@...opsys.com>,
        lkml <linux-kernel@...r.kernel.org>,
        YongQin Liu <yongqin.liu@...aro.org>,
        "linux-usb@...r.kernel.org" <linux-usb@...r.kernel.org>
Subject: Re: dwc2_hc_chhltd_intr_dma - ChHltd set errors?

Hi,

On 4/7/2017 12:18 PM, Felipe Balbi wrote:
>
> Hi,
>
> John Stultz <john.stultz@...aro.org> writes:
>>>>> <Minas.Harutyunyan@...opsys.com <mailto:Minas.Harutyunyan@...opsys.com>>
>>>>> wrote:
>>>>>> On 4/4/2017 11:03 PM, John Stultz wrote:
>>>>>>>
>>>>>>> I did notice when cating the regdump file, I saw:
>>>>>>> dwc2 f72c0000.usb: Mode Mismatch Interrupt: currently in Host mode
>>>>>>> twice. (You'll see it 4 times in the dmesg around 1077 as I cat'ed
>>>>>>> regdump again to verify it wasn't just chance).
>>>>>>>
>>>>>>> Let me know if there is anything else you need!
>>>>>>>
>>>>>>
>>>>>> Could you please apply attached patch and try again.
>>>>>
>>>>> Thanks for sending this out!
>>>>>
>>>>> So it didn't build against mainline, but I tweaked it a bit:
>>>>> -       if ((hsotg->core_params->dma_enable > 0 &&
>>>>> -            hsotg->core_params->dma_desc_enable <= 0) ||
>>>>> +       if ((hsotg->params.host_dma > 0 &&
>>>>> +            hsotg->params.dma_desc_enable <= 0) ||
>>>>>
>>>>>
>>>>> But I'm still seeing similar behavior:
>>>>> [   91.517417] dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 5 -
>>>>> ChHltd set, but reason is unknown
>>>>> [   91.526693] dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x04000029
>>>>> [   91.533613] asix 1-1.2:1.0 eth0: asix_rx_fixup() Bad Header Length
>>>>> 0x8003a0cc, offset 1302
>>>>> [   91.534102] asix 1-1.2:1.0 eth0: asix_rx_fixup() Bad Header Length
>>>>> 0x73ff5a7d, offset 4
>>>>> [  169.116866] dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 1 -
>>>>> ChHltd set, but reason is unknown
>>>>> [  169.126146] dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x06200029
>>>>> [  170.699334] asix 1-1.2:1.0 eth0: asix_rx_fixup() Bad Header Length
>>>>> 0x36000807, offset 68
>>>>>
>>>>> And I'm not seeing the "Channel can't be halted" error from the new logic.
>>>>>
>>>>> Full dmesg and regdump attached.
>>>>>
>>>>> Let me know if there is something else I should try.
>>>>>
>>>>> thanks
>>>>> -john
>>>> Ok. To enable full dwc2 debug messages, please set USB_DWC2_DEBUG and
>>>> USB_DWC2_VERBOSE in Kernel configuration file.
>>>
>>> Huh. So interestingly adding USB_DWC2_VERBOSE changes some behavior,
>>> which suggests some racy logic somewhere.
>>>
>>> In the dmesg logs provided earlier, I would unplug the micro-B cable,
>>> and the hub would be enabled, detect the mouse, reset to slow-speed,
>>> and then both mouse and eth would be detected (see below for topology
>>> and quirkiness here).
>>>
>>> [  609.726186] dwc2 f72c0000.usb: Set speed to high-speed
>>> [  609.731529] usb 1-1: new high-speed USB device number 26 using dwc2
>>> [  609.921447] dwc2 f72c0000.usb: Set speed to high-speed
>>> [  609.949694] hub 1-1:1.0: USB hub found
>>> [  609.954067] hub 1-1:1.0: 3 ports detected
>>> [  610.246008] dwc2 f72c0000.usb: Set speed to full-speed
>>> [  610.251388] usb 1-1.1: new low-speed USB device number 27 using dwc2
>>> [  610.486571] usb 1-1: USB disconnect, device number 26
>>> [  615.722267] dwc2 f72c0000.usb: Set speed to full-speed
>>> [  615.727580] usb 1-1: new full-speed USB device number 31 using dwc2
>>> [  615.914674] dwc2 f72c0000.usb: Set speed to full-speed
>>> [  615.939233] usb 1-1: not running at top speed; connect to a high speed hub
>>> [  615.949500] hub 1-1:1.0: USB hub found
>>> [  615.953815] hub 1-1:1.0: 3 ports detected
>>> [  616.246178] dwc2 f72c0000.usb: Set speed to full-speed
>>> [  616.251539] usb 1-1.1: new low-speed USB device number 32 using dwc2
>>> [  616.342042] dwc2 f72c0000.usb: Set speed to full-speed
>>> [  616.393609] input: Logitech USB Optical Mouse as
>>> /devices/platform/soc/f72c0000.usb/usb1/1-1/1-1.1/1-1.1:1.0/0003:046D:C058.0004/input/in4
>>> [  616.408426] hid-generic 0003:046D:C058.0004: input,hidraw0: USB HID
>>> v1.11 Mouse [Logitech USB Optical Mouse] on usb-f72c0000.usb-1.1/inpu0
>>> [  616.506057] dwc2 f72c0000.usb: Set speed to full-speed
>>> [  616.511449] usb 1-1.2: new full-speed USB device number 33 using dwc2
>>> [  616.598037] dwc2 f72c0000.usb: Set speed to full-speed
>>> [  616.626890] usb 1-1.2: not running at top speed; connect to a high speed hub
>>> [  617.098791] asix 1-1.2:1.0 eth0: register 'asix' at
>>> usb-f72c0000.usb-1.2, ASIX AX88772B USB 2.0 Ethernet,
>>> 00:50:b6:18:82:98
>>> [  617.112147] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
>>> [  618.660076] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
>>> [  618.682072] asix 1-1.2:1.0 eth0: link up, 100Mbps, full-duplex, lpa 0xCDE1
>>>
>>>
>>> But with DWC2_VERBOSE enabled, I'm usually seeing the following (this
>>> is what hit the console, not from the full dmesg output):
>>>
>>> [   83.658545] dwc2 f72c0000.usb: Set speed to high-speed
>>> [   83.663897] usb 1-1: new high-speed USB device number 2 using dwc2
>>> [   83.854516] dwc2 f72c0000.usb: Set speed to high-speed
>>> [   83.901097] hub 1-1:1.0: USB hub found
>>> [   83.910054] hub 1-1:1.0: 3 ports detected
>>> [   84.241753] dwc2 f72c0000.usb: Set speed to full-speed
>>> [   84.247008] usb 1-1.1: new low-speed USB device number 3 using dwc2
>>> [   84.479943] usb 1-1: USB disconnect, device number 2
>>> [   89.646499] dwc2 f72c0000.usb: Set speed to full-speed
>>> [   89.651849] usb 1-1: new full-speed USB device number 7 using dwc2
>>> [   89.842541] dwc2 f72c0000.usb: Set speed to full-speed
>>> [   89.879490] usb 1-1: not running at top speed; connect to a high speed hub
>>> [   89.906483] hub 1-1:1.0: USB hub found
>>> [   89.915009] hub 1-1:1.0: 3 ports detected
>>> [   90.245919] dwc2 f72c0000.usb: Set speed to full-speed
>>> [   90.251114] usb 1-1.1: new low-speed USB device number 8 using dwc2
>>> [   90.337866] dwc2 f72c0000.usb: Set speed to full-speed
>>> [   90.385747] input: Logitech USB Optical Mouse as
>>> /devices/platform/soc/f72c0000.usb/usb1/1-1/1-1.1/1-1.1:1.0/0003:046D:C058.0001/input/in1
>>> [   90.398904] hid-generic 0003:046D:C058.0001: input,hidraw0: USB HID
>>> v1.11 Mouse [Logitech USB Optical Mouse] on usb-f72c0000.usb-1.1/inpu0
>>> [   90.414011] hub 1-1:1.0: hub_ext_port_status failed (err = -71)
>>>
>>> And the eth adapter doesn't seem to be detected.
>>>
>>> So I've attached the dmesg w/ VERBOSE off, but with DEBUG on.
>>
>> I went ahead and collected the VERBOSE logs too around the
>> "dwc2_hc_chhltd_intr_dma: Channel 11 - ChHltd set, but reason is
>> unknown" message.  That VERBOSE flag generates a lot of data! I set my
>> kernel dmesg buffer to 16M and managed save dmesg quickly after I
>> noticed the error message, but I only got ~25 seconds around the
>> event.
>
> you can replace all dev_*() messages with trace_printk() and use the
> ftrace buffer for logging. I generally use 100MiB trace buffer without
> any issues :-)
>

Based on HiKey data book, to USB ports (typeA) can be connected devices
only with same speed. In your case mouse is Low speed and Ethernet
dongle connected as Full speed. It can be cause of issue.
Did you tested Ethernet dongle (in High and Full speed modes) without
connecting mouse? If it work (in Full speed) then connect mouse and see
how it affect on Ethernet.
Thanks,
Minas

Powered by blists - more mailing lists