Isthmus Blog Live

Pura Vida Amigos!,
We at Isthmus are pleased to present you our Architecture blog. The idea here is to provide more value to our clients thru sharing technical information that can be useful for your projects, current or future. We will be sharing with you our experiences with the latest technologies including the good, the bad and the ugly, keeping of course the confidentiality related with each project and each client.
We invite you to challenge us with your thoughts, comments and questions to increase the knowledge base so we all gain.
Let’s create synergy!
Thank you,

Adolfo Cruz
Delivery Director

Wednesday, March 26, 2008

Java Profiling

Since NetBeans 6.0 profiler is no longer a plug-in; therefore, is bundle as a basic component in the Platform. What implications does this have to NB users? Well in practical terms: none. However despite de IDE we are using we should address the fact that writing Java code should go beyond simple typing it as it would be coming from a memory dump; from your head; this statement is even truer when it comes to complex business logic. In the other hand; take source code from a CRUD application using JPA it has not much to optimize; all control has been taken from our hands and given to the compiler and the JPA framework.

In most cases there will be no need no optimization for common database access applications; eventually we might face a challenge beyond annotating POJO classes. It will depend on the nature of the application and the complexity of the business logic at hand or probably you will have to locate the piece that has to be optimized first; there is where the profiling facilities come at hand; so let’s take a look into NetBeans profiling.

For matter of demo we will take one of the latest internal applications a Java Platform, Enterprise Edition called TestOnline currently at QA, the application architecture detailed in the following diagram is basically Isthmus standard architecture for Java Platform, Enterprise Edition applications.

Since we have the source code in a NetBeans’ project we can profile the application easily; however, any Java application can be profiled using NetBeans’ integrated profiler, so first we show how to profile the current project, then how to enable it for a previously compiled application.

From the Profile menu we select the Profile Main Project menu option as shown in the following image:

After selecting this option the profiler will ask for confirmation since it has to modify the build script to enable profiling, so we click ok in the dialog shown in the following image:

Thereafter NetBeans modified the build script, lets see what were the changes it did to our build file, this is very simple since the file is versioned under a SVN repository. The change made to NetBeans build.xml is very simple it includes a newly created file called profiler-build-impl.xml this new file simply adds some information to run the Application Server with the extra parameters required to the profiler to be able to gather information, the parameter is the same we will manually add later to profile any precompiled application.

Now everything is almost set to start profiling our application; although, before we start the information recorded by the profiler can be customize for us to analyze later, the window opened for the options has three sections; first Monitor section as shown in the following image allows to enable monitoring for threads:

Second the CPU section allows us to customize some more options, for this demo we will select the Entire Application option and basically left the other options with their default values.

Finally we can modify the last option section; this section allows the modification of profiling parameters for memory for this test we will modify the default ones and select the option to Record both object creation and garbage collection.

Finally all set clicking on Run button and after waiting for a while we see the following image in the NetBeans status bar. All the sections defined before will get the profiler to store different information; each one will help into analyzing the application in different ways, for this demo we will carry profiling in CPU for time on methods and Memory for object creation and GC.

The previous screenshot shows the AS is starting and therefore our application, the profiler adds some overhead to normal VM operation; therefore, it would take longer to almost any application to start. Another factor to take into consideration is that the AS that works the best with NetBeans’ profiler integration is the bundled GlashFish; although, any Java application should be able to provide profiling information including JBoss AS (as long they run on a Java VM supporting profiling); however, it may not work the integration easily; therefore, it should be done manually, for example the JBoss AS run.bat/sh script should be modified for the JVM to wait for profiler connections. The parameter is agentpath and it default is shown here for the NetBeans installed in the default location, one way to get the parameter to use is by means of NetBeans profiler, first select External Application in the Attach to combo in the Attach Profiler wizard (from the Attach Profiler submenu from the Profile menu); as seen in the following image.

Then click in the change link (if it is the first time you select to attach an external application the wizard will come out right away without having to click on change link); seen in the following image;

to change the attach mode, follow the wizard by first selecting the Target Type as Application

Click next Review Attach Settings, next again and in the Manual Integration step the parameter to add will show up as seen in the following image

Just select and copy the parameter to add when starting the Java (SE 5) application; it should read something similar to this:

-agentpath:"C:\Program Files\NetBeans 6.0\profiler2\lib\deployed\jdk15\windows\profilerinterface.dll=\"C:\Program Files\NetBeans 6.0\profiler2\lib\"",5140

After adding this parameter the Java application should wait until the Profiler connects to it before starting; afterwards the Profiler starts getting profiling information from the application.

In order to show Profiler at work we added some silly code as seen bellow, this code will generate enough overhead; both, on GC and execution time.

Then we started the profiling session to track memory only, this mode allows us to take a look into object creation and garbage collection during the profiled session; although, for this particular example we had silly object creation section we tried the profiler and the results are showed in the next screenshot.

In the results from the Memory profiling session we can see the biggest number of allocated objects are Strings this seems logical since we create lots of this objects in the silly object creation section. Later we test the same application once again but we change the profiler to record execution time information.

This screenshot shows the information after the profiling session has ended; here we have several tabs and the one being shown is the Call Tree view, it shows a summary of the methods using most of the time; first it shows the one we modified with the silly code; this naïve code created lots of objects inside three nested for clauses creating enough overhead to become the most time consuming method in the application; it actually shows up as being called four times only, imaging how big this time might become if the system has 100 simultaneous clients. The second biggest time consuming method is the findEnabled this one shows up from a class $Proxy89; we have enough expertise in the code to point out this method is one in an EJB; that is why it shows up in a $Proxy class. This method does not have any complex business logic what it does is to query the data base to get a small set of data using JPA.

Now that we have located the candidates for optimization the work switches from profiling to coding; first we have to identify which of the methods will give the best results if optimized (reducing execution time) with the minor effort. After analyzing the code we found out the naïve code in the generateExam method; since it is pretty simple to fix we start the optimization work there. Then we can work in the next identified method; findEnabled for this particular one; it appears that the database query is the one adding most of the processing time; therefore; we can try to get some database expert to enhance our database or we can workout JPA to enhance the response time adding cache and some optimizations or perhaps creating an alternate query to the one being automatically created by JPA and run it using JDBC, but who knows maybe is not much we can do to optimize this method or the gain does not justify the effort.

Outstanding Points

NetBean’s profiler could be of great help into identifying potential tuning candidates but good coding practices will save the day; even though; modern compilers and JVM might work out some common coding performance killers.

Graphical profilers such as NetBeans’ could ease the work of identifying possible performance problems; however, most JVM come with command line options to allow profiling.

Profiler features shown in here are just a bit of what NetBeans’ profiler can do for us, graphs, drill-down and profiling points are part of the things available for us to ease the analysis of our applications, for a great demo on these features at work check out http://www.netbeans.org/kb/60/java/profiler-screencast.html.

References:

[1] Shirazi, Jack; Java Performance Tuning Second Edition. O’Reilly Media, Inc.

No comments: