ISCSI Dropouts

[Imagine]

Hello all,

I have strangest situation with iSCSi when used with ESXi. Every now and then we have dropouts which require us to restart the service as all our guest OS's lose their storage and especially Linux boxes go bananas and mount their storage as read-only. I've been looking into this for around 2 weeks now and every time it drops I check the logs and can see lots of entries like this;

Show : Logs

Oct 17 20:00:07 STFreeNAS02 autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs get -H freenas:state volSTSE1SSD01@auto-20141010.2000-1w
Oct 17 20:00:07 STFreeNAS02 autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs destroy -r -d volSTSE1SSD01@auto-20141010.2000-1w
Oct 17 20:00:08 STFreeNAS02 autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs get -H freenas:state volSTSE1SSD01/.system/rrd@auto-20141010.2000-1w
Oct 17 20:00:08 STFreeNAS02 autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs get -H freenas:state volSTSE1SSD01/.system/samba4@auto-20141010.2000-1w
Oct 17 20:00:09 STFreeNAS02 autorepl.py: [common.pipesubr:58] Popen()ing: /usr/bin/ssh -i /data/ssh/replication -o BatchMode=yes -o StrictHostKeyChecking=yes -o ConnectTimeout=7 -p 22 192.168.105.7 "zfs list -Hr -o name -t snapshot -d 1 volSTSE1SATA01 | tail -n 1 | cut -d@ -f2"
Oct 17 20:02:13 STFreeNAS02 istgt[38934]: istgt_lu_disk.c:5318:istgt_lu_disk_queue_start: ***WARNING*** transfer abort CmdSN=65962579
Oct 17 20:02:13 STFreeNAS02 istgt[38934]: istgt_lu.c:3255:luworker: ***WARNING*** LU1: lu_disk_queue_start() aborted
Oct 17 20:02:13 STFreeNAS02 istgt[38934]: istgt_iscsi.c:4764:istgt_iscsi_transfer_out: ***ERROR*** iscsi_read_pdu() failed, r2t_sent=0
Oct 17 20:02:13 STFreeNAS02 istgt[38934]: istgt_iscsi.c:5852:worker: ***ERROR*** iscsi_task_transfer_out() failed on iqn.2013-03.stellarise.com.istgt:freenas02,t,0x0001(iqn.1998-01.com.vmware:localhost-174aa83d,i,0x00023d000001)
Oct 17 20:02:16 STFreeNAS02 istgt[38934]: istgt_iscsi.c:6749:istgt_iscsi_drop_old_conns: ***WARNING*** drop old connections iqn.2013-03.stellarise.com.istgt:freenas02 by iqn.1998-01.com.vmware:localhost-174aa83d,i,0x00023d000001
Oct 17 20:02:20 STFreeNAS02 istgt[38934]: Login from iqn.1998-01.com.vmware:localhost-174aa83d (192.168.105.6) on iqn.2013-03.stellarise.com.istgt:freenas02 LU1 (192.168.105.8:3260,1), ISID=23d000001, TSIH=3, CID=0, HeaderDigest=off, DataDigest=off
Oct 17 20:02:50 STFreeNAS02 istgt[38934]: istgt_lu_disk.c:5318:istgt_lu_disk_queue_start: ***WARNING*** transfer abort CmdSN=65964200
Oct 17 20:02:50 STFreeNAS02 istgt[38934]: istgt_lu.c:3255:luworker: ***WARNING*** LU1: lu_disk_queue_start() aborted
Oct 17 20:02:54 STFreeNAS02 istgt[38934]: istgt_iscsi.c:6749:istgt_iscsi_drop_old_conns: ***WARNING*** drop old connections iqn.2013-03.stellarise.com.istgt:freenas02 by iqn.1998-01.com.vmware:localhost-174aa83d,i,0x00023d000001
Oct 17 20:02:58 STFreeNAS02 istgt[38934]: Login from iqn.1998-01.com.vmware:localhost-174aa83d (192.168.105.6) on iqn.2013-03.stellarise.com.istgt:freenas02 LU1 (192.168.105.8:3260,1), ISID=23d000001, TSIH=4, CID=0, HeaderDigest=off, DataDigest=off
Oct 17 20:03:35 STFreeNAS02 istgt[38934]: istgt_lu_disk.c:5318:istgt_lu_disk_queue_start: ***WARNING*** transfer abort CmdSN=65967163
Oct 17 20:03:36 STFreeNAS02 istgt[38934]: istgt_lu.c:3255:luworker: ***WARNING*** LU1: lu_disk_queue_start() aborted
Oct 17 20:03:36 STFreeNAS02 istgt[38934]: istgt_lu_disk.c:5318:istgt_lu_disk_queue_start: ***WARNING*** transfer abort CmdSN=65967164
Oct 17 20:03:36 STFreeNAS02 istgt[38934]: istgt_lu.c:3255:luworker: ***WARNING*** LU1: lu_disk_queue_start() aborted
Oct 17 20:03:36 STFreeNAS02 istgt[38934]: istgt_iscsi.c:4764:istgt_iscsi_transfer_out: ***ERROR*** iscsi_read_pdu() failed, r2t_sent=0
Oct 17 20:03:36 STFreeNAS02 istgt[38934]: istgt_iscsi.c:5852:worker: ***ERROR*** iscsi_task_transfer_out() failed on iqn.2013-03.stellarise.com.istgt:freenas02,t,0x0001(iqn.1998-01.com.vmware:localhost-174aa83d,i,0x00023d000001)
Oct 17 20:03:36 STFreeNAS02 istgt[38934]: istgt_lu_disk.c:5318:istgt_lu_disk_queue_start: ***WARNING*** transfer abort CmdSN=65967165
Oct 17 20:03:36 STFreeNAS02 istgt[38934]: istgt_lu.c:3255:luworker: ***WARNING*** LU1: lu_disk_queue_start() aborted
Oct 17 20:03:39 STFreeNAS02 istgt[38934]: istgt_iscsi.c:6749:istgt_iscsi_drop_old_conns: ***WARNING*** drop old connections iqn.2013-03.stellarise.com.istgt:freenas02 by iqn.1998-01.com.vmware:localhost-174aa83d,i,0x00023d000001
Oct 17 20:03:40 STFreeNAS02 istgt[38934]: Login from iqn.1998-01.com.vmware:localhost-174aa83d (192.168.105.6) on iqn.2013-03.stellarise.com.istgt:freenas02 LU1 (192.168.105.8:3260,1), ISID=23d000001, TSIH=5, CID=0, HeaderDigest=off, DataDigest=off
Oct 17 20:04:29 STFreeNAS02 istgt[38934]: istgt_iscsi.c:4764:istgt_iscsi_transfer_out: ***ERROR*** iscsi_read_pdu() failed, r2t_sent=0
Oct 17 20:04:29 STFreeNAS02 istgt[38934]: istgt_iscsi.c:5852:worker: ***ERROR*** iscsi_task_transfer_out() failed on iqn.2013-03.stellarise.com.istgt:freenas02,t,0x0001(iqn.1998-01.com.vmware:localhost-174aa83d,i,0x00023d000001)
Oct 17 20:04:29 STFreeNAS02 istgt[38934]: istgt_lu_disk.c:5318:istgt_lu_disk_queue_start: ***WARNING*** transfer abort CmdSN=65972008
Oct 17 20:04:29 STFreeNAS02 istgt[38934]: istgt_lu.c:3255:luworker: ***WARNING*** LU1: lu_disk_queue_start() aborted
Oct 17 20:04:32 STFreeNAS02 istgt[38934]: istgt_iscsi.c:6749:istgt_iscsi_drop_old_conns: ***WARNING*** drop old connections iqn.2013-03.stellarise.com.istgt:freenas02 by iqn.1998-01.com.vmware:localhost-174aa83d,i,0x00023d000001
Oct 17 20:04:33 STFreeNAS02 istgt[38934]: Login from iqn.1998-01.com.vmware:localhost-174aa83d (192.168.105.6) on iqn.2013-03.stellarise.com.istgt:freenas02 LU1 (192.168.105.8:3260,1), ISID=23d000001, TSIH=6, CID=0, HeaderDigest=off, DataDigest=off
Oct 17 20:05:17 STFreeNAS02 istgt[38934]: istgt_iscsi.c:4764:istgt_iscsi_transfer_out: ***ERROR*** iscsi_read_pdu() failed, r2t_sent=0
Oct 17 20:05:17 STFreeNAS02 istgt[38934]: istgt_iscsi.c:5852:worker: ***ERROR*** iscsi_task_transfer_out() failed on iqn.2013-03.stellarise.com.istgt:freenas02,t,0x0001(iqn.1998-01.com.vmware:localhost-174aa83d,i,0x00023d000001)
Oct 17 20:05:17 STFreeNAS02 istgt[38934]: istgt_lu_disk.c:5318:istgt_lu_disk_queue_start: ***WARNING*** transfer abort CmdSN=65972589
Oct 17 20:05:17 STFreeNAS02 istgt[38934]: istgt_lu.c:3255:luworker: ***WARNING*** LU1: lu_disk_queue_start() aborted
Oct 17 20:05:20 STFreeNAS02 istgt[38934]: istgt_iscsi.c:6749:istgt_iscsi_drop_old_conns: ***WARNING*** drop old connections iqn.2013-03.stellarise.com.istgt:freenas02 by iqn.1998-01.com.vmware:localhost-174aa83d,i,0x00023d000001
Oct 17 20:05:21 STFreeNAS02 istgt[38934]: Login from iqn.1998-01.com.vmware:localhost-174aa83d (192.168.105.6) on iqn.2013-03.stellarise.com.istgt:freenas02 LU1 (192.168.105.8:3260,1), ISID=23d000001, TSIH=7, CID=0, HeaderDigest=off, DataDigest=off
Oct 17 20:05:49 STFreeNAS02 autorepl.py: [common.pipesubr:58] Popen()ing: /usr/bin/ssh -i /data/ssh/replication -o BatchMode=yes -o StrictHostKeyChecking=yes -o ConnectTimeout=7 -p 22 192.168.105.7 "zfs list -Hr -o name -t snapshot -d 1 volSTSE1SATA01 | tail -n 1 | cut -d@ -f2"
Oct 17 20:05:50 STFreeNAS02 autorepl.py: [common.pipesubr:72] Executing: /usr/bin/ssh -i /data/ssh/replication -o BatchMode=yes -o StrictHostKeyChecking=yes -o ConnectTimeout=7 -p 22 192.168.105.7 "/sbin/zfs inherit freenas:state volSTSE1SATA01@auto-20141017.2000-1w"
Oct 17 20:05:50 STFreeNAS02 autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs inherit freenas:state volSTSE1SSD01@auto-20141017.1930-1w
Oct 17 20:05:50 STFreeNAS02 autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs release -r freenas:repl volSTSE1SSD01@auto-20141017.1930-1w
Oct 17 20:05:50 STFreeNAS02 autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs set freenas:state=LATEST volSTSE1SSD01@auto-20141017.2000-1w
Oct 17 20:05:51 STFreeNAS02 autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs hold -r freenas:repl volSTSE1SSD01@auto-20141017.2000-1w
Oct 17 20:05:51 STFreeNAS02 common.pipesubr: cannot hold snapshot 'volSTSE1SSD01@auto-20141017.2000-1w': tag already exists on this dataset
Oct 17 20:05:51 STFreeNAS02 autorepl.py: [common.pipesubr:58] Popen()ing: /usr/bin/ssh -i /data/ssh/replication -o BatchMode=yes -o StrictHostKeyChecking=yes -o ConnectTimeout=7 -p 22 192.168.105.7 "zfs list -Hr -o name -t snapshot -d 1 volSTSE1SATA02 | tail -n 1 | cut -d@ -f2"

