Profiling

Version 3.1 by Vincent Massol on 2011/01/13 14:29

Profiling is useful to find out performance bottlenecks and find out memory hogs. There are 2 types of tools that can be easily used to profile XWiki.

Profiling using a Profiler

The best tool for the job is of course a profiler. Follow the steps:

For XWiki committers, we have free YourKit Licenses for developing on XWiki.

  • Build XWiki or simply download a XWiki binary release
  • Check your profiler's documentation to see the command line that needs to be added when starting the XWiki JVM. For example for YourKit, add the following to the xwiki_start_debug.sh script and replace with the location of YourKit on your system (these commands are actually already there so you can simply uncomment them):
JAVA_OPTS="$JAVA_OPTS -agentpath:/path/to/YourKit/linux-x86-64/libyjpagent.so"
  • Run the Profile and then start XWiki

Profiling using XWiki's Debugging Aspect

This is a poor man's profiler but it's very easy to use and useful in some cases where using a proper profiler is not an option (like when you have a novice user having a problem you cannot reproduce on your machine and you need to get information from running XWiki on his machine). Follow these steps:

  • Build XWiki using the debug profile. For example for XE, run mvn clean install -Pdebug,xe from the top level. This will make the xwiki-core module apply an AspectJ aspect to the whole core code. This Aspect logs all methods calls.
  • Before you run the generated distribution, you'll want to create a log4j.properties file in WEB-INF/classes so that it overrides the default one in XWiki's JAR and so that you tell the AspectJ aspect to only log some portion of the code. If you don't do that you'll get overwhelmed by all the logging and performances will drop severely. For example, to only log methods in XWikiAction and in the renderer classes, you'd write something like:
### Direct log messages to stdout
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} [%t] %-5p %-30.30c{2} %x - %m %n

log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.File=xwiki.log
log4j.appender.file.MaxFileSize=10MB
log4j.appender.file.MaxBackupIndex=50
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%d{ABSOLUTE} [%t] %-5p %-30.30c{2} %x - %m %n

### By default everything that is of warning or severity WARN, ERROR or FATAL is logged both to
### the console and to the xwiki.log file.
log4j.rootLogger=warn, stdout, file

### Hibernate logging options
log4j.logger.org.hibernate=warn
log4j.logger.org.hibernate.SQL=warn
log4j.logger.org.hibernate.type=warn
log4j.logger.org.hibernate.ps.PreparedStatementCache=warn

### XWiki logging configuration
log4j.logger.com.xpn.xwiki=warn
log4j.logger.com.xpn.xwiki.render.XWikiRadeoxRenderEngine=warn

### Deactive Radeox warnings
log4j.logger.org.radeox.macro.BaseLocaleMacro=error

### Deactive Struts warnings
log4j.logger.org.apache.struts.util.RequestUtils=error

### Deactivate JGroups warnings
log4j.logger.org.jgroups=error

## Deactive PDF Export CSS Applier warnings
log4j.logger.info.informatica.doc.style.css.dom=error
log4j.logger.org.apache.fop.layoutmgr.inline.ContentLayoutManager=error

## Log only some classes in the AspectJ aspect
log4j.logger.com.xpn.xwiki.XWikiAction=debug
log4j.logger.com.xpn.xwiki.render.DefaultXWikiRenderingEngine=debug
log4j.logger.com.xpn.xwiki.render.XWikiRadeoxRenderer=debug
log4j.logger.com.xpn.xwiki.render.XWikiWikiBaseRenderer=debug
log4j.logger.com.xpn.xwiki.render.XWikiVelocityRenderer=debug
log4j.logger.com.xpn.xwiki.render.XWikiMacrosMappingRenderer=debug
  • Then you need to configure the AspectJ aspect. This is done by passing system properties to the JVM that starts XWiki. If you're using the provided start_xwiki.sh script, modify it such as follows:
...
java %JAVA_OPTS% -Ddebug.active=true -Ddebug.minTime=100 -Ddebug.showDetails=false -Dfile.encoding=iso-8859-1 -Djetty.home=%JETTY_HOME% -Djetty.port=%JETTY_PORT% -jar %JETTY_HOME%/start.jar

The 3 system properties of interest are:

  • debug.active: Whether debugging is on or not. By default it's false and no logging is done by the AspectJ aspect
  • debug.minTime: Only logs methods that take longer than this value. Defaults to 100ms. 
  • debug.showDetails: If true then logs parameter values and method return values. Defaults is false.

