Obtaining actual Request Durations with the StorPort driver logging HotFix

Here is a common scenario - you are performing a benchmark operation. You run your PerfMon file through the PAL tool (https://pal.codeplex.com).

You are seeing massive disk queuing, high latency, high privleged processor time. You talk to your SAN engineers and they tell you that all is good on the SAN - it must be an issue in SQL Server.

To the rescue:

A hotfix is available that improves the logging capabilities of the Storport.sys driver to troubleshoot poor performance issues for the disk I/O in Windows Server 2008 (https://support.microsoft.com/kb/979764/j) or Windows 2008 R2 (https://support.microsoft.com/kb/978000/en-us).

Once installed you can follow the direcdtions to turn this on and off as described in the hotfix documentation.

Howwever if you capture to an .etl file there is still the little matter of translating the binary format into something usable like this

        <EventData>

                <Data Name="MiniportExtension">0xFFFFFA806DBFE008</Data>

                <Data Name="PortNumber">       5</Data>

                <Data Name="PathID">0</Data>

                <Data Name="TargetID">0</Data>

                <Data Name="LUN">25</Data>

                <Data Name="RequestDuration">      92</Data> <-- Note this is in milliseconds!

                <Data Name="Command">42</Data>

                <Data Name="ScsiStatus">0</Data>

                <Data Name="SrbStatus">1</Data>

        </EventData>

After a little poking around i found documentation for TraceRpt.exe which will take the input file and output a nicely formatted XML, txt, or csv file for you.

TraceRpt <etlFilename> -of CSV

TraceRpt StorPort.etl -of XML

The XML format is simplier to scan through looking for RequestDuration threshold violations. Be sure to set a filter when you create your .etl file or the resultant XML file will be extremely large.

 

Hope this helps someone.