RollerCaseStudy

Roller Case Study

This demo script is part of the NetBeans World Tour 2008 session #8, Integrated Profiling Tools. Refer to the top-level demo scripts page for additional information.

Background

This case study is based on an actual usage of the NetBeans profiler when using the Roller open source blog engine. It was originally presented by Jaroslav (Jarda) Bachorík during a technical session at JavaOne 2007.

It should be noted that this case study 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.


Main Points to Hit

  • The NetBeans Profiler has a powerful capability to help you track down performance problems.
  • Using root method selection you can limit the overhead imposed by the profiler to only those parts of an application that you suspect have a problem.
  • With its tight integration into the developer work flow, it is easy to start/stop profiling sessions and more importantly, to go from profiler results directly into the source code that has the problem.

Prerequisities

  • JDK6
  • NetBeans 6.0 Milestone 10 build (or higher) - must be run with -Xmx512m
  • Tomcat 5.5 (or higher)
  • MySQL database server 5.0 (or higher)
  • Required NetBeans modules - "LoadGenerator", "JMeter Module" and "Profiler Bridge" all of which are available from the update center.

Setup

Setup the database

  1. Create a new MySQL database called rollerDB
  2. Stop the mySQL service. On Windows use the System Services dialog. On Ubuntu, you can use the command sudo /etc/init.d/mysql status then use sudo /etc/init.d/mysql stop if necessary. On OpenSolaris use svcadm disable mysql.
  3. Unarchive roller_RollerCaseStudy.tgz and copy its contents to the rollerDB sub-directory that was just created for the rollerDB database.
  • On Windows the location of that sub-directory will vary
  • On Ubuntu the default location is /var/lib/mysql
  • On OS X the default location is /usr/local/mysql/data
  • On OpenSolaris it is /var/mysql/data. Be sure to unarchive the data as the mysql user, otherwise NetBeans may not be able to display the tables. pfexec su mysql.
  1. Save extra copies of these two files into a separate directory: weblogentry.MYD and weblogentry.MYI. They are empty so they are useful to have in order to get the database back to the state where there are no web log entries. You can do this with the tar command as follows: tar -cf weblogentry.tar weblogentry.MYD weblogentry.MYI.
  2. Start the MySQL service. On Windows use the System Services dialog. On Ubuntu, you can use sudo /etc/init.d/mysql start. On OpenSolaris use svcadm enable mysql.
  3. Create a MySQL username (roller) and password (roller) so that you can access the restored database. These commands are based on information from the Roller v2.3 install guide:
               % mysql -u root -p 
               password: *****
               mysql> grant all on rollerDB.* to roller@'%' identified by 'roller';
               mysql> grant all on rollerDB.* to roller@localhost identified by 'roller';

Setup the RollerWeb project

  1. Download this NetBeans project directory, which contains the complete source code for Roller v2.3 (and its /lib directory is fully populated with all the .jar files needed to get Roller v2.3 to compile) and unzip it to a directory on your system.
  2. (Optional) In the IDE's Services tab register the MySql JDBC driver under Databases > Drivers. The .jar file you will need is mysql-connector-java-5.0.5-bin.jar and it is in the /lib subdirectory of the RollerWeb project that was unzipped in the previous step. Registering the driver will allow you to conveniently browse the tables of the sample database in the IDE.
  3. Check the project's context.xml configuration file to make sure that the MySQL database (rollerDB), username (roller), and password (roller) are correct.

Test your setup

  1. Open the RollerWeb project
  2. Resolve any missing references
  3. Build the RollerWeb project - there should be 4 warnings from the compiler
  4. Verify that RollerWeb will start - the IDE should start a web browser and display http://localhost:8084/roller-test/.
  5. Login to Roller with the username/pw of jbachorik/roller in order to see the entries in the blog named j1. If you do not want to use the "jbachorik" username then click the Register link and create a new username/pw and blog name. Be sure to update the project's EntryCreationTest.jmx file though if you decide to create a new username, password, or blog name.
  6. Profile the project at least once so that the IDE can do the one-time modification to build.xml
  7. NOTE: Until this bug gets fixed, there is an additional Setup step that is required:
    1. Right-click the RollerWeb project and choose Profile Project.
    2. Click on the profile dialog's CPU option to expand it (if it is not already expanded).
    3. Click on Create Custom to create a custom CPU profiling configuration
    4. Specify a name for the configuration, for example "Full"
    5. Click OK
    6. The profile dialog should now show that your new configuration is being used (it will be listed at the top of the dialog).
    7. Click Advanced Settings.
    8. Scroll down to Instrumentation Settings and make sure it is set to Total.
    9. Click Basic Settings.
    10. Click Run. The IDE will save your custom CPU profiling configuration. Always use this configuration during the steps outlined below.

