istgt issues - latencies leading to istgt failures

[davegibson]

I have the following setup:
3 Dell R610 servers running ESXi 5.0
Handbuilt FreeNAS box - Asus P8B mobo, LSI 9211-8i SAS cards, Intel Gigabit ET Quad NIC.
FreeNAS 8.0.2

The system is set up with iSCSI serving device extents, and for the most part is working fine.

However, the system is showing iSCSI latencies (see vmkwarning.log below), and after enough of these, FreeNAS will begin to throw errors (see /var/log/messages below). These errors will usually cause the ESXi servers to become unresponsive until a reboot.

I would love it if someone could tell me why istgt is having these issues. But my primary question is how I can troubleshoot this more finely. The latencies are happening all over the place; I believe they are small symptoms of the larger problem. However, I can find no logs that can show this latency; the only evidence FreeNAS shows of these incidents is the warnings seen below in /var/log/messages.

Can someone show me where in FreeNAS to look to perhaps see the causes of these latencies BEFORE they crash the iSCSI connection?

Thanks!
-Dave

vmkwarning.log on ESXi server:
2011-12-13T23:00:31.988Z cpu5:2036924)WARNING: ScsiDeviceIO: 1218: Device t10.FreeBSD_iSCSI_Disk5404a6689318000_ performance has deteriorated. I/O latency increased from average value of 39244 microseconds to 851554 microsec
23:00:35.690Z cpu6:2054)WARNING: ScsiDeviceIO: 1218: Device t10.FreeBSD_iSCSI_Disk5404a6689318000_ performance has deteriorated. I/O latency increased from average value of 39250 microseconds to 788238 microsecond
2011-12-13T23:02:45.754Z cpu5:2038971)WARNING: ScsiDeviceIO: 1218: Device t10.FreeBSD_iSCSI_Disk5404a6689318000_ performance has deteriorated. I/O latency increased from average value of 39252 microseconds to 829039 microsec
23:03:27.209Z cpu5:2053)WARNING: ScsiDeviceIO: 1218: Device t10.FreeBSD_iSCSI_Disk5404a6689318000_ performance has deteriorated. I/O latency increased from average value of 39261 microseconds to 1006948 microsecon
2011-12-13T23:03:27.219Z cpu7:2055)WARNING: ScsiDeviceIO: 1218: Device t10.FreeBSD_iSCSI_Disk5404a6689318000_ performance has deteriorated. I/O latency increased from average value of 39261 microseconds to 2069500 microsecon
2011-12-13T23:03:31.466Z cpu5:2108271)WARNING: ScsiDeviceIO: 1218: Device t10.FreeBSD_iSCSI_Disk5404a6689318000_ performance has deteriorated. I/O latency increased from average value of 39269 microseconds to 813921 microsec

/var/log/messages, FreeNAS 8.0.2:
Dec 15 03:01:40 freenas istgt[15855]: istgt_iscsi.c:4334:istgt_iscsi_transfer_out: *ERROR* iscsi_read_pdu() failed, r2t_sent=0
Dec 15 03:01:40 freenas istgt[15855]: istgt_iscsi.c:5380:worker: *ERROR* iscsi_task_transfer_out() failed on iqn.2011-03.example.org.istgt:ds02targ,t,0x0001(iqn.1998-01.com.vmware:esx5srv3-0d78a45e,i,0x00023d000002)
Dec 15 03:01:53 freenas istgt[15855]: istgt_iscsi.c: 777:istgt_iscsi_write_pdu_internal: *ERROR* iscsi_write() failed (errno=32)

[dwhite]

Hello davegibson,

There's a number of possible causes of this, considering the observation simply is "I/O is taking a long time to complete." I'd examine the I/O path first and ensure there is not any saturation or errors occurring that could trigger retries. Its easiest to examine this from the FreeNAS server's command line to start with since you have a full suite of stats tools available while you have only vSphere Client's rough graphs for the ESXi side.

I would look at:

