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 _______________________________________________ devs mailing list [email protected] http://lists.xwiki.org/mailman/listinfo/devs
