Poor iSCSI response - OI151a4

[packetboy]

Server seem to get into a mode where there's really nothing happening on the server (e.g. very low CPU utilization (<1%), little to no IO ( < 1MB/s), etc...) yet remote clients (e.g. WinXP iSCSI booted (wife!)) are painfully slow.

last pid: 20449;  load avg:  0.07,  0.06,  0.07;  up 13+04:40:40                                         06:12:36
177 processes: 176 sleeping, 1 on cpu
CPU states: 99.5% idle,  0.0% user,  0.5% kernel,  0.0% iowait,  0.0% swap
Kernel: 1523 ctxsw, 11 trap, 951 intr, 158 syscall, 11 flt
Memory: 36G phys mem, 1199M free mem, 18G total swap, 18G free swap

   PID USERNAME NLWP PRI NICE  SIZE   RES STATE    TIME    CPU COMMAND
   728 daemon     18  60  -20 2968K 2064K sleep  124:51  0.04% nfsd
...


root@zulu01:/rz2pool/home~/DTraceToolkit-0.99# zpool iostat 10 10
               capacity     operations    bandwidth
pool        alloc   free   read  write   read  write

----------  -----  -----  -----  -----  -----  -----
hold         558G  3.53T      0      0      0      0
rpool       26.6G   205G      0      0      0      0
rz2pool     9.81T  6.44T      0     58      0   309K
salvage      377M  1.36T      0      0      0      0
----------  -----  -----  -----  -----  -----  -----

I was having this same issue with this server under Solaris 10u9 which is why I updated to OI151 in the first place...figured the kernel-based Comstar iScsi would solve these problems.

When I run a 'hotkernel' trace, there's tons of mwait hits:

(running from DtraceToolkit)
# ./hotkernel

...
unix`disp_getwork                                          14   0.0%
unix`page_nextn                                            36   0.1%
genunix`fsflush_do_pages                                   47   0.1%
unix`mutex_enter                                           69   0.1%
unix`i86_mwait                                          49505  98.8%

Above is from a 10 second trace, so seeing about 5,000 mwaits/second...not sure if that is excessive or not.

When you google on the above mwait thing, you do see tons of discussions with regard to bugs in Solaris from years ago...I presume these things are no longer a factor in OI151.

Anyone have any thoughts/suggestions?

 

[patrickdk]

That looks normal, my completely idle system, without any iscsi clients on it, has a good 36k mwait in approx 10seconds. I haven't had any iscsi speed issues with it, though my iscsi clients are ubuntu 10.04 and windows 7.

 

[packetboy]

Here's a packet trace of the slowness:

Wife (.102) is running Outlook (ug!) and downloading email...so email client is *writing* to her mailbox that is inside her iSCSI boot image on the ZFS server.

Here's the analysis of the above trace.
The WinDoze box has decided to issue writes to the iSCSI server in 12K chunks (not sure why it's chosen this). Packet 27509 is the start of one of these chunk writes from the Windoze box. In Packets 27509 - 27529 8 full sized packets (1460 data bytes each) and one partial packet (650 bytes) are sent to the server..you can see the iSCSI write command details in the last of these segments (27529).

The elapsed time for this data to move across the GigE network is 12.999339-12.999261 or about .0001s. Doing the math to compute throughput, you get 12000/.0001 = 120,000,000 MB/s .... exactly what you'd expect to get over GigE.

Now for the problem, look how long it takes the iScsi server to ACK this write request...note the delta time on packet 27556 (the 'Write GOOD' response from the server)...it's .018s !! (18ms)...THAT is ridiculous. I see this same delay across pretty much every chunk write. Let redo our throughput math again: 12000/.018 = .6MB/s.

So in summary, I have a ZFS server capable of 1000MB/s, a network capable of 100MB/s and yet I'm getting .6MB/s write...pitiful.

Am I missing some finer point of Comstar tuning?

Note: I do NOT have a Zil on the server..could this be the root of the problem?

 

[patrickdk]

hmm, are you using a wide raidz* for this? that would defently do it, a zil drive would defently help yes. The vdev blocksize also would matter, and compression likely.

On my test I just did here, on a mirror 2x vdev (4 disks), with gzip compression on the zvol I am getting for windows 7 iscsi root.

Looks like all my writes are in .1 ms approx. I scanned many writes, but they all look consistant with the sample in the image.

 

[danswartz]

packetboy, do you have writeback cache enabled for the zvol(s)? If not, try enabling it and see if that helps?

 

[patrickdk]

I'm not sure how that delta is calculated, cause it looks like 0.108ms to me, from write request to confirmation.

Also, for mine, I'm using the default zvol blocksize of 8k with gzip-3. the writes above are all 16k (wonder if windows did a clustersize 16k on that machine instead of 4k, oh well).

Just to doublecheck, I disabled writeback cache (I don't care if it corrupts, as it snapshots back to a good known image for this application), and I'm getting speeds between .2 to .4ms

 

[packetboy]

packetboy, do you have writeback cache enabled for the zvol(s)? If not, try enabling it and see if that helps?

I definitely have it disabled. Let me make sure I have daily auto snapshots on this zvol and then I'll retry with it enabled.

Given that this is a WinXP NTFS file system, what ZFS recordsize should I set? 4K, 8K?
I'm guessing that using the ZFS default recordsize is extremely non-optimal for NTFS?

Patrick: With your trace I actually see a potential problem. Notice that pck 352137 appears to be a retransmission of packet 352136. I assume you took the trace on the server? If so, looks like you may be dropping packets somewhere between your server and client....obviously this is just one example...you may want to look closer at the trace and see if it happening more chronically. It looks like you have your server tcp stack setup to do fast_retransmit as you see the retransmit is done in *microseconds* so the impact of this particular drop is neglible...if packet loss is more sever tcp will start backing off the retransmit time and then throughput goes in the toilet...not sure if it's ever coming to that, but you should be aware.

 

[brutalizer]

Have you tried Oracle Solaris 11 too see if the issues are gone?

 

[packetboy]

Have you tried Oracle Solaris 11 too see if the issues are gone?

That's not an option...these servers are used for commercial purposes.

 

[brutalizer]

That's not an option...these servers are used for commercial purposes.

It is available for home use. And also, it is available to do testing. Just to see if the issue is gone on S11.

 

[mwroobel]

Are you running XP SP2 or SP3? Are you using the Microsoft Initiator? What version? Have you unbound all protocols but IPV4 from iscsi in XP? Are you running on a flat network on on a vlan (I am expecting that it is flat since I only see 1514 byte packets vs 1518, though I have seen vlan at 1514 with misreported FCS)