Orbeon Forms community mailing list

Performance issue when removing debug attributes from <p:input> <p:output>

Classic

List

Threaded

9 messages Options

ncrofts

Performance issue when removing debug attributes from <p:input> <p:output>

I have encountered a rather major decrease in performance running my
XPL pipelines when I remove the debug attribute from my <p:input> and
<p:output> nodes.

During development I have been fairly liberally using the debug
attribute to see the output of pipelines at various points. It's not
caused me a problem and performance for loading the each page that is
produced by the pipeline has been in the order of 0.5 seconds in my
test setup. That's fine for what I'm doing.

However, after removing the debug attributes and changing nothing else
I have found some pretty alarming decreases in performance. Pages are
taking many tens of seconds to load.

I've tried removing the debug attributes one by one, but I just can't
see any appreciable pattern as to why the pipeline is not being
evaluated the way it was when the attributes were in place.

I appreciate I have not included a specific example, but has anyone
got any general ideas as to what could be causing my pipelines to
grind so slowly under these circumstances?

It feels like I must be missing something in my understanding of how
the pipelines are being evaluated. Any thoughts on this matter would
be greatly appreciated.

Thanks,
Neil Crofts

--
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
ObjectWeb mailing lists service home page: http://www.objectweb.org/wws

ncrofts

Re: Performance issue when removing debug attributes from <p:input> <p:o

Further to my original message about a significant drop in performance when removing debug attributes from an XPL pipeline, I just came across another OPS users message from last year that showed that someone else had encountered the same sort of problem. The response to that was that it might be something to do with caching within OPS.

Does anyone have any ideas how I can resolve this issue or what control is available over the caching mechanism?

The message that references the similar looking problem to the one I encountered is referenced below:

mob-2 2005-10-17 12:59
....
Related to this problem I put debug statements in xpl-s and strangely I found that the slow down disappeared. Here is the piece of code:

<p:param type="output" name="controllerDataO"/>

<p:processor name="oxf:scope-generator">
<p:input name="config" debug="config">
<config>
<key>mainControllerData</key>
<scope>session</scope>
</config>
</p:input>
<p:output name="data" id="controllerData" />
</p:processor>
<p:processor name="oxf:identity">
<p:input name="data" href="#controllerData"/>
<p:output name="data" ref="controllerDataO"/>
</p:processor>

If I put debug statements either on the p:param or the p:input element on scope-generator the problem does not appear.
....

--
You receive this message as a subscriber of the ops-users@objectweb.org mailing list.
To unsubscribe: mailto:ops-users-unsubscribe@objectweb.org
For general help: mailto:sympa@objectweb.org?subject=help
ObjectWeb mailing lists service home page: http://www.objectweb.org/wws

Stephen Bayliss

RE: Performance issue when removing debug attributes from <p:input> <p:o

Have you tried increasing the JVM memory?

-----Original Message-----
From: ncrofts [mailto:[hidden email]]
Sent: Fri 15-Sep-06 3:50 PM
To: [hidden email]
Subject: Re: [ops-users] Performance issue when removing debug attributes from <p:input> <p:o

Further to my original message about a significant drop in performance when
removing debug attributes from an XPL pipeline, I just came across another
OPS users message from last year that showed that someone else had
encountered the same sort of problem. The response to that was that it
might be something to do with caching within OPS.

Does anyone have any ideas how I can resolve this issue or what control is
available over the caching mechanism?

The message that references the similar looking problem to the one I
encountered is referenced below:

mob-2 2005-10-17 12:59
....
Related to this problem I put debug statements in xpl-s and strangely I
found that the slow down disappeared. Here is the piece of code:

<p:param type="output" name="controllerDataO"/>



<p:processor name="oxf:scope-generator">
<p:input name="config" debug="config">
<config>
<key>mainControllerData</key>
<scope>session</scope>
</config>
</p:input>
<p:output name="data" id="controllerData" />
</p:processor>
<p:processor name="oxf:identity">
<p:input name="data" href="#controllerData"/>
<p:output name="data" ref="controllerDataO"/>
</p:processor>

If I put debug statements either on the p:param or the p:input element on
scope-generator the problem does not appear.
....

--
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
ObjectWeb mailing lists service home page: http://www.objectweb.org/wws

--
View this message in context: http://www.nabble.com/Performance-issue-when-removing-debug-attributes-from-%3Cp%3Ainput%3E-%3Cp%3Aoutput%3E-tf2223178.html#a6326827
Sent from the ObjectWeb OPS - Users forum at Nabble.com.

--
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
ObjectWeb mailing lists service home page: http://www.objectweb.org/wws

winmail.dat (5K) Download Attachment

ncrofts

Re: Performance issue when removing debug attributes from <p:input> <p:o

No I've not tried that yet. I'll do some experiments with the available
memory to see if that impacts the issue.

I guess I'm still unclear though as to why turning off a feature would
actually be negatively impacting the performance in such a marked way
though. From my understanding of the situation, adding the debug attribute
is akin to adding in a debug processor into the pipeline. Hence I would have
just intuitively assumed that not doing so would lead to better performance.

----- Original Message -----
From: "Stephen Bayliss" <[hidden email]>
To: <[hidden email]>
Sent: Saturday, September 16, 2006 10:02 PM
Subject: RE: [ops-users] Performance issue when removing debug attributes
from <p:input> <p:o

Have you tried increasing the JVM memory?

-----Original Message-----
From: ncrofts [mailto:[hidden email]]
Sent: Fri 15-Sep-06 3:50 PM
To: [hidden email]
Subject: Re: [ops-users] Performance issue when removing debug attributes
from <p:input> <p:o

Further to my original message about a significant drop in performance when
removing debug attributes from an XPL pipeline, I just came across another
OPS users message from last year that showed that someone else had
encountered the same sort of problem. The response to that was that it
might be something to do with caching within OPS.

