Archives for category: NetApp

At last part of the mystery is finally coming together.  At least for another set of NetApp devices.  This is another mystery we have had in the same NetApp family of devices.  These are devoted to Windows Workstations.  

We have two different classes of devices in one filer.  One is Fibre Channel and the other is SATA. One spins at 15KRPM and the other at 7.5KRPM. We were told there was no way that they could cause trouble to each other.  WRONG.  They share the Cache.  So if the slower writing devices are being driven hard with writes, then the Cache process becomes a bottleneck.

There is part of cache that is called Non  Volatile Storage (NVS).  This covers the case where you need to have a version of the storage before it is actually written to disk. For a period of time you have a version of the write in Cache and also in NVS.  That way if you would lose power to the device, it is supposed to stay in NVS until it can be destaged to the disk.  At least that is the story as to why it exists. 

When a write happens there are two versions then in the cache.  One in Cache and one in NVS. The Write is signaled that  it is finished and the application can continue on with the work it is doing.  But if the NVS becomes full, then the write is delayed from that signal until the data is physically written to the disk. 

Do you see the problem now?  In our case the slower disk is being used by a function that is taking backups of Workstations. (DLO product). Think massive write operations.  For some reason we have crossed the line where the amount of activity has grown such that we now have delays in all of our writes. 

Normally the write response time is in the 1 millisecond value or less.  But when this problem starts to happen, we see write response time climb to 50 ms and then to 100-200 ms.  That is when the workstation then becomes unresponsive to the user and they start calling in that they are dead in the water.  These are VMware Workstations.  In some cases these are also VMware Servers as well.  So not only are the users impacted, but all of their services they are working with are also impacted. Thus even the non-VMware Workstation users are feeling the pain.

The VMware workstations are using NFS for their access and the DLO Backup process is using CIFS.  We have the ability to cut off all CIFS traffic.  When we do that, the NFS response time instantly goes back to 1 millisecond.  Problem solved as far as they are concerned.

I had no idea that we could use NFS for our VMWare systems but it was a great discovery on my part.  We could ‘fix’ the problem at least for those users. 

We have another set of NetApp systems on order, but they are not here as of yet.  Plus we have other internal delays before we can cut over the DLO work to the other systems.  We may have to limp along with risk to lost files if we can not limit the damage by this DLO workload.

It seems that as the number of users in this DLO sub-system has grown we have finally reached the critical mass that has let us see this problem for what it really is.  A design choice we made to keep costs down.  But there was not a plan already in place to cut this over once the size had reached a critical mass. 

The management screens of the NetApp device did show that the Disk Utilization for the DLO system was in the 80% Device Busy.   That should have been a signal that there were issues.  But we had been told there was complete isolation between the two systems and slowness in one area would not impact the other area.   WRONG.

Until next time.


This is still ongoing.  Lots of Perfstats sent to NetApp for analysis.  One item was found on them that is puzzling.  We are using the NetApp processing of Snap processing.  There is Snap Vault and Snap Mirror.  Mirror creates images on the local filer so recover can take place back to a point in time.  As changes happen, the old blocks are kept in this Mirror block list.  But only so many ‘Mirrors’ are kept active at one time.  As a new one comes online, an old one goes off.  Those Blocks then go back into the free list.  But that can take a while and was one of the symptoms of our problems.  High CPU time.  They attributed this High CPU to the Mirror process releasing these blocks. 

That would then impact the response time of NFS requests for the Clients.  Bummer.  We were seeing response times go from 1-3 milliseconds up to 100 milliseconds.  The one application that was doing the most work would suffer the most of course.

We found another set of files that were being referenced.  There were a set of files with .so that were also being referenced a lot.  Not read, but just referenced.  Once again back to the application team to see if they could be placed somewhere else. 

During this time we were waiting on the Networking team to enable another device to capture the traffic.  Our other approaches  were traces on the application server and switch mirror traces to a windows system.  But to trace on the Filer at a steady rate of 1 Gb is tough as the size grows fast.  We have GigaMon as a monitor switch fabric and have a 10 Gb port connected to a GigaStore device to record. (Network Instruments vendor)  Now we don’t have dropped packets messing up the trace and have 48 TB of space to store the results.  Now we can reach back and look at some history of what was happening when the problem was happening.   I’ll also mention that Riverbed also has some great products to address this as well. 

