Orbeon Forms community mailing list

XPL Profiling

Classic

List

Threaded

2 messages Options

Eric van der Vlist

XPL Profiling

Hi,

I have some hard time trying to understand the XPL profiling output, is
it documented somewhere?

If not I have many questions!

To take a simple example :

<node local-time="1925436" cumulative-time="1925436"
start-time="32577318149110" read-called="true" getKey-called="false">

<input name="config"
processor-class="org.orbeon.oxf.processor.transformer.xslt.XSLT2Transformer" processor-name="oxf:builtin-saxon" processor-object="247" system-id="oxf:/allservices/allservices_message_traiter.xpl" line="172" column="32">

<output name="data"
processor-class="org.orbeon.oxf.processor.generator.DOMGenerator"
processor-name="oxf:dom-generator" processor-object="254"/>

</input>

</node>

Where line 172 is the config input in:

<p:processor name="oxf:xslt">
<p:input name="data" href="#message"/>
<p:input name="dossier" href="#dossier-message-insere"/>
<p:input name="request" href="#request"/>
<p:input name="config">
<key xsl:version="2.0">
.../...
</key>
</p:input>
<p:output name="data" id="key"/>
</p:processor>

My understanding is that the node describes the parsing of this input
and only that. Is that so?

The local-time and cumulative-time here are equal because there are no
sub-nodes, right?

According to
http://wiki.orbeon.com/forms/doc/developer-guide/admin/performance-tuning#TOC-Enable-XPL-profiling, they should be expressed in milliseconds but that can't be the case here: this node is only a small one in a hugs pipeline. The full pipeline has been executed in 169 seconds as a whole and there is no way this node may have taken 1925 seconds!

Are these microseconds then?

Also, this is included in pipeline that is called in a for-each and the
processor has been executed multiple times. Are these times the
accumulation of the local and cumulative times over the iterations?

Is there a way to know how many times the node has been run?

These times can also be weird and the next node has a local-time that
is... negative :

<node local-time="-616838" cumulative-time="45412"
start-time="32744725991995" read-called="true" getKey-called="false">

How should we read that?

Thanks,

Eric

--
You receive this message as a subscriber of the [hidden email] mailing list.
To unsubscribe: mailto:[hidden email]
For general help: mailto:[hidden email]?subject=help
OW2 mailing lists service home page: http://www.ow2.org/wws

Erik Bruchez

Re: XPL Profiling

Administrator

Eric,

Sorry about the delay.

I fear I don't have very good answers on this topic. This was
implemented a very long time ago, and we gave this a refresh in July
2010 while looking at some XPL performance.

I think tracing is not very telling at this time because lots of
processors do some kind of streaming. Or, at least, they don't fully
separate fully reading an input vs. fully writing and output, for
example. That probably explains why it's hard to interpret the
results!

I notice that since July 2010, we use System.nanoTime(). I updated the
doc to reflect that.

On p:for-each: I am not sure, without spending more time, what happens
with the times recorded here. The same does for the negative times!

-Erik

On Tue, Apr 3, 2012 at 2:25 AM, Eric van der Vlist <[hidden email]> wrote:

> Hi,
>
> I have some hard time trying to understand the XPL profiling output, is
> it documented somewhere?
>
> If not I have many questions!
>
> To take a simple example :
>
> <node local-time="1925436" cumulative-time="1925436"
> start-time="32577318149110" read-called="true" getKey-called="false">
>
> <input name="config"
> processor-class="org.orbeon.oxf.processor.transformer.xslt.XSLT2Transformer" processor-name="oxf:builtin-saxon" processor-object="247" system-id="oxf:/allservices/allservices_message_traiter.xpl" line="172" column="32">
>
> <output name="data"
> processor-class="org.orbeon.oxf.processor.generator.DOMGenerator"
> processor-name="oxf:dom-generator" processor-object="254"/>
>
> </input>
>
> </node>
>
> Where line 172 is the config input in:
>
> <p:processor name="oxf:xslt">
> <p:input name="data" href="#message"/>
> <p:input name="dossier" href="#dossier-message-insere"/>
> <p:input name="request" href="#request"/>
> <p:input name="config">
> <key xsl:version="2.0">
> .../...
> </key>
> </p:input>
> <p:output name="data" id="key"/>
> </p:processor>
>
> My understanding is that the node describes the parsing of this input
> and only that. Is that so?
>
> The local-time and cumulative-time here are equal because there are no
> sub-nodes, right?
>
> According to
> http://wiki.orbeon.com/forms/doc/developer-guide/admin/performance-tuning#TOC-Enable-XPL-profiling, they should be expressed in milliseconds but that can't be the case here: this node is only a small one in a hugs pipeline. The full pipeline has been executed in 169 seconds as a whole and there is no way this node may have taken 1925 seconds!
>
> Are these microseconds then?
>
> Also, this is included in pipeline that is called in a for-each and the
> processor has been executed multiple times. Are these times the
> accumulation of the local and cumulative times over the iterations?
>
> Is there a way to know how many times the node has been run?
>
> These times can also be weird and the next node has a local-time that
> is... negative :
>
> <node local-time="-616838" cumulative-time="45412"
> start-time="32744725991995" read-called="true" getKey-called="false">
>
> How should we read that?
>
> Thanks,
>
> Eric
>
>
>
> --
> You receive this message as a subscriber of the [hidden email] mailing list.
> To unsubscribe: mailto:[hidden email]
> For general help: mailto:[hidden email]?subject=help
> OW2 mailing lists service home page: http://www.ow2.org/wws
>

--
You receive this message as a subscriber of the [hidden email] mailing list.
To unsubscribe: mailto:[hidden email]
For general help: mailto:[hidden email]?subject=help
OW2 mailing lists service home page: http://www.ow2.org/wws