Does anyone have any ideas how I can resolve this issue or what control is
available over the caching mechanism?

The message that references the similar looking problem to the one I
encountered is referenced below:

mob-2 2005-10-17 12:59
....
Related to this problem I put debug statements in xpl-s and strangely I
found that the slow down disappeared. Here is the piece of code:

<p:param type="output" name="controllerDataO"/>



<p:processor name="oxf:scope-generator">
<p:input name="config" debug="config">
<config>
<key>mainControllerData</key>
<scope>session</scope>
</config>
</p:input>
<p:output name="data" id="controllerData" />
</p:processor>
<p:processor name="oxf:identity">
<p:input name="data" href="#controllerData"/>
<p:output name="data" ref="controllerDataO"/>
</p:processor>

If I put debug statements either on the p:param or the p:input element on
scope-generator the problem does not appear.
....

--
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
ObjectWeb mailing lists service home page: http://www.objectweb.org/wws

--
View this message in context:
http://www.nabble.com/Performance-issue-when-removing-debug-attributes-from-%3Cp%3Ainput%3E-%3Cp%3Aoutput%3E-tf2223178.html#a6326827
Sent from the ObjectWeb OPS - Users forum at Nabble.com.

--------------------------------------------------------------------------------

>
> --
> 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
> ObjectWeb mailing lists service home page: http://www.objectweb.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
ObjectWeb mailing lists service home page: http://www.objectweb.org/wws

Erik Bruchez

Re: Performance issue when removing debug attributes from <p:input> <p:o

Administrator

Neil,

debug attributes impact caching dependencies in order to force the
relevant input or output to produce data. In short, debug attributes can
modify the behavior of a pipeline.

But in general, adding a debug attribute will impact performance
negatively, not positively!

I am not sure what is happening in your case. Do you have dependencies
on resources fetched through HTTP?

-Erik

Neil Crofts (Gmail) wrote:

> No I've not tried that yet. I'll do some experiments with the available
> memory to see if that impacts the issue.
>
> I guess I'm still unclear though as to why turning off a feature would
> actually be negatively impacting the performance in such a marked way
> though. From my understanding of the situation, adding the debug
> attribute is akin to adding in a debug processor into the pipeline.
> Hence I would have just intuitively assumed that not doing so would lead
> to better performance.
>
>
>
> ----- Original Message ----- From: "Stephen Bayliss"
> <[hidden email]>
> To: <[hidden email]>
> Sent: Saturday, September 16, 2006 10:02 PM
> Subject: RE: [ops-users] Performance issue when removing debug
> attributes from <p:input> <p:o
>
>
> Have you tried increasing the JVM memory?
>
>
> -----Original Message-----
> From: ncrofts [mailto:[hidden email]]
> Sent: Fri 15-Sep-06 3:50 PM
> To: [hidden email]
> Subject: Re: [ops-users] Performance issue when removing debug
> attributes from <p:input> <p:o
>
>
> Further to my original message about a significant drop in performance when
> removing debug attributes from an XPL pipeline, I just came across another
> OPS users message from last year that showed that someone else had
> encountered the same sort of problem. The response to that was that it
> might be something to do with caching within OPS.
>
> Does anyone have any ideas how I can resolve this issue or what control is
> available over the caching mechanism?
>
>
> The message that references the similar looking problem to the one I
> encountered is referenced below:
>
> mob-2 2005-10-17 12:59
> ....
> Related to this problem I put debug statements in xpl-s and strangely I
> found that the slow down disappeared. Here is the piece of code:
>
> <p:param type="output" name="controllerDataO"/>
> 
>
> 
> <p:processor name="oxf:scope-generator">
> <p:input name="config" debug="config">
> <config>
> <key>mainControllerData</key>
> <scope>session</scope>
> </config>
> </p:input>
> <p:output name="data" id="controllerData" />
> </p:processor>
> <p:processor name="oxf:identity">
> <p:input name="data" href="#controllerData"/>
> <p:output name="data" ref="controllerDataO"/>
> </p:processor>
>
> If I put debug statements either on the p:param or the p:input element on
> scope-generator the problem does not appear.
> ....
>
>
>
>
>
> --
> 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
> ObjectWeb mailing lists service home page: http://www.objectweb.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
> ObjectWeb mailing lists service home page: http://www.objectweb.org/wws

--
Orbeon - XForms Everywhere:
http://www.orbeon.com/blog/

--
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
ObjectWeb mailing lists service home page: http://www.objectweb.org/wws

ncrofts

Re: Performance issue when removing debug attributes from <p:input> <p:o

Erik,

No, I'm afraid the pipelines don't go off and fetch anything via HTTP. The
only HTTP traffic at the moment is the initial request. The remainder of the
pipelines do perform quite a few transformations, including generating and
then running XPL dynamically, but the performance of these seems just fine
and consistent. The debug attribute effect I've encountered was just
something I inadvertantly came across and was really suprised when I
realised what was turning on/off the problem.

I've been having to press on with getting the base functionality I need in
place, so have in the short term just been making do with having extra debug
output. I really need to get to the bottom of this though as consistent
performance of the XPL is of crucial importance to my application. It's
pretty clear though, that I've not got enough concrete data to help diagnose
the issue. If it's ok, when I've had the chance to collate some more
information or isolate the problem some more I'll post my findings to the
list.

Anyway, thanks for considering the issue for now.

Neil

----- Original Message -----
From: "Erik Bruchez" <[hidden email]>
To: <[hidden email]>
Sent: Monday, September 18, 2006 6:08 PM
Subject: Re: [ops-users] Performance issue when removing debug attributes
from <p:input> <p:o

