Testing some JVM Analysis Tool

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

Testing some JVM Analysis Tool

Ludovic Dubost
Hi,

I've been testing newrelic which has some interesting live JVM analysis.
I've been running the JVM Profiling while running a load test going on
various XWiki pages (except activity stream) including AWM, LiveTable
Searches, Content pages, Lucene search and loading ressources.

Here is a result of the profiling:

25.0%  - java.net.SocketInputStream.socketRead0
 32 Collapsed methods (show)
  25.0%  - com.xpn.xwiki.store.hibernate.query.HqlQueryExecutor.execute
   21.0%  - org.xwiki.query.internal.DefaultQueryExecutorManager.execute
    11.0%  - org.xwiki.query.internal.DefaultQuery.execute
     127 Collapsed methods (show)
     11.0%  - java.lang.Thread.run
    9.9%  - org.xwiki.query.internal.SecureQueryExecutorManager.execute
   4.2%  - com.xpn.xwiki.store.hibernate.query.DefaultQueryExecutor.execute
12.0%  - org.apache.velocity.runtime.parser.node.SimpleNode.render
 12.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
  12.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
   8.1%  -
org.xwiki.rendering.internal.macro.velocity.VelocityMacro.evaluateString
   4.3%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
9.2%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
8.5%  - com.xpn.xwiki.render.DefaultVelocityManager.getVelocityEngine
4.1%  - org.apache.velocity.runtime.parser.node.ASTBlock.render
4.1%  - com.xpn.xwiki.web.XWikiAction.execute
3.6%  -
org.xwiki.rendering.internal.transformation.macro.MacroTransformation.transformOnce
3.2%  - org.apache.velocity.runtime.directive.Foreach.render
2.9%  -
org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.docElements
2.8%  - com.xpn.xwiki.plugin.lucene.SearchResults.getRelevantResults
2.6%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
2.4%  - com.mysql.jdbc.PreparedStatement.executeQuery
2.4%  - org.xwiki.uiextension.internal.WikiUIExtension.getParameters
2.3%  - org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.line

My understanding is that we spend 25% of time reading from the DB (this
could be livetable related for instance). Around 50 in various velocity
parts. Around 10% in the XWiki rendering and 3% in Lucene search. 2,4% in
UI extensions (no visible rights, probably because running as Admin)

Velocity is clearly quite expensive. Now I see particularly:

8.5%  - com.xpn.xwiki.render.DefaultVelocityManager.getVelocityEngine

Would this mean we are spending 8,5% of the time getting the velocity
engine to use ?
This sounds a lot.

In any case this is food for thoughts for future optimizations.

Ludovic

--
Ludovic Dubost
Founder and CEO
Blog: http://blog.ludovic.org/
XWiki: http://www.xwiki.com
Skype: ldubost GTalk: ldubost
_______________________________________________
devs mailing list
[hidden email]
http://lists.xwiki.org/mailman/listinfo/devs
Reply | Threaded
Open this post in threaded view
|

Re: Testing some JVM Analysis Tool

Ludovic Dubost
In my previous test, the database was not very optimized. Here is the
result with a more optimized mysql 5.1:

15.0%  - org.apache.velocity.runtime.parser.node.SimpleNode.render
 15.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
  15.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
   7.5%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
   7.4%  -
org.xwiki.rendering.internal.macro.velocity.VelocityMacro.evaluateString
9.1%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
8.4%  - com.xpn.xwiki.render.DefaultVelocityManager.getVelocityEngine
6.2%  - java.net.SocketInputStream.socketRead0
5.8%  - com.xpn.xwiki.web.XWikiAction.execute
5.3%  -
org.xwiki.rendering.internal.transformation.macro.MacroTransformation.transformOnce
4.2%  - org.apache.velocity.runtime.directive.Foreach.render
4.1%  - org.apache.velocity.runtime.parser.node.ASTBlock.render
3.4%  - org.xwiki.uiextension.internal.WikiUIExtension.getParameters
3.1%  - com.xpn.xwiki.doc.XWikiDocument.getRenderedContent
2.8%  -
org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScannerTokenManager.jjMoveNfa_6
2.7%  - org.xwiki.rendering.macro.script.AbstractScriptMacro.evaluateBlock
2.6%  -
org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.docElements
2.4%  - com.xpn.xwiki.plugin.lucene.SearchResults.getRelevantResults
2.3%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
2.1%  - org.apache.velocity.runtime.directive.RuntimeMacro.render
2.1%  -
org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.paragraph
2.0%  - com.xpn.xwiki.doc.XWikiDocument.getRenderedTitle
2.0%  - org.apache.velocity.runtime.parser.node.ASTMethod.execute

We could also look into velocity optimizations. Seems like
"SimpleNode.render" has a quite important individual cost.

Ludovic


2013/2/8 Ludovic Dubost <[hidden email]>

>
> Hi,
>
> I've been testing newrelic which has some interesting live JVM analysis.
> I've been running the JVM Profiling while running a load test going on
> various XWiki pages (except activity stream) including AWM, LiveTable
> Searches, Content pages, Lucene search and loading ressources.
>
> Here is a result of the profiling:
>
> 25.0%  - java.net.SocketInputStream.socketRead0
>  32 Collapsed methods (show)
>   25.0%  - com.xpn.xwiki.store.hibernate.query.HqlQueryExecutor.execute
>    21.0%  - org.xwiki.query.internal.DefaultQueryExecutorManager.execute
>     11.0%  - org.xwiki.query.internal.DefaultQuery.execute
>      127 Collapsed methods (show)
>      11.0%  - java.lang.Thread.run
>     9.9%  - org.xwiki.query.internal.SecureQueryExecutorManager.execute
>    4.2%  - com.xpn.xwiki.store.hibernate.query.DefaultQueryExecutor.execute
> 12.0%  - org.apache.velocity.runtime.parser.node.SimpleNode.render
>  12.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
>   12.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
>    8.1%  -
> org.xwiki.rendering.internal.macro.velocity.VelocityMacro.evaluateString
>    4.3%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
> 9.2%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
> 8.5%  - com.xpn.xwiki.render.DefaultVelocityManager.getVelocityEngine
> 4.1%  - org.apache.velocity.runtime.parser.node.ASTBlock.render
> 4.1%  - com.xpn.xwiki.web.XWikiAction.execute
> 3.6%  -
> org.xwiki.rendering.internal.transformation.macro.MacroTransformation.transformOnce
> 3.2%  - org.apache.velocity.runtime.directive.Foreach.render
> 2.9%  -
> org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.docElements
> 2.8%  - com.xpn.xwiki.plugin.lucene.SearchResults.getRelevantResults
> 2.6%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
> 2.4%  - com.mysql.jdbc.PreparedStatement.executeQuery
> 2.4%  - org.xwiki.uiextension.internal.WikiUIExtension.getParameters
> 2.3%  -
> org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.line
>
> My understanding is that we spend 25% of time reading from the DB (this
> could be livetable related for instance). Around 50 in various velocity
> parts. Around 10% in the XWiki rendering and 3% in Lucene search. 2,4% in
> UI extensions (no visible rights, probably because running as Admin)
>
> Velocity is clearly quite expensive. Now I see particularly:
>
> 8.5%  - com.xpn.xwiki.render.DefaultVelocityManager.getVelocityEngine
>
> Would this mean we are spending 8,5% of the time getting the velocity
> engine to use ?
> This sounds a lot.
>
> In any case this is food for thoughts for future optimizations.
>
> Ludovic
>
> --
> Ludovic Dubost
> Founder and CEO
> Blog: http://blog.ludovic.org/
> XWiki: http://www.xwiki.com
> Skype: ldubost GTalk: ldubost
>



--
Ludovic Dubost
Founder and CEO
Blog: http://blog.ludovic.org/
XWiki: http://www.xwiki.com
Skype: ldubost GTalk: ldubost
_______________________________________________
devs mailing list
[hidden email]
http://lists.xwiki.org/mailman/listinfo/devs
Reply | Threaded
Open this post in threaded view
|

Re: Testing some JVM Analysis Tool

vmassol
Administrator
In reply to this post by Ludovic Dubost

On Feb 8, 2013, at 12:35 AM, Ludovic Dubost <[hidden email]> wrote:

