Monday, August 18, 2008

Project is finished! Let's start bug fixing session =) ?

As JIP profiler doesn't provide memory analyzings, I made a decision to search for another one. I decided to use profiler4j (http://profiler4j.sourceforge.net/) because it is very similar to JIP profiler (pure java, hooks the classloader, "on the fly" connection), but also has memory analyzing tool. The tool doesn't provide the full information about objects in the heap, but draws intelligible plot about memory consumption. The minus of the project is that it is only on beta stage and can contain bugs (I fixied one about comparing method results while integrating it).

Another candidate for integration was TIJmp (http://www.khelekore.org/jmp/tijmp/) profiler, this one is using new native profiling library JVMTI, and seems to be more efficient than previous versions on JVMPI, but I didn't find there any ability to get timings, so I used profiler4j for integrated profiler.

I want to say that my project was to get bundle separated results for timings and memory. Timings are ok, I can filter the invoked methods by package and then display the results. But with memory I cannot get such results. Moreover all the profilers I used hadn't the ability to get the representation of objects allocation in heap from an invoked method. Only profiler where you can get similar info was netbeans profiler (http://www.netbeans.org/kb/60/java/profiler-intro.html), it uses SUN's JFluid technology which is experemental and not opened. So the function is needed to be researched and developed, may be it could be a good topic for a Master Thesis. So I used a plot to represent graphically the memory allocation which is also very helpful I think.

I also decided to use in plugin thread profiling, call graph allocation and class filtering options, because they don't slow significantly SC work and are provided by the profiler4j.

Plugin Tutorial

1.Make a new project from performance branch.

2.Assert you use JVM 1.5.0_04+

3.Start SC with ant tasks rebuild, run-with-profiler. SC will be started with the profiler's agent which hooks the classloader and listens on port 7890 for profiler's plugin connection establishment.

4.Profiler plugin is placed into Tools menu -> profiler4j


5. Then the console will establish the connection with the agent and load up filtered classes. In our case that will be all the classes in package net.java.sip.communicator.plugin only exlusion will be package net.java.sip.communicator.plugin.profiler4j because it's a sin ;-) to profile the profiler.




6. Plug-in's window will appear after the connection.



7. I modified a little bit the example plugin, I added there a button and the button's action listener where I make the thread sleep for 3000 millis. Then I click the test button, go to the profiler's window and click on the snapshot icon (camera) and there goes the results of call tree. The results are bundle separated, we can profile other budles, take snapshot and see the timings. The algorithm for profiling is quite simple: you make actions on the bundle(s) and then take a snapshot. It is also possible to resent timing by clicking on "Reset counters" button.





8. We can also see the detailed method invocations using call graph tab.





9. Memory Tab represents graphical plots for heap and non-heap memory consumption, the plots are uptated every second. We can also run the garbage collector (GC) by clicking on GC button.




10. On Threads tab we can get information about threads, the information is needed to be refreshed manually (refresh button). The displaying information is not bundle separated, it is about all the threads in the SC






11. Class list tab provides you inforamtion about all the classes in classloader. The tab is handy when you want to apply filters on packages.




12. Filters can be applied in Profiling Project Details window. The filter is invoked by clicking on "edit profiling project details" button (a pencil).




13. In help menu you can see some tips about using the profiler.





14. Also you can find there some information about the profiler ;)



In conclusion I would like to thank my mentors, profiler4j developer Antonio S. R. Gomes and other developers for their advices and help. I hope the plug-in will be useful for the SC developers.

Sunday, July 27, 2008

Profiler Integration

I've run the profiler plugin with jmemprof support, but it has some disadvantages:
  • Doesn't have timings support
  • Doesn't run on j2se 6+
  • The profiler haven't been updated since year 2005
  • SC starts working very slowly with it, about 5 times slower than usual.
But I found another profiler that supports timings and is more agile than other profilers - JIP, you can find information how the profiler is build in the article "Build your own profiling tool" by the project's author Andrew Wilcox.

I tried JIP with SC and got the next results:

