Date:   Fri, 07 Apr 2017 11:18:10 +0300
From:   Felipe Balbi <felipe.balbi@...ux.intel.com>
To:     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\@vger.kernel.org" <linux-usb@...r.kernel.org>
Subject: Re: dwc2_hc_chhltd_intr_dma - ChHltd set errors?


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 :-)

-- 
balbi

Download attachment "signature.asc" of type "application/pgp-signature" (833 bytes)

Powered by blists - more mailing lists