> That's the only way to get multi-operation concurrency on the > target given existing linux userspace AIO infrastructure: run > multiple IOs at the same time, in separate threads. > > The patch I sent you is just so you can debug, to answer the > question: Is the context switch the source of your performance > problem on a _single_ request. > >
I guess that I missed your point about a single request. Anyway, here's what happens when I use bs_rdwr_sync and run the following command: sgp_dd if=/dev/sdd of=/dev/null bs=512 bpt=1024 count=256 thr=8 time=1 (single 128K READ command) tgtd: [14:33:51.382528] iser_rx_progress(1102) entry tgtd: [14:33:51.382567] handle_wc(897) incoming cmd, len 76 tgtd: [14:33:51.382578] iscsi_iser_read(1302) buf 0x52a628 nbytes 48 tgtd: [14:33:51.382590] iser_parse_hdr(1266) control type PDU tgtd: [14:33:51.382599] iser_parse_hdr(1272) rstag 4aa2003d va 37b0c000 tgtd: [14:33:51.382609] iscsi_scsi_cmd_rx_start(1466) 1 28 0 0 131072 1 17 tgtd: [14:33:51.382622] iscsi_rdma_alloc_data_buf(1660) malloc 0x2b13ddc70000 sz 131072 tgtd: [14:33:51.382633] iscsi_task_queue(1411) 17 17 1 tgtd: [14:33:51.382644] target_cmd_queue(763) 0x536488 28 1 Here, we submit the cmd to bs (I'm using a RAM disk): tgtd: [14:33:51.382655] target_cmd_queue(783) 0x536488 28 1 1 Here, it returns: tgtd: [14:33:51.382984] bs_rdwr_sync_cmd_submit(129) io done 0x536488 28 131072 131072 329 us looks like too much time. On another measurement, I got 276 us (which is also not very good). Even if I measure the time that it takes just to run pread64 (called from bs_rdwr_sync_cmd_submit), I get 273 us. Do you get different numbers on your system? Another question is - how does pread64 access the SCSI device? I understand that it reads from /dev/sdX. Does it call sd? How? Is there any memory copy involved? I'm asking that because I'm used to kernel space where we just call scsi_do_req. tgtd: [14:33:51.383002] target_cmd_queue(794) 17 28 (nil) 0x2b13ddc70000 0 0 131072 0 0 tgtd: [14:33:51.383015] iscsi_rdma_event_modify(1629) tx ready adding 0x52a510 tgtd: [14:33:51.383026] handle_wc(922) incoming cmd proc done, repost tgtd: [14:33:51.383037] iser_rx_progress_one(1072) back from handle_wc tgtd: [14:33:51.383047] iser_tx_progress(1017) entry tgtd: [14:33:51.383056] iser_tx_progress(1028) trying tx tgtd: [14:33:51.383065] iscsi_task_tx_start(1759) found a task 17 131072 0 0 tgtd: [14:33:51.383075] iscsi_data_rsp_build(974) 131072 131072 131072 524288 17 tgtd: [14:33:51.383085] iscsi_rdma_rdma_write(1492) offset 0 len 131072 stag 4aa2003d va 37b0c000 Here, we start RDMA: tgtd: [14:33:51.383118] iscsi_rdma_event_modify(1634) tx ready removing 0x52a510 tgtd: [14:33:51.383129] iscsi_scsi_cmd_tx_done(1707) more data or sense or bidir 17 Here, the notification from IB is received: tgtd: [14:33:51.383227] iser_rx_progress(1102) entry It takes 109 us, which looks ok. On another measurement, I got 108 us. tgtd: [14:33:51.383245] handle_wc(932) RDMA write done tgtd: [14:33:51.383255] iscsi_rdma_event_modify(1629) tx ready adding 0x52a510 tgtd: [14:33:51.383265] iser_rx_progress_one(1072) back from handle_wc tgtd: [14:33:51.383274] iser_tx_progress(1017) entry tgtd: [14:33:51.383283] iser_tx_progress(1028) trying tx tgtd: [14:33:51.383292] iscsi_task_tx_start(1759) found a task 17 131072 131072 0 tgtd: [14:33:51.383302] iscsi_cmd_rsp_build(901) 0x5363c8 28 tgtd: [14:33:51.383311] iscsi_iser_write_begin(1353) new sendl 0x2b13edbbf010 len 48 tgtd: [14:33:51.383322] iscsi_iser_write_end(1388) sendl 0x2b13edbbf010 len 76 tgtd: [14:33:51.383332] iscsi_iser_write_end(1403) inc progress to finish cmd tgtd: [14:33:51.383342] __cmd_done(855) 8 (nil) 0x2b13ddc70000 0 131072 0 tgtd: [14:33:51.383352] iscsi_rdma_free_data_buf(1679) free 0x2b13ddc70000 tgtd: [14:33:51.383361] iser_tx_progress(1028) trying tx tgtd: [14:33:51.383370] iscsi_task_tx_start(1784) no more data tgtd: [14:33:51.383379] iscsi_rdma_event_modify(1634) tx ready removing 0x52a510 tgtd: [14:33:51.383388] iser_tx_progress(1017) entry tgtd: [14:33:51.383398] iser_rx_progress(1102) entry tgtd: [14:33:51.383407] handle_wc(880) outgoing rsp complete tgtd: [14:33:51.383416] iser_rx_progress_one(1072) back from handle_wc _______________________________________________ Stgt-devel mailing list [email protected] https://lists.berlios.de/mailman/listinfo/stgt-devel
