Hi, Felipe Balbi <felipe.balbi@xxxxxxxxxxxxxxx> writes: > [ Unknown signature status ] > > Hi, > > Felipe Balbi <felipe.balbi@xxxxxxxxxxxxxxx> writes: >>>>> Any ideas on how to debug this would be apreciated. >>>> >>>> You can start by enabling verbose debugging in f_mass_storage.c. >>>> Uncomment the two lines that say: >>>> >>>> /* #define VERBOSE_DEBUG */ >>>> /* #define DUMP_MSGS */ >>>> >>>> You'll probably also have to enable dynamic debugging for the >>>> g_mass_storage module. >>> >>> right, I'll do that tomorrow. I'll probably need some rather larger >>> kernel logbuf too. Hopefully some 8MiB is enough. >> >> Here are the last few transfers. It's as if we don't get as far as >> check_command() in this particular case: > > [...] > >> another READ(10), but nothing else. I'll continue debugging this one. > > Seems like the kthread doesn't execute. I've added a few __func__, > __LINE__ prints to fsg_main_thread(). Here's what we have now: [...] Here's the best log I could capture. I've put everything on trace. > irq/17-dwc3-3530 [001] d..1 62.504184: dwc3_complete_trb: ep1out: 0/255 trb ffff880087404f80 buf 000000002829c000 size 993 ctrl 00000c18 (hlcS:SC:normal) > irq/17-dwc3-3530 [001] d..1 62.504186: dwc3_gadget_giveback: ep1out: req ffff880067ee6180 length 31/1024 zsI ==> 0 > irq/17-dwc3-3530 [001] d... 62.504186: usb_gadget_giveback_request: ep1out: length 31/1024 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3530 [001] d... 62.504187: bulk_out_complete: 55 53 42 43 fffffff0 09 00 00 > irq/17-dwc3-3530 [001] d... 62.504202: bulk_out_complete: 00 00 02 00 ffffff80 00 0a 28 > irq/17-dwc3-3530 [001] d... 62.504203: bulk_out_complete: 00 00 09 ffffffa6 00 00 01 00 > irq/17-dwc3-3530 [001] d... 62.504204: bulk_out_complete: 00 00 00 00 00 00 00 00 > file-storage-3529 [002] .... 62.504207: do_scsi_command: SCSI CDB: > file-storage-3529 [002] .... 62.504208: do_scsi_command: 28 00 00 09 ffffffa6 00 00 01 > file-storage-3529 [002] .... 62.504209: do_scsi_command: 00 00 00 00 00 00 00 00 > file-storage-3529 [002] .... 62.504214: do_read: lun0: file read 16384 @ 323747840 -> 16384 > file-storage-3529 [002] d..1 62.504215: dwc3_ep_queue: ep1in: req ffff880067ee6e40 length 0/16384 zsI ==> -115 > file-storage-3529 [002] d..1 62.504220: dwc3_gadget: ep1in: req ffff880067ee6e40 dma 2829c000 length 16384 > file-storage-3529 [002] d..1 62.504221: dwc3_prepare_trb: ep1in: 1/255 trb ffff880087413e60 buf 000000002829c000 size 16384 ctrl 00000c19 (HlcS:SC:normal) > file-storage-3529 [002] d..1 62.504229: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > file-storage-3529 [002] .... 62.504230: usb_ep_queue: ep1in: length 0/16384 sgs 0/0 stream 0 zsI status -115 --> 0 > file-storage-3529 [002] .... 62.504235: do_read: lun0: file read 16384 @ 323764224 -> 16384 > file-storage-3529 [002] d..1 62.504235: dwc3_ep_queue: ep1in: req ffff880067ee66c0 length 0/16384 zsI ==> -115 > file-storage-3529 [002] d..1 62.504240: dwc3_gadget: ep1in: req ffff880067ee66c0 dma 282a0000 length 16384 > file-storage-3529 [002] d..1 62.504241: dwc3_prepare_trb: ep1in: 2/255 trb ffff880087413e70 buf 00000000282a0000 size 16384 ctrl 00000c19 (HlcS:SC:normal) > file-storage-3529 [002] d..1 62.504243: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > file-storage-3529 [002] .... 62.504243: usb_ep_queue: ep1in: length 0/16384 sgs 0/0 stream 0 zsI status -115 --> 0 > file-storage-3529 [002] .... 62.504246: do_read: lun0: file read 16384 @ 323780608 -> 16384 > file-storage-3529 [002] d..1 62.504247: dwc3_ep_queue: ep1in: req ffff880067ee6900 length 0/16384 zsI ==> -115 > file-storage-3529 [002] d..1 62.504251: dwc3_gadget: ep1in: req ffff880067ee6900 dma 282a4000 length 16384 > file-storage-3529 [002] d..1 62.504252: dwc3_prepare_trb: ep1in: 3/255 trb ffff880087413e80 buf 00000000282a4000 size 16384 ctrl 00000c19 (HlcS:SC:normal) > file-storage-3529 [002] d..1 62.504254: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > file-storage-3529 [002] .... 62.504255: usb_ep_queue: ep1in: length 0/16384 sgs 0/0 stream 0 zsI status -115 --> 0 > file-storage-3529 [002] .... 62.504258: do_read: lun0: file read 16384 @ 323796992 -> 16384 > file-storage-3529 [002] d..1 62.504259: dwc3_ep_queue: ep1in: req ffff880067ee6840 length 0/16384 zsI ==> -115 > file-storage-3529 [002] d..1 62.504263: dwc3_gadget: ep1in: req ffff880067ee6840 dma 282a8000 length 16384 > file-storage-3529 [002] d..1 62.504264: dwc3_prepare_trb: ep1in: 4/255 trb ffff880087413e90 buf 00000000282a8000 size 16384 ctrl 00000c19 (HlcS:SC:normal) > file-storage-3529 [002] d..1 62.504267: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > file-storage-3529 [002] .... 62.504267: usb_ep_queue: ep1in: length 0/16384 sgs 0/0 stream 0 zsI status -115 --> 0 > file-storage-3529 [002] .... 62.504270: do_read: lun0: file read 16384 @ 323813376 -> 16384 > file-storage-3529 [002] d..1 62.504271: dwc3_ep_queue: ep1in: req ffff880067ef8a80 length 0/16384 zsI ==> -115 > file-storage-3529 [002] d..1 62.504275: dwc3_gadget: ep1in: req ffff880067ef8a80 dma 282ac000 length 16384 > file-storage-3529 [002] d..1 62.504276: dwc3_prepare_trb: ep1in: 5/255 trb ffff880087413ea0 buf 00000000282ac000 size 16384 ctrl 00000c19 (HlcS:SC:normal) > file-storage-3529 [002] d..1 62.504278: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > file-storage-3529 [002] .... 62.504278: usb_ep_queue: ep1in: length 0/16384 sgs 0/0 stream 0 zsI status -115 --> 0 > file-storage-3529 [002] .... 62.504284: do_read: lun0: file read 16384 @ 323829760 -> 16384 > file-storage-3529 [002] d..1 62.504284: dwc3_ep_queue: ep1in: req ffff880067ef8780 length 0/16384 zsI ==> -115 > file-storage-3529 [002] d..1 62.504289: dwc3_gadget: ep1in: req ffff880067ef8780 dma 282b0000 length 16384 > file-storage-3529 [002] d..1 62.504289: dwc3_prepare_trb: ep1in: 6/255 trb ffff880087413eb0 buf 00000000282b0000 size 16384 ctrl 00000c19 (HlcS:SC:normal) > file-storage-3529 [002] d..1 62.504294: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > file-storage-3529 [002] .... 62.504294: usb_ep_queue: ep1in: length 0/16384 sgs 0/0 stream 0 zsI status -115 --> 0 > file-storage-3529 [002] .... 62.504298: do_read: lun0: file read 16384 @ 323846144 -> 16384 > file-storage-3529 [002] d..1 62.504298: dwc3_ep_queue: ep1in: req ffff880067ef8d80 length 0/16384 zsI ==> -115 > file-storage-3529 [002] d..1 62.504303: dwc3_gadget: ep1in: req ffff880067ef8d80 dma 282b4000 length 16384 > file-storage-3529 [002] d..1 62.504303: dwc3_prepare_trb: ep1in: 7/255 trb ffff880087413ec0 buf 00000000282b4000 size 16384 ctrl 00000c19 (HlcS:SC:normal) > file-storage-3529 [002] d..1 62.504308: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > file-storage-3529 [002] .... 62.504308: usb_ep_queue: ep1in: length 0/16384 sgs 0/0 stream 0 zsI status -115 --> 0 > file-storage-3529 [002] .... 62.504312: do_read: lun0: file read 16384 @ 323862528 -> 16384 > file-storage-3529 [002] d..1 62.504312: dwc3_ep_queue: ep1in: req ffff880067ef8540 length 0/16384 zsI ==> -115 > file-storage-3529 [002] d..1 62.504316: dwc3_gadget: ep1in: req ffff880067ef8540 dma 282b8000 length 16384 > file-storage-3529 [002] d..1 62.504316: dwc3_prepare_trb: ep1in: 8/255 trb ffff880087413ed0 buf 00000000282b8000 size 16384 ctrl 00000c19 (HlcS:SC:normal) > file-storage-3529 [002] d..1 62.504319: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > file-storage-3529 [002] .... 62.504319: usb_ep_queue: ep1in: length 0/16384 sgs 0/0 stream 0 zsI status -115 --> 0 > file-storage-3529 [002] .... 62.504320: start_transfer: 55 53 42 53 fffffff0 09 00 00 > file-storage-3529 [002] .... 62.504320: start_transfer: 00 00 00 00 00 00 00 00 > file-storage-3529 [002] d..1 62.504320: dwc3_ep_queue: ep1in: req ffff880067ef8b40 length 0/13 zsI ==> -115 > file-storage-3529 [002] d..1 62.504324: dwc3_gadget: ep1in: req ffff880067ef8b40 dma 282bc000 length 13 > file-storage-3529 [002] d..1 62.504324: dwc3_prepare_trb: ep1in: 9/255 trb ffff880087413ee0 buf 00000000282bc000 size 13 ctrl 00000c19 (HlcS:SC:normal) > file-storage-3529 [002] d..1 62.504329: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > file-storage-3529 [002] .... 62.504329: usb_ep_queue: ep1in: length 0/13 sgs 0/0 stream 0 zsI status -115 --> 0 > file-storage-3529 [002] d..1 62.504330: dwc3_ep_queue: ep1out: req ffff880067ef8000 length 0/1024 zsI ==> -115 > file-storage-3529 [002] d..1 62.504334: dwc3_gadget: ep1out: req ffff880067ef8000 dma 282c0000 length 1024 > file-storage-3529 [002] d..1 62.504334: dwc3_prepare_trb: ep1out: 1/255 trb ffff880087404f90 buf 00000000282c0000 size 1024 ctrl 00000c19 (HlcS:SC:normal) > file-storage-3529 [002] d..1 62.504337: dwc3_gadget_ep_cmd: ep1out: cmd 'Update Transfer' [131079] params 00000000 00000000 00000000 --> status: Successful > file-storage-3529 [002] .... 62.504337: usb_ep_queue: ep1out: length 0/1024 sgs 0/0 stream 0 zsI status -115 --> 0 > irq/17-dwc3-3530 [001] d..1 62.504338: dwc3_event: event (00004086): ep1in: Transfer In-Progress > irq/17-dwc3-3530 [001] d..1 62.504338: dwc3_complete_trb: ep1in: 8/255 trb ffff880087413e60 buf 000000002829c000 size 0 ctrl 00000c18 (hlcS:SC:normal) > irq/17-dwc3-3530 [001] d..1 62.504339: dwc3_gadget_giveback: ep1in: req ffff880067ee6e40 length 16384/16384 zsI ==> 0 > irq/17-dwc3-3530 [001] d... 62.504339: usb_gadget_giveback_request: ep1in: length 16384/16384 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3530 [001] d..1 62.504342: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > irq/17-dwc3-3530 [001] d..1 62.504342: dwc3_event: event (00004086): ep1in: Transfer In-Progress > irq/17-dwc3-3530 [001] d..1 62.504342: dwc3_complete_trb: ep1in: 7/255 trb ffff880087413e70 buf 00000000282a0000 size 0 ctrl 00000c18 (hlcS:SC:normal) > irq/17-dwc3-3530 [001] d..1 62.504343: dwc3_gadget_giveback: ep1in: req ffff880067ee66c0 length 16384/16384 zsI ==> 0 > irq/17-dwc3-3530 [001] d... 62.504343: usb_gadget_giveback_request: ep1in: length 16384/16384 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3530 [001] d..1 62.504347: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > irq/17-dwc3-3530 [001] d..1 62.504429: dwc3_event: event (00004086): ep1in: Transfer In-Progress > irq/17-dwc3-3530 [001] d..1 62.504429: dwc3_complete_trb: ep1in: 6/255 trb ffff880087413e80 buf 00000000282a4000 size 0 ctrl 00000c18 (hlcS:SC:normal) > irq/17-dwc3-3530 [001] d..1 62.504430: dwc3_gadget_giveback: ep1in: req ffff880067ee6900 length 16384/16384 zsI ==> 0 > irq/17-dwc3-3530 [001] d... 62.504430: usb_gadget_giveback_request: ep1in: length 16384/16384 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3530 [001] d..1 62.504433: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > irq/17-dwc3-3530 [001] d..1 62.504433: dwc3_event: event (00004086): ep1in: Transfer In-Progress > irq/17-dwc3-3530 [001] d..1 62.504434: dwc3_complete_trb: ep1in: 5/255 trb ffff880087413e90 buf 00000000282a8000 size 0 ctrl 00000c18 (hlcS:SC:normal) > irq/17-dwc3-3530 [001] d..1 62.504434: dwc3_gadget_giveback: ep1in: req ffff880067ee6840 length 16384/16384 zsI ==> 0 > irq/17-dwc3-3530 [001] d... 62.504434: usb_gadget_giveback_request: ep1in: length 16384/16384 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3530 [001] d..1 62.504438: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > irq/17-dwc3-3530 [001] d..1 62.504516: dwc3_event: event (00004086): ep1in: Transfer In-Progress > irq/17-dwc3-3530 [001] d..1 62.504516: dwc3_complete_trb: ep1in: 4/255 trb ffff880087413ea0 buf 00000000282ac000 size 0 ctrl 00000c18 (hlcS:SC:normal) > irq/17-dwc3-3530 [001] d..1 62.504517: dwc3_gadget_giveback: ep1in: req ffff880067ef8a80 length 16384/16384 zsI ==> 0 > irq/17-dwc3-3530 [001] d... 62.504517: usb_gadget_giveback_request: ep1in: length 16384/16384 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3530 [001] d..1 62.504521: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > irq/17-dwc3-3530 [001] d..1 62.504521: dwc3_event: event (00004086): ep1in: Transfer In-Progress > irq/17-dwc3-3530 [001] d..1 62.504521: dwc3_complete_trb: ep1in: 3/255 trb ffff880087413eb0 buf 00000000282b0000 size 0 ctrl 00000c18 (hlcS:SC:normal) > irq/17-dwc3-3530 [001] d..1 62.504522: dwc3_gadget_giveback: ep1in: req ffff880067ef8780 length 16384/16384 zsI ==> 0 > irq/17-dwc3-3530 [001] d... 62.504522: usb_gadget_giveback_request: ep1in: length 16384/16384 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3530 [001] d..1 62.504526: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > irq/17-dwc3-3530 [001] d..1 62.504605: dwc3_event: event (00004086): ep1in: Transfer In-Progress > irq/17-dwc3-3530 [001] d..1 62.504605: dwc3_complete_trb: ep1in: 2/255 trb ffff880087413ec0 buf 00000000282b4000 size 0 ctrl 00000c18 (hlcS:SC:normal) > irq/17-dwc3-3530 [001] d..1 62.504606: dwc3_gadget_giveback: ep1in: req ffff880067ef8d80 length 16384/16384 zsI ==> 0 > irq/17-dwc3-3530 [001] d... 62.504606: usb_gadget_giveback_request: ep1in: length 16384/16384 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3530 [001] d..1 62.504610: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > irq/17-dwc3-3530 [001] d..1 62.504610: dwc3_event: event (00004086): ep1in: Transfer In-Progress > irq/17-dwc3-3530 [001] d..1 62.504611: dwc3_complete_trb: ep1in: 1/255 trb ffff880087413ed0 buf 00000000282b8000 size 0 ctrl 00000c18 (hlcS:SC:normal) > irq/17-dwc3-3530 [001] d..1 62.504611: dwc3_gadget_giveback: ep1in: req ffff880067ef8540 length 16384/16384 zsI ==> 0 > irq/17-dwc3-3530 [001] d... 62.504612: usb_gadget_giveback_request: ep1in: length 16384/16384 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3530 [001] d..1 62.504615: dwc3_gadget_ep_cmd: ep1in: cmd 'Update Transfer' [196615] params 00000000 00000000 00000000 --> status: Successful > irq/17-dwc3-3530 [001] d..1 62.504674: dwc3_event: event (00004086): ep1in: Transfer In-Progress > irq/17-dwc3-3530 [001] d..1 62.504674: dwc3_complete_trb: ep1in: 0/255 trb ffff880087413ee0 buf 00000000282bc000 size 0 ctrl 00000c18 (hlcS:SC:normal) > irq/17-dwc3-3530 [001] d..1 62.504675: dwc3_gadget_giveback: ep1in: req ffff880067ef8b40 length 13/13 zsI ==> 0 > irq/17-dwc3-3530 [001] d... 62.504676: usb_gadget_giveback_request: ep1in: length 13/13 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3530 [001] d..1 62.504677: dwc3_event: event (00006084): ep1in: Transfer In-Progress > irq/17-dwc3-3530 [001] d..1 62.504678: dwc3_complete_trb: ep1out: 0/255 trb ffff880087404f90 buf 00000000282c0000 size 993 ctrl 00000c18 (hlcS:SC:normal) > irq/17-dwc3-3530 [001] d..1 62.504680: dwc3_gadget_giveback: ep1out: req ffff880067ef8000 length 31/1024 zsI ==> 0 > irq/17-dwc3-3530 [001] d... 62.504680: usb_gadget_giveback_request: ep1out: length 31/1024 sgs 0/0 stream 0 zsI status 0 --> 0 > irq/17-dwc3-3530 [001] d... 62.504681: bulk_out_complete: 55 53 42 43 fffffff1 09 00 00 > irq/17-dwc3-3530 [001] d... 62.504682: bulk_out_complete: 00 00 02 00 ffffff80 00 0a 28 > irq/17-dwc3-3530 [001] d... 62.504683: bulk_out_complete: 00 00 09 ffffffa7 00 00 01 00 > irq/17-dwc3-3530 [001] d... 62.504683: bulk_out_complete: 00 00 00 00 00 00 00 00 Doesn't have a lot more information. It just shows that we completed 31-byte CBW and we *certainly* woke up the thread (or it was already running), but then nothing happens :-) I'm thinking we might have a race WRT our use of memory barriers; could it be? /me goes try Yeah, I've converted all smp_[wr]mb() to smp_mb() and the problem went away (apparently). It was failing on first iteration of my test but it has now been running for over 20 iterations without a problem. Now we just need to figure out which of the barriers is wrong. -- balbi
Attachment:
signature.asc
Description: PGP signature
