[Stgt-devel] Tuning iSER for performance

[Pete Wyckoff]

erezz at Voltaire.COM wrote on Sun, 09 Mar 2008 16:06 +0200:
> 
> > 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)

I thought thr=8 meant multiple commands.  But the trace snippet
below looks like just one, so fine.

> 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?

Agreed, that's rather slow, 480 MB/s.  Something else is going on.
Closest number I can lay my hands on says 350 kB was 94 us in the
pread, 3800 MB/s.  You should be measuring memory copy speed here.

> 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.

It reads from wherever it put your device with ./tgtadm ...
--backing-store ... .  Presumably a file on the file system, or a
raw block device like /dev/sdb.  Either way, after the first read,
the data stays in page cache, and pread is just a memcpy.

You should watch if you're hitting the disk (vmstat 1) while doing
some runs.  You might try strace -T to see what the target is doing
with all its time.  If it's really just the pread or something we
have overlooked.

> 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.

I'd measure from .383085 to .383227, getting 923 MB/s.  Reasonable
network speed for SDR.

		-- Pete