We saw that one of the high traffic sinks was the Snap Vault process.  During this time frame the application was also seeing high response time.  We did not have that knowledge before.  One more thing to talk with NetApp about.

For those interested this is the Wireshark – tshark.exe to read the trace and create a text file with certain fields.  I then used Excel to summarize that.

“C:\Program Files\Wireshark\tshark.exe” ^
-o nfs.default_fhandle_type:ONTAP_V3 ^
-T fields -E separator=, -e frame.number -e rpc.auth.uid -e rpc.time -e nfs.procedure_v3 -e nfs.fh.hash -e ^
-e nfs.fh.mount.fileid -e nfs.fh.fileid -e nfs.fh.export.fileid -e nfs.count3 ^
-R “(tcp.dstport == 2049) && (rpc)” ^
-r file-name-of-trace-file

Run this and > output.txt   to a file that you then bring into excel.  The -E separator tells tshark to use ‘,’ for a separator for the output fields.  This makes putting into columns an easy process for excel.

Lots of items in here this week – a lot of digest. 

Our problem is still being worked on.  This is taking way to long to come to a conclusion.


We have a mystery question as to what is all this activity to the NFS Filer from a given server?  It has been blamed for some slow downs noticed by some applications.

The challenge has been to find what is causing this activity since this is a general purpose work horse server that is used by a number of different applications.  It seems not all of them are playing nice in the same sandbox.

Some people would want to use this challenge as a reason for each application area to have their server and even their own NetApp Filer system.  That way they can not be impacted by anyone else.  But that is not how it is done when you want to manage your data center as an Enterprise and have some scaling and flexible buying power.  When resources are cut up into small parts and each area has their own, you are challenged to get the utilization very high.  You end up with a lot of waste all in the name of Fear, Uncertainty and Doubt (F.U.D.) of the risk of sharing. 

Many times we have found that when we have found the Impacting workload, it is the very user that is crying the most.  They are doing it to themselves and costing the Enterprise to spend a lot more money instead of fixing the problems.

We used some network captures to assist us with finding out what was going on between the server and the Filer.  (Wireshark was used but that is the topic of another blog). This showed a lot of activity with the function GetAttribute.  This is testing a file to see if it has changed since the last time it was used.  This turned out to be for files used by an Adobe PDF Creation process.  Fonts and Templates were being checked and causing a lot of overhead.  They do not change very often (like a couple of times per year) once they are established.  Templates might change with a new version or release of something but then would settle down again.  We had some SAN space we could define for this system but it would not be Shared Storage like the Filer is.  So once placed there, we would need it duplicated for the Test / Stage and Production versions of the Server.  But we only needed less than 80 GB of space for this.  The system already had HBAs so we could add some SAN storage and reduce the amount of activity taking place over the network.  This ended up reducing the GetAttribute workload by 10x.  

Step one provided some relief to the Filer CPU activity.  But the CPU busy was still very high – in the high 80s to low 90s. Plus we saw some pauses taking place.

I fired up some simple Netstat -p tcp and nfsstat -c and had that output going to a set of files along with a date/time stamp.  I put this into a 10 second interval and let it pump data to files with the name of the $(hostname) and $(date ‘+%y%m%d-%H’) so that I could keep the number of files small, but also make it self naming in case I needed to do this on other systems at the same time. 

Enter one of my fave programs for data analysis.  Perl.  I use this to assist with analysis and transforming output into input for Excel. Excel is my other fave program for data analysis.   Each of these commands (netstat and nfsstat)  create a very verbose output that is hard to bring in to see if there really is a problem or not.  By using Perl to clean that up, I can then use Excel to create Deltas between this interval and the prior interval to see if there is a pattern or not.

We began to see that there were periods of time of very good service and file response time and then some short intervals of very poor service.  Something was indeed happening that was not normal.  Now we had the proof that we needed to be able to talk with NetApp.  They had been running their PerfStat process but the process was not showing anything wrong which is partly caused by the length of time they had for their interval.  Using the 10 second interval output from these two unix commands provided the information that we needed to show them that something was not proper. 

This is still ongoing so I don’t have a fix to the problem.  But we do have better information now that it is a real problem.  At least for a few of the 10 second intervals.  But not for all of them which is why this has been so hard to find.

By the way, the Network trace of the NFS traffic showed us the UID of the user making the request and also gave us the File inode that we could then use to look up on the Filer to find out the real file name.  That gave us clues as to what was going on with the PDF Generation process for instance. 

Till next time.