> Neil,
>
> debug attributes impact caching dependencies in order to force the
> relevant input or output to produce data. In short, debug attributes can
> modify the behavior of a pipeline.
>
> But in general, adding a debug attribute will impact performance
> negatively, not positively!
>
> I am not sure what is happening in your case. Do you have dependencies
> on resources fetched through HTTP?
>
> -Erik
>
> Neil Crofts (Gmail) wrote:
>> No I've not tried that yet. I'll do some experiments with the available
>> memory to see if that impacts the issue.
>>
>> I guess I'm still unclear though as to why turning off a feature would
>> actually be negatively impacting the performance in such a marked way
>> though. From my understanding of the situation, adding the debug
>> attribute is akin to adding in a debug processor into the pipeline.
>> Hence I would have just intuitively assumed that not doing so would lead
>> to better performance.
>>
>>
>>
>> ----- Original Message ----- From: "Stephen Bayliss"
>> <[hidden email]>
>> To: <[hidden email]>
>> Sent: Saturday, September 16, 2006 10:02 PM
>> Subject: RE: [ops-users] Performance issue when removing debug
>> attributes from <p:input> <p:o
>>
>>
>> Have you tried increasing the JVM memory?
>>
>>
>> -----Original Message-----
>> From: ncrofts [mailto:[hidden email]]
>> Sent: Fri 15-Sep-06 3:50 PM
>> To: [hidden email]
>> Subject: Re: [ops-users] Performance issue when removing debug
>> attributes from <p:input> <p:o
>>
>>
>> Further to my original message about a significant drop in performance
>> when
>> removing debug attributes from an XPL pipeline, I just came across
>> another
>> OPS users message from last year that showed that someone else had
>> encountered the same sort of problem. The response to that was that it
>> might be something to do with caching within OPS.
>>
>> Does anyone have any ideas how I can resolve this issue or what control
>> is
>> available over the caching mechanism?
>>
>>
>> The message that references the similar looking problem to the one I
>> encountered is referenced below:
>>
>> mob-2 2005-10-17 12:59
>> ....
>> Related to this problem I put debug statements in xpl-s and strangely I
>> found that the slow down disappeared. Here is the piece of code:
>>
>> <p:param type="output" name="controllerDataO"/>
>> 
>>
>> 
>> <p:processor name="oxf:scope-generator">
>> <p:input name="config" debug="config">
>> <config>
>> <key>mainControllerData</key>
>> <scope>session</scope>
>> </config>
>> </p:input>
>> <p:output name="data" id="controllerData" />
>> </p:processor>
>> <p:processor name="oxf:identity">
>> <p:input name="data" href="#controllerData"/>
>> <p:output name="data" ref="controllerDataO"/>
>> </p:processor>
>>
>> If I put debug statements either on the p:param or the p:input element on
>> scope-generator the problem does not appear.
>> ....
>>
>>
>>
>>
>>
>> --
>> 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
>> ObjectWeb mailing lists service home page: http://www.objectweb.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
>> ObjectWeb mailing lists service home page: http://www.objectweb.org/wws
>
>
> --
> Orbeon - XForms Everywhere:
> http://www.orbeon.com/blog/
>
>

--------------------------------------------------------------------------------

>
> --
> 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
> ObjectWeb mailing lists service home page: http://www.objectweb.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
ObjectWeb mailing lists service home page: http://www.objectweb.org/wws

Erik Bruchez

Re: Performance issue when removing debug attributes from <p:input> <p:o

Administrator

Neil,

Thanks for looking into this, and please be sure to let us know once you
have more information and/or a reproducible case.

-Erik

Neil Crofts (Gmail) wrote:

> Erik,
>
> No, I'm afraid the pipelines don't go off and fetch anything via HTTP.
> The only HTTP traffic at the moment is the initial request. The
> remainder of the pipelines do perform quite a few transformations,
> including generating and then running XPL dynamically, but the
> performance of these seems just fine and consistent. The debug attribute
> effect I've encountered was just something I inadvertantly came across
> and was really suprised when I realised what was turning on/off the
> problem.
>
> I've been having to press on with getting the base functionality I need
> in place, so have in the short term just been making do with having
> extra debug output. I really need to get to the bottom of this though as
> consistent performance of the XPL is of crucial importance to my
> application. It's pretty clear though, that I've not got enough concrete
> data to help diagnose the issue. If it's ok, when I've had the chance to
> collate some more information or isolate the problem some more I'll post
> my findings to the list.
>
> Anyway, thanks for considering the issue for now.
>
> Neil
>
> ----- Original Message ----- From: "Erik Bruchez" <[hidden email]>
> To: <[hidden email]>
> Sent: Monday, September 18, 2006 6:08 PM
> Subject: Re: [ops-users] Performance issue when removing debug
> attributes from <p:input> <p:o
>
>
>> Neil,
>>
>> debug attributes impact caching dependencies in order to force the
>> relevant input or output to produce data. In short, debug attributes can
>> modify the behavior of a pipeline.
>>
>> But in general, adding a debug attribute will impact performance
>> negatively, not positively!
>>
>> I am not sure what is happening in your case. Do you have dependencies
>> on resources fetched through HTTP?
>>
>> -Erik
>>
>> Neil Crofts (Gmail) wrote:
>>> No I've not tried that yet. I'll do some experiments with the available
>>> memory to see if that impacts the issue.
>>>
>>> I guess I'm still unclear though as to why turning off a feature would
>>> actually be negatively impacting the performance in such a marked way
>>> though. From my understanding of the situation, adding the debug
>>> attribute is akin to adding in a debug processor into the pipeline.
>>> Hence I would have just intuitively assumed that not doing so would lead
>>> to better performance.
>>>
>>>
>>>
>>> ----- Original Message ----- From: "Stephen Bayliss"
>>> <[hidden email]>
>>> To: <[hidden email]>
>>> Sent: Saturday, September 16, 2006 10:02 PM
>>> Subject: RE: [ops-users] Performance issue when removing debug
>>> attributes from <p:input> <p:o
>>>
>>>
>>> Have you tried increasing the JVM memory?
>>>
>>>
>>> -----Original Message-----
>>> From: ncrofts [mailto:[hidden email]]
>>> Sent: Fri 15-Sep-06 3:50 PM
>>> To: [hidden email]
>>> Subject: Re: [ops-users] Performance issue when removing debug
>>> attributes from <p:input> <p:o
>>>
>>>
>>> Further to my original message about a significant drop in
>>> performance when
>>> removing debug attributes from an XPL pipeline, I just came across
>>> another
>>> OPS users message from last year that showed that someone else had
>>> encountered the same sort of problem. The response to that was that it
>>> might be something to do with caching within OPS.
>>>
>>> Does anyone have any ideas how I can resolve this issue or what
>>> control is
>>> available over the caching mechanism?
>>>
>>>
>>> The message that references the similar looking problem to the one I
>>> encountered is referenced below:
>>>
>>> mob-2 2005-10-17 12:59
>>> ....
>>> Related to this problem I put debug statements in xpl-s and strangely I
>>> found that the slow down disappeared. Here is the piece of code:
>>>
>>> <p:param type="output" name="controllerDataO"/>
>>> 
>>>
>>> 
>>> <p:processor name="oxf:scope-generator">
>>> <p:input name="config" debug="config">
>>> <config>
>>> <key>mainControllerData</key>
>>> <scope>session</scope>
>>> </config>
>>> </p:input>
>>> <p:output name="data" id="controllerData" />
>>> </p:processor>
>>> <p:processor name="oxf:identity">
>>> <p:input name="data" href="#controllerData"/>
>>> <p:output name="data" ref="controllerDataO"/>
>>> </p:processor>
>>>
>>> If I put debug statements either on the p:param or the p:input
>>> element on
>>> scope-generator the problem does not appear.
>>> ....

