[Stgt-devel] Tuning iSER for performance

[Erez Zilber]

> 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