Re: Memory barrier needed with wake_up_process()?

[Alan Stern]

On Tue, 20 Sep 2016, Felipe Balbi wrote:

> And here's trace output (complete, scroll to bottom). It seems to me
> like the thread didn't wake up at all. It didn't even try to
> execute. I'll add some more traces and try to get better information
> about what's going on.
> 
> 
> 
> # tracer: nop
> #
> # entries-in-buffer/entries-written: 2865/2865   #P:4
> #
> #                              _-----=> irqs-off
> #                             / _----=> need-resched
> #                            | / _---=> hardirq/softirq
> #                            || / _--=> preempt-depth
> #                            ||| /     delay
> #           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
> #              | |       |   ||||       |         |

Skipping to the end...

>      irq/17-dwc3-2522  [002] d...    43.504199: bulk_out_complete: 0, 31/31
>     file-storage-2521  [001] ....    43.504202: fsg_main_thread: get_next_command -> 0
>     file-storage-2521  [001] ....    43.504288: fsg_main_thread: do_scsi_command -> 0
>     file-storage-2521  [001] ....    43.504295: fsg_main_thread: finish_reply -> 0
>     file-storage-2521  [001] ....    43.504298: fsg_main_thread: send_status -> 0
>      irq/17-dwc3-2522  [002] d...    43.504347: bulk_in_complete: 0, 16384/16384
>      irq/17-dwc3-2522  [002] d...    43.504351: bulk_in_complete: 0, 16384/16384
>      irq/17-dwc3-2522  [002] d...    43.504434: bulk_in_complete: 0, 16384/16384
>      irq/17-dwc3-2522  [002] d...    43.504438: bulk_in_complete: 0, 16384/16384
>      irq/17-dwc3-2522  [002] d...    43.504535: bulk_in_complete: 0, 16384/16384
>      irq/17-dwc3-2522  [002] d...    43.504539: bulk_in_complete: 0, 16384/16384
>      irq/17-dwc3-2522  [002] d...    43.504618: bulk_in_complete: 0, 16384/16384
>      irq/17-dwc3-2522  [002] d...    43.504703: bulk_in_complete: 0, 16384/16384
>      irq/17-dwc3-2522  [002] d...    43.504794: bulk_in_complete: 0, 13/13
>      irq/17-dwc3-2522  [002] d...    43.504797: bulk_out_complete: 0, 31/31

Like you say, it appears that the thread didn't get woken up at all.
But this is inconsistent with your earlier results.  On Sep. 9, you 
posted a message that ended with these lines:

>      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

This indicates that in the earlier test, the thread did start running 
and get_next_command should have returned.

The trace you posted after this one doesn't seem to show anything new, 
as far as I can tell.

So I still can't tell what's happening.  Maybe the patch below will 
help.  It concentrates on the critical area.

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
@@ -402,8 +402,12 @@ static void wakeup_thread(struct fsg_com
 	smp_wmb();	/* ensure the write of bh->state is complete */
 	/* Tell the main thread that something has happened */
 	common->thread_wakeup_needed = 1;
-	if (common->thread_task)
-		wake_up_process(common->thread_task);
+	if (common->thread_task) {
+		if (wake_up_process(common->thread_task))
+			trace_printk("wakeup_thread 1\n");
+		else
+			trace_printk("wakeup_thread 0\n");
+	}
 }
 
 static void raise_exception(struct fsg_common *common, enum fsg_state new_state)
@@ -479,6 +483,8 @@ static void bulk_out_complete(struct usb
 		    req->status, req->actual, bh->bulk_out_intended_length);
 	if (req->status == -ECONNRESET)		/* Request was cancelled */
 		usb_ep_fifo_flush(ep);
+	trace_printk("bulk_out: %d, %u/%u\n", req->status, req->actual,
+			bh->bulk_out_intended_length);
 
 	/* Hold the lock while we update the request and buffer states */
 	smp_wmb();
@@ -2204,13 +2210,17 @@ static int get_next_command(struct fsg_c
 
 	/* Wait for the CBW to arrive */
 	while (bh->state != BUF_STATE_FULL) {
+		trace_printk("get_next: sleep\n");
 		rc = sleep_thread(common, true);
+		trace_printk("get_next: sleep -> %d loop %d\n",
+				rc, bh->state != BUF_STATE_FULL);
 		if (rc)
 			return rc;
 	}
 	smp_rmb();
 	rc = fsg_is_set(common) ? received_cbw(common->fsg, bh) : -EIO;
 	bh->state = BUF_STATE_EMPTY;
+	trace_printk("get_next: return %d\n", rc);
 
 	return rc;
 }