Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1480187 > unrolled thread
| Started by | Alan Stern <stern@rowland.harvard.edu> |
|---|---|
| First post | 2016-09-09 18:20 +0200 |
| Last post | 2016-09-19 19:40 +0200 |
| Articles | 3 — 2 participants |
Back to article view | Back to linux.kernel
This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by
below is the oldest one visible, not the original post.
Re: Memory barrier needed with wake_up_process()? Alan Stern <stern@rowland.harvard.edu> - 2016-09-09 18:20 +0200
Re: Memory barrier needed with wake_up_process()? Felipe Balbi <felipe.balbi@linux.intel.com> - 2016-09-19 13:20 +0200
Re: Memory barrier needed with wake_up_process()? Alan Stern <stern@rowland.harvard.edu> - 2016-09-19 19:40 +0200
| From | Alan Stern <stern@rowland.harvard.edu> |
|---|---|
| Date | 2016-09-09 18:20 +0200 |
| Subject | Re: Memory barrier needed with wake_up_process()? |
| Message-ID | <sfwGZ-5gP-19@gated-at.bofh.it> |
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?
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.
Alan Stern
Index: usb-4.x/drivers/usb/gadget/function/f_mass_storage.c
===================================================================
--- usb-4.x.orig/drivers/usb/gadget/function/f_mass_storage.c
+++ usb-4.x/drivers/usb/gadget/function/f_mass_storage.c
@@ -415,6 +415,7 @@ static void raise_exception(struct fsg_c
* If a lower-or-equal priority exception is in progress, preempt it
* and notify the main thread by sending it a signal.
*/
+ trace_printk("raise_exception %d\n", new_state);
spin_lock_irqsave(&common->lock, flags);
if (common->state <= new_state) {
common->exception_req_tag = common->ep0_req_tag;
@@ -2495,6 +2496,7 @@ static void handle_exception(struct fsg_
static int fsg_main_thread(void *common_)
{
struct fsg_common *common = common_;
+ int rc;
/*
* Allow the thread to be killed by a signal, but set the signal mask
@@ -2518,6 +2520,7 @@ static int fsg_main_thread(void *common_
/* The main loop */
while (common->state != FSG_STATE_TERMINATED) {
if (exception_in_progress(common) || signal_pending(current)) {
+ trace_printk("handling exception\n");
handle_exception(common);
continue;
}
@@ -2527,24 +2530,38 @@ static int fsg_main_thread(void *common_
continue;
}
- if (get_next_command(common))
+ rc = get_next_command(common);
+ if (rc) {
+ trace_printk("get_next_command -> %d\n", rc);
continue;
+ }
spin_lock_irq(&common->lock);
if (!exception_in_progress(common))
common->state = FSG_STATE_DATA_PHASE;
spin_unlock_irq(&common->lock);
- if (do_scsi_command(common) || finish_reply(common))
+ rc = do_scsi_command(common);
+ if (rc) {
+ trace_printk("do_scsi_command -> %d\n", rc);
+ continue;
+ }
+ rc = finish_reply(common);
+ if (rc) {
+ trace_printk("finish_reply -> %d\n", rc);
continue;
+ }
spin_lock_irq(&common->lock);
if (!exception_in_progress(common))
common->state = FSG_STATE_STATUS_PHASE;
spin_unlock_irq(&common->lock);
- if (send_status(common))
+ rc = send_status(common);
+ if (rc) {
+ trace_printk("send_status -> %d\n", rc);
continue;
+ }
spin_lock_irq(&common->lock);
if (!exception_in_progress(common))
[toc] | [next] | [standalone]
| From | Felipe Balbi <felipe.balbi@linux.intel.com> |
|---|---|
| Date | 2016-09-19 13:20 +0200 |
| Message-ID | <sj4Ma-4KI-19@gated-at.bofh.it> |
| In reply to | #1480187 |
[Multipart message — attachments visible in raw view] — view raw
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
[toc] | [prev] | [next] | [standalone]
| From | Alan Stern <stern@rowland.harvard.edu> |
|---|---|
| Date | 2016-09-19 19:40 +0200 |
| Message-ID | <sjaHU-8o6-13@gated-at.bofh.it> |
| In reply to | #1486367 |
On Mon, 19 Sep 2016, Felipe Balbi wrote:
> >> 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?
I'm afraid not. The only thing I can think of to try next is complete
tracing of fsg_main_thread, as in the patch below. It will generate
continuous output as long as the gadget is doing something, but there
doesn't seem to be any way to avoid this. At least when everything
stops, it should be able to tell us exactly where and why.
Alan Stern
Index: usb-4.x/drivers/usb/gadget/function/f_mass_storage.c
===================================================================
--- usb-4.x.orig/drivers/usb/gadget/function/f_mass_storage.c
+++ usb-4.x/drivers/usb/gadget/function/f_mass_storage.c
@@ -415,6 +415,7 @@ static void raise_exception(struct fsg_c
* If a lower-or-equal priority exception is in progress, preempt it
* and notify the main thread by sending it a signal.
*/
+ trace_printk("raise_exception %d\n", new_state);
spin_lock_irqsave(&common->lock, flags);
if (common->state <= new_state) {
common->exception_req_tag = common->ep0_req_tag;
@@ -2495,6 +2496,7 @@ static void handle_exception(struct fsg_
static int fsg_main_thread(void *common_)
{
struct fsg_common *common = common_;
+ int rc;
/*
* Allow the thread to be killed by a signal, but set the signal mask
@@ -2518,16 +2520,20 @@ static int fsg_main_thread(void *common_
/* The main loop */
while (common->state != FSG_STATE_TERMINATED) {
if (exception_in_progress(common) || signal_pending(current)) {
+ trace_printk("handling exception\n");
handle_exception(common);
continue;
}
if (!common->running) {
+ trace_printk("fsg_main_thread not running...\n");
sleep_thread(common, true);
continue;
}
- if (get_next_command(common))
+ rc = get_next_command(common);
+ trace_printk("get_next_command -> %d\n", rc);
+ if (rc)
continue;
spin_lock_irq(&common->lock);
@@ -2535,7 +2541,13 @@ static int fsg_main_thread(void *common_
common->state = FSG_STATE_DATA_PHASE;
spin_unlock_irq(&common->lock);
- if (do_scsi_command(common) || finish_reply(common))
+ rc = do_scsi_command(common);
+ trace_printk("do_scsi_command -> %d\n", rc);
+ if (rc)
+ continue;
+ rc = finish_reply(common);
+ trace_printk("finish_reply -> %d\n", rc);
+ if (rc)
continue;
spin_lock_irq(&common->lock);
@@ -2543,7 +2555,9 @@ static int fsg_main_thread(void *common_
common->state = FSG_STATE_STATUS_PHASE;
spin_unlock_irq(&common->lock);
- if (send_status(common))
+ rc = send_status(common);
+ trace_printk("send_status -> %d\n", rc);
+ if (rc)
continue;
spin_lock_irq(&common->lock);
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web