SQL Velocity

Windows I/O Tracing

I am creating this post out of order (I was planning to demonstrate I/O when various queries are applied with and without indexes – but that will have to wait for a later time. I will end up using XPERF to analyze the I/O).

XPERF.EXE is the holy grail of server performance analysis. It allows software developers to track what each and every process running on a computer is doing. Powerful stuff…

This power comes at a cost – analysis files grow quickly!

WARNING – I suggest only running this tool in a test environment or a lab. It puts extra load on the tested platform and makes simply huge capture files!

Windows Performance Analysis Tools

The Windows Performance Analysis Toolkit, or WPT, ships with the Windows SDK.

Supported Platforms:

• Windows Vista SP1
• Windows Server 2008
• Windows Server 2008R2
• Windows 7
• Windows XP SP2 – Special Install Required
• Windows Server 2003 SP1 – Special Install Required

Installation Instructions

The Windows 7 SDK (also used for Windows server 2008 and 2008R2) requires .Net 4.0 (it will be installed through the web based install). Download the Windows 7 SDK from:

http://msdn.microsoft.com/en-us/windows/bb980924

This post covers the basics for installing Windows SDK 7.1.

Kick off the web based install (it also can be downloaded as an .ISO file).

Agree to the license terms.

Select the appropriate Install Location.

At a minimum the Windows SDK 7.1 will install the application verifier and debugging tools for Windows. Ensure that the Windows Performance toolkit is selected.

Installing on Windows XP or Server 2003

From the MSDN WPA article:

Windows XP

Windows Performance Analyzer can be used on Windows XP SP2 and Windows Server 2003 SP1 to gather trace information. All operations that require trace decoding must be done on Vista or Windows Server 2008. This includes viewing traces in the Windows Performance Analyzer tool (Xperfview.exe).

In order to capture trace information on Windows XP SP2 or Windows Server 2003 SP1 take the following steps:

1.From the "Windows Performance Analyzer" directory on a Windows Vista or Windows Server 2008 machine copy xperf.exe and perfctrl.dll to a directory that is in the PATH of the Windows XP SP2 or Windows Server 2003 target system.

2.On the Windows XP SP2 or Windows Server 2003 target system, run the trace using standard WPA syntax.

3.Copy the "etl" files to a Windows Vista or Windows Server 2008 system that has a full installation of WPA.

WPT Tools

The WPT tools are made up of:

• Xperf.exe – Captures traces, post-processes traces.
• Xperfview.exe – Presents trace content in the form of interactive graphs and summary tables.
• Xbootmgr.exe – Automates on/off state transitions and captures traces during these transitions.
• Perfctrl.dll – DLL file used by xperf.exe to complete traces.

Collect Data

The WPT tools are designed to produce in-depth performance profiles of Windows operating systems and applications. Xperf.exe is used to both start and stop tracing activates. Xperf.exe is designed to log Kernel Groups. The specific kernel group dealing with Disk calls is DISK_IO.

Execute a DISK_IO trace by executing the following command:

xperf -on DISK_IO

Note that xperf traces can become extremely large. The xperf tool by default records all tracing information to a file called kernel.etl. The file location defaults to C:\. To configure a different logging file location use the –f <filename> parameter.

    Xperf –on DISK_IO –f

The trace may be stopped by executing:

    Xperf –stop

Once the trace is stopped it can be merged with other files. The –d flag will merge a stopped trace. If the –d flag is used on a running trace the –stop command is implied. The trace will be stopped and merged in one step. Define the location of the ETL file using the <filename>.etl parameter. The processed .ETL file will be written to the directory that xperf –d is executed from.

xperf -d test.etl

Analyzing Results

View graph results by opening the ETL file (or use the Windows Performance Analyzer GUI from the programs menu).

xperf test.etl

This will open the Xperfview.exe graph viewing tool. WPA defaults to the Disk I/O and Disk Utilization graphs.

The tool defaulted to use the Disk I/O and Disk Utilization graphs (this was due to the fact that only Disk I/O was traced). The charts can be customized to display only desired data.

Clicking on the Graphs tab will allow the user to add or remove graphs from the analysis.

The most useful Xperf feature is the Disk I/O Detail Graph. To view the detailed Disk I/O detail chart right-click a region on the Disk I/O or Disk utilization chart and click Detail Graph.

The detail chart will display a graphical representation of all offsets (offsets are also called Logical Block Numbers), and offset accesses. This view will immediately identify random and sequential disk access. Red lines denote forced flushes. Hovering over each data point will detail the type of I/O operation, the start time, end time, location, and the calling process.

Note: Only capturing the DISK_IO counter will not allow Xperf.exe to determine the calling process. Using the DiagEasy flag on startup will capture DISK_IO, Process information, and kernel information. Unfortunately the use of DiagEasy will significantly increase the size of any trace.

More Information

By design this section only covers basic WPA features relating to disk access. WPA is an extremely powerful performance analysis tool.

Detailed WPA features and documents can be accessed via MSDN:

http://msdn.microsoft.com/en-us/library/ff191077.aspx

As you can see this tool provides the same data as Process Explorer, but you don't need to run through configuration steps, or fire up Microsoft Excel to graph the results.

In the coming weeks I will be using XPERF to analyze different queries, the benefits of indexes, and outline a process for integrating performance analysis into an engineering life cycle. Enjoy tinkering with XPERF!

Detailed Windows I/O: Process Monitor Part 2

Today's post is the second in a long series. Part one covered the Microsoft Process Monitor tool. Part will cover interpreting Process Monitor results. In my lab I have a TPC-H "Like" environment (If testing is not sanctioned by the TPC committee then you are legally obliged to call it TPCH Like - http://www.tpc.org/tpch/). The environment consists of a 300GB data base with clustered and Non-Unique Indexes (depending on the table and keys). The data is generated by the TCPH utility called DBGEN.EXE (you can download the source files and documentation at http://www.tpc.org/tpch/).

Here is the database structure:

For the purposes of these examples I am using the Supplier table. It consists of 3000000 rows.

I fired up two different queries and ran Process Monitor to track the I/O (http://technet.microsoft.com/en-us/sysinternals/bb896645.aspx - Version 2.95 as of this writing).

The first query simply counts the rows in the table:

    Select COUNT(*) as "row count"

FROM (select * FROM [TPCH300R10Thk].[dbo].[H_Supplier]) as t

The query returns a value of 3000000. It scans the .mdf file with 64K and larger I/O (a total of 209 reads averaging 165K each). For quick setup I only created one data file and one log file.

I set up Process Monitor to track only sqlservr.exe events (see Part 1 http://sqlvelocity.typepad.com/blog/2011/04/detailed-windows-io-process-monitor.html). I saved all of the events that generated the query values as a .csv file:

Next, open the .csv file in Excel. We first need to separate the detail column into usable parts. Each detail records the offset, length and I/O flags:

Offset: 1,245,184, Length: 65,536, I/O Flags: Non-cached, Priority: Normal

I use the text to columns feature of Excel to separate the values into columns (Data tab then Text to Columns):

I use a Space as the delimiter of choice (using comma does not work as commas are used as both a 1000's separator and a value Delimiter):

Finally I use step 3 of the text to column wizard to clean up the import by skipping the text (as I don't want it for this analysis).

I am left with an offset column and a length column:

1,245,184,    65,536,

As a final step I clean up the data by removing the commas and converting the columns to number with no decimal places.

I inserted a Scatter graph (Scatter with Markers only) and plotted all of the offsets (Insert tab – charts – scatter). This creates a visual representation of the query:

This graph shows that the row count query created a nice sequential access pattern. In addition to the access pattern we can also look at the actual size of each I/O. In this example SQL server issued 30 64K I/O requests. As the SQL engine detected sequential access it began to size up the I/O request to 128, 192 and 256K.

Note: I wanted to specifically point out that the offset range is localized. If the data set was more varied, for instance starting at 0 and going all the way up to 361,380,839,424 the graph will appear to show only sequential data access. It is important to look at the data ranges before plotting to ensure the graph shows the appropriate data. In other words, zoom…

Excluding the first 6 I/O's and re-creating the chart will result in a more detailed data view:

The graph reveals that the initial I/O requests were purely sequential and extremely small. SQL Server realized the sequentially of the data and cranked up the request size. Realize that this is a 2TB volume with approximately 600GB of data (this is why the offsets values are so large). This query is accessing 463MB of data space with 33MB of index.

The second query lists the supplier's phone numbers that are from PERU (Country 17 is PERU – I skipped the join to simplify the I/O access):

    SELECT s_phone

FROM [TPCH300R10Thk].[dbo].[H_Supplier]

Where s_nationkey =17

The query caused a more random I/O access pattern that is localized to the specific table and the I/O sizes were highly varied (from 16K all the way up to 512K).

As you can see, tying procmon.exe with Microsoft Excel results in an extremely detailed view of each I/O request. We can view the size of each request and exactly how the request accessed the disk. Using procmon.exe when testing new queries can lead to code optimization that is simply not possible with other tools. Perfmon is a great tool for looking at long term trends and finding problems but it is not granular enough to really diagnose specific problems.

Please remember to always experiment with these tools. Never run Process Monitor in production unless it is an emergency and you take precautions to limit system impact (as noted in the last post; this tool is tracing EVERYTHING in memory. Tracing SQLServer.exe as it scans a 100TB data warehouse will result in a runaway application and a system reboot). View the Process Monitor help file for notes on scripting etc…

Enjoy!