On 17 Oct 2015, at 12:30, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote: > Paul, can you tell your email client to wrap lines after 72 columns or > so? It would make replying a lot easier… Mac Mail is not very friendly in this respect, but I can pay attention to not make long lines :) > ... >>> One thing you did not show here was the delay between sending the last >>> data buffer of one command and sending the first data buffer of the >>> next command. That overhead could significantly affect the overall >>> throughput. >> The next read command is generally handled within 20us after the previous one. >> Switched over to ftrace to include the net2280 irq/dma handling, logging of the >> spin locks and thread handling in bulk_in_complete: > > Why are you still using 8 buffers? I think 2 buffers (the default) > would give the same performance. It's worth checking. It doesn’t make much difference end-to-end (135MB/s vs 132 MB/s). > >> ----- FIRST REQUEST----- >> file-storage-1333 [002] .... 59.898705: do_read: READ: 122880 @ 0 >> file-storage-1333 [002] .... 59.898706: do_read: file read 16384 @ 0 >> file-storage-1333 [002] .... 59.898709: do_read: file read 16384 @ 0 -> 16384 >> file-storage-1333 [002] .... 59.898709: start_transfer: bulk-in start >> file-storage-1333 [002] .... 59.898710: net2280_queue: received request >> file-storage-1333 [002] d... 59.898711: net2280_queue: starting request >> ----- FIRST DMA ------ >> file-storage-1333 [002] d... 59.898712: start_dma: start >> file-storage-1333 [002] d... 59.898713: start_dma: start queue >> file-storage-1333 [002] d... 59.898717: start_dma: end >> file-storage-1333 [002] d... 59.898717: net2280_queue: finished >> file-storage-1333 [002] .... 59.898717: start_transfer: bulk-in queued > > ... > >> ----- FIRST IRQ ----- >> <idle>-0 [002] d.h. 59.898828: net2280_irq: start > > ... > >> ----- SECOND IRQ ----- >> <idle>-0 [002] d.h. 59.898945: net2280_irq: start > > ... > >> ----- SECOND REQUEST ----- >> file-storage-1333 [002] .... 59.899702: do_read: READ: 8192 @ 122880 >> file-storage-1333 [002] .... 59.899702: do_read: file read 8192 @ 122880 >> file-storage-1333 [002] .... 59.899703: do_read: file read 8192 @ 122880 -> 8192 >> file-storage-1333 [002] .... 59.899704: start_transfer: bulk-in start >> file-storage-1333 [002] .... 59.899704: net2280_queue: received request >> file-storage-1333 [002] d... 59.899704: net2280_queue: starting request >> file-storage-1333 [002] d... 59.899706: start_dma: start >> file-storage-1333 [002] d... 59.899707: start_dma: start queue >> file-storage-1333 [002] d... 59.899710: start_dma: end >> file-storage-1333 [002] d... 59.899710: net2280_queue: finished >> file-storage-1333 [002] .... 59.899710: start_transfer: bulk-in queued > > Why did you cut the log short? The figure I wanted to see here was the > time from the IRQ preceding the 8th bulk-in completion to the IRQ > preceding the 10th bulk-in completion, which hasn't occurred yet. Trying not to send longer emails than necessary. I’ve included a new log showing two full requests: --- FIRST REQUEST --- file-storage-1345 [002] .... 214.987721: do_read: READ: 122880 @ 0 file-storage-1345 [002] .... 214.987722: do_read: file read 16384 @ 0 file-storage-1345 [002] .... 214.987731: do_read: file read 16384 @ 0 -> 16384 file-storage-1345 [002] .... 214.987731: start_transfer: bulk-in start file-storage-1345 [002] .... 214.987732: net2280_queue: received request file-storage-1345 [002] d... 214.987736: net2280_queue: starting request file-storage-1345 [002] d... 214.987738: start_dma: start file-storage-1345 [002] d... 214.987739: start_dma: start queue file-storage-1345 [002] d... 214.987743: start_dma: end file-storage-1345 [002] d... 214.987743: net2280_queue: finished file-storage-1345 [002] .... 214.987743: start_transfer: bulk-in queued file-storage-1345 [002] .... 214.987744: do_read: file read 16384 @ 16384 file-storage-1345 [002] .... 214.987750: do_read: file read 16384 @ 16384 -> 16384 file-storage-1345 [002] .... 214.987751: start_transfer: bulk-in start file-storage-1345 [002] .... 214.987751: net2280_queue: received request file-storage-1345 [002] d... 214.987754: net2280_queue: starting request file-storage-1345 [002] d... 214.987755: net2280_queue: finished file-storage-1345 [002] .... 214.987755: start_transfer: bulk-in queued <idle>-0 [002] d.h. 214.987838: net2280_irq: start <idle>-0 [002] d.h. 214.987846: done: start <idle>-0 [002] d.h. 214.987847: done: calling complete callback <idle>-0 [002] d.h. 214.987847: bulk_in_complete: start <idle>-0 [002] d.h. 214.987848: bulk_in_complete: wakeup thread <idle>-0 [002] dNh. 214.987849: bulk_in_complete: wokeup thread <idle>-0 [002] dNh. 214.987849: bulk_in_complete: end <idle>-0 [002] dNh. 214.987849: done: complete callback done <idle>-0 [002] dNh. 214.987849: done: end <idle>-0 [002] dNh. 214.987851: start_dma: start <idle>-0 [002] dNh. 214.987853: start_dma: start queue <idle>-0 [002] dNh. 214.987856: start_dma: end <idle>-0 [002] dNh. 214.987860: handle_ep_small: data packet transmitted <idle>-0 [002] dNh. 214.987861: net2280_irq: end file-storage-1345 [002] .... 214.987865: do_read: file read 16384 @ 32768 file-storage-1345 [002] .... 214.987872: do_read: file read 16384 @ 32768 -> 16384 file-storage-1345 [002] .... 214.987872: start_transfer: bulk-in start file-storage-1345 [002] .... 214.987872: net2280_queue: received request file-storage-1345 [002] d... 214.987875: net2280_queue: starting request file-storage-1345 [002] d... 214.987876: net2280_queue: finished file-storage-1345 [002] .... 214.987876: start_transfer: bulk-in queued <idle>-0 [002] d.h. 214.987946: net2280_irq: start <idle>-0 [002] d.h. 214.987953: done: start <idle>-0 [002] d.h. 214.987954: done: calling complete callback <idle>-0 [002] d.h. 214.987955: bulk_in_complete: start <idle>-0 [002] d.h. 214.987955: bulk_in_complete: wakeup thread <idle>-0 [002] dNh. 214.987956: bulk_in_complete: wokeup thread <idle>-0 [002] dNh. 214.987956: bulk_in_complete: end <idle>-0 [002] dNh. 214.987956: done: complete callback done <idle>-0 [002] dNh. 214.987956: done: end <idle>-0 [002] dNh. 214.987958: start_dma: start <idle>-0 [002] dNh. 214.987959: start_dma: start queue <idle>-0 [002] dNh. 214.987963: start_dma: end <idle>-0 [002] dNh. 214.987967: handle_ep_small: data packet transmitted <idle>-0 [002] dNh. 214.987967: net2280_irq: end file-storage-1345 [002] .... 214.987971: do_read: file read 16384 @ 49152 file-storage-1345 [002] .... 214.987977: do_read: file read 16384 @ 49152 -> 16384 file-storage-1345 [002] .... 214.987978: start_transfer: bulk-in start file-storage-1345 [002] .... 214.987979: net2280_queue: received request file-storage-1345 [002] d... 214.987982: net2280_queue: starting request file-storage-1345 [002] d... 214.987982: net2280_queue: finished <idle>-0 [002] d.h. 214.988053: net2280_irq: start <idle>-0 [002] d.h. 214.988060: done: start <idle>-0 [002] d.h. 214.988061: done: calling complete callback <idle>-0 [002] d.h. 214.988061: bulk_in_complete: start <idle>-0 [002] d.h. 214.988062: bulk_in_complete: wakeup thread <idle>-0 [002] dNh. 214.988063: bulk_in_complete: wokeup thread <idle>-0 [002] dNh. 214.988063: bulk_in_complete: end <idle>-0 [002] dNh. 214.988064: done: complete callback done <idle>-0 [002] dNh. 214.988064: done: end <idle>-0 [002] dNh. 214.988066: start_dma: start <idle>-0 [002] dNh. 214.988068: start_dma: start queue <idle>-0 [002] dNh. 214.988071: start_dma: end <idle>-0 [002] dNh. 214.988073: handle_ep_small: data packet transmitted <idle>-0 [002] dNh. 214.988076: net2280_irq: end file-storage-1345 [002] .... 214.988079: do_read: file read 16384 @ 65536 file-storage-1345 [002] .... 214.988085: do_read: file read 16384 @ 65536 -> 16384 file-storage-1345 [002] .... 214.988085: start_transfer: bulk-in start file-storage-1345 [002] .... 214.988086: net2280_queue: received request file-storage-1345 [002] d... 214.988089: net2280_queue: starting request file-storage-1345 [002] d... 214.988090: net2280_queue: finished file-storage-1345 [002] .... 214.988090: start_transfer: bulk-in queued <idle>-0 [002] d.h. 214.988160: net2280_irq: start <idle>-0 [002] d.h. 214.988168: done: start <idle>-0 [002] d.h. 214.988169: done: calling complete callback <idle>-0 [002] d.h. 214.988169: bulk_in_complete: start <idle>-0 [002] d.h. 214.988170: bulk_in_complete: wakeup thread <idle>-0 [002] dNh. 214.988170: bulk_in_complete: wokeup thread <idle>-0 [002] dNh. 214.988171: bulk_in_complete: end <idle>-0 [002] dNh. 214.988171: done: complete callback done <idle>-0 [002] dNh. 214.988171: done: end <idle>-0 [002] dNh. 214.988173: start_dma: start <idle>-0 [002] dNh. 214.988175: start_dma: start queue <idle>-0 [002] dNh. 214.988179: start_dma: end <idle>-0 [002] dNh. 214.988182: handle_ep_small: data packet transmitted <idle>-0 [002] dNh. 214.988184: net2280_irq: end file-storage-1345 [002] .... 214.988187: do_read: file read 16384 @ 81920 file-storage-1345 [002] .... 214.988193: do_read: file read 16384 @ 81920 -> 16384 file-storage-1345 [002] .... 214.988194: start_transfer: bulk-in start file-storage-1345 [002] .... 214.988194: net2280_queue: received request file-storage-1345 [002] d... 214.988197: net2280_queue: starting request file-storage-1345 [002] d... 214.988197: net2280_queue: finished file-storage-1345 [002] .... 214.988198: start_transfer: bulk-in queued <idle>-0 [002] d.h. 214.988268: net2280_irq: start <idle>-0 [002] d.h. 214.988276: done: start <idle>-0 [002] d.h. 214.988277: done: calling complete callback <idle>-0 [002] d.h. 214.988277: bulk_in_complete: start <idle>-0 [002] d.h. 214.988277: bulk_in_complete: wakeup thread <idle>-0 [002] dNh. 214.988278: bulk_in_complete: wokeup thread <idle>-0 [002] dNh. 214.988279: bulk_in_complete: end <idle>-0 [002] dNh. 214.988279: done: complete callback done <idle>-0 [002] dNh. 214.988280: done: end <idle>-0 [002] dNh. 214.988282: start_dma: start <idle>-0 [002] dNh. 214.988284: start_dma: start queue <idle>-0 [002] dNh. 214.988284: start_dma: end <idle>-0 [002] dNh. 214.988289: handle_ep_small: data packet transmitted <idle>-0 [002] dNh. 214.988290: net2280_irq: end file-storage-1345 [002] .... 214.988316: do_read: file read 16384 @ 98304 file-storage-1345 [002] .... 214.988322: do_read: file read 16384 @ 98304 -> 16384 file-storage-1345 [002] .... 214.988323: start_transfer: bulk-in start file-storage-1345 [002] .... 214.988324: net2280_queue: received request file-storage-1345 [002] d... 214.988327: net2280_queue: starting request file-storage-1345 [002] d... 214.988327: net2280_queue: finished file-storage-1345 [002] .... 214.988328: start_transfer: bulk-in queued <idle>-0 [002] dNh. 214.988387: net2280_irq: start <idle>-0 [002] dNh. 214.988395: done: start <idle>-0 [002] dNh. 214.988396: done: calling complete callback <idle>-0 [002] dNh. 214.988396: bulk_in_complete: start <idle>-0 [002] dNh. 214.988396: bulk_in_complete: wakeup thread <idle>-0 [002] dNh. 214.988400: bulk_in_complete: wokeup thread <idle>-0 [002] dNh. 214.988400: bulk_in_complete: end <idle>-0 [002] dNh. 214.988401: done: complete callback done <idle>-0 [002] dNh. 214.988402: done: end <idle>-0 [002] dNh. 214.988403: start_dma: start <idle>-0 [002] dNh. 214.988405: start_dma: start queue file-storage-1345 [000] .... 214.988408: do_read: file read 8192 @ 114688 <idle>-0 [002] dNh. 214.988408: start_dma: end <idle>-0 [002] dNh. 214.988411: handle_ep_small: data packet transmitted <idle>-0 [002] dNh. 214.988413: net2280_irq: end file-storage-1345 [000] .... 214.988415: do_read: file read 8192 @ 114688 -> 8192 file-storage-1345 [000] .... 214.988416: start_transfer: bulk-in start file-storage-1345 [000] .... 214.988417: net2280_queue: received request file-storage-1345 [000] d... 214.988420: net2280_queue: starting request file-storage-1345 [000] d... 214.988420: net2280_queue: finished file-storage-1345 [000] .... 214.988421: start_transfer: bulk-in queued <idle>-0 [002] d.h. 214.988498: net2280_irq: start <idle>-0 [002] d.h. 214.988506: done: start <idle>-0 [002] d.h. 214.988507: done: calling complete callback <idle>-0 [002] d.h. 214.988507: bulk_in_complete: start <idle>-0 [002] d.h. 214.988507: bulk_in_complete: wakeup thread <idle>-0 [002] dNh. 214.988509: bulk_in_complete: wokeup thread <idle>-0 [002] dNh. 214.988509: bulk_in_complete: end <idle>-0 [002] dNh. 214.988509: done: complete callback done <idle>-0 [002] dNh. 214.988509: done: end <idle>-0 [002] dNh. 214.988511: start_dma: start <idle>-0 [002] dNh. 214.988513: start_dma: start queue <idle>-0 [002] dNh. 214.988513: start_dma: end <idle>-0 [002] dNh. 214.988519: handle_ep_small: data packet transmitted <idle>-0 [002] dNh. 214.988519: net2280_irq: end file-storage-1345 [002] .... 214.988526: start_transfer: bulk-in start file-storage-1345 [002] .... 214.988527: net2280_queue: received request file-storage-1345 [002] d... 214.988527: net2280_queue: starting request file-storage-1345 [002] d... 214.988528: net2280_queue: finished file-storage-1345 [002] .... 214.988528: start_transfer: bulk-in queued <idle>-0 [002] d.h. 214.988576: net2280_irq: start <idle>-0 [002] d.h. 214.988584: done: start <idle>-0 [002] d.h. 214.988585: done: calling complete callback <idle>-0 [002] d.h. 214.988586: bulk_in_complete: start <idle>-0 [002] d.h. 214.988587: bulk_in_complete: wakeup thread <idle>-0 [002] dNh. 214.988588: bulk_in_complete: wokeup thread <idle>-0 [002] dNh. 214.988588: bulk_in_complete: end <idle>-0 [002] dNh. 214.988589: done: complete callback done <idle>-0 [002] dNh. 214.988589: done: end <idle>-0 [002] dNh. 214.988590: start_dma: start <idle>-0 [002] dNh. 214.988592: start_dma: start queue <idle>-0 [002] dNh. 214.988595: start_dma: end <idle>-0 [002] dNh. 214.988600: handle_ep_small: data packet transmitted <idle>-0 [002] dNh. 214.988600: net2280_irq: end <idle>-0 [002] dNh. 214.988604: net2280_irq: start <idle>-0 [002] dNh. 214.988614: done: start <idle>-0 [002] dNh. 214.988615: done: calling complete callback <idle>-0 [002] dNh. 214.988615: bulk_in_complete: start <idle>-0 [002] dNh. 214.988616: bulk_in_complete: wakeup thread <idle>-0 [002] dNh. 214.988617: bulk_in_complete: wokeup thread <idle>-0 [002] dNh. 214.988617: bulk_in_complete: end <idle>-0 [002] dNh. 214.988617: done: complete callback done <idle>-0 [002] dNh. 214.988618: done: end <idle>-0 [002] dNh. 214.988619: net2280_irq: end <idle>-0 [002] dNh. 214.988623: net2280_irq: start <idle>-0 [002] dNh. 214.988627: net2280_irq: end file-storage-1345 [002] .... 214.988632: start_transfer: bulk-out start file-storage-1345 [002] .... 214.988633: net2280_queue: received request file-storage-1345 [002] d... 214.988634: net2280_queue: starting request file-storage-1345 [002] d... 214.988636: start_dma: start file-storage-1345 [002] d... 214.988640: start_dma: start queue file-storage-1345 [002] d... 214.988645: start_dma: end file-storage-1345 [002] d... 214.988646: net2280_queue: finished file-storage-1345 [002] .... 214.988647: start_transfer: bulk-out queued <idle>-0 [002] d.h. 214.988698: net2280_irq: start <idle>-0 [002] d.h. 214.988714: done: start <idle>-0 [002] d.h. 214.988715: done: calling complete callback <idle>-0 [002] d.h. 214.988716: bulk_out_complete: start <idle>-0 [002] d.h. 214.988716: bulk_out_complete: wakeup thread <idle>-0 [002] dNh. 214.988718: bulk_out_complete: wokeup thread <idle>-0 [002] dNh. 214.988718: bulk_out_complete: end <idle>-0 [002] dNh. 214.988718: done: complete callback done <idle>-0 [002] dNh. 214.988719: done: end <idle>-0 [002] dNh. 214.988719: net2280_irq: end <idle>-0 [002] dNh. 214.988723: net2280_irq: start <idle>-0 [002] dNh. 214.988727: net2280_irq: end <idle>-0 [002] dNh. 214.988732: net2280_irq: start <idle>-0 [002] dNh. 214.988737: net2280_irq: end --- SECOND REQUEST --- file-storage-1345 [002] .... 214.988753: do_read: READ: 8192 @ 122880 file-storage-1345 [002] .... 214.988754: do_read: file read 8192 @ 122880 file-storage-1345 [002] .... 214.988761: do_read: file read 8192 @ 122880 -> 8192 file-storage-1345 [002] .... 214.988762: start_transfer: bulk-in start file-storage-1345 [002] .... 214.988763: net2280_queue: received request file-storage-1345 [002] d... 214.988765: net2280_queue: starting request file-storage-1345 [002] d... 214.988767: start_dma: start file-storage-1345 [002] d... 214.988769: start_dma: start queue file-storage-1345 [002] d... 214.988769: start_dma: end file-storage-1345 [002] d... 214.988772: net2280_queue: finished file-storage-1345 [002] .... 214.988773: start_transfer: bulk-in queued file-storage-1345 [002] .... 214.988774: start_transfer: bulk-in start file-storage-1345 [002] .... 214.988774: net2280_queue: received request file-storage-1345 [002] d... 214.988775: net2280_queue: starting request file-storage-1345 [002] d... 214.988775: net2280_queue: finished file-storage-1345 [002] .... 214.988775: start_transfer: bulk-in queued <idle>-0 [002] d.h. 214.988829: net2280_irq: start <idle>-0 [002] d.h. 214.988837: done: start <idle>-0 [002] d.h. 214.988838: done: calling complete callback <idle>-0 [002] d.h. 214.988838: bulk_in_complete: start <idle>-0 [002] d.h. 214.988839: bulk_in_complete: wakeup thread <idle>-0 [002] dNh. 214.988840: bulk_in_complete: wokeup thread <idle>-0 [002] dNh. 214.988841: bulk_in_complete: end <idle>-0 [002] dNh. 214.988841: done: complete callback done <idle>-0 [002] dNh. 214.988841: done: end <idle>-0 [002] dNh. 214.988843: start_dma: start <idle>-0 [002] dNh. 214.988844: start_dma: start queue <idle>-0 [002] dNh. 214.988848: start_dma: end <idle>-0 [002] dNh. 214.988850: handle_ep_small: data packet transmitted <idle>-0 [002] dNh. 214.988853: net2280_irq: end <idle>-0 [002] dNh. 214.988855: net2280_irq: start <idle>-0 [002] dNh. 214.988863: done: start <idle>-0 [002] dNh. 214.988864: done: calling complete callback <idle>-0 [002] dNh. 214.988864: bulk_in_complete: start <idle>-0 [002] dNh. 214.988864: bulk_in_complete: wakeup thread <idle>-0 [002] dNh. 214.988864: bulk_in_complete: wokeup thread <idle>-0 [002] dNh. 214.988865: bulk_in_complete: end <idle>-0 [002] dNh. 214.988866: done: complete callback done <idle>-0 [002] dNh. 214.988867: done: end <idle>-0 [002] dNh. 214.988867: net2280_irq: end <idle>-0 [002] dNh. 214.988872: net2280_irq: start <idle>-0 [002] dNh. 214.988874: net2280_irq: end file-storage-1345 [002] .... 214.988879: start_transfer: bulk-out start file-storage-1345 [002] .... 214.988880: net2280_queue: received request file-storage-1345 [002] d... 214.988880: net2280_queue: starting request file-storage-1345 [002] d... 214.988882: start_dma: start file-storage-1345 [002] d... 214.988886: start_dma: start queue file-storage-1345 [002] d... 214.988891: start_dma: end file-storage-1345 [002] d... 214.988892: net2280_queue: finished file-storage-1345 [002] .... 214.988892: start_transfer: bulk-out queued dd-1385 [002] d.h. 214.989086: net2280_irq: start dd-1385 [002] d.h. 214.989103: done: start dd-1385 [002] d.h. 214.989105: done: calling complete callback dd-1385 [002] d.h. 214.989105: bulk_out_complete: start dd-1385 [002] d.h. 214.989106: bulk_out_complete: wakeup thread dd-1385 [002] d.h. 214.989109: bulk_out_complete: wokeup thread dd-1385 [002] d.h. 214.989110: bulk_out_complete: end dd-1385 [002] d.h. 214.989110: done: complete callback done dd-1385 [002] d.h. 214.989111: done: end dd-1385 [002] d.h. 214.989111: net2280_irq: end dd-1385 [002] d.h. 214.989115: net2280_irq: start dd-1385 [002] d.h. 214.989122: net2280_irq: end dd-1385 [002] d.h. 214.989124: net2280_irq: start dd-1385 [002] d.h. 214.989127: net2280_irq: end > ... >> Measured end-to-end performance: 135MB/s (145MB/s with tweaked max_sector). >> That�s not bad given that the DMA is only managing 153MB/s. > > How do you arrive at that number? 16384 B / 107 us? I'm not sure why > you refer to that as the DMA peformance. In fact it is the overall > performance for the USB data transfer, which includes driver delays, > DMA delays, bus transfer delays, and controller delays. Most of the > remaining overhead (i.e., the difference between 135 MB/s and 153 MB/s) > comes from the MSC BOT protocol, and as you found, it can be reduced by > increasing max_sectors. I called it the DMA performance as the driver doesn’t do anything else but setup DMA and wait for the IRQ to signal completion of the USB transfer. I calculated the performance by dividing the transferred data by the transfer time (between DMA setup and IRQ reception). > Even if the DMA setup delay were eliminated, it would increase the > transfer rate by no more than 10%, to 168 MB/s or less. That's still > not a very impressive fraction of the total bus capacity of 500 MB/s, > and the difference can be attributed almost entirely to things that are > out of the software's control. I did some testing using gadget zero and max out at 166 MB/s. The big question is why the hardware won’t go any faster than that. I am wondering whether it has something to do with the fact that the internal FIFO size for each endpoint is currently set to 1k. Paul. -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html