I've looked at https://bugs.freenas.org/issues/1531

And taken away a few lessons which have helped reduce the frequency of these issues but still can't shake it off permanently.

The specs of the machine this is running on are as follows;

FreeNAS 9.2.1.6 64-bit
Intel Xeon Quad Core 3.00Ghz (Core 2 Era)
8GB DDR2 ECC Memory
2x 1TB Samsung Evo 840 SSD's

Currently we use ZFS with RAIDing through FreeNAS (If that's how to term it), currently banging my head against a wall on this one. I'm a little bit worried about making changes if I don't understand what it's doing so I've been a little conservative on this one. Any tips?

 

[HoneyBadger]

Myriad of questions inbound.

Can you add more RAM?

With 9.2.1.6 I'm assuming you've left compression on by default. Considered turning it off?

Have you heard of/applied the firmware fix to those EVOs for the stale data read speeds?

Is NFS an option? Your pool is all-SSD so the sync writes would be less of an issue.

Did you underprovision those SSDs at all to allow for better wear-leveling and consistent performance?

What's the network connectivity world look like? Is your iSCSI network isolated from other traffic?

 

[Imagine]

Will look into disabling the compression on the drives. Right now we have our disks set up to have all their capacity available to the file system and right now they're about 25% full with compression. I've deliberately setup our box so that we never have full storage as that can effectively kill TRIM which is bad.

I know about the SSD's firmware but I can't get any access to the physical drives in person to do this, (Mostly a boss who will need some convincing for this.)

NFS might be an option if, might look into this to see if dropping iSCSi all together fixes.

In terms of our local network our 2x ESXi hosts don't pull enough traffic over our office network to pull strain over a local gigabit ethernet connection. I don't believe our network load is too high based on logs from Firewall but that could be interesting.

 

[Imagine]

Just a small update, I made a small change to my FreeNAS configuration and it seems that now we have some points where ZFS is writing a whole load of data, and ESXi slows down to almost a grind but still responsive. I haven't been able to spot any drop outs in iSCSi for a while.

I might look into more performance tuning in order to reduce either the amount of time it's sluggish for, or to keep ESXi responsive during these flushes. Any ideas?

 

[HoneyBadger]

It'd always be good information to post those changes either here or as a comment on #1531 so that future queries might be aided. Assuming it was tweaks beyond those already covered (reducing transaction group sizing/synctime/etc) - did you modify your burst/segment lengths in ESXi or other timeouts along with it?

What I find a little odd is that your initial logs are indicating read timeouts, where most cases of this I've seen are write timeouts. That might be in relation to the small amount of RAM (in terms of "systems I'd host VMs on") you have though.

Still wondering about the network configuration. How many NICs are on your ESXi hosts? Sharing storage traffic with anything else (even management) is a good way to get these kinds of dropouts.

 

[Imagine]

Currently our network run through a pfSense firewall sitting virtually within the ESXi host. Effectively each of our office Subnetworks are connected to an indepedent NIC (we only have 4 subnetworks). Although in terms of traffic over the same network as FreeNAS we've got the 2 ESXi hosts (10 or so VM's each), some workstations which don't do much, a couple printers and that's about it really.

In terms of the RAM situation the current machine has just 8GB bit I've managed to explain to colleagues that it's simply not enough to go between ZFS, L2ARC, ISCSI and lord knows what else. It was quite easy to explain seeing as most of the people running similar to setups to us, have at least 20GB RAM and here we are trying to shoe-string it together on 8GB.

This evening I'm moving our FreeNAS box onto a HP ProLiant DL360 G6 with 40GB RAM, far more CPU resources and I believe it has a much, much better SATA controller than our current G4 model I believe.

Yeah the only changes I made were stuff I picked up from bug 1531 so nothing really new to throw into the mix from my end. I did slightly raise the timeouts for the ISCSI service which seems to have alleviated the dropouts but we have small periods of time where both ESXI servers just go catatonic and don't do too much for a few mins. Looks like snapshots causing stalls;

Show : Logs

Oct 22 16:30:03 STFreeNAS02 autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs get -H freenas:state volSTSE1SSD01/.system/syslog@auto-20141015.1630-1w
Oct 22 16:30:03 STFreeNAS02 autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs get -H freenas:state volSTSE1SSD01/.system/rrd@auto-20141015.1630-1w
Oct 22 16:30:03 STFreeNAS02 autosnap.py: [tools.autosnap:58] Popen()ing: /sbin/zfs get -H freenas:state volSTSE1SSD01/.system/samba4@auto-20141015.1630-1w
Oct 22 16:30:04 STFreeNAS02 autorepl.py: [common.pipesubr:58] Popen()ing: /usr/bin/ssh -i /data/ssh/replication -o BatchMode=yes -o StrictHostKeyChecking=yes -o ConnectTimeout=7 -p 22 192.168.105.7 "zfs list -Hr -o name -t snapshot -d 1 volSTSE1SATA01 | tail -n 1 | cut -d@ -f2"
Oct 22 16:35:30 STFreeNAS02 autorepl.py: [common.pipesubr:58] Popen()ing: /usr/bin/ssh -i /data/ssh/replication -o BatchMode=yes -o StrictHostKeyChecking=yes -o ConnectTimeout=7 -p 22 192.168.105.7 "zfs list -Hr -o name -t snapshot -d 1 volSTSE1SATA01 | tail -n 1 | cut -d@ -f2"
Oct 22 16:35:30 STFreeNAS02 autorepl.py: [common.pipesubr:72] Executing: /usr/bin/ssh -i /data/ssh/replication -o BatchMode=yes -o StrictHostKeyChecking=yes -o ConnectTimeout=7 -p 22 192.168.105.7 "/sbin/zfs inherit freenas:state volSTSE1SATA01@auto-20141022.1630-1w"
Oct 22 16:35:30 STFreeNAS02 autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs inherit freenas:state volSTSE1SSD01@auto-20141022.1600-1w
Oct 22 16:35:30 STFreeNAS02 autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs release -r freenas:repl volSTSE1SSD01@auto-20141022.1600-1w
Oct 22 16:35:30 STFreeNAS02 autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs set freenas:state=LATEST volSTSE1SSD01@auto-20141022.1630-1w
Oct 22 16:35:30 STFreeNAS02 autorepl.py: [common.pipesubr:72] Executing: /sbin/zfs hold -r freenas:repl volSTSE1SSD01@auto-20141022.1630-1w
Oct 22 16:35:30 STFreeNAS02 common.pipesubr: cannot hold snapshot 'volSTSE1SSD01@auto-20141022.1630-1w': tag already exists on this dataset