> Hi,
>
> I've been testing newrelic which has some interesting live JVM analysis.
> I've been running the JVM Profiling while running a load test going on
> various XWiki pages (except activity stream) including AWM, LiveTable
> Searches, Content pages, Lucene search and loading ressources.
>
> Here is a result of the profiling:
>
> 25.0%  - java.net.SocketInputStream.socketRead0
> 32 Collapsed methods (show)
>  25.0%  - com.xpn.xwiki.store.hibernate.query.HqlQueryExecutor.execute
>   21.0%  - org.xwiki.query.internal.DefaultQueryExecutorManager.execute
>    11.0%  - org.xwiki.query.internal.DefaultQuery.execute
>     127 Collapsed methods (show)
>     11.0%  - java.lang.Thread.run
>    9.9%  - org.xwiki.query.internal.SecureQueryExecutorManager.execute
>   4.2%  - com.xpn.xwiki.store.hibernate.query.DefaultQueryExecutor.execute
> 12.0%  - org.apache.velocity.runtime.parser.node.SimpleNode.render
> 12.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
>  12.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
>   8.1%  -
> org.xwiki.rendering.internal.macro.velocity.VelocityMacro.evaluateString
>   4.3%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
> 9.2%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
> 8.5%  - com.xpn.xwiki.render.DefaultVelocityManager.getVelocityEngine
> 4.1%  - org.apache.velocity.runtime.parser.node.ASTBlock.render
> 4.1%  - com.xpn.xwiki.web.XWikiAction.execute
> 3.6%  -
> org.xwiki.rendering.internal.transformation.macro.MacroTransformation.transformOnce
> 3.2%  - org.apache.velocity.runtime.directive.Foreach.render
> 2.9%  -
> org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.docElements
> 2.8%  - com.xpn.xwiki.plugin.lucene.SearchResults.getRelevantResults
> 2.6%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
> 2.4%  - com.mysql.jdbc.PreparedStatement.executeQuery
> 2.4%  - org.xwiki.uiextension.internal.WikiUIExtension.getParameters
> 2.3%  - org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.line
>
> My understanding is that we spend 25% of time reading from the DB (this
> could be livetable related for instance). Around 50 in various velocity
> parts. Around 10% in the XWiki rendering and 3% in Lucene search. 2,4% in
> UI extensions (no visible rights, probably because running as Admin)
>
> Velocity is clearly quite expensive. Now I see particularly:
>
> 8.5%  - com.xpn.xwiki.render.DefaultVelocityManager.getVelocityEngine
>
> Would this mean we are spending 8,5% of the time getting the velocity
> engine to use ?

Yes, I had already noticed that. There's a synchronization done on that method that is probably costly. I'll look into it.

Thanks
-Vincent

> This sounds a lot.
>
> In any case this is food for thoughts for future optimizations.
>
> Ludovic
_______________________________________________
devs mailing list
[hidden email]
http://lists.xwiki.org/mailman/listinfo/devs
Reply | Threaded
Open this post in threaded view
|

Re: Testing some JVM Analysis Tool

Jean-Vincent Drean
In reply to this post by Ludovic Dubost
On Fri, Feb 8, 2013 at 1:15 AM, Ludovic Dubost <[hidden email]> wrote:
> In my previous test, the database was not very optimized. Here is the
> result with a more optimized mysql 5.1:

Could you elaborate on what you do to optimize the databse ?

JV.
_______________________________________________
devs mailing list
[hidden email]
http://lists.xwiki.org/mailman/listinfo/devs
Reply | Threaded
Open this post in threaded view
|

Re: Testing some JVM Analysis Tool

Ludovic Dubost
Some bigger settings for a few things.
The test is on innodb and I believe this setting is the most important:

innodb_buffer_pool_size=512M

But the cache size also might have an effect. I think it was either low or
turned off before.

key_buffer              = 32M
query_cache_limit       = 1M
query_cache_size        = 32M
query_cache_type        = 1
innodb_buffer_pool_size=512M
innodb_additional_mem_pool_size = 2M


We plan to do more testing to know exactly what is important.

Ludovic


2013/2/8 Jean-Vincent Drean <[hidden email]>

