Re: Memory barrier needed with wake_up_process()?

From: Felipe Balbi
Date: Tue Sep 20 2016 - 08:53:54 EST

Next message: Christoffer Dall: "Re: [PATCH 1/2] jump_labels: Add API to deal with keys embedded in structures"
Previous message: Joerg Roedel: "Re: [PATCH v5 8/8] iommu/amd: Update domain into to dte entry during device driver init"
In reply to: Felipe Balbi: "Re: Memory barrier needed with wake_up_process()?"
Next in thread: Alan Stern: "Re: Memory barrier needed with wake_up_process()?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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

Next message: Christoffer Dall: "Re: [PATCH 1/2] jump_labels: Add API to deal with keys embedded in structures"
Previous message: Joerg Roedel: "Re: [PATCH v5 8/8] iommu/amd: Update domain into to dte entry during device driver init"
In reply to: Felipe Balbi: "Re: Memory barrier needed with wake_up_process()?"
Next in thread: Alan Stern: "Re: Memory barrier needed with wake_up_process()?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]