All of lore.kernel.org
 help / color / mirror / Atom feed
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: Tue, 20 Sep 2016 15:53:30 +0300	[thread overview]
Message-ID: <87bmzi4trp.fsf@linux.intel.com> (raw)
In-Reply-To: <87eg4e517d.fsf@linux.intel.com>


[-- Attachment #1.1: Type: text/plain, Size: 16299 bytes --]


Hi,

Felipe Balbi <felipe.balbi@linux.intel.com> writes:
> [ Unknown signature status ]
>
> Hi,
>
> Alan Stern <stern@rowland.harvard.edu> writes:
>
> [...]
>
>>> $ 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.
>
> tried with your changes plus a trace_printk() added to both
> bulk_out_complete and bulk_in_complete. Here's the diff:

another version of diff and logs. Any ideas of what could be going on?
(full trace compressed and attached)

diff --git a/drivers/usb/gadget/function/f_mass_storage.c b/drivers/usb/gadget/function/f_mass_storage.c
index 8f3659b65f53..de0a9ebe7f61 100644
--- a/drivers/usb/gadget/function/f_mass_storage.c
+++ b/drivers/usb/gadget/function/f_mass_storage.c
@@ -395,11 +395,24 @@ static int fsg_set_halt(struct fsg_dev *fsg, struct usb_ep *ep)
 /* Caller must hold fsg->lock */
 static void wakeup_thread(struct fsg_common *common)
 {
+	struct task_struct *p = common->thread_task;
+
 	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);
+
+	trace_printk("wkup needed %d task %p [comm=%s pid=%d prio=%d target_cpu=%03d on_rq %d state %lx]\n",
+			common->thread_wakeup_needed, p, p->comm, p->pid,
+			p->prio, task_cpu(p), p->on_rq, p->state);
+
+	if (common->thread_task) {
+		int rc;
+		rc = wake_up_process(common->thread_task);
+		if (rc)
+			trace_printk("thread_task woken up\n");
+		else
+			trace_printk("NOT woken up\n");
+	}
 }
 
 static void raise_exception(struct fsg_common *common, enum fsg_state new_state)
@@ -411,6 +424,7 @@ static void raise_exception(struct fsg_common *common, enum fsg_state new_state)
 	 * 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;
@@ -449,6 +463,8 @@ static void bulk_in_complete(struct usb_ep *ep, struct usb_request *req)
 	struct fsg_common	*common = ep->driver_data;
 	struct fsg_buffhd	*bh = req->context;
 
+	trace_printk("%d, %u/%u\n", req->status, req->actual, req->length);
+
 	if (req->status || req->actual != req->length)
 		DBG(common, "%s --> %d, %u/%u\n", __func__,
 		    req->status, req->actual, req->length);
@@ -470,6 +486,8 @@ static void bulk_out_complete(struct usb_ep *ep, struct usb_request *req)
 	struct fsg_buffhd	*bh = req->context;
 
 	dump_msg(common, "bulk-out", req->buf, req->actual);
+
+	trace_printk("%d, %u/%u\n", req->status, req->actual, bh->bulk_out_intended_length);
 	if (req->status || req->actual != bh->bulk_out_intended_length)
 		DBG(common, "%s --> %d, %u/%u\n", __func__,
 		    req->status, req->actual, bh->bulk_out_intended_length);
@@ -573,6 +591,10 @@ static void start_transfer(struct fsg_dev *fsg, struct usb_ep *ep,
 	spin_unlock_irq(&fsg->common->lock);
 
 	rc = usb_ep_queue(ep, req, GFP_KERNEL);
+
+	trace_printk("%d: %s: req %u bytes state %d ---> %d\n", __LINE__, ep->name,
+			req->length, *state, rc);
+
 	if (rc == 0)
 		return;  /* All good, we're done */
 
@@ -2496,6 +2518,7 @@ static void handle_exception(struct fsg_common *common)
 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
@@ -2519,6 +2542,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;
 		}
@@ -2528,7 +2552,9 @@ static int fsg_main_thread(void *common_)
 			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);
@@ -2536,16 +2562,24 @@ 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);
 		if (!exception_in_progress(common))
 			common->state = FSG_STATE_STATUS_PHASE;
 		spin_unlock_irq(&common->lock);
 
