Profiling Real-life Applications Using the NetBeans Profiler

You will install MySQL as a database to RollerWeb application you are going to build, run and profile in Exercise 1.

• Open a terminal window.
• Type "cd <MySQL-Install-Directory>\bin".
• Type "mysqld".  (Figure-1.11 below) This will start MySQL database server.

• Open a terminal window.
• Type "cd <MySQL-Installation-Directory>/bin".
• Windows: cd C:\mysql-5.0.45-win32\bin
  
• Type "mysql -u root -p".  (Figure-0.12 below) 
  
• Press Enter key without entering a password - there is no password.
• Type "source <LAB_UNZIPPED_DIRECTORY>/nbprofilerreallife/
• Windows: source C:\handsonlabs\nbprofilerreallife\sqlscripts\createInstanceAndUser.sql
  

• Study the SQL script.  You are basically recreating rollerDB table.
  

• Type "mysqladmin -u root -p shutdown" to shutdown the databaser server. The steps for doing a shutdown of MySQL vary depending on your operating system; see the MySQL Shutdown Process documentation for more information.

• Observe that there is rollerdb directory under data directory.
  

• Copy files in the  <LAB_UNZIPPED_DIRECTORY>/nbprofilerreallife/sqlscripts/sample directory to the <MySQL_DIRECTORY>/data/rollerdb.  (Figure-0.16 below)
  
• Windows: copy C:\handsonlabs\nbprofilerreallife\sqlscripts\sample\*.* C:\mysql-5.0.45-win32\data\rollerdb
  

• Click Services tab.
• Right click Databases and select New Connection. (Figure-0.18 below)
  

• For the Name field, select MySQL (Connector/J driver)
• For the Database URL field, enter jdbc:mysql://localhost:3306/rollerdb.
• For the User Name field, enter roller.
• For the Password field, enter roller.
• Click OK.  (Figure-0.19 below)
  

• Click OK.  (Figure-0.20 below)
  

• Expand jdbc:mysql://localhost:3306/rollerdb [...].
• Expand Tables and observe the tables. (Figure-0.21 below)
  

• Expand Servers.
• Right click GlassFish V2 and select Start. (Figure-0.22 below)
  

• Right click GlassFish V2 and select Properties. (Figure-0.23 below)
  

• Click Classes tab and see the lib directory of GlassFish V2.  This is the directory, to which you want to copy MySQL client driver.
• Clocl Close. (Figure-0.24 below)
  

• Expand Databases->Drivers.
• Right click MySQL and select Customize. (Figure-0.25 below)
  

• Check where the MySQL client driver, mysql-connector-java-5.0.7-bin.jar, is located.  In this example, it is located in C:\Program Files\NetBeans 6.0.1\ide8\modules\ext directory. (Figure-0.26 below)
  

• Copy MySQL client driver to the lib directory of GlassFish V2. (Figure-0.27 below)
  
• Windows: cd C:\Program Files\NetBeans 6.0.1\ide8\modules\ext and then copy mysql-connector-java-5.0.7-bin.jar C:\PROGRA~1\glassfish-v2ur1\lib
  

• In a terminal window, cd <GlassFish-Home-Directory>/bin. For Windows, it is something like cd C:\PROGRA~1\glassfish-v2ur1\bin.
  
• Type the command as shown in Code-0.28 (actual command) and Figure-0.29 (screen capture) below
  

asadmin create-jdbc-connection-pool --user admin --datasourceclassname com.mysql.jdbc.jdbc2.optional.MysqlConnectionPoolDataSource --steadypoolsize 8 --maxpoolsize 32 --property port=3306:databaseName=rollerdb:serverName=localhost:password=roller:user=roller --restype javax.sql.DataSource rollerpool

Code-0.28: Create Connection Pool


Figure-0.29: Create Connection Pool

11. Create JDBC resource.

• In a terminal window, type the command as shown in Code-0.30 (actual command) and Code-0.31 (screen capture) below

asadmin create-jdbc-resource --user admin --connectionpoolid rollerpool jdbc/rollerdb

Code-0.30: Create JDBC resource


Figure-0.31: CreateJDBC resource

12. Restart GlassFish V2 app server.


Figure-0.32:Restart GlassFish app server


                                                                                                                       return to top of the exercise

This exercise is based on an actual usage of the NetBeans profiler to find a performance problem in the Roller open source blog engine. It was originally presented by Jaroslav (Jarda) Bachor�k during a technical session at JavaOne 2007.

While experimenting with Roller, Jarda noticed that the process of saving a new blog entry seemed to take longer than it really should. Using the NetBeans profiler's ability to select a root method for performance profiling, Jarda was able to quickly and easily locate some inefficient code in the Roller source.

