eCube The XSLT Profiler.

Reading the results.

Transformation and run-times

The measured "transformation time" is the overall time needed for preparing the input sources plus running the xsl transformation n-times. We also deliver a "run-time" for each single run, which is the time needed for the JAXP-call transformer.transform(streamSource, result). As this call includes parsing of the xml-source, the resulting own-time (see below) of each run is more or less remarkable.


Understanding style-events

In each run catchXSL! traces all style instructions which are processed by the XSLT transformer. The profiler logs them as "style-events" and provides them with a timestamp. Such instructions may be an XSLT command like <xsl:copy-of>. But also when an XML elements is processed, this is regarded as style-event like <html> or <body> inside a template rule. Simple text in the style-sheet with either <xsl:text> around or not, are treated as "text-events" (see also Differences in Processors).


Understanding select-events

We spent some effort to extract the sometimes remarkable time needed for selecting nodes (occurs in for-each and apply-templates). Thus we created the event type "select-event" and display them as a child node of the for-each / apply-templates-instruction. It's worth to mention is that the "own-time" of the main insruction includes the time of the select-child. So, just don't get confused when trying to interpret the resulting times.


Understanding write-events

catchXSL! provides the option to trace "write-events" as well. With the command line tool this is the option -tw and with the gui you can set this when creating a project. When set each flushing of output lines by the xslt processor is traced as well. This may not seem important, but as these flushings may distort the times of style-events, it's sometimes useful to know when they occur.


Template sum

This result representation gives you you a "template-orientied" view. There, you can immediatley spot the time the processor spent in each template. As templates usually call other templates ( with apply-templates or call-template) the used time of the called template is extracted from the duration time of the caller. Otherwise, the "root-template" (match="/index.html") would contain all the other template times as well.

This output lists each xsl-file (in case of imports there might be more than one xsl-file) with each of its processed lines and the summed up time spent in each of it.

The meaning of the columns is as follows:

shows the xsl-instruction
time spent in this source line
time spent in this source and its children but without the time spent in other templates called within
% part of the net-time in relation to the time of the run
Calls how often the line is called
Avg per call average net-time time per call
Line line number of instruction
Column column number

With Saxon as processor, the template view also contains top-level elements, like variable- or key-declarations which appear at the beginning of the style-sheet.


Tree View

With the tree representation you can examine how style instructions are processed. This result view is also named call-tree, as it represents the order of style processings. Here, you can also find the write-events in case you have them enabled.

The profiling result shows the duration time for each of the style-instruction including the time needed for its called children. Thus, it's obvious that the outermost call captures the longest time.


Average times

For the two kinds of representation there's also an 'average view' possible.

With the command line starter you specify the average view in the runlist, e.g. -template avg. In this case, you'll get the average view over all runs.

With the gui version of catchXSL! you specify the average view when creating the result views, e.g. specifying 1-4 gives you the average over runs 1 to 4. In this case the gui version provides more functionality.


Profiling results as XML

With the command line option -format xml you'll get the profiling results as XML. This is especially useful when you want to develop your individual view on the profiling results. Of course, this is done then in writing an xsl-stylesheet which transformes the result xml. We provide a dtd-file which specifies the format of the result xml, this is to be found under $PROFILER_HOME/docs/profile-results.dtd.


Transformation results

You won't find the file resulting from the transformation in the output of the profiler. This is not its task anyway. But you can get it with the option -out <file> in the command line starter. In the gui version you specify this when creating a profiling task. What's important to mention is, that once you have increased the number of runs, you'll find the output written the same number of times in this file. It would have been easy for us to filter the output after the first run but that could have distorted the measuring.

When the write events are traced as well (see Understanding write-events), we provide the write-events with line and column numbers which refer to the location in the specified output file.