Re: Memory barrier needed with wake_up_process()?

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



Hi,

Felipe Balbi <felipe.balbi@xxxxxxxxxxxxxxx> writes:
> [ Unknown signature status ]
>
> Hi,
>
> Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> 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: trace.txt.xz
Description: application/xz


-- 
balbi

Attachment: signature.asc
Description: PGP signature


[Index of Archives]     [Linux Media]     [Linux Input]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]     [Old Linux USB Devel Archive]

  Powered by Linux