-		if (send_status(common))
-			continue;
+		rc = send_status(common);
+		trace_printk("send_status -> %d\n", rc);
+		if (rc)
+		       continue;
 
 		spin_lock_irq(&common->lock);
 		if (!exception_in_progress(common))





     irq/17-dwc3-2533  [002] d...    29.576760: bulk_out_complete: 0, 31/31
     irq/17-dwc3-2533  [002] d..1    29.576760: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.576761: wakeup_thread.isra.15: thread_task woken up
    file-storage-2532  [003] ....    29.576763: fsg_main_thread: get_next_command -> 0
    file-storage-2532  [003] ....    29.576794: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.576802: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.576812: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.576834: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.576845: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.576852: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.576862: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.576867: fsg_main_thread: do_scsi_command -> 0
    file-storage-2532  [003] ....    29.576873: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.576873: fsg_main_thread: finish_reply -> 0
    file-storage-2532  [003] ....    29.576876: start_transfer.isra.14: 596: ep1in: req 13 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.576877: fsg_main_thread: send_status -> 0
     irq/17-dwc3-2533  [002] d...    29.576877: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.576878: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 1 state 0]
     irq/17-dwc3-2533  [002] d..1    29.576878: wakeup_thread.isra.15: NOT woken up
    file-storage-2532  [003] ....    29.576880: start_transfer.isra.14: 596: ep1out: req 1024 bytes state 2 ---> 0
     irq/17-dwc3-2533  [002] d...    29.576971: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.576971: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.576972: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.576975: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.576976: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.576976: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577060: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577061: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577062: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577065: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577065: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577066: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577149: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577150: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577150: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577153: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577154: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577155: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577241: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577242: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577242: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577246: bulk_in_complete: 0, 13/13
     irq/17-dwc3-2533  [002] d..1    29.577246: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577247: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577309: bulk_out_complete: 0, 31/31
     irq/17-dwc3-2533  [002] d..1    29.577309: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577310: wakeup_thread.isra.15: thread_task woken up
    file-storage-2532  [003] ....    29.577312: fsg_main_thread: get_next_command -> 0
    file-storage-2532  [003] ....    29.577340: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.577361: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.577369: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.577379: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.577387: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.577394: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.577404: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.577407: fsg_main_thread: do_scsi_command -> 0
    file-storage-2532  [003] ....    29.577410: start_transfer.isra.14: 596: ep1in: req 16384 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.577411: fsg_main_thread: finish_reply -> 0
    file-storage-2532  [003] ....    29.577414: start_transfer.isra.14: 596: ep1in: req 13 bytes state 2 ---> 0
    file-storage-2532  [003] ....    29.577414: fsg_main_thread: send_status -> 0
    file-storage-2532  [003] ....    29.577418: start_transfer.isra.14: 596: ep1out: req 1024 bytes state 2 ---> 0
     irq/17-dwc3-2533  [002] d...    29.577419: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577419: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577420: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577512: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577513: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577513: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577516: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577517: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577517: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577603: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577603: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577604: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577607: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577608: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577608: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577695: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577695: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577696: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577699: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577700: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577701: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577835: bulk_in_complete: 0, 16384/16384
     irq/17-dwc3-2533  [002] d..1    29.577836: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577837: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577840: bulk_in_complete: 0, 13/13
     irq/17-dwc3-2533  [002] d..1    29.577840: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 0 state 1]
     irq/17-dwc3-2533  [002] d..1    29.577841: wakeup_thread.isra.15: thread_task woken up
     irq/17-dwc3-2533  [002] d...    29.577842: bulk_out_complete: 0, 31/31
     irq/17-dwc3-2533  [002] d..1    29.577843: wakeup_thread.isra.15: wkup needed 1 task ffff88016e3dd100 [comm=file-storage pid=2532 prio=120 target_cpu=003 on_rq 1 state 0]
     irq/17-dwc3-2533  [002] d..1    29.577844: wakeup_thread.isra.15: thread_task woken up


[-- Attachment #1.2: trace.txt.xz --]
[-- Type: application/x-xz, Size: 44564 bytes --]

[-- Attachment #1.3: Type: text/plain, Size: 16 bytes --]



-- 
balbi

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 800 bytes --]

  reply	other threads:[~2016-09-20 12:53 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
2016-09-19 17:35                                 ` Alan Stern
2016-09-20 10:12                                   ` Felipe Balbi
2016-09-20 12:53                                     ` Felipe Balbi [this message]
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=87bmzi4trp.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.