> On Fri, Feb 8, 2013 at 1:15 AM, Ludovic Dubost <[hidden email]> wrote:
> > In my previous test, the database was not very optimized. Here is the
> > result with a more optimized mysql 5.1:
>
> Could you elaborate on what you do to optimize the databse ?
>
> JV.
> _______________________________________________
> devs mailing list
> [hidden email]
> http://lists.xwiki.org/mailman/listinfo/devs
>



--
Ludovic Dubost
Founder and CEO
Blog: http://blog.ludovic.org/
XWiki: http://www.xwiki.com
Skype: ldubost GTalk: ldubost
_______________________________________________
devs mailing list
[hidden email]
http://lists.xwiki.org/mailman/listinfo/devs
Reply | Threaded
Open this post in threaded view
|

Re: Testing some JVM Analysis Tool

vmassol
Administrator
In reply to this post by vmassol

On Feb 8, 2013, at 9:46 AM, Vincent Massol <[hidden email]> wrote:

>
> On Feb 8, 2013, at 12:35 AM, Ludovic Dubost <[hidden email]> wrote:
>
>> Hi,
>>
>> I've been testing newrelic which has some interesting live JVM analysis.
>> I've been running the JVM Profiling while running a load test going on
>> various XWiki pages (except activity stream) including AWM, LiveTable
>> Searches, Content pages, Lucene search and loading ressources.
>>
>> Here is a result of the profiling:
>>
>> 25.0%  - java.net.SocketInputStream.socketRead0
>> 32 Collapsed methods (show)
>> 25.0%  - com.xpn.xwiki.store.hibernate.query.HqlQueryExecutor.execute
>>  21.0%  - org.xwiki.query.internal.DefaultQueryExecutorManager.execute
>>   11.0%  - org.xwiki.query.internal.DefaultQuery.execute
>>    127 Collapsed methods (show)
>>    11.0%  - java.lang.Thread.run
>>   9.9%  - org.xwiki.query.internal.SecureQueryExecutorManager.execute
>>  4.2%  - com.xpn.xwiki.store.hibernate.query.DefaultQueryExecutor.execute
>> 12.0%  - org.apache.velocity.runtime.parser.node.SimpleNode.render
>> 12.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
>> 12.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
>>  8.1%  -
>> org.xwiki.rendering.internal.macro.velocity.VelocityMacro.evaluateString
>>  4.3%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
>> 9.2%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
>> 8.5%  - com.xpn.xwiki.render.DefaultVelocityManager.getVelocityEngine
>> 4.1%  - org.apache.velocity.runtime.parser.node.ASTBlock.render
>> 4.1%  - com.xpn.xwiki.web.XWikiAction.execute
>> 3.6%  -
>> org.xwiki.rendering.internal.transformation.macro.MacroTransformation.transformOnce
>> 3.2%  - org.apache.velocity.runtime.directive.Foreach.render
>> 2.9%  -
>> org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.docElements
>> 2.8%  - com.xpn.xwiki.plugin.lucene.SearchResults.getRelevantResults
>> 2.6%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
>> 2.4%  - com.mysql.jdbc.PreparedStatement.executeQuery
>> 2.4%  - org.xwiki.uiextension.internal.WikiUIExtension.getParameters
>> 2.3%  - org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.line
>>
>> My understanding is that we spend 25% of time reading from the DB (this
>> could be livetable related for instance). Around 50 in various velocity
>> parts. Around 10% in the XWiki rendering and 3% in Lucene search. 2,4% in
>> UI extensions (no visible rights, probably because running as Admin)
>>
>> Velocity is clearly quite expensive. Now I see particularly:
>>
>> 8.5%  - com.xpn.xwiki.render.DefaultVelocityManager.getVelocityEngine
>>
>> Would this mean we are spending 8,5% of the time getting the velocity
>> engine to use ?
>
> Yes, I had already noticed that. There's a synchronization done on that method that is probably costly. I'll look into it.

I've created and implemented http://jira.xwiki.org/browse/XWIKI-8801

Would be great if you could retest with it.

Thanks
-Vincent

> Thanks
> -Vincent
>
>> This sounds a lot.
>>
>> In any case this is food for thoughts for future optimizations.
>>
>> Ludovic

_______________________________________________
devs mailing list
[hidden email]
http://lists.xwiki.org/mailman/listinfo/devs
Reply | Threaded
Open this post in threaded view
|

Re: Testing some JVM Analysis Tool

Ludovic Dubost
Hi,

Looks like Vincent's changes have had some effect on the profiling.
However on my test results in terms of average request performance it has
not changed too much.
I think it's because it's a "light" contention that makes some requests
wait
but in the end while there is wait the CPU of the machine is still used for
serious stuff.
But anyway it's always good to get rid of a contention point.

I will publish the first results of the load test on xwiki.org so that we
can check which part (XWiki pages) of XWiki requires some performance work.

The profiling results are interesting as then can show which internals
would require some work.

Before velocity change:
Wall clock time:
13.0%  - java.net.SocketInputStream.socketRead0
 30 Collapsed methods (show)
  13.0%  - com.xpn.xwiki.store.XWikiCacheStore.search
   9.2%  -
com.xpn.xwiki.plugin.activitystream.impl.ActivityStreamImpl.searchDailyPages
   3.7%  -
com.xpn.xwiki.plugin.activitystream.impl.ActivityStreamImpl.searchEvents
10.0%  - org.apache.velocity.runtime.parser.node.ASTBlock.render
  3.9%  - org.apache.velocity.runtime.parser.node.ASTIfStatement.render
  2.8%  - org.apache.velocity.runtime.directive.VelocimacroProxy.render
  2.7%  - org.apache.velocity.runtime.directive.Foreach.render
9.6%  - com.xpn.xwiki.render.DefaultVelocityManager.getVelocityEngine
  3 Collapsed methods (show)
   9.6%  - java.util.Arrays.mergeSort
    5.0%  - java.util.Arrays.mergeSort
    4.6%  - java.util.Arrays.sort
7.0%  - org.apache.velocity.runtime.parser.node.SimpleNode.render
6.9%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
3.9%  - com.xpn.xwiki.store.XWikiHibernateStore.search
3.8%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
3.6%  -
org.xwiki.rendering.internal.transformation.macro.MacroTransformation.transformOnce
3.5%  - com.xpn.xwiki.web.XWikiAction.execute
3.4%  - org.apache.velocity.runtime.parser.node.ASTMethod.execute
3.3%  - org.apache.velocity.runtime.directive.Foreach.render
3.3%  - org.hibernate.loader.Loader.doQuery
2.9%  - com.mysql.jdbc.MysqlIO.sendCommand
2.9%  - org.hibernate.transaction.JDBCTransaction.rollback
2.8%  - org.apache.velocity.runtime.parser.node.ASTExpression.value
2.7%  -
org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.docElements
2.4%  - sun.reflect.DelegatingMethodAccessorImpl.invoke
2.2%  - org.xwiki.uiextension.internal.WikiUIExtension.getParameters

CPU Burn:
15.0%  - org.apache.velocity.runtime.parser.node.ASTBlock.render:72
15.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate:187
 11.0%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate:105
  15 Collapsed methods (show)
   11.0%  - org.apache.velocity.runtime.parser.node.ASTDirective.render:207
    5.5%  - org.apache.velocity.runtime.parser.node.ASTBlock.render:72
    5.1%  - org.apache.velocity.runtime.parser.node.SimpleNode.render:342
 4.5%  -
org.xwiki.rendering.internal.macro.velocity.VelocityMacro.evaluateString:124
8.4%  - org.apache.velocity.runtime.parser.node.SimpleNode.render:342
6.3%  -
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections:274
5.9%  -
org.xwiki.uiextension.internal.filter.SortByParameterFilter$UIExtensionParameterComparator.compare:52
5.2%  -
org.xwiki.rendering.internal.transformation.macro.MacroTransformation.transformOnce:185
4.2%  - org.apache.velocity.runtime.parser.node.ASTDirective.render:207
3.9%  - sun.reflect.DelegatingMethodAccessorImpl.invoke:25
3.5%  - org.apache.velocity.runtime.parser.node.ASTExpression.value:71
2.9%  -
org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.doParse:216
2.5%  - org.hibernate.loader.Loader.doQuery:829
2.4%  - com.xpn.xwiki.web.XWikiAction.execute:116
2.4%  - java.util.Arrays.sort:1210
2.3%  - com.xpn.xwiki.web.XWikiAction.execute:231
2.1%  - org.xwiki.rendering.macro.script.AbstractScriptMacro.execute:198
2.1%  -
org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.paragraph:891
2.1%  - org.apache.velocity.runtime.parser.node.ASTReference.execute:280

