[xwiki-devs] Testing some JVM Analysis Tool
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
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 <[email protected]>
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
On Fri, Feb 8, 2013 at 1:15 AM, Ludovic Dubost <[email protected]> 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.
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 <[email protected]>
On Fri, Feb 8, 2013 at 1:15 AM, Ludovic Dubost <[email protected]> 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 [email protected] 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
On Feb 8, 2013, at 12:35 AM, Ludovic Dubost <[email protected]> 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
On Feb 8, 2013, at 9:46 AM, Vincent Massol <[email protected]> wrote:
On Feb 8, 2013, at 12:35 AM, Ludovic Dubost <[email protected]> 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
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 <[email protected]>
On Feb 8, 2013, at 9:46 AM, Vincent Massol <[email protected]> wrote:
On Feb 8, 2013, at 12:35 AM, Ludovic Dubost <[email protected]> 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 [email protected] 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
participants (3)
-
Jean-Vincent Drean -
Ludovic Dubost -
Vincent Massol