Re: Memory barrier needed with wake_up_process()?

[Alan Stern]

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);