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 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 a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox
Powered by JetHome