Tutorial: Profiling Java Programs

--D. Thiebaut (talk) 15:01, 30 September 2013 (EDT)

---

This tutorial is intended to give a brief overview of JVisualVM, the profiler for Java. We use this profiler with Eclipse and use a 2D-packing application as our target application. Our goal is to figure out where the program is spending most of its time. The environment used to create this tutorial is VisualVM 1.3.6 running on OS X 10.7.5, and the hardware is a 2.8 GHz dual quad-core MacPro.

VisualVM

• On some system Java VisualVM is already part of the installed software, so test first if you have it. It is sometimes in the Applications folder under Java VisualVM, or sometimes it starts in the Terminal with the command jvisualvm.
• VisualVM can be downloaded from visualvm.java.net. Once you have downloaded and installed it, you should be ready for running the application.
• The documentation for VisualVM is available here, as well as on the Oracle Website.

This section is only visible to computers located at Smith College

The Packing Application

• The packing application we are going to use for this tutorial is a Processing application. The YouTube movie below illustrates how it proceeds at packing randomly sized rectangles into a larger rectangle.
• Setup the packing application either as an Eclipse project, or using the Processing IDE. If you are using Eclipse, do not forget to include the core.jar as an external library in your Build Path.
• Run the application (or watch the movie) and observe that the application starts quite fast, but slows down significantly. One factor is the fact that the list containing the random rectangles is sorted by decreasing area, and the algorithm picks them largest first, smallest last. So as the algorithm progresses with the packing from left to right, it packs smaller and smaller rectangles and the right frontier advances more slowly than at first.

The second reason is that there is potentially some bottleneck in the program. VisualVM should allow us to look at different aspects of the program.

Starting Monitoring the Processing/Java Application

• First start Java Visual VM.

• Start your packing application. In our case we are starting it from Eclipse. As soon as the applet opens and fills up with purple rectangles, a new entry appears in the Java VisualVM window:

• Click on the new entry, and in the right panel click on Monitor:

• The monitor window presents you with 4 different charts

CPU (1)

The CPU chart incates the CPU usage. The documentation is not clear as to what this means on multicore machines. But in the figure above the 30% or so usage seems to indicate the utilization on 1 core. The blue line that overlaps the x-axis is the Garbage Collector, or (GC). If this line is ever growing above the x-axis, it will indicate that your application is creating a lot of objects that it leaves behind, and the GC is busy cleaning up after the application.

Heap (2)

The Heap graph shows the amount of heap (memory available for dynamic objects) available (in orange) and used up (in blue). If the blue line is very close to the orange one, your application is filling up the heap with objects. You may have a leak in your program.

Classes (3)

This is the number of different loaded classes your application uses. You may think that your application is using much fewer classes, but actually all the libraries and imported classes you use in your program contribute to about 2,000 definitions. The number of objects created by your application can easily range in several tens of millions.

Threads (4)

That's the number of all threads running while your application runs. The packing application has only 3 threads: the main application, the GUI thread, and the packing thread. However, almost 20 live threads are running while the application is on-going. StackOverflow has interesting answers to the question a programmer asked about "why so many threads!?"

Viewing Threads

• the thread tab shows the diffrrent threads running, waiting, dead. You can easily spot the Main Application Thread and the GUI thread. Our packing thread is harder to spot. But it should be green, as it is running all the time...

Sampling the Application

The Sampler tab offers a lot of very cool information. What the Java Visual VM application does is to regularly sample our Java/Processing application and recording which method or class it is inside of at the sample time, and similarly it looks at the different number of objects currently in the heap.

CPU

When you click the CPU button, you get a list of methods and the amount of time the CPU (or CPUs) are spending in these method, by default sorted from most time consuming to least time consuming.

In the image above we see that our application is spending 31% of the processor time in the get() method of the RedBlackTree class, followed very closely by the getLessThanOrEqual() method of the same class.. Keys() is not far behind with 25% of the time used. So definitely these three methods account for roughly 85% of the time spent by the packing algorithm.

If we were interested in speeding up the application, these would be the three we should look at first.

Memory

When you click on the Memory button, you get a list of the objects or data-structures that occupy the most amount of space in the heap.

The image above shows that the Node objects of the RedBlackTree class account for 22% of the memory use. Look at the number of objects, though: 602,343 million, taking a total of 24 MBytes! If we were to analyze the program closer we would find that the nodes actually hold segments that define band of free packing space, or rectangles. If we further look at the packing algorithm, we would notice that whenever a new rectangle is added, it generates only a handful of segments. Since we are packing 20,000 rectangles, the number of segments should be in the 100,000 range, but not 24 million. The reason we have so many is that some of these segments are actually dead, deleted objects, that haven't been caught up by the Garbage Collector (GC).

This leads us to the concept of memory leak. A memory leak occurs in an application when this application, while running, slowly fills up the heap with objects that are not officially deleted by the program. If an object that is not used by the program is not deleted, then it remains in memory and the GC cannot reclaim its space. It is as if the application is leaking objects in the heap, hence the name we give to this condition. If the number of bytes and number of instances in your application were to increase constantly and significantly in your program to the point of using up all the space, that could be an indication of a memory leak.

Profiler

The difference between Sampling and Profiling is provided by User npe on Slashdot (captured on 9/30/13):

Sampling means taking lots of thread dumps and analyzing stack traces. This is usually faster, does not require runtime changes in your bytecode (which may break it), but is also less accurate.

Profiling means instrumenting your classes and methods, so they "report" whenever they are run. This is more accurate, as it counts every invocation of instrumented method, not only those caught when the dump is done. However instrumentation means that the bytecode of your classes is changed, and this may break your program. Actually, for that reason, using profiling on large application servers (like JBoss, or WebLogic) often causes everything to die or hang.

Nicely said. The sampling is fast and does not modify the code, and therefore affects the application less. Profiling requires changing the code, and if you are after a particular bug or bad behavior, sometimes the action of profiling will hide the problem you're trying to recreate and monitor.

The figure below shows the result of profiling our packing application, and notice that the information displayed is quite different from what the sampler was showing.

Exercise

• Look at the code for the three methods that seem to consume the most CPU and propose ways to reduce their execution time.