• gstat -I 1s or iostat -x 1 -- Watch the command latency columns for your disk devices (da##). If they are shooting up randomly to thousands of miliseconds, check if there is a lot of activity from a particular VM or if there are disk errors or unexplained messages from the mps driver in the FreeNAS messages log. It may help to only run a single test VM that you can run simple disk I/O tests from (dd, etc.) as to reduce sources of unpredictable traffic.
• netstat -iwb 1 -- this will show network traffic in/out. If network I/O is hitting the bandwidth limit on your NIC/path to the VMware server then I/O could be delayed that way. Try splitting your iSCSI traffic to its own NIC or set up link aggregation if you're using more than one NIC's worth of bandwidth. Also note if you are seeing error counts in this output; if you are, try replacing the Ethernet cables.

Can you briefly describe your disk configuration? Which models, and how they are connected to the SAS HBA? There may be some drive-specific information I can provide once I know that information.

[davegibson]

Thanks for the info - very helpful.

What I'm starting to believe is that the array is not able to keep up with iSCSI requests. Here are the specs for the system running FreeNAS:
Asus P8B mobo, Intel i3 processor
4GB RAM
LSI 9211-8i SAS HBA
8x Hitachi HHD-0S03208 Deskstar 3TB 7.2KRPM
SuperMicro? SATA backplane (in SC-843 case) w/ independent SATA connects to each drive (no concentrator)

I think the first place to worry is the RAM. How much should I be using for a 24TB RAIDZ array?

We had another slow-moving failure today with the ESXi5 hosts. It appears that the iSCSI LUN reservations aren't being responded to quickly enough. Although the SAN is running with usually-fine statistics (via gstat), I can see the array frequently building up a moment of large latency - and then return to normal.

In gstat, the ms/r (request ack latencies, correct?), I see these normally between 0-20ms; when under load, these can sometimes briefly flash by as 50-100ms. The largest I've seen yet - over 500ms. Every time I see "load" ( a brief flash of %busy activity), the largest %busy numbers are on the drives themselves, and the drive partitions (da1p2, etc.). So I believe that the problem may be general sluggishness of the array. I see RAM (4GB) fully in use, and I believe that RAIDZ will want much more RAM.

Do you know of any ways to monitor the LUN reservations/releases? I'm afraid that the hosts may not be releasing properly - but I doubt that this is the issue.

Thanks for the help - I look forward to your reply.

-Dave

[gcooper]

Replying to davegibson:

Thanks for the info - very helpful.

What I'm starting to believe is that the array is not able to keep up with iSCSI requests. Here are the specs for the system running FreeNAS:
Asus P8B mobo, Intel i3 processor
4GB RAM
LSI 9211-8i SAS HBA
8x Hitachi HHD-0S03208 Deskstar 3TB 7.2KRPM
SuperMicro? SATA backplane (in SC-843 case) w/ independent SATA connects to each drive (no concentrator)

I think the first place to worry is the RAM. How much should I be using for a 24TB RAIDZ array?

48GB of RAM (plus 3~5GB for additional headroom from my calculations) is what we quote in the hardware requirements: ​http://doc.freenas.org/index.php/Hardware_Requirements .

Your CPU is also too slow for iSCSI because iSCSI is an asynch protocol and operations will backup and eventually deadlock the filesystem / storage if the CPU can't service them in time ;).

We had another slow-moving failure today with the ESXi5 hosts. It appears that the iSCSI LUN reservations aren't being responded to quickly enough. Although the SAN is running with usually-fine statistics (via gstat), I can see the array frequently building up a moment of large latency - and then return to normal.

In gstat, the ms/r (request ack latencies, correct?), I see these normally between 0-20ms; when under load, these can sometimes briefly flash by as 50-100ms. The largest I've seen yet - over 500ms. Every time I see "load" ( a brief flash of %busy activity), the largest %busy numbers are on the drives themselves, and the drive partitions (da1p2, etc.). So I believe that the problem may be general sluggishness of the array. I see RAM (4GB) fully in use, and I believe that RAIDZ will want much more RAM.

That is high.

Do you know of any ways to monitor the LUN reservations/releases? I'm afraid that the hosts may not be releasing properly - but I doubt that this is the issue.

Not sure. We'll have to check with Daisuke-san to see if he has any observability hooks for istgt.

[jgreco]

Check out ticket #1531, it might be related. I do see this sort of thing under moderate load. I've also got a Xeon E3-1230 with 32GB of RAM and some slow-ish 400GB drives that can be made to make the system hang for MINUTES at a time with the default FreeNAS configuration, so I'm not too sure about the idea that an Intel e3 processor is too slow for iSCSI. We used to do iSCSI on much slower stuff without a problem. FreeNAS may require some specific tuning for your environment.

[william]

Do you have any updates for this issue?

[william]

Closing as duplicated of #1531