Although when it goes catatonic I've noticed late at night (3am-ish) when none of my colleagues are awake and nobody resets the ISCSI service, if I leave it for 15mins the server usually regains responsiveness so looks like lots of traffic going through ZFS at those points in time.

Also, I'll update you on how it goes moving FreeNAS onto a much better equipped machine.

 

[HoneyBadger]

I'm going to have to come back to this thread post-meetings, but I can see trouble brewing. I have a lot of HP kit here and I'll tell you right now that the embedded P410i in the DL360 G6 is absolutely not a good fit for FreeNAS. You may already know this if you've switched over. Unless the latest firmware has significantly changed things, it's incapable of acting as a regular SAS HBA and won't properly pass SMART information.

If you're actually running L2ARC on that system with only 8GB that's likely going to do more harm than good as well, especially if it's a big one. Indexing L2ARC costs RAM, which you're already short on.

Re: the network layout, I'm going to have to provide a diagram to indicate what I'm looking for, but it sounds like you have your iSCSI traffic on the same network as everything else, which is a gigantic no-no as well and is probably a significant contributor to your dropout issues.

Edit: See (ugly) diagram. You want your iSCSI storage traffic to be on completely separate paths from your regular VMware network traffic, so that when other network traffic revs up, it doesn't impact storage I/O.

 

