Performance Analysis

This section describes tools designed to assist with performance monitoring and tuning.

Profiling Execution Time

Saxon comes with a simple tool allowing profiling of the execution time in a stylesheet.

To run this tool, first execute the transformation with the -TP:filename option, which will gather timed tracing information and create a profile report to the specified file (or to the standard error output if no filename is given). For example:

java net.sf.saxon.Transform -TP:profile.html -s:source -xsl:stylesheet

Then view the resulting profile.html file in your browser.

The output identifies templates and functions in the original stylesheet by their name or match pattern, line number, and the last part of the URI of their module. For each instruction it gives the number of times the instruction was executed, the average time in milliseconds of each execution, and the total time. Timings are given both gross (the time for a template including all the templates it calls recursively), and net (the time for a template excluding time in its called templates). The table is sorted according to a weighting function that attempts to put the dominant functions and templates at the top. These will not necessarily be those with the greatest time, which tend to be instructions that were only executed once but remained active for the duration of the transformation.

Monitoring Bytecode Performance

Saxon-EE by default generates bytecode to speed up execution of the most frequently executed parts of a stylesheet.

On the Transform command line, the option -TB:filename can be used to request a report showing the effectiveness of bytecode generation. The output is in XML format, something like this:

<stats unit='microseconds'> <exp id="0" text="($title, ...)" intCount="1" ... module="books.xsl" line="36" /> <exp id="2" text="@CODE" intCount="3" ... module="books.xsl" line="83" /> <exp id="1" text="@DESC" intCount="3" ... module="books.xsl" line="82" /> </stats>

In this report, each exp element represents an expression that was compiled as a candidate for bytecode generation. The report contains the following attributes:

text: Abbreviated text of the expression
intCount: Number of times the expression was evaluated in the interpreter
intTime: Cumulative time spent evaluating the expression (including subexpressions) in the interpreter
bcCount: Number of times the expression was evaluated as bytecode
bcTime: Cumulative time spent evaluating the expression (including subexpressions) as bytecode
compileTime: Time spent generating bytecode for the expression
ratio: Average bytecode execution time as a proportion of average interpreted execution time
ebv: Number of evaluations of the expression's effectiveBooleanValue() method
eval: Number of evaluations of the expression's evaluateItem() method
iterate: Number of evaluations of the expression's iterate() method
process: Number of evaluations of the expression's process() method
module: URI of the module containing the expression
line: Line number of the expression within this module

Note that if an expression A contains an expression B and both are candidates for bytecode generation, then the statistics for B relate only to the time before A was compiled in its own right.