Hey John,
We've noticed that when using usb ethernet adapters on HiKey, we
occasionally see errors like:
dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 0 - ChHltd set,
but reason is unknown
dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x06200029
dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 11 - ChHltd set,
but reason is unknown
dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x04200029
Sometimes followed up by a usb error in the driver, something like:
asix 1-1.2:1.0 eth0: asix_rx_fixup() Bad Header Length 0x36000807, offset 68
Curious if you've seen any reports like this?
We haven't seen it with a older 4.4 tree we've been using (which had a
bit more out of tree changes to it), but it was discovered with the
4.9 branch we have, and I've confirmed its happening with the upstream
kernel too, so I need to try to jump back to some older trees to see
where it might have first cropped up.
thanks
-john
On Thu, Mar 2, 2017 at 12:00 PM, John Stultz <[email protected]> wrote:
> Hey John,
> We've noticed that when using usb ethernet adapters on HiKey, we
> occasionally see errors like:
>
> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 0 - ChHltd set,
> but reason is unknown
> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x06200029
>
> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 11 - ChHltd set,
> but reason is unknown
> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x04200029
>
> Sometimes followed up by a usb error in the driver, something like:
> asix 1-1.2:1.0 eth0: asix_rx_fixup() Bad Header Length 0x36000807, offset 68
>
> Curious if you've seen any reports like this?
Hey John,
Just wanted to check in again on this to see if you've seen anything
like it? I've not had too much time to debug it, but my attempts so
far haven't been productive.
thanks
-john
On 03/31/2017 04:04 PM, John Stultz wrote:
> On Thu, Mar 2, 2017 at 12:00 PM, John Stultz <[email protected]> wrote:
>> Hey John,
>> We've noticed that when using usb ethernet adapters on HiKey, we
>> occasionally see errors like:
>>
>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 0 - ChHltd set,
>> but reason is unknown
>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x06200029
>>
>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 11 - ChHltd set,
>> but reason is unknown
>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x04200029
>>
>> Sometimes followed up by a usb error in the driver, something like:
>> asix 1-1.2:1.0 eth0: asix_rx_fixup() Bad Header Length 0x36000807, offset 68
>>
>> Curious if you've seen any reports like this?
>
> Hey John,
> Just wanted to check in again on this to see if you've seen anything
> like it? I've not had too much time to debug it, but my attempts so
> far haven't been productive.
>
I don't think I've seen that.
We'll try to take a look this week.
Thanks,
John
Hi,
On 4/3/2017 9:23 AM, John Youn wrote:
> On 03/31/2017 04:04 PM, John Stultz wrote:
>> On Thu, Mar 2, 2017 at 12:00 PM, John Stultz <[email protected]> wrote:
>>> Hey John,
>>> We've noticed that when using usb ethernet adapters on HiKey, we
>>> occasionally see errors like:
>>>
>>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 0 - ChHltd set,
>>> but reason is unknown
>>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x06200029
>>>
>>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 11 - ChHltd set,
>>> but reason is unknown
>>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x04200029
>>>
>>> Sometimes followed up by a usb error in the driver, something like:
>>> asix 1-1.2:1.0 eth0: asix_rx_fixup() Bad Header Length 0x36000807, offset 68
>>>
>>> Curious if you've seen any reports like this?
>>
>> Hey John,
>> Just wanted to check in again on this to see if you've seen anything
>> like it? I've not had too much time to debug it, but my attempts so
>> far haven't been productive.
>>
>
> I don't think I've seen that.
>
> We'll try to take a look this week.
>
> Thanks,
> John
>
>
>
The core version is less than 2.71a, am I right?
Please send full debug log to do more investigation.
Also send us regdump after connecting ethernet adapter.
Thanks,
Minas
On Mon, Apr 3, 2017 at 5:54 AM, Minas Harutyunyan
<[email protected]> wrote:
> On 4/3/2017 9:23 AM, John Youn wrote:
>> On 03/31/2017 04:04 PM, John Stultz wrote:
>>> On Thu, Mar 2, 2017 at 12:00 PM, John Stultz <[email protected]> wrote:
>>>> Hey John,
>>>> We've noticed that when using usb ethernet adapters on HiKey, we
>>>> occasionally see errors like:
>>>>
>>>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 0 - ChHltd set,
>>>> but reason is unknown
>>>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x06200029
>>>>
>>>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 11 - ChHltd set,
>>>> but reason is unknown
>>>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x04200029
>>>>
>>>> Sometimes followed up by a usb error in the driver, something like:
>>>> asix 1-1.2:1.0 eth0: asix_rx_fixup() Bad Header Length 0x36000807, offset 68
>>>>
>>>> Curious if you've seen any reports like this?
>
> The core version is less than 2.71a, am I right?
So it looks like its reporting 0x4f54300a for hsotg->regs + GSNPSID
which looks like DWC2_CORE_REV_3_00a
> Please send full debug log to do more investigation.
Full dmesg, or is there special debugging you want me to enable?
> Also send us regdump after connecting ethernet adapter.
Sorry, can you clarify how to generate this?
thanks
-john
Hi,
On 4/4/2017 7:04 AM, John Stultz wrote:
> On Mon, Apr 3, 2017 at 5:54 AM, Minas Harutyunyan
> <[email protected]> wrote:
>> On 4/3/2017 9:23 AM, John Youn wrote:
>>> On 03/31/2017 04:04 PM, John Stultz wrote:
>>>> On Thu, Mar 2, 2017 at 12:00 PM, John Stultz <[email protected]> wrote:
>>>>> Hey John,
>>>>> We've noticed that when using usb ethernet adapters on HiKey, we
>>>>> occasionally see errors like:
>>>>>
>>>>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 0 - ChHltd set,
>>>>> but reason is unknown
>>>>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x06200029
>>>>>
>>>>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 11 - ChHltd set,
>>>>> but reason is unknown
>>>>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x04200029
>>>>>
>>>>> Sometimes followed up by a usb error in the driver, something like:
>>>>> asix 1-1.2:1.0 eth0: asix_rx_fixup() Bad Header Length 0x36000807, offset 68
>>>>>
>>>>> Curious if you've seen any reports like this?
>>
>> The core version is less than 2.71a, am I right?
>
> So it looks like its reporting 0x4f54300a for hsotg->regs + GSNPSID
> which looks like DWC2_CORE_REV_3_00a
>
>> Please send full debug log to do more investigation.
>
> Full dmesg, or is there special debugging you want me to enable?
Full dmesg around issue.
>
>> Also send us regdump after connecting ethernet adapter.
>
> Sorry, can you clarify how to generate this?
cat regdump. To locate dwc2 regdump file: cd /; find -name regdump
>
> thanks
> -john
>
Thanks,
Minas
Hi,
Minas Harutyunyan <[email protected]> writes:
>>>>>> We've noticed that when using usb ethernet adapters on HiKey, we
>>>>>> occasionally see errors like:
>>>>>>
>>>>>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 0 - ChHltd set,
>>>>>> but reason is unknown
>>>>>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x06200029
>>>>>>
>>>>>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 11 - ChHltd set,
>>>>>> but reason is unknown
>>>>>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x04200029
>>>>>>
>>>>>> Sometimes followed up by a usb error in the driver, something like:
>>>>>> asix 1-1.2:1.0 eth0: asix_rx_fixup() Bad Header Length 0x36000807, offset 68
>>>>>>
>>>>>> Curious if you've seen any reports like this?
>>>
>>> The core version is less than 2.71a, am I right?
>>
>> So it looks like its reporting 0x4f54300a for hsotg->regs + GSNPSID
>> which looks like DWC2_CORE_REV_3_00a
>>
>>> Please send full debug log to do more investigation.
>>
>> Full dmesg, or is there special debugging you want me to enable?
>
> Full dmesg around issue.
>>
>>> Also send us regdump after connecting ethernet adapter.
>>
>> Sorry, can you clarify how to generate this?
>
> cat regdump. To locate dwc2 regdump file: cd /; find -name regdump
this won't work if his distro doesn't mount debugfs. Please give
complete instructions ;-)
# mkdir -p /d
# mount -t debugfs none /d
# cd /d
# find . -name regdump
The directory name is the same name as the dwc2 device name, AFAICT. So,
check your DTS for the name of the device.
--
balbi
On Tue, Apr 4, 2017 at 12:38 AM, Felipe Balbi
<[email protected]> wrote:
>
> Hi,
>
> Minas Harutyunyan <[email protected]> writes:
>>>>>>> We've noticed that when using usb ethernet adapters on HiKey, we
>>>>>>> occasionally see errors like:
>>>>>>>
>>>>>>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 0 - ChHltd set,
>>>>>>> but reason is unknown
>>>>>>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x06200029
>>>>>>>
>>>>>>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 11 - ChHltd set,
>>>>>>> but reason is unknown
>>>>>>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x04200029
>>>>>>>
>>>>>>> Sometimes followed up by a usb error in the driver, something like:
>>>>>>> asix 1-1.2:1.0 eth0: asix_rx_fixup() Bad Header Length 0x36000807, offset 68
>>>>>>>
>>>>>>> Curious if you've seen any reports like this?
>>>>
>>>> The core version is less than 2.71a, am I right?
>>>
>>> So it looks like its reporting 0x4f54300a for hsotg->regs + GSNPSID
>>> which looks like DWC2_CORE_REV_3_00a
>>>
>>>> Please send full debug log to do more investigation.
>>>
>>> Full dmesg, or is there special debugging you want me to enable?
>>
>> Full dmesg around issue.
>>>
>>>> Also send us regdump after connecting ethernet adapter.
>>>
>>> Sorry, can you clarify how to generate this?
>>
>> cat regdump. To locate dwc2 regdump file: cd /; find -name regdump
>
> this won't work if his distro doesn't mount debugfs. Please give
> complete instructions ;-)
>
> # mkdir -p /d
> # mount -t debugfs none /d
> # cd /d
> # find . -name regdump
>
> The directory name is the same name as the dwc2 device name, AFAICT. So,
> check your DTS for the name of the device.
Thanks for the extra details! I didn't have DEBUG_FS built in, so this
helped clue me in.
Attached are dmesg including the issue and the regdump.
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!
thanks
-john
Hi,
On 4/4/2017 11:03 PM, John Stultz wrote:
> On Tue, Apr 4, 2017 at 12:38 AM, Felipe Balbi
> <[email protected]> wrote:
>>
>> Hi,
>>
>> Minas Harutyunyan <[email protected]> writes:
>>>>>>>> We've noticed that when using usb ethernet adapters on HiKey, we
>>>>>>>> occasionally see errors like:
>>>>>>>>
>>>>>>>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 0 - ChHltd set,
>>>>>>>> but reason is unknown
>>>>>>>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x06200029
>>>>>>>>
>>>>>>>> dwc2 f72c0000.usb: dwc2_hc_chhltd_intr_dma: Channel 11 - ChHltd set,
>>>>>>>> but reason is unknown
>>>>>>>> dwc2 f72c0000.usb: hcint 0x00000002, intsts 0x04200029
>>>>>>>>
>>>>>>>> Sometimes followed up by a usb error in the driver, something like:
>>>>>>>> asix 1-1.2:1.0 eth0: asix_rx_fixup() Bad Header Length 0x36000807, offset 68
>>>>>>>>
>>>>>>>> Curious if you've seen any reports like this?
>>>>>
>>>>> The core version is less than 2.71a, am I right?
>>>>
>>>> So it looks like its reporting 0x4f54300a for hsotg->regs + GSNPSID
>>>> which looks like DWC2_CORE_REV_3_00a
>>>>
>>>>> Please send full debug log to do more investigation.
>>>>
>>>> Full dmesg, or is there special debugging you want me to enable?
>>>
>>> Full dmesg around issue.
>>>>
>>>>> Also send us regdump after connecting ethernet adapter.
>>>>
>>>> Sorry, can you clarify how to generate this?
>>>
>>> cat regdump. To locate dwc2 regdump file: cd /; find -name regdump
>>
>> this won't work if his distro doesn't mount debugfs. Please give
>> complete instructions ;-)
>>
>> # mkdir -p /d
>> # mount -t debugfs none /d
>> # cd /d
>> # find . -name regdump
>>
>> The directory name is the same name as the dwc2 device name, AFAICT. So,
>> check your DTS for the name of the device.
>
> Thanks for the extra details! I didn't have DEBUG_FS built in, so this
> helped clue me in.
>
> Attached are dmesg including the issue and the regdump.
>
> 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!
>
> thanks
> -john
>
Could you please apply attached patch and try again.
Thanks,
Minas
On 4/6/2017 1:03 AM, John Stultz wrote:
>
>
> On Wed, Apr 5, 2017 at 5:58 AM, Minas Harutyunyan
> <[email protected] <mailto:[email protected]>>
> 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.
Also provide the topology of connected devices(class, speed) to dwc2
root hub.
Thanks,
Minas
On Thu, Apr 6, 2017 at 12:36 AM, Minas Harutyunyan
<[email protected]> wrote:
> On 4/6/2017 1:03 AM, John Stultz wrote:
>>
>>
>> On Wed, Apr 5, 2017 at 5:58 AM, Minas Harutyunyan
>> <[email protected] <mailto:[email protected]>>
>> 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.
> Also provide the topology of connected devices(class, speed) to dwc2
> root hub.
So HiKey is a bit quirky, and you can see how things are conencted on
page 12 of this manual:
https://www.96boards.org/wp-content/uploads/2015/02/HiKey_User_Guide_Rev0.2.pdf
Baiscally there's one OTG controller, that is connected to a switch,
which goes between the micro-B socket, and a hub. The hub is then
connected to two A sockets (and lines on the highspeed port).
Unfortunately the hub cannot handle mixed highspeed and lowspeed
devices at the same time (so, if I recall the terms properly, it
doesn't handle "split transactions").
Anyway the micro-B socket has priority, so if a cable is connected
there, the hub/A sockets are disconnected.
Normally, I've been plugging in a usb-mouse (low-speed) and
usb-ethernet adapter (high-speed) to the two A sockets, hanging off
the built-in hub. Since there is the usb-mouse involved, the
interface is set to low-speed, so everything is running at low-speed.
Let me know if you have more questions or need more debug data.
thanks
-john
Hi,
John Stultz <[email protected]> writes:
>>>> <[email protected] <mailto:[email protected]>>
>>>> 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
Hi,
On 4/7/2017 12:18 PM, Felipe Balbi wrote:
>
> Hi,
>
> John Stultz <[email protected]> writes:
>>>>> <[email protected] <mailto:[email protected]>>
>>>>> 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