Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755793AbdDGITC (ORCPT ); Fri, 7 Apr 2017 04:19:02 -0400 Received: from mga07.intel.com ([134.134.136.100]:59901 "EHLO mga07.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1755597AbdDGISa (ORCPT ); Fri, 7 Apr 2017 04:18:30 -0400 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.37,164,1488873600"; d="asc'?scan'208";a="245742435" From: Felipe Balbi To: John Stultz , Minas Harutyunyan Cc: John Youn , lkml , YongQin Liu , "linux-usb\@vger.kernel.org" Subject: Re: dwc2_hc_chhltd_intr_dma - ChHltd set errors? In-Reply-To: References: <2B3535C5ECE8B5419E3ECBE300772909021B4A47FF@US01WEMBX2.internal.synopsys.com> <410670D7E743164D87FA6160E7907A56FD9F691E@am04wembxb.internal.synopsys.com> <410670D7E743164D87FA6160E7907A56FD9F6F17@am04wembxb.internal.synopsys.com> <87inmkipwc.fsf@linux.intel.com> <410670D7E743164D87FA6160E7907A56FD9F832E@am04wembxb.internal.synopsys.com> <410670D7E743164D87FA6160E7907A56FD9F8F15@am04wembxb.internal.synopsys.com> Date: Fri, 07 Apr 2017 11:18:10 +0300 Message-ID: <87fuhkfx6l.fsf@linux.intel.com> MIME-Version: 1.0 Content-Type: multipart/signed; boundary="=-=-="; micalg=pgp-sha256; protocol="application/pgp-signature" Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 7578 Lines: 169 --=-=-= Content-Type: text/plain Content-Transfer-Encoding: quoted-printable Hi, John Stultz writes: >>>> > >>>> 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 <=3D 0) || >>>> + if ((hsotg->params.host_dma > 0 && >>>> + hsotg->params.dma_desc_enable <=3D 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 lo= gic. >>>> >>>> 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 spee= d 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:C0= 58.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 sp= eed 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 0= xCDE1 >> >> >> 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 spee= d 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:C0= 58.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 =3D -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 :-) =2D-=20 balbi --=-=-= Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- iQIzBAEBCAAdFiEElLzh7wn96CXwjh2IzL64meEamQYFAljnS0IACgkQzL64meEa mQZWfA//cfgcR+AVHZP8LoS/yCtNnvojRSYV+IFcENgPbSalxhJHgHB7R2rFG9Ul MSmLwa2Xd28LXYbbn2WTEGarziQjPyX2vUtsDugnwhDAzKW29R+aCbYRrPJw4bXN v+naMdAm5WohmLcrIJVIzOU5kUkgeztomg8aoCqZOlBzZVRRx+dnxV3RhkwLI3oz B7mHqy2U1iK4YFcRabjOJefoU5eBdN1tIxo1dPV4/U+DLWEbw7h16kCE4GSom5lD TIPxqv1zzOqcqCqNCCp8bnQ1f7NLwuskJuzbDe2lmjic2O2qGsGJmiy7hrVL0yeB lzUbFf+Bol3p0Eru/NDKsMvevx2uvtlAVNEBSGi4w90uwhZrFyI2suRLti8gTGR0 JR8XyC1TLkK9sQ3HypkGeLt9ybcvN5ofBOv6oxaYEJjA7X8CBQmSMU61tutI5DRG Y2pEBLhYSmFNmMONYTZ4NF9Cvjs1POOX6+fIO+OjmcQo8Z5Z2/bxaYKziEkarUyZ xB9ncIwo6u07V02rWj2aRL9/31QR2U0EJ3ZBL96LnzzEPsWcPQ7w1dR7U6pFhx/3 gDzmdIIjmoP+a/l2TasUkadDuiZhQ4ojTG+pcTXz20XyxuHML8JqXjySjQn1UHd/ /bgCNG+XUm0aB3jG+OOLjrFtSRkyKSOb4nO2oze0hJMaB+1fhxU= =srDA -----END PGP SIGNATURE----- --=-=-=--