From: Felipe Balbi <felipe.balbi@linux.intel.com>
To: Alan Stern <stern@rowland.harvard.edu>
Cc: Peter Zijlstra <peterz@infradead.org>,
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com>,
Ingo Molnar <mingo@redhat.com>,
USB list <linux-usb@vger.kernel.org>,
Kernel development list <linux-kernel@vger.kernel.org>,
Will Deacon <will.deacon@arm.com>
Subject: Re: Memory barrier needed with wake_up_process()?
Date: Mon, 19 Sep 2016 14:11:51 +0300 [thread overview]
Message-ID: <878tuo4008.fsf@linux.intel.com> (raw)
In-Reply-To: <Pine.LNX.4.44L0.1609091045530.2050-100000@iolanthe.rowland.org>
[-- Attachment #1: Type: text/plain, Size: 9575 bytes --]
Hi Alan,
Alan Stern <stern@rowland.harvard.edu> writes:
> On Fri, 9 Sep 2016, Felipe Balbi wrote:
>
>> Finally :-) Here's the diff I used:
>>
>> 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, struct usb_request *req)
>> spin_lock(&common->lock);
>> bh->outreq_busy = 0;
>> bh->state = BUF_STATE_FULL;
>> + if (bh->bulk_out_intended_length == 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 *common)
>> rc = sleep_thread(common, true);
>> if (rc)
>> return rc;
>> + trace_printk("next: bh %p state %d\n", bh, bh->state);
>> }
>> smp_rmb();
>> rc = fsg_is_set(common) ? received_cbw(common->fsg, bh) : -EIO;
>>
>>
>> And here's trace output:
>>
>> # tracer: nop
>> #
>> # entries-in-buffer/entries-written: 1002/1002 #P:4
>> #
>> # _-----=> irqs-off
>> # / _----=> need-resched
>> # | / _---=> hardirq/softirq
>> # || / _--=> preempt-depth
>> # ||| / delay
>> # TASK-PID CPU# |||| TIMESTAMP FUNCTION
>> # | | | |||| | |
>> file-storage-3578 [000] .... 21166.789127: fsg_main_thread: next: bh ffff880111e69a00 state 2
>> file-storage-3578 [000] .... 21166.789312: fsg_main_thread: next: bh 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: bh ffff880111e69a00 state 1
>
> Okay, that's normal. 2 = BUF_STATE_BUSY, 1 = 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 completes
> and the buffer is read.
>
> ...
>
>> file-storage-3578 [002] .... 21167.726827: fsg_main_thread: next: bh 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: bh ffff880111e69a80 state 1
>> file-storage-3578 [002] .... 21167.729458: fsg_main_thread: next: bh 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: bh ffff880111e6aac0 state 1
>
> And this is where everything stopped?
yeah, that's everything.
> This also looks normal. So the question is what happened when
> 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/255 trb ffff880084813e70 buf 0000000080808000 size 0 ctrl 00000c18 (hlcS:SC:normal)
> irq/17-dwc3-3527 [003] d..1 34.215214: dwc3_gadget_giveback: ep1in: req ffff88016d046840 length 16384/16384 zsI ==> 0
> irq/17-dwc3-3527 [003] d... 34.215215: usb_gadget_giveback_request: ep1in: 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: Successful
> 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/255 trb ffff880084813e80 buf 000000008080c000 size 0 ctrl 00000c18 (hlcS:SC:normal)
> irq/17-dwc3-3527 [003] d..1 34.215282: dwc3_gadget_giveback: ep1in: req ffff88016d046f00 length 13/13 zsI ==> 0
> irq/17-dwc3-3527 [003] d... 34.215283: usb_gadget_giveback_request: ep1in: 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/255 trb ffff880084804320 buf 000000008080c800 size 993 ctrl 00000c18 (hlcS:SC:normal)
> irq/17-dwc3-3527 [003] d..1 34.215285: dwc3_gadget_giveback: ep1out: req ffff880154205300 length 31/1024 zsI ==> 0
> irq/17-dwc3-3527 [003] d... 34.215285: usb_gadget_giveback_request: ep1out: 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 Complete: 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 trb ffff880084802000 buf 0000000084801000 size 0 ctrl 00000c33 (HLcs:SC:status2)
> irq/17-dwc3-3527 [003] d..1 64.832258: dwc3_gadget_ep_cmd: ep0in: cmd 'Start Transfer' [6] params 00000000 84802000 00000000 --> status: Successful
> 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 Complete: 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:status2)
> 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:setup)
> irq/17-dwc3-3527 [003] d..1 64.832360: dwc3_gadget_ep_cmd: ep0out: cmd 'Start Transfer' [6] params 00000000 84802000 00000000 --> status: Successful
> 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
/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_main_thread: get_next_command -> -4
/tmp/trace.txt:111746: file-storage-3526 [002] .... 64.833140: fsg_main_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_main_thread: handling exception
Any ideas?
--
balbi
[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 800 bytes --]
next prev parent reply other threads:[~2016-09-19 11:15 UTC|newest]
Thread overview: 41+ messages / expand[flat|nested] mbox.gz Atom feed top
2016-09-02 18:10 Memory barrier needed with wake_up_process()? Alan Stern
2016-09-02 18:47 ` Paul E. McKenney
2016-09-02 20:29 ` Alan Stern
2016-09-03 9:07 ` Paul E. McKenney
2016-09-03 12:31 ` Peter Zijlstra
2016-09-03 14:26 ` Alan Stern
2016-09-03 14:49 ` Alan Stern
2016-09-05 8:33 ` Peter Zijlstra
2016-09-05 15:29 ` Alan Stern
2016-09-06 11:36 ` Peter Zijlstra
2016-09-06 11:43 ` Felipe Balbi
2016-09-06 11:49 ` Peter Zijlstra
2016-09-06 12:20 ` Peter Zijlstra
2016-09-06 14:46 ` Alan Stern
2016-09-06 15:05 ` Peter Zijlstra
2016-09-07 10:12 ` Felipe Balbi
2016-09-09 10:36 ` Felipe Balbi
2016-09-09 16:12 ` Alan Stern
2016-09-19 11:11 ` Felipe Balbi [this message]
2016-09-19 17:35 ` Alan Stern
2016-09-20 10:12 ` Felipe Balbi
2016-09-20 12:53 ` Felipe Balbi
2016-09-20 14:40 ` Alan Stern
2017-01-16 11:12 ` Felipe Balbi
2017-01-16 17:09 ` Alan Stern
2017-01-16 19:04 ` Felipe Balbi
2017-01-16 19:19 ` Felipe Balbi
2016-09-02 19:18 ` Peter Zijlstra
2016-09-02 20:16 ` Alan Stern
2016-09-02 22:14 ` Peter Zijlstra
2016-09-02 22:16 ` Peter Zijlstra
2016-09-05 9:43 ` Will Deacon
2016-09-06 11:10 ` Peter Zijlstra
2016-09-02 22:16 ` Peter Zijlstra
2016-09-03 6:58 ` Felipe Balbi
2016-09-03 12:19 ` Peter Zijlstra
2016-09-03 13:51 ` Felipe Balbi
2016-09-05 8:09 ` Peter Zijlstra
2016-09-03 14:16 ` Alan Stern
2016-09-05 8:08 ` Peter Zijlstra
2016-09-05 14:33 ` Alan Stern
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=878tuo4008.fsf@linux.intel.com \
--to=felipe.balbi@linux.intel.com \
--cc=linux-kernel@vger.kernel.org \
--cc=linux-usb@vger.kernel.org \
--cc=mingo@redhat.com \
--cc=paulmck@linux.vnet.ibm.com \
--cc=peterz@infradead.org \
--cc=stern@rowland.harvard.edu \
--cc=will.deacon@arm.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.