8 Feb
2013
8 Feb
'13
12:35 a.m.
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
8 Feb
8 Feb
1:15 a.m.
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 <ludovic(a)xwiki.com>
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
12:57 p.m.
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 <jv(a)xwiki.com>
On Fri, Feb 8, 2013 at 1:15 AM, Ludovic Dubost
<ludovic(a)xwiki.com> wrote:
--
Ludovic Dubost
Founder and CEO
Blog: http://blog.ludovic.org/
XWiki: http://www.xwiki.com
Skype: ldubost GTalk: ldubost
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
devs(a)xwiki.org
http://lists.xwiki.org/mailman/listinfo/devs
9:46 a.m.
On Feb 8, 2013, at 12:35 AM, Ludovic Dubost <ludovic(a)xwiki.com> 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
9 Feb
9 Feb
10 a.m.
On Feb 8, 2013, at 9:46 AM, Vincent Massol <vincent(a)massol.net> wrote:
On Feb 8, 2013, at 12:35 AM, Ludovic Dubost <ludovic(a)xwiki.com> wrote:
I've created and implemented http://jira.xwiki.org/browse/XWIKI-8801
Would be great if you could retest with it.
Thanks
-Vincent
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
11 Feb
11 Feb
10:15 p.m.
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 <vincent(a)massol.net>
On Feb 8, 2013, at 9:46 AM, Vincent Massol <vincent(a)massol.net> wrote:
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
--
Ludovic Dubost
Founder and CEO
Blog: http://blog.ludovic.org/
XWiki: http://www.xwiki.com
Skype: ldubost GTalk: ldubost
On Feb 8, 2013, at 12:35 AM, Ludovic Dubost <ludovic(a)xwiki.com> 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 Thanks
-Vincent
> This sounds a lot.
>
> In any case this is food for thoughts for future optimizations.
>
> Ludovic
_______________________________________________
devs mailing list
devs(a)xwiki.org
http://lists.xwiki.org/mailman/listinfo/devs
4331
days inactive
4335
days old
6 comments
3 participants
participants (3)
-
Jean-Vincent Drean -
Ludovic Dubost -
Vincent Massol