Pluses:
  • Has timings support
  • Runs on j2se 5+, the profiler needs the version 5 too hook the classloader.
  • SC is working almost as fast as usually.
  • It outputs the results in txt and xml formats
  • Has GUI for the results




Minuses:

  • It doesn't support memory analyzing
  • The results can be reprsented in GUI only by using the xml file with the results as an input.
  • You need to siwtch off and on the profiler to update the results (may be there is any other possibility)
  • The updated results don't contain previous ones after profiler stop/start issues (so called updates)

Next steps:

  • Now the profiler gives mostly the timings of OSGI framework, I'll need SC ones.
  • Try to get bundle separated results by package filtering.

Monday, July 21, 2008

New objectives

We have decided to change the objectives of my GSOC project by adding an integrated mem/cpu profiler for sip-communicator to give bundle dependent results.
The profiler will be used as a plugin for SC and print out UI such information:

bundle1: CPU 50% Mem 510kb
bundle2: CPU 12% Mem 120kb
bundle3: CPU 0.1% Mem 12kb

Also here can be added an information about a bundle loading time.

What is done:
- Java code is changed to suit the new version of SC

I am doing right now:
- integration with jmemprof, actually compile jmemprof for windows, it seems that jdk 6 doesn't have needed includes (jvmpi was depricated), so I now trying old versions of java, to get it compiled

Next steps:
- get bundle separated profiling information

The results of the first part of profiling SC

The found problems from user perspective were:
1. slow sip-communicator loading
2. graphics slow loading
3. large chat history slow processing

The starting up of the sip-communicator is slow enough, it takes about 10 - 15 seconds. SC uses apache felix for loading up the bundles, it takes up to 330 milliseconds for every bundle to start up. Other time for starting up is going to the drawing swing/awt components and loading up images. When profiling the functionality I just see Felix and JDK methods invocations, it is up profiling JDK and Felix, their methods are time-consumptive.Very similar situation was with big chat history slow processing.

The slowest part is the text parsing with javax.swing.text.html.HTMLFactory (see net.java.sip.communicator.impl.gui.utils.SIPCommHTMLEditorKit's inner class HTMLFactoryX).
There are two ways for eliminating the problem:
- wait for updated and more optimized java version
- to profile jdk
- to use other technology for text formating

Then I just monitored the sip-communicator with a profile to search for anomalies (took the 10 most expensive methods). I found that processSmilies() method from ChattConversationPanel class class is also consumpitve with big texts, thist uses regular expressions for smilies finding and the regular expression is very complex for it.

I noticed that net.java.sip.communicator.util.ScLogFormatter is also time-consumptive, it takes about 2-3% of sip-communicator execution. The problems are format(LogRecord record) and inferCaller(LogRecord record) methods. First is using DecimalFormat for formatting is required time to process and also sending the messages to the output. The second is using StackTraceElement objects and processings, that are time consumptive.
These methods are made with help of JDK and those are not very effective.There are Thread.sleep's in sip-comm code which are look like performance problems in profiler (look in net.java.sip.communicator.plugin.statusupdate.StatusUpdateActivator or just search for .sleep in sip-comm's source, you will found some), is the value of the sleeping time correct ?
There are minor time problems that are also connected with libraries that are slow.

Notes for developers.
What I can suggest to community is to continue adhere design patterns. Also quite effective is not to return a new created object, but reuse an already existing one - a creation of an object take more time and makes the heap larger. Of course it is not often possible, for example in net.java.sip.communicator.impl.gui.utils.SIPCommHTMLEditorKit inner class HTMLFactoryX.

static class HTMLFactoryX extends HTMLFactory
implements ViewFactory {
public View create(Element elem) {
View v = super.create(elem);
if(v instanceof ImageView){
return new SIPCommImageView(elem);
} else if (v instanceof ParagraphView) {
return new ParagraphViewX(elem);
}
return v;
}
}

Namely View is created by create(Element element) method from javax.swing.text.html.HTMLFactory class, the Element object is necessary for the new instance of view, and there is no possible to clean up and return existing View class. But if we see the createDefaultDocument() in c class, we see that HTMLDocument doc variable can be reused - there is no in parameter for the object:

public Document createDefaultDocument() {
if(doc != null) return doc;
StyleSheet styles = getStyleSheet();
StyleSheet ss = new StyleSheet();
ss.addStyleSheet(styles);
doc = new HTMLDocument(ss);
doc.setParser(getParser());
doc.setAsynchronousLoadPriority(4);
doc.setTokenThreshold(100);
return doc;
}

Also I reused the creation of new SIPCommHTMLEditorKit classes in ChatConversationPanel. Actually the fix is not very helpful, because the method createDefaultDocument() is called only once from ChatConversationPanel but the same logic you can use in your projects.

Next Steps for SC profiling:
1. Profile and fix increasing threads problem
2. Look for memory leaks using different profilers

Sunday, June 15, 2008

GSOCing

During the profiling SC I understood that some profilers needs to be profiled ant optimized. For example TPTP profiler is helpful but slow (IMHO) and my laptop sounds like a jet on a take off when profiling.


TPTP allows to see the execution statistics and when some action is made it markes the methods that became work slower.
JProfiler offers to freeze the previous state and the compare it graphically with a new one. This approach is more snappy.
Current Status:
I am optimizing the known issues and still looking for anomalies.
Next Steps:
Optimize the problem of a big chat history (that hangs up a chat window) and others. Prolong to discover anomalies.

Sunday, May 11, 2008

Hello again!

The weather in Estonia is excellent: sun is shining, trees are green and the sky is without the clouds. It means that the summer is very close!

I was a little bit busy this week, I am writing my bachelor thesis right now, the dealine is 29 of May, but I have good news about the gsoc project - now I can profile sip-communicator with
  1. hprof
  2. Eclipse TPTP project
  3. NetBeans
  4. JProfiler

All the profilers have own peculiar features concerning the configuration. General rule for profiling sip-communicator is to provide bundles implicit access to stuff on the class path in sip-comm\lib\felix.client.run.properties. This is obligatory because of OGSi architecture - you need to delegate a boot of profiler classes first. Only exclusion was NetBeans, it supports a dynamic profiler attachment for a running application (only with java6 +), but the use of direct invocation is also available.

So if you wish to use sip-communicator with a profiler listed before insert the next a definition in felix.client.run.properties:

  1. org.osgi.framework.bootdelegation=com.sun.demo.jvmti.hprof.* \
  2. org.osgi.framework.bootdelegation=org.eclipse.tptp.martini.* \
  3. org.osgi.framework.bootdelegation=org.netbeans.lib.profiler.server.* \
  4. org.osgi.framework.bootdelegation=com.jprofiler.agent.*\

If you use another profiler, you will see a missing package in the exception.

As netbeans uses ant for running the sip-communicator, I made an ant task for profiling it.

Next steps:

Read the profilers documentation, see the profiling tutorials (i.e. http://www.ej-technologies.com/products/jprofiler/tutorials.html), try to profile demo applications and sip-communicator - to get some profiling experience for a start.

P.S. Thanks to Thiago Bolaum for the help with working under TPTP. Your information was very essential.

Wednesday, April 30, 2008

First week

With a subscription on GSoC groups I receive now about 100 mails per a day, nice =) I have to spend about an hour to read all of them. Im waiting for a letter of acceptance from my university, then I can fax all the documents to google. And I have been acquainted with my mentor, Ben.

The week status:
The week was more about management and getting acquianted with the project, I spent an evening to start working with TPTP and agent controllers, but the work is still in progress.

Problems:
1. When I start ACServer and connecting to it with TPTP a don't see any informarion in ACServer's console. Even doing telnet localhost 10002 doesn't result any data in the server's console. Is it ok ?
2. Actually I don't really know what the agent controllers are needed for. I have to read about them in TPTP documantation.
3. I added in felix.client.run.properties a row:
org.osgi.framework.bootdelegation= org.eclipse.tptp.jvmti \
then the needed classes are found by eclipse. But when I starting the profiling there is only silence and it is impossible to get any visual inforamation.

Next week steps:
Prolong with administrational stuff and resolve the problems.