Poor iSCSI performance when enabling sync=always

[Chris LaDuke]

I had posted in another thread and jgreco helped me determine why my SLOG was never being touched, it was because iSCSI default writes everything async and only sync writes get sent to the SLOG. So I changed my pool to sync=always. I then watched my performance plummet from 169MB/sec to consistent 105MB/sec and go from 2700 IOPS to 1660 IOPS. The benchmark is iostat 64k blocks 100% sequential write. my I am running my SLOG in a mirror or two Intel DCS 3700's. gstat shows them at about 65% busy when running iometer. I understand writing sync will be slower, but this seems really slow. I am not familiar enough to know what changes from an OS/zfs standpoint when writing sync that may cause other bottlenecks besides drive. Admittedly the gear is far from new, so I'm wondering CPU? Please let me know other tests I could run to help figure this out. Or, if this seems acceptable to those that know more than I, just let m know!

zpool status:
pool: FREENAS1
state: ONLINE
scan: none requested
config:

NAME STATE READ WRITE CKSUM
FREENAS1 ONLINE 0 0 0
mirror-0 ONLINE 0 0 0
gptid/d2ab336e-8399-11e3-90e5-003048d5067c ONLINE 0 0 0
gptid/d31578b5-8399-11e3-90e5-003048d5067c ONLINE 0 0 0
mirror-1 ONLINE 0 0 0
gptid/eb375035-8399-11e3-90e5-003048d5067c ONLINE 0 0 0
gptid/ebabd762-8399-11e3-90e5-003048d5067c ONLINE 0 0 0
mirror-2 ONLINE 0 0 0
gptid/f4c37d34-8399-11e3-90e5-003048d5067c ONLINE 0 0 0
gptid/f52850fc-8399-11e3-90e5-003048d5067c ONLINE 0 0 0
logs
mirror-3 ONLINE 0 0 0
gptid/0b6f26b5-839a-11e3-90e5-003048d5067c ONLINE 0 0 0
gptid/0b99c5c1-839a-11e3-90e5-003048d5067c ONLINE 0 0 0

errors: No known data errors

Machine Specs:
Processor E5430 at 2.66 GHz
RAM: 12 GB
IO: IBM 1015 flashed to LSI-9211
(2) dual intel Gb server nics, each interface on its on VLAN
Drives: (6) 15k SAS 300GB in 3 mirrored pools
(2) Intel DC S3700 drives in a mirrored pool for SLOG


Each network interface was pushing about 350 mbit/sec and now is about 200 mbit/sec
Since the only thing I changed was on the ZFS side, seems like a FreeNAS/server issue.

Based on iozone the spool seems blazing fast.
output of iozone -s100M -r64K -I -t32 -T -i0 -i2
Record Size 64 KB
O_DIRECT feature enabled
Command line used: iozone -s100M -r64K -I -t32 -T -i0 -i2
Output is in Kbytes/sec
Time Resolution = 0.000001 seconds.
Processor cache size set to 1024 Kbytes.
Processor cache line size set to 32 bytes.
File stride size set to 17 * record size.
Throughput test with 32 threads
Each thread writes a 102400 Kbyte file in 64 Kbyte records

Children see throughput for 32 initial writers = 573816.64 KB/sec
Parent sees throughput for 32 initial writers = 175807.93 KB/sec
Min throughput per thread = 12081.14 KB/sec
Max throughput per thread = 27432.43 KB/sec
Avg throughput per thread = 17931.77 KB/sec
Min xfer = 43712.00 KB

Children see throughput for 32 rewriters = 3860336.24 KB/sec
Parent sees throughput for 32 rewriters = 199144.62 KB/sec
Min throughput per thread = 24573.29 KB/sec
Max throughput per thread = 705705.94 KB/sec
Avg throughput per thread = 120635.51 KB/sec
Min xfer = 5056.00 KB

Children see throughput for 32 random readers = 5929731.27 KB/sec
Parent sees throughput for 32 random readers = 4651177.25 KB/sec
Min throughput per thread = 0.00 KB/sec
Max throughput per thread = 1241152.12 KB/sec
Avg throughput per thread = 185304.10 KB/sec
Min xfer = 0.00 KB

Children see throughput for 32 random writers = 417524.02 KB/sec
Parent sees throughput for 32 random writers = 54434.60 KB/sec
Min throughput per thread = 839.97 KB/sec
Max throughput per thread = 59052.09 KB/sec
Avg throughput per thread = 13047.63 KB/sec
Min xfer = 2368.00 KB
VMSTAT output during a test
0 1 0 1837M 1723M 2 0 0 0 0 0 0 0 12976 21628 95554 2 18 81
1 1 0 1837M 1723M 0 0 0 0 0 0 0 0 13717 23124 100732 4 23 72
0 1 0 1837M 1723M 0 0 0 0 0 0 0 0 12924 20699 93545 1 17 82
0 1 0 1837M 1723M 29 0 0 0 0 0 0 0 13287 21942 99070 1 21 78
0 1 0 1837M 1723M 0 0 0 0 0 0 0 0 13536 21483 100533 2 23 75
2 1 0 1837M 1723M 11 0 0 0 0 0 0 0 13549 22777 99822 2 20 79

 

[jgreco]

I'd say that's pretty good actually.

sync is all about the latency through the system, the more the system has to do the slower it is. So your initiator has to get a request from the userland, and packages it up into an iSCSI request, which gets piped onto a TCP connection, which goes over your network, hits FreeNAS, where the data is delivered to a userland daemon, which may involve a context switch and syscall to receive the data, processed, translated into an I/O request, which then goes through another syscall and into the kernel, then into ZFS, which sees a sync write request and launches it off towards the mirrored SSD's, which involves queuing some commands to the HBA, which in turn sends them to the SSD's, over a SAS channel, and the SSDS then have to each write that to flash, then confirm the write, which then goes back through this chain of crazy step by step until ultimately your initiator gets a confirmation, at which point it is free to write its next block in sync mode....

Do you get a bit of a feeling that there's so much opportunity for latency in the system?

The CPU being slow is definitely not going to be helping but quite frankly I'd say it is doing pretty good as is..

 

[Chris LaDuke]

Well thanks for that, and if its good enough for you, its good enough for me!

 

[jgreco]

I also meant to point out that this is kind of in-line with the performance loss seen by others when pushing async over to sync.

 

[cyberjock]

You've also got only 12GB of RAM. #1 rule for more speed.. more RAM!