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