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