Tracing with Storport in Windows 2012 and Windows 8 with KB2819476 hotfix

Tracing with Storport in Windows 2012 and Windows 8 with KB2819476 hotfix

  • Comments 5
  • Likes

Welcome back to the CORE Team Blog. Paul Reynolds here. I would like to let everyone know about changes on how to capture Storport traces in Windows Server 2012 and Windows 8.

NOTE: The information below is based on having hotfix KB2819476 installed (part of the April 2013 cumulative update for Windows 8 and Windows 2012). If you do not have this hotfix installed, see the previously written blog:

Tracing with Storport in Windows 2012 and Windows 8 without KB2819476 hotfix
http://blogs.technet.com/b/askcore/archive/2013/01/12/tracing-with-storport-in-windows-2012-and-windows-8-without-kb2819476-hotfix.aspx

We DO recommend installing the hotfix as it enhances the ability to take Storport traces in Windows 8 and Windows 2012.  Please note that KB2819476 is already in Windows Server 2012 R2 and Windows 8.1.

Previously, Bob Golding wrote a blog on how to do Storport Tracing in Windows 2008 and Windows 2008 R2. If you have Windows 2008 or 2008 R2 continue to use that blog for your Storport traces.

 

TRACE GATHERING STEPS

The process to capture a Storport trace is similar (though not identical) to the way we do it with Windows 2008 and Windows 2008 R2 (see Bob Golding’s blog for more detail). For those already familiar with the process, the main change is:

· Instead of choosing IOPERNOTIFICATION, a new choice called IO_PERMORMANCE is picked

For those not familiar with the process, here is an overview of how to start a Storport trace. (Most of the information is from Bob’s original blog)

1. Hit the Windows button and type Perfmon.exe, then press enter to start performance monitor.

2. Expand “Data Collector Sets” and “Event Trace Sessions”


clip_image001

3. Right-Click on “Event Trace Sessions”

 

clip_image002

4. Select “New, Data Collector Set”


clip_image003

5. The following dialogue will appear:


clip_image004

Give the new data collector set a name in the dialogue box. In this example I called it “Storport”.

6. Choose the “Create manually (Advanced) option and then click Next to see the following dialogue:


clip_image005

7. Click Add on the dialogue box above and the following list of providers will appear.


clip_image006

8. Select “Microsoft-Windows-Storport” and click OK. You should now see the following screen:


clip_image007

9. Select “Keywords (Any)” then click Edit.


clip_image008

10. Check the box for IO_Performance, and then click OK:


clip_image009

11. You should see the following screen:


clip_image010

12. At this point you can choose a filter to use for the Storport trace. This is useful for a long-running trace where you want to capture Storport data above a certain threshold.

Select Filter, then Edit:


clip_image011

This is where we enter our threshold. Anything equal to or greater than this value will be logged in the trace. If you leave the filter disabled it will create more data but will cause averages for request duration values in the Storport trace to be more in agreement to values obtained for physical disk sec/transfer from a Performance Monitor trace.


Select “Filter Enabled”, choose “Binary”, and in the “Filter Data” field enter the threshold in 100ths of nanoseconds (number of milliseconds X 10,000). This must be entered in little endian format. Refer to the table below for sample values:


clip_image012

 

Decimal

Hexadecimal

Binary (little endian)

1ms (10,000)

2710

10 27 00 00 00 00 00 00

5ms (50,000)

C350

50 C3 00 00 00 00 00 00

10ms (100,000)

186A0

A0 86 01 00 00 00 00 00

15ms (150,000)

249F0

F0 49 02 00 00 00 00 00

 

Note: the “Filter type” value will always remain 0 as in the example above.

Warning: the whole data line needs to be filled in when entering a threshold. For demonstration purposes, here is how to do it the WRONG WAY:


clip_image013

Filter values have to be reset after each successful run of a Storport trace. It DOES NOT remember the previous values used.

13. Click next and choose a root directory for the trace. In this example I use C:\perflogs:


clip_image014

14. Click finish. You should see a new Event Trace Session that is stopped. In this example it is called Storport.


clip_image015

15. Right-click the new Event Trace Session and click Start to start it:


clip_image016

16. You should now see your new Event Trace Session started:


clip_image017clip_image018

17. After you are done collecting data, right-click the running Storport trace and select “Stop”.


 

DECIPHERING TRACE DATA

Now that we have a Storport trace, let’s look at the data it contains. A simple way to see the data is via Event Viewer:

1. Hit the Windows key, type “eventvwr.exe” and hit the enter key. The Event Viewer utility will start:


clip_image020

2. Right-Click on Event Viewer (local) and click on “Open Saved Log”:

 

clip_image022

3. Choose the directory the Storport trace was saved to, highlight the ETL files and click Open. In this example, we chose c:\perflogs.


clip_image023

4. After clicking “Open” a dialogue box will appear asking to create a new event log copy. Click “Yes”.


clip_image024

5. You will see the following screen. We left the settings as the default and clicked “OK”.


clip_image025

6. After clicking OK you will see Event ID 201 messages:


clip_image027

7. Let’s look at the detail of the data:

Request Duration: how long the (firmware/drivers/hardware/storage network/SAN) took to process a I/O request packet in 100ns. To convert to milliseconds, divide this number by 10,000.

Command: decimal form of SCSI command. If you wish to look up the SCSI command (convert decimal value to hex first) see http://en.wikipedia.org/wiki/SCSI_command.

SrbStatus: Status Request Block status returned from the adapter (see srb.h and scsi.h in the Microsoft WDK)

Port: This is the adapter port number (e.g. RaidPort1, etc.)

Bus: This is the Bus number

Target: Target ID of the LUN exposed to the Operating System

LUN: Logical Unit Number of the physical storage

ScsiStatus: decimal form of SCSI Status Code. If you wish to look up the SCSI Status Code (convert decimal value to hex first) see http://en.wikipedia.org/wiki/SCSI_Status_Code

DataTransferLength: the length of the data transfer in Bytes

BuildIODuration – length of time the miniport has spent in the build I/O function (usually very small, measured in 100ths of nanoseconds )

StartIODuration – length of time the miniport has spent in the start I/O function (usually very small, measured in 100ths of nanoseconds)

 

CLOSING THOUGHTS

When troubleshooting disk performance issues, Storport traces capture data from the last layer of software in Windows that an I/O Request Packet (IRP) will pass through before being handed off to hardware. It is an excellent tool for checking if slow disk performance is hardware related.

In a next blog post I will show a way to look at Storport data via Excel Spreadsheets with Pivot Tables and Pivot Charts. You can look at millions of rows of data if you use the free PowerPivot add-on available with Office 2013.

Paul Reynolds
Support Escalation Engineer
Windows Core Support Team

Your comment has been posted.   Close
Thank you, your comment requires moderation so it may take a while to appear.   Close
Leave a Comment
  • Excellent post

  • Is there any way to export in excel the detailed part of each event log

  • Yes, detailed data can be extracted into CSV files using XPERF.

  • I do not see the EventData part in our events. Instead I see a ProcessingErrorData part.

    Any help with this please ?

  • Metek, is the event you are looking at have a 201 ID or something else?