ncrofts

Re: Performance issue when removing debug attributes from <p:input> <p:o

I've got a little more information about the performance issue when removing a debug attribute from an XPL pipeline. To recap, I see a significant degradation in performance when I remove a debug attribute associated with an XPL input to a pipeline. This is the only debug attribute left in my application.

eg. <p:param type="input" name="data" debug="without_this_performance_problem_occurs"/>

I've not been able to isolate the problem to a simple piece of XPL yet, but I have now got some results obtained by profiling the application using jProbe. There appears to be a major difference in the profile just by omitting the debug attribute. I've included extracts of the output of the profiling. In the case with the debug attribute removed, the number of calls to org.orbeon.ox.cache classes seems to rise dramatically. I don't know if this is linked to the problem?

I can supply the full results and/or the actual jProbe snapshots if this would be considered helpful.

I'm using OPS 3.0.1 by the way. We're going to see what the effect of the 3.5 build in the near future, as well as see if we can isolate the problem in the XPL.

Regards,
Neil Crofts

snapshot_without_debug_attribute: performance problem occurs

Package Name Calls Cumulative Time Method Time
org.orbeon.oxf.cache MemoryCacheImpl.lowerOrEqual(Object, Object) 86,629 1,371 (0.3%) 782 (0.2%)
org.orbeon.oxf.cache CacheKey.getClazz() 50,738 54 (0.0%) 54 (0.0%)
org.orbeon.oxf.cache CacheUtils.getShortClassName(Class) 50,738 387 (0.1%) 220 (0.0%)
org.orbeon.oxf.cache SimpleOutputCacheKey.toString() 25,388 927 (0.2%) 341 (0.1%)
org.orbeon.oxf.cache CompoundOutputCacheKey.toString() 19,928 27,920 (6.1%) 267 (0.1%)
org.orbeon.oxf.processor.serializer CachedSerializer.findLastModified(Object) 16,629 201 (0.0%) 119 (0.0%)
org.orbeon.oxf.processor.generator DOMGenerator$DocKey.toString() 16,303 849 (0.2%) 126 (0.0%)
org.orbeon.oxf.xml SAXStore.addToLineBuffer(int) 12,202 14 (0.0%) 14 (0.0%)
org.orbeon.oxf.pipeline.api PipelineContext.getAttribute(Object) 7,449 136 (0.0%) 16 (0.0%)
org.orbeon.saxon.tinytree CharSlice.length() 6,480 7 (0.0%) 7 (0.0%)
org.orbeon.oxf.xml SAXStore.addToEventBuffer(byte) 6,374 8 (0.0%) 7 (0.0%)
org.orbeon.oxf.processor ProcessorImpl$ProcessorOutputImpl.getFilter(PipelineContext) 5,667 10 (0.0%) 6 (0.0%)
org.orbeon.oxf.processor ProcessorInput.getOutput() 5,512 19 (0.0%) 13 (0.0%)
org.orbeon.oxf.xml ForwardingContentHandler.characters(char[], int, int) 4,984 55 (0.0%) 9 (0.0%)
org.orbeon.oxf.processor ProcessorImpl$ProcessorInputImpl.getOutput() 4,832 5 (0.0%) 5 (0.0%)
org.orbeon.oxf.cache CacheKey.equals(Object) 4,158 13 (0.0%) 9 (0.0%)
org.orbeon.oxf.processor.generator URLGenerator.access$000(URLGenerator) 3,584 4 (0.0%) 4 (0.0%)
org.orbeon.oxf.cache InputCacheKey.toString() 2,994 6,757 (1.5%) 52 (0.0%)
org.orbeon.oxf.cache InputCacheKey.getInputName() 2,994 3 (0.0%) 3 (0.0%)
org.orbeon.oxf.cache InputCacheKey.getOutputKey() 2,994 3 (0.0%) 3 (0.0%)
org.orbeon.oxf.xml SAXStore.addToCharBuffer(char[], int, int) 2,990 10 (0.0%) 7 (0.0%)