[Imagine]

In terms of the controller, I had to flash it to behave as a simple passthrough to allow FreeNAS to handle RAID'ing.

I know, it 's a bad idea to run L2ARC + de-duping + compression with only 8GB, I wasn't the one who built it originally and frankly I'm quite suprised nobody read up on that one, they only knew about the 1GB RAM for 1TB storage and thought 8GB is enough..

Yes you're right about the networking, what I'll do is, I'll draw a diagram for you once I get home so you can better understand what I'm saying (my wording may not be clear sometimes, English as a 3rd language).

 

[HoneyBadger]

L2ARC + de-duping + compression with only 8GB

I'm only willing to run dedup on limited sets here because I've got 48GB or 96GB depending on the box, plus L2ARC, and even then it's a very specific scenario that offers big wins for deduping a limited selection of zvols. Your pool can very easily collapse on itself if you're running all of that on just 8GB.

 

[Imagine]

Been running the new server for close to a couple days now and it seems to be behaving a lot better than the old one, even with the P410i controller. I've even felt brave enough to remove the tuning configs I placed on it from the old server and seems rock solid. We've gone from having periods of iSCSi unresponsiveness for upwards of 15minutes to literally having a 2 minute hiccup once a day I've noticed but still a damn sight more reliable than before.

I'm looking into building out an extra network to accomodate the two ESXI host's + FreeNAS to further alleviate any issues.

I'm only willing to run dedup on limited sets here because I've got 48GB or 96GB depending on the box, plus L2ARC, and even then it's a very specific scenario that offers big wins for deduping a limited selection of zvols. Your pool can very easily collapse on itself if you're running all of that on just 8GB.

In all honesty the way it was setup before, it was probably an outright miracle it never messed up the entire pool, which would have been the literal definition of catastrophe, (definitely not FreeNAS's fault, more human ignorance I guess).

Now that I have a good understanding of the specs required for a typical-ish enterprise FreeNAS setup I can now work on building out a 2nd box in the office.