Performance

Hello,

I am now trying to track down a performance problem. The observation is that after a couple of page switches back and forth between non-static pages, orbeon gradually slows and almost comes to a halt.
As a new adventure I started JConsole and checked out it's thread tab, where I found that the working thread shows a stack trace whith the top entries being:
...MemoryCacheImpl.lowerOrEqual(...line 179)
...MemoryCacheImpl.lowerOrEqual(...line 182)
about 150 from the above with line 182
...MemoryCacheImpl.findValid(...line 92)

The problem disappears if I sign off from the session, and the slowing starts again with initially good performance.

If you have some ideas please let me know.

regards,
Balazs



--
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

Balazs,

Are you storing documents into the session? Your symptom appears to be a
growing session, but OPS itself does not store anything into the session.

-Erik

[hidden email] wrote:

--
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

Hello Erik,

I indeed have session attributes. I put some debugging in OXFServletDelegate to see what the session holds. I only use 2 smaller documents stored in the session and they seem to be OK.

In my logs I have observed the display of my session debug info more than 1 times for each request. I do not understand that much about Serlvet servicing but it seemed strange. The five threads - if indeed that is what they are - are being serviced paralelly and finish about the same time.

regards,
Balazs



--
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

A few important tips:

o Be sure to provide OPS with enough heap. 128 MB is a strict minimum,
and you may want to go up to 512 MB depending on what you are doing.

o You can tune the number of objects held in the OPS object cache.
Larger numbers allow for more objects in the cache, but also take up
more memory which, if your heap is too small, may cause performance to
actually degrade. You set this with a property in properties.xml:

<property as="xs:integer" name="oxf.cache.size"
          value="384"/>

Try smaller values (like 100) or larger values (500), and observe the
behavior of the application under load. Do this in conjunction with
playing with the application heap size.

Beyond cache size questions, OPS 2.8 should definitely not leak by
itself dramatically, otherwise this would have been reported. This is
why I asked if you were storing your own documents into the session.
Clearly if you do that wrong, you can get dramatic memory consumption.

In addition, make sure you have no debug attributes in XPL for
production use: those do make XPL pipelines slower.

-Erik

[hidden email] wrote:
> Hello Erik,
>
> I indeed have session attributes. I put some debugging in OXFServletDelegate to see what the session holds. I only use 2 smaller documents stored in the session and they seem to be OK.
>
> In my logs I have observed the display of my session debug info more than 1 times for each request. I do not understand that much about Serlvet servicing but it seemed strange. The five threads - if indeed that is what they are - are being serviced paralelly and finish about the same time.
>
> regards,
> Balazs



--
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

Hi Balazs,

Also, if you are using an automated tool for your testing (e.g.
JMeter), a new session might be created for each request sent by the
tool, which can quickly lead to a major slow down as the VM spends
more time doing garbage collections than anything else. With JMeter,
you can control this by adding an "HTTP Cookie Manager" to your test
plan.

Alex

On 10/14/05, [hidden email] <[hidden email]> wrote:

--
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

Hello,

Thanks for the suggestions. I run my tests with 512 MB heap size. I am currently using a cache size of 500.
I put some additional logging in MemoryCacheImpl.java findValid(PipelineContext context, CacheKey key, Object validity) - as this was the method shown for observably long time in JConsole. I measured the current time in millis at the beginning of the method and at the point of returns. It turned out that initially the time spent values are quite small (near to zero), then they grow continually up to the ranges around 500 to above 600 milliseconds. Currently this is the only track I am having.

regards,
Bal??zs



--
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

[hidden email] wrote:
> Hello,
>
> Thanks for the suggestions. I run my tests with 512 MB heap size. I am currently using a cache size of 500.
> I put some additional logging in MemoryCacheImpl.java findValid(PipelineContext context, CacheKey key, Object validity) - as this was the method shown for observably long time in JConsole. I measured the current time in millis at the beginning of the method and at the point of returns. It turned out that initially the time spent values are quite small (near to zero), then they grow continually up to the ranges around 500 to above 600 milliseconds. Currently this is the only track I am having.

Balazs,

This method is not much more than a lookup in a HashMap followed by a
comparison with a depth which can depend on the length of the pipeline
but should not increase dramatically: it sounds surprising that you can
even measure a time > 1ms for each invocation. Your machine has enough
physical memory for the entire Java heap to be kept in it, right?

-Erik



--
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

Hello,

I have checked my system and I have more than 460MB free memory out of 1,5 GB.
In the meantime I have localized the problem to the point when I access my session attributes. It seems that this is the point that slows down the application - although as I have previously checked I keep only two small objects in the session.

Related to this problemI 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:param type="output" name="controllerDataO" /-->

    <!-- try to read controller instance from session -->
    <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. (I have  measured values above 1000 milliseconds in findValid(); the identity processor was also put there only for testing but it had no effect). I do not know it this is related to this problem but checking catalina.out there is an exception after starting up tomcat:
-------------
2005.10.17. 12:56:56 org.apache.catalina.session.StandardManager doLoad
SEVERE: IOException while loading persisted sessions: java.io.WriteAbortedException: writing aborte
d; java.io.NotSerializableException: org.orbeon.oxf.xml.SAXStore$1
java.io.WriteAbortedException: writing aborted; java.io.NotSerializableException: org.orbeon.oxf.xm
l.SAXStore$1
        at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1278)
        at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1845)
        at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1769)
        at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1646)
        at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1274)
        at java.io.ObjectInputStream.defaultReadFields(ObjectInputStream.java:1845)
-------------
The above exception only appears once at loading presentation server web app.

regards,
Bal??zs



--
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

Hi Balázs,

On 10/17/05, [hidden email] <[hidden email]> wrote:
> I have checked my system and I have more than 460MB free memory out of 1,5 GB.

The 1.5 GB is really physical memory, right? The last thing you would
like to happen is to have the VM to use so much more memory than your
operating system has to constantly move pages between the disk and
physical memory (swapping).

> I do not know it this is related to this problem but checking catalina.out there is an exception after starting up tomcat:
> -------------
> 2005.10.17. 12:56:56 org.apache.catalina.session.StandardManager doLoad
> SEVERE: IOException while loading persisted sessions: java.io.WriteAbortedException: writing aborte
> d; java.io.NotSerializableException: org.orbeon.oxf.xml.SAXStore$1
> java.io.WriteAbortedException: writing aborted; java.io.NotSerializableException: org.orbeon.oxf.xm
> l.SAXStore$1

I don't think this exception is related to the slow down you are
experimenting. This exception tells you that some objects in the
session cannot be serialized to disk when Tomcat shut down. Tomcat is
doing that so it can restore the session when it is started again.

Alex



--
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

Hello Alex,

Yes, the memory I wrote about is physical memory.

regards,
Balazs



--
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

So this appears to rule out a swapping issue. I guess that's just what
Alex was trying to do.

Now by adding a "debug" attribute at that point, what you are doing is
making sure that the output of the Scope generator is not cacheable,
therefore making sure the XPL engine caching algorithm stops right
there. Now this is really weird, because the cost of the caching
algorithm figuring out whether some value is cached and still valid is
meant to be quick!

Now the Scope generator's caching is itself based on computing a digest
of the XML document in scope by going through the
XMLUtils.DigestContentHandler. But if this was the code taking time, you
would probably see that when you are profiling?

-Erik

[hidden email] wrote:
> Hello Alex,
>
> Yes, the memory I wrote about is physical memory.
>
> regards,
> Balazs



--
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

Hello Erik,

I put some measurement inside DOMGenerator constructor around the code
------
key.setKey(NumberUtils.toHexString(XMLUtils.getDigest(document)));
------
which I found was one place where digest is called. The other place was also inside DOMGenerator
in
------
public ProcessorOutput createOutput(String name) {
....
public OutputCacheKey getKeyImpl(org.orbeon.oxf.pipeline.api.PipelineContext context) {
...
   key = new OutputCacheKey(this, NumberUtils.toHexString(digest));
------

I could only see findValid spending 5-6 hunder millisesonds while could only once or twice measure digest in these places taking around 170 milliseconds.


regards,
Balazs



--
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

[hidden email] wrote: It seems to me that 170ms in one invocation of a digest is an awfully
long time! Is it possible that this method is very inefficient? But then
you also notice increasingly long times, right?

-Erik



--
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

Hello Erik,

It is still MemoryCacheImpl.findValid() that shows me progressively larger numbers. To be clear what and how I measure I send the piece of code I am using.

----------------------------------------------------------------------
public synchronized Object findValid(PipelineContext context, CacheKey key, Object validity) {

    // mob begin
    long start = System.currentTimeMillis();
        CacheEntry entry = (CacheEntry) keyToEntryMap.get(key);
        long end1 = System.currentTimeMillis(); //mob
        long timeSpent1 = end1 - start; //mob
        if (timeSpent1 > 100){ //mob
    logger.info("mob/MemoryCacheImpl.findValid()/timeSpent1 in millis=["+timeSpent1+"]"); //mob
        } //mob
       
        if (entry != null && lowerOrEqual(validity, entry.validity)) {
            long end2 = System.currentTimeMillis(); //mob
            long timeSpent2 = end2 - end1; //mob
            if (timeSpent2 > 100){ //mob
        logger.info("mob/MemoryCacheImpl.findValid()/timeSpent2 in millis=["+timeSpent2+"]"); //mob
            } //mob

            // Place in first position and return
            if (context != null)
                ((Statistics) getStatistics(context)).incrementHitsCount();
            if (linkedList.getFirst() != entry) {
                linkedList.remove(entry);
                linkedList.addFirst(entry);
            }
            long end3 = System.currentTimeMillis();
            long timeSpent3 = end3- end2;
            if (timeSpent3 > 100){
            logger.info("mob/MemoryCacheImpl.findValid()/timeSpent3 in millis=["+timeSpent3+"]");
            }
            long timeSpentTotal = end3  - start;
            if (timeSpentTotal > 100){
        logger.info("mob/MemoryCacheImpl.findValid()/timeSpentTotal in millis=["+timeSpentTotal+"]");
            }
------------------------------

The logs begin with values like this:
"mob/MemoryCacheImpl.findValid()/timeSpent2 in millis=[206]"
"mob/MemoryCacheImpl.findValid()/timeSpentTotal in millis=[208]"

and after a couple of requests:

"mob/MemoryCacheImpl.findValid()/timeSpent2 in millis=[772]"
"mob/MemoryCacheImpl.findValid()/timeSpentTotal in millis=[808]"

The above suggests time gets lost in "lowerOrEqual()". I also suspect that it is the scope generator that somehow is related to the problem. This is so because the way we organized functions is we have a central "page" without any views that gets called when page/transaction A calling page/transaction B. When doing so it accesses the session. The performance problem appears only with page transfers that  leave page A. With actions that do not result in calls to this code there is no slowdown.
This central dispatcher calls session manipulation  and XSL transformation processors.

regards,
Balazs



--
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

Balazs,

I don't know if you have progressed, but maybe the solution consists in
using a real profiler, which will tell you with more details where the
time is spent.

In the meanwhile, a solution where the Scope generator doesn't cache may
be enough to alleviate the problem.

-Erik

[hidden email] wrote:

--
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

Hello Erik,

I had to leave this task for others so there was no progress.

Which performance tools do you advise ? (for eclipse)

thanks,
Bal??zs



--
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

Balazs,

I don't know about Eclipse, but there is the JProbe Profiler, Freeware
Edition, that you may want to try:

   http://www.quest.com/jprobe/profiler_freeware.asp

We have used it successfully in the past.

-Erik

[hidden email] wrote:
> Hello Erik,
>
> I had to leave this task for others so there was no progress.
>
> Which performance tools do you advise ? (for eclipse)
>
> thanks,
> Bal??zs



--
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