snapshot_with_debug_attribute: no performance issue

Package Name Calls Cumulative Time Method Time
org.orbeon.oxf.xml SAXStore.addToLineBuffer(int) 12,273 14 (0.0%) 14 (0.0%)
org.orbeon.oxf.pipeline.api PipelineContext.getAttribute(Object) 8,486 155 (0.2%) 18 (0.0%)
org.orbeon.saxon.tinytree CharSlice.length() 6,488 7 (0.0%) 7 (0.0%)
org.orbeon.oxf.xml SAXStore.addToEventBuffer(byte) 6,412 8 (0.0%) 8 (0.0%)
org.orbeon.oxf.cache MemoryCacheImpl.lowerOrEqual(Object, Object) 6,184 96 (0.1%) 54 (0.1%)
org.orbeon.oxf.processor ProcessorImpl$ProcessorOutputImpl.getFilter(PipelineContext) 5,846 9 (0.0%) 7 (0.0%)
org.orbeon.oxf.processor ProcessorInput.getOutput() 5,498 18 (0.0%) 13 (0.0%)
org.orbeon.oxf.xml ForwardingContentHandler.characters(char[], int, int) 4,990 60 (0.1%) 9 (0.0%)
org.orbeon.oxf.processor ProcessorImpl$ProcessorInputImpl.getOutput() 4,971 5 (0.0%) 5 (0.0%)
org.orbeon.oxf.cache CacheKey.equals(Object) 4,305 14 (0.0%) 9 (0.0%)
org.orbeon.oxf.processor.generator URLGenerator.access$000(URLGenerator) 3,473 4 (0.0%) 4 (0.0%)
org.orbeon.oxf.processor ProcessorImpl$ProcessorOutputImpl.getKey(PipelineContext) 3,296 817 (1.0%) 12 (0.0%)
org.orbeon.oxf.processor ProcessorImpl$6.getKey(PipelineContext) 3,245 802 (1.0%) 11 (0.0%)
org.orbeon.saxon.event Receiver.characters(CharSequence, int, int) 3,005 80 (0.1%) 7 (0.0%)
org.orbeon.oxf.xml SAXStore.addToCharBuffer(char[], int, int) 3,002 15 (0.0%) 11 (0.0%)
org.orbeon.oxf.xml SAXStore.access$200(SAXStore) 2,994 3 (0.0%) 3 (0.0%)
org.orbeon.oxf.processor ProcessorImpl.getInputKey(PipelineContext, ProcessorInput) 2,941 837 (1.1%) 10 (0.0%)
org.orbeon.oxf.cache Cacheable.getKey(PipelineContext) 2,941 824 (1.0%) 7 (0.0%)
org.orbeon.oxf.xml SAXStore.addToIntBuffer(int) 2,906 4 (0.0%) 3 (0.0%)
org.orbeon.oxf.xml ForwardingContentHandler.endElement(String, String, String) 2,826 29 (0.0%) 5 (0.0%)
org.orbeon.oxf.xml ForwardingContentHandler.startElement(String, String, String, Attributes) 2,826 54 (0.1%) 5 (0.0%)

Erik Bruchez wrote

Neil,

Thanks for looking into this, and please be sure to let us know once you
have more information and/or a reproducible case.

-Erik

Neil Crofts (Gmail) wrote:
> Erik,
>
> No, I'm afraid the pipelines don't go off and fetch anything via HTTP.
> The only HTTP traffic at the moment is the initial request. The
> remainder of the pipelines do perform quite a few transformations,
> including generating and then running XPL dynamically, but the
> performance of these seems just fine and consistent. The debug attribute
> effect I've encountered was just something I inadvertantly came across
> and was really suprised when I realised what was turning on/off the
> problem.
>
> I've been having to press on with getting the base functionality I need
> in place, so have in the short term just been making do with having
> extra debug output. I really need to get to the bottom of this though as
> consistent performance of the XPL is of crucial importance to my
> application. It's pretty clear though, that I've not got enough concrete
> data to help diagnose the issue. If it's ok, when I've had the chance to
> collate some more information or isolate the problem some more I'll post
> my findings to the list.
>
> Anyway, thanks for considering the issue for now.
>
> Neil
>
> ----- Original Message ----- From: "Erik Bruchez" <ebruchez@orbeon.com>
> To: <ops-users@objectweb.org>
> Sent: Monday, September 18, 2006 6:08 PM
> Subject: Re: [ops-users] Performance issue when removing debug
> attributes from <p:input> <p:o
>
>
>> Neil,
>>
>> debug attributes impact caching dependencies in order to force the
>> relevant input or output to produce data. In short, debug attributes can
>> modify the behavior of a pipeline.
>>
>> But in general, adding a debug attribute will impact performance
>> negatively, not positively!
>>
>> I am not sure what is happening in your case. Do you have dependencies
>> on resources fetched through HTTP?
>>
>> -Erik
>>
>> Neil Crofts (Gmail) wrote:
>>> No I've not tried that yet. I'll do some experiments with the available
>>> memory to see if that impacts the issue.
>>>
>>> I guess I'm still unclear though as to why turning off a feature would
>>> actually be negatively impacting the performance in such a marked way
>>> though. From my understanding of the situation, adding the debug
>>> attribute is akin to adding in a debug processor into the pipeline.
>>> Hence I would have just intuitively assumed that not doing so would lead
>>> to better performance.
>>>
>>>
>>>
>>> ----- Original Message ----- From: "Stephen Bayliss"
>>> <stephen.bayliss@rightscom.com>
>>> To: <ops-users@objectweb.org>
>>> Sent: Saturday, September 16, 2006 10:02 PM
>>> Subject: RE: [ops-users] Performance issue when removing debug
>>> attributes from <p:input> <p:o
>>>
>>>
>>> Have you tried increasing the JVM memory?
>>>
>>>
>>> -----Original Message-----
>>> From: ncrofts [mailto:neil.crofts@gmail.com]
>>> Sent: Fri 15-Sep-06 3:50 PM
>>> To: ops-users@objectweb.org
>>> Subject: Re: [ops-users] Performance issue when removing debug
>>> attributes from <p:input> <p:o
>>>
>>>
>>> Further to my original message about a significant drop in
>>> performance when
>>> removing debug attributes from an XPL pipeline, I just came across
>>> another
>>> OPS users message from last year that showed that someone else had
>>> encountered the same sort of problem. The response to that was that it
>>> might be something to do with caching within OPS.
>>>
>>> Does anyone have any ideas how I can resolve this issue or what
>>> control is
>>> available over the caching mechanism?
>>>
>>>
>>> The message that references the similar looking problem to the one I
>>> encountered is referenced below:
>>>
>>> mob-2 2005-10-17 12:59
>>> ....
>>> Related to this problem I put debug statements in xpl-s and strangely I
>>> found that the slow down disappeared. Here is the piece of code:
>>>
>>> <p:param type="output" name="controllerDataO"/>
>>>
>>>
>>>
>>> <p:processor name="oxf:scope-generator">
>>> <p:input name="config" debug="config">
>>> <config>
>>> <key>mainControllerData</key>
>>> <scope>session</scope>
>>> </config>
>>> </p:input>
>>> <p:output name="data" id="controllerData" />
>>> </p:processor>
>>> <p:processor name="oxf:identity">
>>> <p:input name="data" href="#controllerData"/>
>>> <p:output name="data" ref="controllerDataO"/>
>>> </p:processor>
>>>
>>> If I put debug statements either on the p:param or the p:input
>>> element on
>>> scope-generator the problem does not appear.
>>> ....

