The quest for the Java Portal - Profiling Liferay

It's time to run the Profiler. I start JBoss with "run-nbprofiler.bat" (created by NetBeans) and ask NB to attach profiler. I'm using "analyze performance", filtering Java core classes. JBoss runs very slow, but this is normal, since profiler is collecting execution of every method.

My first try showed that Lucene is called a lot of times, even when server is on "idle" state. Maybe it is a background job that should have a smaller frequency.

The second try filters out Lucene classes (using NB Profiler options). I found two bootlenecks: com.liferay.portal.lucene.IndexWriterFactory.decrement (takes 58% of startup time) and JBoss classloaders. And I found that Liferay auto deploy is running too often (~5 seconds of delay). Nice for develoment, awful for production use.

I had to remove JBoss classes from profiling, and I got amazed on things I discovered. I got a OutOfMemoryError (perm gen space) - solved by adding "-XX:MaxPermSize=256m" to run script - but I could find a lot of interesting things:

1. getResourceAsStream was called 12068 times;
2. Xerces' ChildNode was instantiated 853808 times (does anybody imagine why Java is "slow"?);
3. Stacktrace got really deep. About 50 levels or more, not including JBoss, Lucene and JDK classes;
   
4. A chain of 7 filters was called before hitting Liferay's MainServlet. If you consider a little forward made after MainServlet, we reach 14 filters before hitting a JSP file;
5. JSP compilation took 19s on this environment - total execution was 180s;
6. LR's VelocityTaglib has 8 iconXXX() methods that took 8 seconds each - detail: each one forwards another request;
7. Everytime a "include" is made, the chain of 7 filter is called. And there's a LOT of includes.
   

Remember that this was only ONE hit and the request wasn't complete, because of the OOM error. After that, I'm going to have some fun in the "real world". I'll try to go deeper tomorrow. Maybe I can send a RFE to Liferay team after I organize the arguments.