Re: Memory barrier needed with wake_up_process()?

From: Felipe Balbi
Date: Mon Sep 19 2016 - 07:15:46 EST

Next message: Matt Fleming: "Re: [tip regression] efi: Allow drivers to reserve boot services forever == toxic"
Previous message: Matt Fleming: "Re: Cannot load linux after recent efi-related changes"
Next in thread: Alan Stern: "Re: Memory barrier needed with wake_up_process()?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hi Alan,

Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> writes:
> On Fri, 9 Sep 2016, Felipe Balbi wrote:
>
>> Finally :-) Here's the diff I used:
>>
>> diff --git a/drivers/usb/gadget/function/f_mass_storage.c b/drivers/usb/gadget/function/f_mass_storage.c
>> index 8f3659b65f53..0716024f6b65 100644
>> --- a/drivers/usb/gadget/function/f_mass_storage.c
>> +++ b/drivers/usb/gadget/function/f_mass_storage.c
>> @@ -481,6 +481,8 @@ static void bulk_out_complete(struct usb_ep *ep, struct usb_request *req)
>> spin_lock(&common->lock);
>> bh->outreq_busy = 0;
>> bh->state = BUF_STATE_FULL;
>> + if (bh->bulk_out_intended_length == US_BULK_CB_WRAP_LEN)
>> + trace_printk("compl: bh %p state %d\n", bh, bh->state);
>> wakeup_thread(common);
>> spin_unlock(&common->lock);
>> }
>> @@ -2208,6 +2210,7 @@ static int get_next_command(struct fsg_common *common)
>> rc = sleep_thread(common, true);
>> if (rc)
>> return rc;
>> + trace_printk("next: bh %p state %d\n", bh, bh->state);
>> }
>> smp_rmb();
>> rc = fsg_is_set(common) ? received_cbw(common->fsg, bh) : -EIO;
>>
>>
>> And here's trace output:
>>
>> # tracer: nop
>> #
>> # entries-in-buffer/entries-written: 1002/1002 #P:4
>> #
>> # _-----=> irqs-off
>> # / _----=> need-resched
>> # | / _---=> hardirq/softirq
>> # || / _--=> preempt-depth
>> # ||| / delay
>> # TASK-PID CPU# |||| TIMESTAMP FUNCTION
>> # | | | |||| | |
>> file-storage-3578 [000] .... 21166.789127: fsg_main_thread: next: bh ffff880111e69a00 state 2
>> file-storage-3578 [000] .... 21166.789312: fsg_main_thread: next: bh ffff880111e69a00 state 2
>> irq/17-dwc3-3579 [003] d..1 21166.789395: bulk_out_complete: compl: bh ffff880111e69a00 state 1
>> file-storage-3578 [000] .... 21166.789445: fsg_main_thread: next: bh ffff880111e69a00 state 1
>
> Okay, that's normal. 2 = BUF_STATE_BUSY, 1 = BUF_STATE_FULL. So we get woken
> up a couple of times while the transfer is in progress (probably because some
> earlier buffers have finished transferring), then the CBW transfer completes
> and the buffer is read.
>
> ...
>
>> file-storage-3578 [002] .... 21167.726827: fsg_main_thread: next: bh ffff880111e69a80 state 2
>> irq/17-dwc3-3579 [003] d..1 21167.727066: bulk_out_complete: compl: bh ffff880111e69a80 state 1
>> 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?

--
balbi

Attachment: signature.asc
Description: PGP signature

Next message: Matt Fleming: "Re: [tip regression] efi: Allow drivers to reserve boot services forever == toxic"
Previous message: Matt Fleming: "Re: Cannot load linux after recent efi-related changes"
Next in thread: Alan Stern: "Re: Memory barrier needed with wake_up_process()?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]