--
Orbeon - XForms Everywhere:
http://www.orbeon.com/blog/

--
You receive this message as a subscriber of the ops-users@objectweb.org mailing list.
To unsubscribe: mailto:ops-users-unsubscribe@objectweb.org
For general help: mailto:sympa@objectweb.org?subject=help
ObjectWeb mailing lists service home page: http://www.objectweb.org/wws

ncrofts

Re: Performance issue when removing debug attributes from <p:input> <p:o

I've finally produced a standalone example that illustrates the
performance problem I have encountered when removing a debug attribute
from an XPL pipeline. The attached zip file contains the XPL files and
page flow used to illustrate the problem.

The application calls a model XPL which stores small amounts of data
in the session, retrieves it and then passes a small document to the
view which outputs a very rough approximation of the time taken
between the model and view being displayed. This cut down application
isn't really doing any useful processing here, but it is enough to
illustrate the progressive slowdown problem.

To use the sample, host the application in combination with either OPS
3.0.1 or OPS 3.5. I've tested it in Jetty 6 as well as in Tomcat 4+5
and using both JDK 1.4 and 1.5. Note that the problem shows up most
clearly when the Log4J setting java.loglevel=DEBUG is defined.

The page flow defines two URLs: /fast and /slow

The behaviour I see is that repeated refreshes of
http://localhost/fast are always processed within a consistent period
of time. However repeated calls to http://localhost/slow get
progressively slower and slower until eventually the HTTP serializer
in epilogue.xpl throws an exception.

The only difference in the two pipelines is that the /fast URL
ultimately calls a sub-pipeline that defines a single debug attribute
on one of the pipeline inputs (see documentWithDebug.xpl). The /slow
version does not have any debug attributes (see
documentWithoutDebug.xpl)

I was hoping that this example may help isolate the issue such that
someone may be able to diagnose or recognise the cause of the slow
down.

My own observations tend to make me think that it may be related to
the use of the session for storing data. Also my earlier attempts at
profiling showed that when the debug attribute is removed massive
numbers of additional calls are made by the OPS caching mechanism. I
don't understand the OPS caching mechanism enough yet to determine why
this is happening.

If anyone has additional thoughts on how we can figure out the exact
cause of the problem then their advice would be greatly appreciated.

Regards,
Neil Crofts

On 23/10/06, ncrofts <[hidden email]> wrote:

>
> I've got a little more information about the performance issue when removing
> a debug attribute from an XPL pipeline. To recap, I see a significant
> degradation in performance when I remove a debug attribute associated with
> an XPL input to a pipeline. This is the only debug attribute left in my
> application.
>
> eg. <p:param type="input" name="data"
> debug="without_this_performance_problem_occurs"/>
>
> I've not been able to isolate the problem to a simple piece of XPL yet, but
> I have now got some results obtained by profiling the application using
> jProbe. There appears to be a major difference in the profile just by
> omitting the debug attribute. I've included extracts of the output of the
> profiling. In the case with the debug attribute removed, the number of calls
> to org.orbeon.ox.cache classes seems to rise dramatically. I don't know if
> this is linked to the problem?
>
> I can supply the full results and/or the actual jProbe snapshots if this
> would be considered helpful.
>
> I'm using OPS 3.0.1 by the way. We're going to see what the effect of the
> 3.5 build in the near future, as well as see if we can isolate the problem
> in the XPL.
>
> Regards,
> Neil Crofts
>
>
> snapshot_without_debug_attribute: performance problem occurs
>
> Package Name Calls Cumulative Time Method Time
> org.orbeon.oxf.cache MemoryCacheImpl.lowerOrEqual(Object, Object) 86,629
> 1,371 (0.3%) 782 (0.2%)
> org.orbeon.oxf.cache CacheKey.getClazz() 50,738 54 (0.0%) 54 (0.0%)
> org.orbeon.oxf.cache CacheUtils.getShortClassName(Class) 50,738 387
> (0.1%) 220 (0.0%)
> org.orbeon.oxf.cache SimpleOutputCacheKey.toString() 25,388 927 (0.2%)
> 341 (0.1%)
> org.orbeon.oxf.cache CompoundOutputCacheKey.toString() 19,928 27,920
> (6.1%) 267 (0.1%)
> org.orbeon.oxf.processor.serializer
> CachedSerializer.findLastModified(Object) 16,629 201 (0.0%) 119
> (0.0%)
> org.orbeon.oxf.processor.generator DOMGenerator$DocKey.toString() 16,303
> 849 (0.2%) 126 (0.0%)
> org.orbeon.oxf.xml SAXStore.addToLineBuffer(int) 12,202 14 (0.0%) 14
> (0.0%)
> org.orbeon.oxf.pipeline.api PipelineContext.getAttribute(Object) 7,449
> 136 (0.0%) 16 (0.0%)
> org.orbeon.saxon.tinytree CharSlice.length() 6,480 7 (0.0%) 7 (0.0%)
> org.orbeon.oxf.xml SAXStore.addToEventBuffer(byte) 6,374 8 (0.0%) 7
> (0.0%)
> org.orbeon.oxf.processor
> ProcessorImpl$ProcessorOutputImpl.getFilter(PipelineContext) 5,667 10
> (0.0%) 6 (0.0%)
> org.orbeon.oxf.processor ProcessorInput.getOutput() 5,512 19 (0.0%) 13
> (0.0%)
> org.orbeon.oxf.xml ForwardingContentHandler.characters(char[], int, int)
> 4,984 55 (0.0%) 9 (0.0%)
> org.orbeon.oxf.processor ProcessorImpl$ProcessorInputImpl.getOutput()
> 4,832 5 (0.0%) 5 (0.0%)
> org.orbeon.oxf.cache CacheKey.equals(Object) 4,158 13 (0.0%) 9
> (0.0%)
> org.orbeon.oxf.processor.generator URLGenerator.access$000(URLGenerator)
> 3,584 4 (0.0%) 4 (0.0%)
> org.orbeon.oxf.cache InputCacheKey.toString() 2,994 6,757 (1.5%) 52
> (0.0%)
> org.orbeon.oxf.cache InputCacheKey.getInputName() 2,994 3 (0.0%) 3
> (0.0%)
> org.orbeon.oxf.cache InputCacheKey.getOutputKey() 2,994 3 (0.0%) 3
> (0.0%)
> org.orbeon.oxf.xml SAXStore.addToCharBuffer(char[], int, int) 2,990 10
> (0.0%) 7 (0.0%)
>
>
>
> snapshot_with_debug_attribute: no performance issue
>
> Package Name Calls Cumulative Time Method Time
> org.orbeon.oxf.xml SAXStore.addToLineBuffer(int) 12,273 14 (0.0%) 14
> (0.0%)
> org.orbeon.oxf.pipeline.api PipelineContext.getAttribute(Object) 8,486
> 155 (0.2%) 18 (0.0%)
> org.orbeon.saxon.tinytree CharSlice.length() 6,488 7 (0.0%) 7 (0.0%)
> org.orbeon.oxf.xml SAXStore.addToEventBuffer(byte) 6,412 8 (0.0%) 8
> (0.0%)
> org.orbeon.oxf.cache MemoryCacheImpl.lowerOrEqual(Object, Object) 6,184
> 96 (0.1%) 54 (0.1%)
> org.orbeon.oxf.processor
> ProcessorImpl$ProcessorOutputImpl.getFilter(PipelineContext) 5,846 9
> (0.0%) 7 (0.0%)
> org.orbeon.oxf.processor ProcessorInput.getOutput() 5,498 18 (0.0%) 13
> (0.0%)
> org.orbeon.oxf.xml ForwardingContentHandler.characters(char[], int, int)
> 4,990 60 (0.1%) 9 (0.0%)
> org.orbeon.oxf.processor ProcessorImpl$ProcessorInputImpl.getOutput()
> 4,971 5 (0.0%) 5 (0.0%)
> org.orbeon.oxf.cache CacheKey.equals(Object) 4,305 14 (0.0%) 9
> (0.0%)
> org.orbeon.oxf.processor.generator URLGenerator.access$000(URLGenerator)
> 3,473 4 (0.0%) 4 (0.0%)
> org.orbeon.oxf.processor
> ProcessorImpl$ProcessorOutputImpl.getKey(PipelineContext) 3,296 817
> (1.0%) 12 (0.0%)
> org.orbeon.oxf.processor ProcessorImpl$6.getKey(PipelineContext) 3,245
> 802 (1.0%) 11 (0.0%)
> org.orbeon.saxon.event Receiver.characters(CharSequence, int, int) 3,005
> 80 (0.1%) 7 (0.0%)
> org.orbeon.oxf.xml SAXStore.addToCharBuffer(char[], int, int) 3,002 15
> (0.0%) 11 (0.0%)
> org.orbeon.oxf.xml SAXStore.access$200(SAXStore) 2,994 3 (0.0%) 3
> (0.0%)
> org.orbeon.oxf.processor ProcessorImpl.getInputKey(PipelineContext,
> ProcessorInput) 2,941 837 (1.1%) 10 (0.0%)
> org.orbeon.oxf.cache Cacheable.getKey(PipelineContext) 2,941 824 (1.0%)
> 7 (0.0%)
> org.orbeon.oxf.xml SAXStore.addToIntBuffer(int) 2,906 4 (0.0%) 3
> (0.0%)
> org.orbeon.oxf.xml ForwardingContentHandler.endElement(String, String,
> String) 2,826 29 (0.0%) 5 (0.0%)
> org.orbeon.oxf.xml ForwardingContentHandler.startElement(String, String,
> String, Attributes) 2,826 54 (0.1%) 5 (0.0%)
>
>
>
> Erik Bruchez wrote:
> >
> > Neil,
> >
> > Thanks for looking into this, and please be sure to let us know once you
> > have more information and/or a reproducible case.
> >
> > -Erik
> >
> > Neil Crofts (Gmail) wrote:
> >> Erik,
> >>
> >> No, I'm afraid the pipelines don't go off and fetch anything via HTTP.
> >> The only HTTP traffic at the moment is the initial request. The
> >> remainder of the pipelines do perform quite a few transformations,
> >> including generating and then running XPL dynamically, but the
> >> performance of these seems just fine and consistent. The debug attribute
> >> effect I've encountered was just something I inadvertantly came across
> >> and was really suprised when I realised what was turning on/off the
> >> problem.
> >>
> >> I've been having to press on with getting the base functionality I need
> >> in place, so have in the short term just been making do with having
> >> extra debug output. I really need to get to the bottom of this though as
> >> consistent performance of the XPL is of crucial importance to my
> >> application. It's pretty clear though, that I've not got enough concrete
> >> data to help diagnose the issue. If it's ok, when I've had the chance to
> >> collate some more information or isolate the problem some more I'll post
> >> my findings to the list.
> >>
> >> Anyway, thanks for considering the issue for now.
> >>
> >> Neil
> >>
> >> ----- Original Message ----- From: "Erik Bruchez" <[hidden email]>
> >> To: <[hidden email]>
> >> Sent: Monday, September 18, 2006 6:08 PM
> >> Subject: Re: [ops-users] Performance issue when removing debug
> >> attributes from <p:input> <p:o
> >>
> >>
> >>> Neil,
> >>>
> >>> debug attributes impact caching dependencies in order to force the
> >>> relevant input or output to produce data. In short, debug attributes can
> >>> modify the behavior of a pipeline.
> >>>
> >>> But in general, adding a debug attribute will impact performance
> >>> negatively, not positively!
> >>>
> >>> I am not sure what is happening in your case. Do you have dependencies
> >>> on resources fetched through HTTP?
> >>>
> >>> -Erik
> >>>
> >>> Neil Crofts (Gmail) wrote:
> >>>> No I've not tried that yet. I'll do some experiments with the available
> >>>> memory to see if that impacts the issue.
> >>>>
> >>>> I guess I'm still unclear though as to why turning off a feature would
> >>>> actually be negatively impacting the performance in such a marked way
> >>>> though. From my understanding of the situation, adding the debug
> >>>> attribute is akin to adding in a debug processor into the pipeline.
> >>>> Hence I would have just intuitively assumed that not doing so would
> >>>> lead
> >>>> to better performance.
> >>>>
> >>>>
> >>>>
> >>>> ----- Original Message ----- From: "Stephen Bayliss"
> >>>> <[hidden email]>
> >>>> To: <[hidden email]>
> >>>> Sent: Saturday, September 16, 2006 10:02 PM
> >>>> Subject: RE: [ops-users] Performance issue when removing debug
> >>>> attributes from <p:input> <p:o
> >>>>
> >>>>
> >>>> Have you tried increasing the JVM memory?
> >>>>
> >>>>
> >>>> -----Original Message-----
> >>>> From: ncrofts [mailto:[hidden email]]
> >>>> Sent: Fri 15-Sep-06 3:50 PM
> >>>> To: [hidden email]
> >>>> Subject: Re: [ops-users] Performance issue when removing debug
> >>>> attributes from <p:input> <p:o
> >>>>
> >>>>
> >>>> Further to my original message about a significant drop in
> >>>> performance when
> >>>> removing debug attributes from an XPL pipeline, I just came across
> >>>> another
> >>>> OPS users message from last year that showed that someone else had
> >>>> encountered the same sort of problem. The response to that was that it
> >>>> might be something to do with caching within OPS.
> >>>>
> >>>> Does anyone have any ideas how I can resolve this issue or what
> >>>> control is
> >>>> available over the caching mechanism?
> >>>>
> >>>>
> >>>> The message that references the similar looking problem to the one I
> >>>> encountered is referenced below:
> >>>>
> >>>> mob-2 2005-10-17 12:59
> >>>> ....
> >>>> Related to this problem I put debug statements in xpl-s and strangely I
> >>>> found that the slow down disappeared. Here is the piece of code:
> >>>>
> >>>> <p:param type="output" name="controllerDataO"/>
> >>>> 
> >>>>
> >>>> 
> >>>> <p:processor name="oxf:scope-generator">
> >>>> <p:input name="config" debug="config">
> >>>> <config>
> >>>> <key>mainControllerData</key>
> >>>> <scope>session</scope>
> >>>> </config>
> >>>> </p:input>
> >>>> <p:output name="data" id="controllerData" />
> >>>> </p:processor>
> >>>> <p:processor name="oxf:identity">
> >>>> <p:input name="data" href="#controllerData"/>
> >>>> <p:output name="data" ref="controllerDataO"/>
> >>>> </p:processor>
> >>>>
> >>>> If I put debug statements either on the p:param or the p:input
> >>>> element on
> >>>> scope-generator the problem does not appear.
> >>>> ....
> >
> > --
> > Orbeon - XForms Everywhere:
> > http://www.orbeon.com/blog/
> >
> >
> >
> > --
> > 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
> > ObjectWeb mailing lists service home page: http://www.objectweb.org/wws
> >
> >
>
> --
> View this message in context: http://www.nabble.com/Performance-issue-when-removing-debug-attributes-from-%3Cp%3Ainput%3E-%3Cp%3Aoutput%3E-tf2223178.html#a6963845
> Sent from the ObjectWeb OPS - Users mailing list archive at Nabble.com.
>
>
>
>
>
> --
> 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
> ObjectWeb mailing lists service home page: http://www.objectweb.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
ObjectWeb mailing lists service home page: http://www.objectweb.org/wws

ops-slowfast.zip (14K) Download Attachment