Here's for example what you'll get with the values defined above:

14:27:10,685 [P1-16] DEBUG render.XWikiVelocityRenderer    - 386      evaluate
14:27:10,685 [P1-16] DEBUG render.XWikiVelocityRenderer    - 386     evaluate
14:27:10,948 [P1-16] DEBUG render.XWikiVelocityRenderer    - 411      evaluate
14:27:10,948 [P1-16] DEBUG render.XWikiVelocityRenderer    - 411     evaluate
14:27:11,116 [P1-16] DEBUG render.XWikiVelocityRenderer    - 348      evaluate
14:27:11,116 [P1-16] DEBUG render.XWikiVelocityRenderer    - 348     evaluate
14:27:11,631 [P1-16] DEBUG render.XWikiVelocityRenderer    - 694      evaluate
14:27:11,631 [P1-16] DEBUG render.XWikiVelocityRenderer    - 694     evaluate
14:27:11,631 [P1-16] DEBUG render.XWikiVelocityRenderer    - 1337    evaluate
14:27:11,631 [P1-16] DEBUG render.XWikiVelocityRenderer    - 1337   evaluate
14:27:11,801 [P1-16] DEBUG render.XWikiRadeoxRenderer      - 307        render
14:27:11,808 [P1-16] DEBUG er.DefaultXWikiRenderingEngine  - 356       renderText
14:27:11,808 [P1-16] DEBUG er.DefaultXWikiRenderingEngine  - 356      renderText
14:27:11,809 [P1-16] DEBUG er.DefaultXWikiRenderingEngine  - 357     renderDocument
14:27:11,857 [P1-16] DEBUG render.XWikiVelocityRenderer    - 406    evaluate
14:27:11,857 [P1-16] DEBUG render.XWikiVelocityRenderer    - 406   evaluate
14:27:12,035 [P1-16] DEBUG render.XWikiVelocityRenderer    - 359    evaluate
14:27:12,036 [P1-16] DEBUG render.XWikiVelocityRenderer    - 360   evaluate
14:27:12,154 [P1-16] DEBUG er.DefaultXWikiRenderingEngine  - 286        renderText
14:27:12,154 [P1-16] DEBUG er.DefaultXWikiRenderingEngine  - 286       renderText
14:27:12,416 [P1-16] DEBUG render.XWikiRadeoxRenderer      - 352         render
14:27:12,425 [P1-16] DEBUG er.DefaultXWikiRenderingEngine  - 449        renderText
14:27:12,426 [P1-16] DEBUG er.DefaultXWikiRenderingEngine  - 450       renderText
14:27:12,654 [P1-16] DEBUG render.XWikiVelocityRenderer    - 393           evaluate
14:27:12,654 [P1-16] DEBUG render.XWikiVelocityRenderer    - 393          evaluate
14:27:12,655 [P1-16] DEBUG render.XWikiVelocityRenderer    - 393         render
14:27:12,698 [P1-16] DEBUG er.DefaultXWikiRenderingEngine  - 452        renderText
14:27:12,698 [P1-16] DEBUG er.DefaultXWikiRenderingEngine  - 452       renderText
14:27:12,805 [P1-16] DEBUG render.XWikiVelocityRenderer    - 944      evaluate
14:27:12,805 [P1-16] DEBUG render.XWikiVelocityRenderer    - 944     evaluate
14:27:12,866 [P1-16] DEBUG render.XWikiVelocityRenderer    - 1011    evaluate
14:27:12,866 [P1-16] DEBUG render.XWikiVelocityRenderer    - 1011   evaluate
14:27:12,866 [P1-16] DEBUG render.XWikiVelocityRenderer    - 2579  evaluate
14:27:12,867 [P1-16] DEBUG render.XWikiVelocityRenderer    - 2580 evaluate
14:27:13,651 [P1-16] DEBUG er.DefaultXWikiRenderingEngine  - 318 interpretText
14:27:13,885 [P1-16] DEBUG er.DefaultXWikiRenderingEngine  - 287 interpretText
14:27:14,051 [P1-17] DEBUG er.DefaultXWikiRenderingEngine  - 302  interpretText
14:27:14,392 [P1-16] DEBUG er.DefaultXWikiRenderingEngine  - 342  interpretText

About

About

Support

Platform

User Guide

Admin Guide

Developer Guide

Projects

XWiki

Extensions

Other

Contribute

Status

Practices

Under the Hood

Get Involved

Get Connected