Windows Server: Analyzing a Storport Trace with Excel and Xperf

xperf -i D:\Path\storport.etl -o D:\Path\storport.csv 

This creates a comma-delimited file (CSV) named storport.csv. This file can now be opened in Microsoft Office Excel. However, if the trace ran for an extended number of minutes, resulting in a large ETL file and a comma delimited file with over a million rows, the following message is displayed when trying to open it in Excel:
 

In this case, it is convenient to use PowerShell to extract only the relevant lines from the comma-delimited file and, with these, create a new comma-delimited file before opening it in Excel.

• Back in Powershell, enter the command:

 Get-Content D:\Path\storport.csv | Where-Object {$_ -like "Microsoft-Windows-Storport/Port/win:Info*"} | Set-Content D:\Path\filtered_storport.csv 

(Replace "D:\Path" with the drive letter and directory path containing the source CSV file created in step 2.)
 

Analyze the results in Microsoft Office Excel:

• The resulting filtered CSV file can be sorted and filtered by columns "Timestamp," "RequestDuration_100ns" and "Target."
• Use average functions to calculate average latency.
• "Timestamp" is a clock or timer used for calculating how long the I/O request takes to complete.
• "RequestDuration_100ns" is the number of hundred's of nanoseconds the I/O request took to complete.
• "Target" sees the disk number (disk 0, disk 1, disk 2, etc.)

Highlighting the "RequestDuration_100ns" column, you can get an idea of the average latency:

 

Using common Excel filters and charts can help visualize the data easier. For instance, the chart below, shows the scattered plot of the various I/O requests captured during the storport trace for disk #1. This is accomplished by creating a scattered chart with the columns "Timestamp" and "RequestDuration_100ns" and then filtering the raw data table on the "Target" column by "1":

 

Notice that although most I/O requests are taking below 100 ms to complete, a significant number takes over 100 ms; some more over 200 ms and there are some taking over 300 ms.
If the issue being investigated in this example is a disk performance bottleneck, this would be a critical aspect to consider in determining if there is disk contention.

Similarly, the chart below shows the various I/O requests during the storport trace but this time for disk #2 (accomplished filtering the raw data table on the "Target" column by "2"):

 

On this second chart, the significant majority of I/O requests to disk #2 accumulates well below 15 ms (the average is 0.06 ms). It would be accurate to say that this disk #2 is showing no signs of contention during this storport trace.