From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S935524AbcISLPn (ORCPT ); Mon, 19 Sep 2016 07:15:43 -0400 Received: from mga07.intel.com ([134.134.136.100]:15671 "EHLO mga07.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S938583AbcISLMt (ORCPT ); Mon, 19 Sep 2016 07:12:49 -0400 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.30,361,1470726000"; d="asc'?scan'208";a="10877284" From: Felipe Balbi To: Alan Stern Cc: Peter Zijlstra , "Paul E. McKenney" , Ingo Molnar , USB list , Kernel development list , Will Deacon Subject: Re: Memory barrier needed with wake_up_process()? In-Reply-To: References: User-Agent: Notmuch/0.22.1+63~g994277e (https://notmuchmail.org) Emacs/25.1.3 (x86_64-pc-linux-gnu) Date: Mon, 19 Sep 2016 14:11:51 +0300 Message-ID: <878tuo4008.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-Type: text/plain Content-Transfer-Encoding: quoted-printable Hi Alan, Alan Stern writes: > On Fri, 9 Sep 2016, Felipe Balbi wrote: > >> Finally :-) Here's the diff I used: >>=20 >> diff --git a/drivers/usb/gadget/function/f_mass_storage.c b/drivers/usb/= gadget/function/f_mass_storage.c >> index 8f3659b65f53..0716024f6b65 100644 >> --- a/drivers/usb/gadget/function/f_mass_storage.c >> +++ b/drivers/usb/gadget/function/f_mass_storage.c >> @@ -481,6 +481,8 @@ static void bulk_out_complete(struct usb_ep *ep, str= uct usb_request *req) >> spin_lock(&common->lock); >> bh->outreq_busy =3D 0; >> bh->state =3D BUF_STATE_FULL; >> + if (bh->bulk_out_intended_length =3D=3D US_BULK_CB_WRAP_LEN) >> + trace_printk("compl: bh %p state %d\n", bh, bh->state); >> wakeup_thread(common); >> spin_unlock(&common->lock); >> } >> @@ -2208,6 +2210,7 @@ static int get_next_command(struct fsg_common *com= mon) >> rc =3D sleep_thread(common, true); >> if (rc) >> return rc; >> + trace_printk("next: bh %p state %d\n", bh, bh->state); >> } >> smp_rmb(); >> rc =3D fsg_is_set(common) ? received_cbw(common->fsg, bh) : -EIO; >>=20 >>=20 >> And here's trace output: >>=20 >> # tracer: nop >> # >> # entries-in-buffer/entries-written: 1002/1002 #P:4 >> # >> # _-----=3D> irqs-off >> # / _----=3D> need-resched >> # | / _---=3D> hardirq/softirq >> # || / _--=3D> preempt-depth >> # ||| / delay >> # TASK-PID CPU# |||| TIMESTAMP FUNCTION >> # | | | |||| | | >> file-storage-3578 [000] .... 21166.789127: fsg_main_thread: next: b= h ffff880111e69a00 state 2 >> file-storage-3578 [000] .... 21166.789312: fsg_main_thread: next: b= h ffff880111e69a00 state 2 >> irq/17-dwc3-3579 [003] d..1 21166.789395: bulk_out_complete: compl= : bh ffff880111e69a00 state 1 >> file-storage-3578 [000] .... 21166.789445: fsg_main_thread: next: b= h ffff880111e69a00 state 1 > > Okay, that's normal. 2 =3D BUF_STATE_BUSY, 1 =3D BUF_STATE_FULL. So we = get woken > up a couple of times while the transfer is in progress (probably because = some > earlier buffers have finished transferring), then the CBW transfer comple= tes > and the buffer is read. > > ... > >> file-storage-3578 [002] .... 21167.726827: fsg_main_thread: next: b= h ffff880111e69a80 state 2 >> irq/17-dwc3-3579 [003] d..1 21167.727066: bulk_out_complete: compl= : bh ffff880111e69a80 state 1 >> file-storage-3578 [002] .... 21167.727072: fsg_main_thread: next: b= h ffff880111e69a80 state 1 >> file-storage-3578 [002] .... 21167.729458: fsg_main_thread: next: b= h ffff880111e6aac0 state 2 >> irq/17-dwc3-3579 [003] d..1 21167.729666: bulk_out_complete: compl= : bh ffff880111e6aac0 state 1 >> file-storage-3578 [002] .... 21167.729670: fsg_main_thread: next: b= h ffff880111e6aac0 state 1 > > And this is where everything stopped? yeah, that's everything. > This also looks normal. So the question is what happened when=20 > get_next_command() returned after this? > > Felipe, maybe the patch below (in place of your current patch) will > help. Since the events that it logs are all supposed to be unusual, > you can use printk if you want, but I wrote it with trace_printk. I've applied your patch and it wasn't giving me any output, which hinted that g_mass_storage wasn't returning any failures. So I enabled dwc3's traces to get more data out of it. Here's the final snippet (with comments, again). Let me know if you want the entire thing (it's ~14MiB). > irq/17-dwc3-3527 [003] d..1 34.215214: dwc3_event: event (00110301): = Link Change [U1] > irq/17-dwc3-3527 [003] d..1 34.215214: dwc3_event: event (00004086): = ep1in: Transfer In-Progress > irq/17-dwc3-3527 [003] d..1 34.215214: dwc3_complete_trb: ep1in: 2/25= 5 trb ffff880084813e70 buf 0000000080808000 size 0 ctrl 00000c18 (hlcS:SC:n= ormal) > irq/17-dwc3-3527 [003] d..1 34.215214: dwc3_gadget_giveback: ep1in: r= eq ffff88016d046840 length 16384/16384 zsI =3D=3D> 0 > irq/17-dwc3-3527 [003] d... 34.215215: usb_gadget_giveback_request: e= p1in: length 16384/16384 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3527 [003] d..1 34.215218: dwc3_gadget_ep_cmd: ep1in: cmd= 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: S= uccessful > irq/17-dwc3-3527 [003] d..1 34.215281: dwc3_event: event (00100301): = Link Change [U0] > irq/17-dwc3-3527 [003] d..1 34.215281: dwc3_event: event (00110301): = Link Change [U1] > irq/17-dwc3-3527 [003] d..1 34.215282: dwc3_event: event (00004086): = ep1in: Transfer In-Progress > irq/17-dwc3-3527 [003] d..1 34.215282: dwc3_complete_trb: ep1in: 1/25= 5 trb ffff880084813e80 buf 000000008080c000 size 0 ctrl 00000c18 (hlcS:SC:n= ormal) > irq/17-dwc3-3527 [003] d..1 34.215282: dwc3_gadget_giveback: ep1in: r= eq ffff88016d046f00 length 13/13 zsI =3D=3D> 0 > irq/17-dwc3-3527 [003] d... 34.215283: usb_gadget_giveback_request: e= p1in: length 13/13 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3527 [003] d..1 34.215284: dwc3_event: event (00100301): = Link Change [U0] > irq/17-dwc3-3527 [003] d..1 34.215284: dwc3_event: event (00110301): = Link Change [U1] > irq/17-dwc3-3527 [003] d..1 34.215284: dwc3_event: event (00006084): = ep1out: Transfer In-Progress > irq/17-dwc3-3527 [003] d..1 34.215284: dwc3_complete_trb: ep1out: 1/2= 55 trb ffff880084804320 buf 000000008080c800 size 993 ctrl 00000c18 (hlcS:S= C:normal) > irq/17-dwc3-3527 [003] d..1 34.215285: dwc3_gadget_giveback: ep1out: = req ffff880154205300 length 31/1024 zsI =3D=3D> 0 > irq/17-dwc3-3527 [003] d... 34.215285: usb_gadget_giveback_request: e= p1out: length 31/1024 sgs 0/0 stream 0 zsI status 0 --> 0 completed and gave back CBW. > irq/17-dwc3-3527 [003] d..1 34.215349: dwc3_event: event (00100301): = Link Change [U0] > irq/17-dwc3-3527 [003] d..1 34.215349: dwc3_event: event (00110301): = Link Change [U1] > irq/17-dwc3-3527 [003] d..1 34.225616: dwc3_event: event (00120301): = Link Change [U2] > irq/17-dwc3-3527 [003] d... 34.225617: usb_gadget_vbus_draw: speed 5/= 5 state 7 0mA [sg:out_aligned:self-powered:activated:connected] --> -95 > irq/17-dwc3-3527 [003] d..1 64.832221: dwc3_event: event (00100301): = Link Change [U0] 30 seconds of nothing. > irq/17-dwc3-3527 [003] d..1 64.832240: dwc3_event: event (0000c040): = ep0out: Transfer Complete > irq/17-dwc3-3527 [003] d..1 64.832243: dwc3_ep0: ep0out: Transfer Com= plete: state 'Setup Phase' > irq/17-dwc3-3527 [003] d..1 64.832243: dwc3_ep0: Setup Phase > irq/17-dwc3-3527 [003] d..1 64.832244: dwc3_ctrl_req: bRequestType 00= bRequest 01 wValue 0030 wIndex 0000 wLength 0 > irq/17-dwc3-3527 [003] d..1 64.832244: dwc3_ep0: USB_REQ_CLEAR_FEATURE > irq/17-dwc3-3527 [003] d..1 64.832253: dwc3_event: event (000020c2): = ep0in: Transfer Not Ready (Not Active) > irq/17-dwc3-3527 [003] d..1 64.832254: dwc3_ep0: ep0in: Transfer Not = Ready (Not Active): state 'Setup Phase' > irq/17-dwc3-3527 [003] d..1 64.832254: dwc3_ep0: Control Status > irq/17-dwc3-3527 [003] d..1 64.832255: dwc3_prepare_trb: ep0in: 0/0 t= rb ffff880084802000 buf 0000000084801000 size 0 ctrl 00000c33 (HLcs:SC:stat= us2) > irq/17-dwc3-3527 [003] d..1 64.832258: dwc3_gadget_ep_cmd: ep0in: cmd= 'Start Transfer' [6] params 00000000 84802000 00000000 --> status: Success= ful > irq/17-dwc3-3527 [003] d..1 64.832348: dwc3_event: event (0000c042): = ep0in: Transfer Complete > irq/17-dwc3-3527 [003] d..1 64.832349: dwc3_ep0: ep0in: Transfer Comp= lete: state 'Status Phase' > irq/17-dwc3-3527 [003] d..1 64.832350: dwc3_ep0: Status Phase > irq/17-dwc3-3527 [003] d..1 64.832350: dwc3_complete_trb: ep0out: 0/1= trb ffff880084802000 buf 0000000084801000 size 0 ctrl 00000c32 (hLcs:SC:st= atus2) > irq/17-dwc3-3527 [003] d..1 64.832351: dwc3_prepare_trb: ep0out: 0/1 = trb ffff880084802000 buf 0000000084801000 size 8 ctrl 00000c23 (HLcs:SC:set= up) > irq/17-dwc3-3527 [003] d..1 64.832360: dwc3_gadget_ep_cmd: ep0out: cm= d 'Start Transfer' [6] params 00000000 84802000 00000000 --> status: Succes= sful > irq/17-dwc3-3527 [003] d..1 64.832362: dwc3_event: event (00120301): = Link Change [U2] > irq/17-dwc3-3527 [003] d... 64.832364: usb_gadget_vbus_draw: speed 5/= 5 state 7 0mA [sg:out_aligned:self-powered:activated:connected] --> -95 > irq/17-dwc3-3527 [003] d..1 64.832718: dwc3_event: event (00100301): = Link Change [U0] > irq/17-dwc3-3527 [003] d..1 64.832737: dwc3_event: event (0000c040): = ep0out: Transfer Complete New enumeration. Nothing really screaming wrong here. The only errors returned by mass storage happen after the 30s timeout: $ grep -RnH "raise_exception\|fsg_main_thread" /tmp/trace.txt=20 /tmp/trace.txt:111743: irq/17-dwc3-3527 [003] d..1 64.833078: raise= _exception: raise_exception 4 /tmp/trace.txt:111745: file-storage-3526 [002] .... 64.833139: fsg_m= ain_thread: get_next_command -> -4 /tmp/trace.txt:111746: file-storage-3526 [002] .... 64.833140: fsg_m= ain_thread: handling exception /tmp/trace.txt:112950: irq/17-dwc3-3527 [003] d..1 64.951349: raise= _exception: raise_exception 4 /tmp/trace.txt:112956: file-storage-3526 [002] .... 64.951401: fsg_m= ain_thread: handling exception Any ideas? =2D-=20 balbi --=-=-= Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- iQIcBAEBCAAGBQJX38f3AAoJEMy+uJnhGpkG52kP/jxJH/DRSsxJVOG36VXGRhkV advR828oBxJt5o2ZcJ1IMCSUN4OxI+Rzecteho6GZr/mKWqKVghUXTWkvQ9d/kVu ekcykBo3AT3yFeFpJG8eA1l6xWMVUGuxXoKIJvk014MOdMFs9WxARbc4mYLApbqT qUlGDH5HjKHyv72zR9v++itZcdwFkn+jPFsRcxn49xOo61N5ATSdrlzWU26PG6yh If6xGylZj6UdZZ7T+x7MIdxMx7uPUsSGZ+7592MOzXkxsDfMsvIjofiWCU2KFcWH Mkgyrnr2quw34P0plxXoxdkjFkXCp64fT4B/z4KIwtpMitcJUc123MG5scLwm/gR 7kwYWXisvQ8go1KmuxDBurljhGkgZXmHu2K4tuxjkzzEMehNM1P3AAKrWgmMFont SEBFJ6e0/xBOQJY6NlPZ2ES9qRNR/5BPLywzkHc5/ZIJv+n9huSbmnZl/ilqmEoC 26C4mQdBK0BKtzrS11T3wb6gZKx6rI1Mi5EeFviIzL/27ZDAinbqlpRcuSL+PfJg sCJHBaRwVfx9A9cnyEhdQMGApu95UyjRYotyAEkh8wbILbwehu4vStvd4fJvsGbV GjSsohMfmWCO350h0MTWrQUzYRoTN8CpFJ7WuDXDrqTXy+dSP/TgjK7xsQeF8pUp qoMIo6c2gL0vhaMOaX5g =p5rr -----END PGP SIGNATURE----- --=-=-=--