After velocity change
Wall clock time
23.0%  - java.net.SocketInputStream.socketRead0
 30 Collapsed methods (show)
  23.0%  - com.xpn.xwiki.store.XWikiCacheStore.search
   16.0%  -
com.xpn.xwiki.plugin.activitystream.impl.ActivityStreamImpl.searchDailyPages
    33 Collapsed methods (show)
     16.0%  - org.xwiki.display.internal.DocumentContentDisplayer.display
      11.0%  -
org.xwiki.display.internal.DocumentContentDisplayer.displayInIsolatedExecutionContext
       108 Collapsed methods (show)
       11.0%  - java.lang.Thread.run
      5.4%  - org.xwiki.display.internal.DocumentContentDisplayer.display
   7.4%  -
com.xpn.xwiki.plugin.activitystream.impl.ActivityStreamImpl.searchEvents
13.0%  - org.apache.velocity.runtime.parser.node.ASTBlock.render
  7.0%  - org.apache.velocity.runtime.parser.node.ASTIfStatement.render
  3.0%  - org.apache.velocity.runtime.directive.Foreach.render
7.6%  - org.apache.velocity.runtime.parser.node.SimpleNode.render
5.4%  - org.hibernate.transaction.JDBCTransaction.rollback
4.5%  - org.xwiki.uiextension.internal.WikiUIExtension.getParameters
4.3%  - org.apache.velocity.runtime.parser.node.ASTMethod.execute
4.2%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
3.7%  -
org.xwiki.rendering.internal.transformation.macro.MacroTransformation.transformOnce
3.6%  - org.hibernate.loader.Loader.doQuery
3.2%  - com.xpn.xwiki.store.XWikiHibernateStore.search
3.2%  - com.xpn.xwiki.web.XWikiAction.execute
3.0%  -
org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.docElements
2.9%  - com.xpn.xwiki.web.Utils.parseTemplate
2.8%  - org.apache.velocity.runtime.parser.node.ASTExpression.value
2.1%  - sun.reflect.DelegatingMethodAccessorImpl.invoke


CPU Burn
14.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate:187
 11.0%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate:105
  15 Collapsed methods (show)
   11.0%  - org.apache.velocity.runtime.parser.node.ASTDirective.render:207
    5.5%  - org.apache.velocity.runtime.parser.node.ASTBlock.render:72
    5.0%  - org.apache.velocity.runtime.parser.node.SimpleNode.render:342
 3.1%  -
org.xwiki.rendering.internal.macro.velocity.VelocityMacro.evaluateString:124
12.0%  - org.apache.velocity.runtime.parser.node.ASTBlock.render:72
8.4%  - org.apache.velocity.runtime.parser.node.SimpleNode.render:342
6.5%  -
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections:274
4.9%  - org.apache.velocity.runtime.parser.node.ASTDirective.render:207
4.5%  - org.apache.velocity.runtime.parser.node.ASTReference.execute:280
4.4%  - java.util.Arrays.sort:1210
4.3%  - org.apache.velocity.runtime.parser.node.ASTExpression.value:71
4.2%  - org.xwiki.rendering.macro.script.AbstractScriptMacro.execute:198
3.2%  -
org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.doParse:216
3.2%  -
org.xwiki.rendering.internal.transformation.macro.MacroTransformation.transformOnce:185
3.1%  -
org.xwiki.uiextension.internal.filter.SortByParameterFilter$UIExtensionParameterComparator.compare:52
2.8%  - com.xpn.xwiki.web.XWikiAction.execute:231
2.6%  - org.hibernate.loader.Loader.doQuery:829
2.3%  - org.xwiki.rendering.internal.macro.html.HTMLMacro.cleanHTML:180
2.1%  -
org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.paragraph:891
2.0%  - sun.reflect.GeneratedMethodAccessor196.invoke


Ludovic


2013/2/9 Vincent Massol <[hidden email]>