Pre-Demo

  1. Verify that the MySQL service is not running.
  2. Copy the saved copies of weblogentry.MYD and weblogentry.MYI into the rollerDB database directory, overwriting the files that are there
  3. Start the MySQL service
  4. Check HibernateWeblogManagerImpl.java and WeblogCategoryData.java to verify that they are not optimized already (section marked with OLD should be in use - section marked with NEW comment should be commented out)
  5. Right-click the RollerWeb project and choose Profile Project
  6. Click the Monitor option on the left-side of the dialog
  7. Make sure that the Load Generator script option is not checked
  8. Click the Run button
  9. After the web browser displays, login to Roller
  10. Click the Entries link. There are no web log entries, so Roller should show Displaying 0 weblog entries

Demo

  1. Show the Roller entries page. Suggested Comment (SC): "There are no Roller entries for this user. It was during the adding of entries that Jarda noticed slow performance."
  2. Switch back to the NetBeans IDE and if it is not already open, open the VM Telemetry Overview window (Window > Profiling > VM Telemetry). SC: "I'm profiling Roller, but only in Monitoring mode, which imposes no overhead (and therefore provides no detailed performance information). We can see some basic information about heap usage, classes, and threads in this overview window."
  3. Select Profile > Modify Profiling Session and then click the CPU button on the left-side of the dialog and click the CPU configuration you created earlier ("Full" or whatever you called it). SC: "Let's do some more detailed profiling in order to track down this performance problem."
  4. Select Part of application and click the define link
  5. Click the Add from Project button to bring up the (improved for 6.0!) Select Root Methods dialog.
  6. Expand RollerWeb then expand JSPs and then expand weblog.
  7. Check the box next to WeblogEdit.jsp.
    Image:select_RollerCaseStudy.png
  8. SC: "Jarda knew that this JSP was the starting point for the creation of new web log entries, and since we are using an integrated profiling tool we can easily select it as a root method. "
  9. Click OK and then click OK again on the Select Root Method dialog
  10. Set the filter to Profile Only Project Classes
  11. Make sure Use defined Profiling Points is not checked. The dialog should look like:
    Image:modify_RollerCaseStudy.png
  12. Click OK. It will take a few moments for the profiler to do the necessary instrumentation, so use that time to explain the root method concept; SC: "The profiler is doing the necessary instrumentation. The profiler examines the JSP that we selected and determines which methods get invoked by that JSP. It will examine each of those methods to figure out which methods they invoke, and so on. This way it can determine the exact list of methods that need to be instrumented in order to monitor CPU performance during the saving of a web log entry - the rest of the application's methods are not instrumented so they continue to run at full speed."
  13. In the Projects tab expand the RollerWeb entry's Test Packages node. Expand the <default package> under it.
  14. Right-click the EntryCreationTest.jmx file and choose Run File. SC: "I've got a JMeter script that will put some load on this application - specifically it will create two weblog entries."
  15. Switch to the Services tab and expand the Load Generators node and then expand the JMeter node to show the entry for EntryCreationTest.jmx. SC: "One of the new features in NetBeans 6.0 is integrated support for JMeter."
  16. After the status next to EntryCreationTest.jmx changes to Stopped, maximize the Output window. SC: "We can also see the detailed output from the JMeter script here in the IDE's Output window."
    Image:output_RollerCaseStudy.png
  17. Switch to the browser and refresh the entries page to show the two newly created blog entries
  18. Switch back to the IDE and in the Profiler tab click the Live Results button.
  19. On the toolbar of the Live Results window, click the green pie chart button to open the Areas Of Interest graph:
    Image:aoi_RollerCaseStudy.png
  20. Most of the CPU time has been spent in "Persistence," which is not surprising. SC: "One of the new features in NetBeans 6.0 is this high-level view we call the 'Areas of Interest' graph. This graph displays the amount of time by specific categories. Not surprisingly, lots of time is being spent in persistence since all we have really done thus far is save two new blog entries. If we drill-down into the persistence section by clicking its pie segment we see that Roller uses Hibernate."
  21. Close the Areas of Interest graph.
  22. Click the Take Snapshot button in the profiler tab. SC: "We can get more detailed information by having the profiler show us a snapshot of the results it has collected thus far."
  23. Click the Hot Spots tab in the CPU snapshot window. SC: "'Hot Spots' are the methods that are using up the most time. This display is sorted in descending order."
  24. The method at the top should be org.apache.roller.business.hibernate.HibernateWeblogManagerImpl.getWeblogCategoryParentAssoc()
  25. Right-click the hot spot method and choose Go to Source.
  26. SC: "Since we chose Profile Project classes only as the filter, there is no break down of the CPU time spent in the methods called by this "hot spot" method. That is because those methods that got called by getWeblogCategoryParentAssoc() are outside our project - they are lower level Hibernate methods that we don't want to change anyway. So it's not possible for us to optimize this 'hot spot method' itself any further."
  27. Go back to the results snapshot window and click the Combined tab. SC: "So here's what we know so far: there is a method that is taking up quite a bit of time. The method itself looked fairly simple so the time must be in the methods it calls. But those methods are not in our source, so we would prefer not to mess with them. The next thing to look at then is how is this time-consuming method being used by our code? That is what the profiler's Combined view shows us - the call tree between the root method we selected (that JSP) and the 'hot spot' method."
  28. In the lower half of the Combined tab click on the first entry (which should be for getWeblogCategoryParentAssoc(). This will change the display in the upper half: Image:combined_RollerCaseStudy.png
  29. SC: "There is something interesting here. Notice that in the call tree from the root method the "hot spot" method (getWeblogCategoryParentAssoc()) gets called 160 times. This matches up with the method that calls it: getParentAssoc(). But look at the next method up in the call tree - getParent() is only called 80 times. Why is it calling getParentAssoc() twice for each time it is invoked? Could we optimize that? One of the advantages of an integrated tool is that it is easy to find out...."  :-)
  30. Right-click the entry in the call tree for getParent() and choose Go To Source. Image:wcd_RollerCaseStudy.png
  31. SC: "On line 219 this method calls getParentAssoc(). If the return value is not null it calls getParentAssoc() again on line 221. Each of those calls results in a call to the 'hot spot' method we identified so making two calls is unnecessarily expensive! I just happen to have here a version of the code that has been optimized to cache the return value so that only one call is made...."  :-)
  32. Comment-out the code marked OLD and un-comment the code marked NEW. Save the file and close it.
  33. Go back to the call tree. The same exact anti-pattern exists in org.apache.roller.business.hibernate.getPath() - it is making two calls to getParent() that are expensive instead of just one call. Follow the same process as above: use Go To Source, show the code, and then comment-out the OLD code and uncomment the NEW code and save the file.
  34. Select Profile > Stop Profiling Session
  35. Right-click the RollerWeb project and choose Profile Project. Everything is the same as before - make sure the "Full" configuration (or whatever you called it) is selected. The only difference is that this time be sure to select the Load Generator Script option so that the profiler will run the JMeter script for you. SC: "This time, we'll have the profiler run the JMeter script for us."
  36. After you click Run it will take a few moments to restart Tomcat, do the instrumentation, and then run the JMeter script. So recap what has been done so far, emphasizing each new feature that was used: the improved root method selection dialog, areas of interest graph, JMeter integration. SC: "To recap: we suspected slow performance when creating and saving a new blog entry, so we used the profiler to select the appropriate JSP as a root method. The profiler did its job by making it easy for us to see a pattern of inefficient method calls that resulted from that JSP. We made the necessary changes to the code, stopped the profiling session, restarted it so that we can profile the new code, and now the IDE will start the server again, do the instrumentation, and with a new feature in NetBeans 6 it will actually run our JMeter script automatically once all setup has been completed. And along the way we took a look at the new Areas of Interest graph to see a high-level view of where time was being spent."
  37. After the EntryCreationTest.jmx script has finished, refresh the browser window to show that 2 new entries have just been added - thus the load generator works as expected
  38. Show live results - if the Persistence category takes significantly less CPU, mention it.
  39. Take snapshot, save it, locate the "hot spot" and find it in the call-tree, just like before.
  40. Place the snapshots side-by-side and point out the dramatically lower number of invocations of the hot spot method. Total time required should also be lower. SC: "Admittedly, microbenchmarks like this have limitations, but I think we can all agree that calling your slowest method 40 times instead of 160 times will lead to a performance improvement. The NetBeans profiler made it easy to see the pattern of inefficient CPU usage - and since it is integrated into the IDE it was easy to modify the code and then see the improvement."
Not logged in. Log in, Register

By use of this website, you agree to the NetBeans Policies and Terms of Use. © 2012, Oracle Corporation and/or its affiliates. Sponsored by Oracle logo