Instrumenting and tracing XSLT transformations by treating XSLT as a regular programming language can provide very useful diagnostic data to help analyze and troubleshoot problems.

In this article I will walk you through sample scenarios to illustrate the use of the sample XSLT tracing implementation described in Part 1 of this series [.NETDJ, Vol. 1, issue 9]. The source code and supporting files can be downloaded from www.sys-con.com/dotnet/sourcec.cfm.

Sample Use Case 1: Transforming Dynamically Generated XML
The scenario described in this section will use the sample XSLT tracing implementation to profile and identify performance bottlenecks in an XSLT transformation executed by applying a style sheet to XML data generated dynamically by querying a SQL Server 2000 database. The SQL Server 2000 Northwind sample database will be used in this illustration. You can read this section and walk through the Transforming Static XML use case described in the next section if you do not have access to a SQL Server 2000 installation with the Northwind sample database. The functional base and steps to configure/use the XSLT tracing feature are common to both sample scenarios.

The DynamicClient.cs file in the TracingClient project contains the client code that will be used in this scenario. Open this file and study the code and inline comments in the Main method. The scenario is very straightforward. ADO.NET code is used to fill a DataSet with data from the Orders and Order Details tables for a user-specified date range. The XML representation of the data is then extracted from the DataSet and transformed to HTML by applying a style sheet (OrderDetailsData.xsl). The style sheet is nothing fancy (kept simple to focus on the tracing functionality) and the generated HTML displays the Order data in a simple HTML table. Also note that initially the transformation is executed using a System.Xml.Xsl.XslTransform object.

Change the ADO.NET connection string in the code to point to your instance of SQL Server (you must have the Northwind sample database) and build the solution. Open the Visual Studio .NET 2003 command prompt and navigate to the TracingClient executable folder (C:TracingDemoTracingClientindebug). The Orders and Order Details tables contain data for dates (Order date) ranging from 7/4/1996 to 5/6/1998.

Issue the following command to retrieve and transform data from the year 1996. Note the timing information reported for the phases that load the style sheet and execute the transformation. You will see that the actual transformation (note the time before and after the transform) executes in < 1 second. You can open and view the HTML generated by the transformation (output.html in the same folder) in IE to see how the data is tabulated:

TracingClient 7/4/1996 12/31/1996

Now let's reexecute the process by increasing the date ranges to the following periods and observe the transformation execution times (the time before and after the transform):

1. 7/4/1996-12/31/1997
2. 7/4/1996-5/6/1998

Executing troubleshooting and analysis with the above factors in mind to isolate the cause of the observed behavior can be an arduous task without supporting diagnostic data. Also note that in a scenario like this the XML is generated dynamically and the performance degradation varies based on the query executed to retrieve the data. In live production environments where queries executed vary by user, such problems can occur sporadically and be tough to reproduce for subsequent analysis.

I will now show you how the sample XSLT Tracing implementation can be used to isolate the cause of the performance degradation observed in this sample scenario.

Switch to the TracingClient solution in the VS.NET 2003 IDE. Change the line of code in the Main method in DynamicClient.cs to instantiate an XsltDiagnostics .XslTransform2 object instead of a System.Xml.Xsl.XslTransform object to execute the transformation. The XsltDiagnostics assembly is referenced by the TracingClient solution. (Check this reference to make sure that it is good; you might need to refresh it if you extracted the sample files to a folder other than C:.) Its parent namespace is imported in DynamicClient.cs. All you need to do is change this line of code:

XslTransform stylesheet = new XslTransform();

to the following:

XslTransform2 stylesheet = new XslTransform2();

Open the application configuration file (App.config) to configure the settings required to trace the XSLT transformation. On viewing the initial XSLT tracing configuration, notice that all parameter settings are at their defaults as described in Part 1 of this series. You will need to change the following configuration settings to obtain the diagnostic data required to analyze and troubleshoot the performance degradation observed in this sample scenario:
1.  Enable the option to trace XSLT transformations.
2.  Enable the option to persist the source XML data (in order to obtain the dynamically generated XML to be transformed).
3.  Disable the option to delete the trace logs for successful transformations (because the transformation in this scenario runs successfully to completion and the objective is to profile its performance).

After making the configuration changes specified above, your application configuration file should look like Listing 1. Note that the changes have been highlighted.

Save and rebuild the TracingClient solution. Open the VS.NET 2003 command prompt and navigate to the TracingClient executable folder (C:TracingDemoTracingClientindebug). Issue the following command to retrieve and transform data for the period that exhibited the slowest transformation performance in the initial runs of the test:

TracingClient 7/4/1996 5/6/1998

You will notice that it takes about 8-10 seconds for the transformation to complete. On completion, launch Windows Explorer and navigate to the C:TraceOutput folder (the folder configured as the trace output path in the application configuration file). You will see the trace log (XSLTTraceOutput-<time stamp>.txt) generated for the transformation, along with an XML file containing the dynamically generated data (XMLData-<time stamp> .txt) that was transformed. The XML Data file would not have been persisted if the XSLTTracePersistSource XML option had been disabled (the default), and both files would have been deleted if the XSLTTraceDelet eLogsWhenSuccessful option had been enabled (also the default). The changes made to the default configuration settings for these options in order to enable XSLT tracing resulted in the generation of these two files. Also note that the time stamps appended to the trace log and the XML data file generated for a single transformation are the same. The time stamp can be used to match up trace logs with the corresponding XML data files in scenarios in which multiple transformations are traced during the course of an application's execution.

The instrumented style sheet (InstrumentedStyleSheet.xsl) that resulted in the generation of the trace log is persisted for reference in the TracingClient application executable folder. You can open and view this style sheet to see that the configured XSLT instructions have been instrumented. In a typical scenario in which multiple style sheets are being executed and traced, you will want to remove the line of code in the Load method of the XsltDiagnostics.XslTransform2 type that saves the instrumented style sheet to disk.