It should be noted that this exercise uses the source code for Roller v2.3, which was current at the time that Jarda discovered the performance problem. The current version of Roller no longer has the performance problem that is described here.

<Learning points>

• CPU profiling
  
• Root method
• Setting up a JSP page as a root method
• Filtering
• Creating custom profiling configuration
• Call Tree
  
• Hot Spots (and Self-time)
• Need for excluding warmup time (or rampup time) for accurate profiling
• Using JMeter for loading testing
• Analyzing calling patterns - identifying poorly designed ones.
  

<Tasks to be performed>

1. Profile "RollerWeb" sample application
   
2. Analyize profiling result
   
3. Run automated test with JMeter
4. Analyze calling patterns - identify poorly designed codes
   
5. Correct the performance problem
   

0. Make sure MySQL is running as described in Exercise 0 above.
1. Open the project.

• Select File->Open Project (Ctrl+Shift+O).
  
• Observe the Open Project dialog box appears.
• Browse down to <LAB_UNZIPPED_DIRECTORY>/nbprofilerreallife/samples directory.
  
• Select RollerWeb.
• Click Open Project. (Figure-1.11 below)
  

Figure-1.11: Open RollerWeb project

2. Start profiling.

• Right click RollerWeb project and select Profile. (Figure-1.12 below)
  

Figure-1.12: Start Profiling

• You might observe that the Select Java Platform for Profiling dialog box appears.
  
• Select JDK 1.6 (or JDK 1.5).
  
• Click OK. (Figure-1.13 below)
  

Figure-1.13: Select JDK

• Observe that the Enable Profiling of RollerWeb dialog box appears.  (This happens only once per project.)
  
• Click OK. (Figure-1.14 below)
  

Figure-1.14: Enable profiling

• Observe that the Profile RollerWeb dialog box appears.
  

3. Create custom profiling configuration.

• Click Create Custom... under CPU section on the left. (Figure-1.15 below)
  

Figure-1.15: Create custom profiling configuration

• Observe that the New Custom Configuration dialog box appears.
  
• For the Name field, enter Roller.
• For the Initial Settings, select Default (if it has not been selected already). (Figure-1.16 below)
• Click OK.
  

Figure-1.16: Give a name

4. Define a root method for profiling.

• Select Part of application radio button (if it has not been selected already.)
• Click define... link. (Figure-1.18 below)  This will let you define a root method.
  

<Learning point: CPU profiling> CPU profiling is done with instrumentation, which means the profiler inserts bytecode on the fly into your application. This adds overhead, so the more instrumentation is done, the more overhead is imposed. By choosing to profile just part of the application you reduce the overhead imposed by the profiler.  The portions of your application that have instrumentation will run more slowly, but the rest of your application will run at full speed.


Figure-1.18: Define root method

• Observe that the Specify Root Methods dialog box appears.
  
• Click Add From Project... button. (Figure-1.19 below)

Figure-1.19: Specify root methods

• Expand JSPs->weblog.
• Select WeblogEdit.jsp. (Figure-1.20 below)
• Click OK.

Note: Jarda examined the source for Roller enough to figure out that WeblogEntry.jsp was the entry point to the "save a new blog entry" logic.


Figure-1.20: Select root method

• Observe that the org.apache.jsp.weblog.WeblogEdit_jsp._jspService(..) method is added as a root method.  Since a JSP was selected as the root method, the profiler lists the _jspService() method as the root method.
• Click OK to close the Specify Root Methods dialog box. (Figure-1.21 below)
  

Figure-1.21: Close dialog box

5. Specify Filter mode and Run.

• For the Filter drop-down menu, select Profile only project classes (if it has not been selected already).
  
• Uncheck Use defined Profiling Points since we are not using Profiling points.
  
• Click Run. (Figure-1.22 below)
• Observe that it will take a few moments for the IDE to start the GlassFish app server, deploy the application, and then perform the instrumentation.
  

<Learning point: Filter> The Filter setting allows us to optionally specify one or more additional filters in order to limit the amount of instrumentation overhead. By profiling only the classes that are defined in our project, we will reduce the overhead dramatically.


Figure-1.22: Start the profiling

Trouble-shooting:  If you see the following error condition, it is likely due to the fact that MySQL database server is not running or it is not properly configured as described above.  Start the MySQL database server if it has not been started or follow the instruction again for configuring MySQL database with the GlassFish V2.


Figure-1.23: Possible error when MySQL database server is not running

6. Do the login.

• Observe that the browser gets displayed.
• Click Login. (Figure-1.24 below) 
  

Figure-1.24: Click Login

• For the Username field, enter blogger.
• For the Password field, enter blogger.
• Click Login button. (Figure-1.25 below)
  

Figure-1.25: Enter Username and Password

• For the Title field, enter My First Entry.
• For the Content text area, enter This is the content.
• Scroll down the page and click Post to Weblog button at the bottom of the page. (Figure-1.26 below)  This will call the root method that was defined above and profiling data will be collected.
  

Figure-1.26: User operations

                                                                                                                       return to top of the exercise

1. Take the snapshot of the profiling.

• Click Take Snapshot.  A snapshot is a display of all the results that the profiler has accumulated at a single point in time.
  
• Observe that the Call Tree - Method tab is displayed on the right side of the IDE.
  
• Observe that the org.apache.jsp.weblog.WeblogEdit_jsp._jspService(..) method is displayed as a root method. (Figure-1.27 below)

<Learning point: Call Tree> The Call Tree tab displays the CPU results organized by threads and then by methods called on that thread, with the root method at the top. Since a JSP was selected as the root method, the profiler lists the org.apache.jsp.weblog.WeblogEdit_jsp._jspService() method as the root method.


Figure-1.27: Take Snapshot

2. Display Hot Spots view of the snapshot.

• Click Hot Spots tab at the bottom of the window. (You can maximize the window by double-clciking the CPU  11:05:32 PM tab.  You can then minimize it by double-clicking it again.)
  

<Learning point: Hot Spots> The Hot Spots tab displays the CPU results organized by Self Time. Self time is the amount of time spent executing a method's own instructions - any time that is spent in instrumented methods that it calls is not part of that method's Self Time. The methods with the highest values for Self Time are taking up the most CPU time and are therefore referred to as "hot spots."

Note that time spent in called methods that are not instrumented is reported as part of the Self time for the calling method. This has an important implication for this profiling session; since only the application's classes are being instrumented, a large Self Time value does not necessarily indicate that a method's code is taking up all that time - it could be that the method calls long-running methods that are not part of the source of the application.


Figure-1.28: Hot Spots view of the snapshot

3. Display the Combined view of the snapshot.

• Click Combined tab at the bottom of the window.
• Click the mouse once on the _jspService() method in the Hot Spots window.
  
• Observe that the Call Tree - Method view displays the _jspService() in highlighted mode. (Figure-1.29 below) 
  
• Double click CPU tab to minimize the window (if you have maximized it before).
  

<Learning point: Combined view> The Combined tab displays both the Call Tree and the Hot Spots in one window. Click with the mouse on a method in the Hot Spots list and the Call Tree will be expanded to show you where in the calling sequence that method was invoked. This makes it easy to see the connection between the root method(s) you selected and the methods that are consuming the most CPU time.

<Learning point: Need for excluding warmup time (called rampup time sometimes) for accurate profiling> In the example screen snapshot in Figure-1.29 below, the _jspService() method took up a large percentage of the time: 68.9%. (What explanation might there be for that?)  In all likelihood, the majority of that time was probably in methods that it called, but it is reported as Self Time because those methods are outside the application and are not instrumented.

The time used in _jspService() is mostly a one-time cost for initially loading included JSPs, tag libraries, etc. This leads to an important observation about CPU profiling: to be accurate, you must allow for warmup.  In this case, the web server needs to warmup a bit before it will begin serving up this JSP efficiently. An even more commmon example is that the Java Virtual Machine (JVM) does its own internal profiling of your application as it runs and will compile the most frequently executed bytecode into machine code so that it will run faster. So all Java applications should be run for a while before the collected profiling results can be considered valid.


Figure-1.29: Combined view of the snapshot - Sang show the selection of _jspService un the Hot Spots view

4. Reset Collected Result.

• Click Reset Collected Results on the left. (Figure-1.30 below)  This is in order to prepare for the automated test in the next step.
  

Figure-1.30: Reset Collected Results.

                                                                                                                       return to top of the exercise

1. Start the test.

• Click Project tab.
  
• Expand RollerWeb->Load Generator Scripts.
• Right click EntryCreationTest.jmx and select Run File. (Figure-1.31 below)
  

Figure-1.31:  Run Load Generator Script

• Observe that the the Output window of the IDE displays the progress of the test.
  

Figure-3.12: Progress of the test

2. Observe the result.

• In the browser, click Entries.
• Observe that the two entries are added as part of the test. (Figure-3.13 below)  Everytime you run the automated test, two entries are added.
  

<Learning point: JMeter> JMeter is an automated testing tool that emulates users accessing a web site. A JMeter script was used here to create two new entries to the weblog.


Figure-3.13: Two entries are added

3. Take the profiling snapshot.

• Click Profiler tab.
  
• Click Take Snapshot button in the profiler window.
• Observe that Call Tree - Method is displayed.
• Click Combined tab at the bottom of the IDE. (Figure-3.14 below)
  

Figure-3.14: Combined view

4. Analyze the data.

• Click CPU .. tab to maximize the window.
• Observe that the getWeblogCategoryParentAssoc() method has the largest self-time.
  
• Click getWeblogCategoryParentAssoc() method in the Hot Spots window.
• Observe that the Call Tree view displays the getWeblogCategoryParentAssoc() method in an expanded form.  (Figire-3.15 below)
  

Figure-3.15: Detect the most time-consuming methods

5. Analyze the code.

• Right click getWeblogCategoryParentAssoc() and select Go To Source.
  
• Observe that the source code of the getWeblogCategoryParentAssoc() is displayed. (Figure-3.16 below)
  

Figure-3.16: getWeblogCategoryParentAssoc()

Figure-3.18: getWeblogCategoryParentAssoc()

                                                                                                                       return to top of the exercise

1. Right-click the entry for getParent() in the Call Tree window and select Go To Source. (Figure-1.41 below)


Figure-1.41: Go To Source on getParent() method.

2. Observe the inefficiently written code in getParent() method..

• Notice what is happening on line 222 - getParentAssoc() is being called just to check to see if it is not null. If it is not null then it is called again. Since each of those calls results in a disk access, it would be better to cache the returned value in order to cut the number of calls in half.

public WeblogCategoryData getParent() throws RollerException {         if (mNewParent != null) {             // Category has new parent, so return that             return (WeblogCategoryData) mNewParent;         } else if (getParentAssoc() != null) {             // Return parent found in database             return ((WeblogCategoryAssoc) getParentAssoc()).getAncestorCategory();         } else {             return null;         }     }

Code-1.42: Inefficiently wriiten code


Figure-1.43: Inefficiently wriiten code

3. Modify the getParent() method.

• Comment out lines 218 through 228.
• Un-comment lines 234 through 248.
• Select File->Save to save the changes.
  

/*     public WeblogCategoryData getParent() throws RollerException {     if (mNewParent != null) {       // Category has new parent, so return that       return (WeblogCategoryData)mNewParent;     } else if (getParentAssoc() != null) {       // Return parent found in database       return ((WeblogCategoryAssoc)getParentAssoc()).getAncestorCategory();     } else {       return null;     }   }     */       // *** NEW ***     public WeblogCategoryData getParent() throws RollerException {         if (mNewParent != null) {            // Category has new parent, so return that             return (WeblogCategoryData)mNewParent;        } else {             Assoc parentAssoc = getParentAssoc();             if (parentAssoc != null) {                 // Return parent found in database                 mNewParent = ((WeblogCategoryAssoc)parentAssoc).getAncestorCategory();                 return (WeblogCategoryData)mNewParent;             } else {                 return null;             }         }     }   //   *** NEW ***

Code-1.44: Modified code

• Observe that the ine 239 is the key change to the code - a local copy of the result is kept and then if it is not null, it is used to do the second invocation.
  

Figure-1.45: Modified code

4. Right click getPath() in the Call Tree window and select Go To Source.


Figure-1.46: Go to source of getPath()

5. Observe the inefficiently written code in getPath() method..

• The same thing happens here - a single call with a cached result would cut the number of calls to getParent() in half.
  

public String getPath(WeblogCategoryData category) throws RollerException {             if (null == category.getParent()) {               return "/";             } else {               String parentPath = getPath(category.getParent());               parentPath = "/".equals(parentPath) ? "" : parentPath;               return parentPath + "/" + category.getName();             }     }

Code-1.47: Inefficiently wriiten code

6. Modify the getPath() method.

• Comment out lines 856 through 864.
• Un-comment lines 868 through 877:
• Select File->Save to save the changes.

public String getPath(WeblogCategoryData category) throws RollerException {            WeblogCategoryData parent = category.getParent();         if (null == parent) {             return "/";         } else {             String parentPath = getPath(parent);             parentPath = "/".equals(parentPath) ? "" : parentPath;             return parentPath + "/" + category.getName();         }     }

Code-1.48: Modified getPath() method


Figure-1.49: Modified getPath() method

7. Profile the RollerWeb application again.

• Select Profile from top-level menu and select Stop Profiling Session.
• Select Projects tab window.
• Right click RollerWeb project and select Profile.
• Observe that the number of times the getParent() and getPath() are now reduced.
  

This exercise is based "Advanced Profiling: Theory in Practice with NetBeans" article written by Osvaldo Pinali Doederlein with his permission.

<to be provided>

                                                                                                                       return to top of the exercise