>
> On Feb 8, 2013, at 9:46 AM, Vincent Massol <[hidden email]> wrote:
>
> >
> > On Feb 8, 2013, at 12:35 AM, Ludovic Dubost <[hidden email]> wrote:
> >
> >> Hi,
> >>
> >> I've been testing newrelic which has some interesting live JVM analysis.
> >> I've been running the JVM Profiling while running a load test going on
> >> various XWiki pages (except activity stream) including AWM, LiveTable
> >> Searches, Content pages, Lucene search and loading ressources.
> >>
> >> Here is a result of the profiling:
> >>
> >> 25.0%  - java.net.SocketInputStream.socketRead0
> >> 32 Collapsed methods (show)
> >> 25.0%  - com.xpn.xwiki.store.hibernate.query.HqlQueryExecutor.execute
> >>  21.0%  - org.xwiki.query.internal.DefaultQueryExecutorManager.execute
> >>   11.0%  - org.xwiki.query.internal.DefaultQuery.execute
> >>    127 Collapsed methods (show)
> >>    11.0%  - java.lang.Thread.run
> >>   9.9%  - org.xwiki.query.internal.SecureQueryExecutorManager.execute
> >>  4.2%  -
> com.xpn.xwiki.store.hibernate.query.DefaultQueryExecutor.execute
> >> 12.0%  - org.apache.velocity.runtime.parser.node.SimpleNode.render
> >> 12.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
> >> 12.0%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
> >>  8.1%  -
> >> org.xwiki.rendering.internal.macro.velocity.VelocityMacro.evaluateString
> >>  4.3%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
> >> 9.2%  - org.xwiki.velocity.internal.DefaultVelocityEngine.evaluate
> >> 8.5%  - com.xpn.xwiki.render.DefaultVelocityManager.getVelocityEngine
> >> 4.1%  - org.apache.velocity.runtime.parser.node.ASTBlock.render
> >> 4.1%  - com.xpn.xwiki.web.XWikiAction.execute
> >> 3.6%  -
> >>
> org.xwiki.rendering.internal.transformation.macro.MacroTransformation.transformOnce
> >> 3.2%  - org.apache.velocity.runtime.directive.Foreach.render
> >> 2.9%  -
> >>
> org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.docElements
> >> 2.8%  - com.xpn.xwiki.plugin.lucene.SearchResults.getRelevantResults
> >> 2.6%  - com.xpn.xwiki.render.XWikiVelocityRenderer.evaluate
> >> 2.4%  - com.mysql.jdbc.PreparedStatement.executeQuery
> >> 2.4%  - org.xwiki.uiextension.internal.WikiUIExtension.getParameters
> >> 2.3%  -
> org.xwiki.rendering.wikimodel.xwiki.xwiki21.javacc.XWikiScanner.line
> >>
> >> My understanding is that we spend 25% of time reading from the DB (this
> >> could be livetable related for instance). Around 50 in various velocity
> >> parts. Around 10% in the XWiki rendering and 3% in Lucene search. 2,4%
> in
> >> UI extensions (no visible rights, probably because running as Admin)
> >>
> >> Velocity is clearly quite expensive. Now I see particularly:
> >>
> >> 8.5%  - com.xpn.xwiki.render.DefaultVelocityManager.getVelocityEngine
> >>
> >> Would this mean we are spending 8,5% of the time getting the velocity
> >> engine to use ?
> >
> > Yes, I had already noticed that. There's a synchronization done on that
> method that is probably costly. I'll look into it.
>
> I've created and implemented http://jira.xwiki.org/browse/XWIKI-8801
>
> Would be great if you could retest with it.
>
> Thanks
> -Vincent
>
> > Thanks
> > -Vincent
> >
> >> This sounds a lot.
> >>
> >> In any case this is food for thoughts for future optimizations.
> >>
> >> Ludovic
>
> _______________________________________________
> devs mailing list
> [hidden email]
> http://lists.xwiki.org/mailman/listinfo/devs
>



--
Ludovic Dubost
Founder and CEO
Blog: http://blog.ludovic.org/
XWiki: http://www.xwiki.com
Skype: ldubost GTalk: ldubost
_______________________________________________
devs mailing list
[hidden email]
http://lists.xwiki.org/mailman/listinfo/devs