In IE, open the XML data file persisted for this transformation and view its structure. You will notice that the data is predominantly flat. Elements representing records from the Orders table are listed first, followed by elements representing records from the Order Details table.

Open the trace log in Microsoft Excel (it is a tab-delimited text file and can be more easily viewed and analyzed using Excel). A spreadsheet column is generated for each of the columns in the trace log (determined by the tab delimiters). Select all the columns in the Excel spreadsheet and do a Format > Column > AutoFit selection from the Excel menu to resize them automatically to the width required to facilitate easy viewing of the data. Table 1 provides brief descriptions of the columns of data in the generated trace log and the XSLT instructions to which they apply.

 

Scroll down to the bottom of the spreadsheet and examine the line generated for the last instruction traced. Observe the value for this instruction in the "Cumulative elapsed time" column. This is the time taken to execute the transformation to the point of tracing the last instrumented instruction. It should be approximately equal to the transformation execution time in most cases. You will notice a line reporting the successful completion of the transformation and the total number of instructions traced during its execution (roughly 8-10 seconds, in this scenario).

Scroll back up to the top of the spreadsheet and sort the data in descending order on the "Elapsed time from last traced instruction" column. This will sort and display the trace log entries in descending order of the approximate time taken to execute each traced instruction. Figure 1 is a screen shot of the sorted trace log for an execution of this scenario on my machine.

 

On scrolling through the instruction trace in this sorted view, notice that the core chunk of time is being spent on evaluating the select expressions of the xsl:for-each loops used to iterate the Orders and OrderDetails elements in the XML data. On examining the style sheet you will see that the xsl:for-each statement used to iterate the OrderDetails elements is nested within the xsl:for-each that iterates the Orders elements. This snippet is shown below:

<xsl:for-each select="Orders">
....
....
<xsl:variable name="OrdID" select="OrderID" />
....
....
<xsl:for-each select="following-sibling::OrderDetails[OrderID=$OrdID]">

On examining the persisted XML that was transformed, you will again notice that the data is predominantly flat. All the Orders elements are listed first, followed by the OrderDetails elements, which results in them being sibling nodes. As each Orders element is processed, the parser must switch context from the element to its related OrderDetails elements by evaluating the predicate used in the select expression of the xsl:for-each loop to iterate the OrderDetails elements. The following-sibling XPath function is used in this sample to achieve this context switch.

An alternate option, given the structure of the data, might have been to use a select expression of ..OrderDetails[OrderID=$OrdID] for the inner xsl:for-each loop used to iterate the OrderDetails elements. The scalability of this expression will be the same as or, more likely, less than the following::sibling expression.

After the OrderDetails elements for an Order have been iterated, the parser's context has to switch back to the next Orders element that must be processed by the outer xsl:for-each loop. Both of these are expensive context switches whose scalability and performance will degrade in a scenario like this as the size of the XML data increases. These expensive context switches could have been avoided if the XML data had been structured to nest the OrderDetails elements within their corresponding Orders elements. This would also have resulted in the XML format being more representative of the structure of the data that it contains.

This analysis leads to the conclusion that only these two possibilities from the initial list of possible causes are applicable to the performance degradation observed in this sample scenario:
1.  Inefficient XPath queries in an otherwise well-structured style sheet
2.  Poorly structured XML data that mandates the use of inefficient XPath queries in the style sheet

The following steps can be executed to remedy this situation:
1.  Implement code changes required to nest the OrderDetails elements within their corresponding Orders elements when generating the dynamic XML.
2.  Change the select expression of the inner xsl:for-each loop to access an Order's OrderDetails elements as its direct children, thereby achieving a clean top-down processing of the data as the transformation is executed.

To achieve the nesting in the XML data in this scenario all you have to do is add the following line of code to the Main method in DynamicClient.cs to set the Nested property of the DataRelation object that links the Orders and the Order Details tables to true. This line should be added immediately after the line of code that adds the DataRelation to the DataSet object:

dsOrderData.Relations["OrderOrderDetails"].Nested = true;

The OrderDetailsData-Nested.xsl style sheet in the TracingClient application executable folder addresses the XSLT style sheet modification described above. Change the line of code in the Main method in DynamicClient.cs that loads the style sheet into the XslTransform2 instance to load this style sheet instead of OrderDetailsData.xsl.

Save the changes and rebuild the solution. Open the VS.NET 2003 command prompt and navigate to the TracingClient executable folder (C:TracingDemoTracingClientindebug). Issue the following command to retrieve and transform the data for the period that exhibited the slowest transformation performance in the initial test runs:

TracingClient 7/4/1996 5/6/1998

Notice that the transformation - which took about 8-10 seconds initially - now completes in 1-2 seconds for the same data (in a more cleanly structured format).

Sample Use Case 2: Transforming Static XML
The scenario described in this section will use the sample XSLT tracing implementation to profile and identify performance bottlenecks in an XSLT transformation executed by applying a style sheet to static XML loaded from a hard disk. The functional base and steps to configure/use the XSLT tracing feature are the same as those described in the dynamic scenario in the previous section. Read the dynamic scenario section first (if you have not already done so) to understand these aspects.

The StaticClient.cs file in the TracingClient project contains the client code that will be used in this scenario. Open this file and study the code in the Main method (see Listing 2). You will notice that the ADO.NET code to dynamically retrieve the data to be transformed from the SQL Server Northwind sample database is not used in here. The XML data is directly loaded from the disk and transformed.

The following XML data files in the TracingClient application executable folder are provided for this scenario: