Profiling With VisualVM, Part 1
By Jiri Sedlacek on Jul 28, 2008
This article describes the out-of-the-box profiling features of the VisualVM tool available without any additional configuration, just using the default settings.
Beside various monitoring features, the tool contains a built-in profiler based on the NetBeans profiler. While the profiler UI in VisualVM looks simple (especially when compared to the NetBeans profiler), the profiling capabilities are almost as powerful as in NetBeans. The main difference between these two tools is their workflow: whereas NetBeans profiler is project/sources-centered and is a great tool for iterative testing/improving performance during application development, VisualVM can be used as a standalone profiler which works with any running application without having any context of the source code.
Note: For profiling applications running on JDK 6.0 Update 6 and earlier, the applications need to be started with the Xshare:off flag which disables the class sharing, otherwise the profiling may cause a crash of profiled JVM. For applications running on JDK 6.0 Update 7 and higher the profiling should work without any modifications.
The profiling UI is very simple, by default it shows just three buttons for analyzing performance (CPU button), memory usage (Memory button) and stopping the profiling session (Stop button). The other UI elements are Status area where the actual profiling status is shown and Profiling results section which displays live profiling data collected during the profiling session. For advanced profiling there's also a Settings section which is hidden by default. It allows to fine-tune the profiling settings, this is described in detail in Profiling With VisualVM, Part 2 article.
Note: Whereas the Profiler tab is available for each application which can be profiled, only one application can be profiled at a time, concurrent profiling sessions are not supported.
When the CPU button in Profiler tab is pressed, the profiler attaches to the application and starts profiling its performance. At the beginning the profiler needs to instrument some methods of the application, the actual number of instrumented methods is displayed in the Status area. Since the profiler uses dynamic instrumentation, the number of instrumented methods may change during the profiling session. After the profiler is attached and starts collecting the data, the view looks like on the screenshot:
You can see live profiling data for the application, for each profiled method number of invocations and total execution time is displayed. Note that not all methods are profiled, by default the profiler doesn't profile methods from
java.*, javax.*, sun.*, sunw.*, com.sun.* (+
com.apple.*, apple.awt.* on Mac OS X) packages. Time spent in methods from these packages is added to execution time of profiled methods calling them, for example constructor execution time of a custom class (
CustomClass.<init>) includes execution time of super constructor etc.
The toolbar of Profiling results section contains the following actions (from the left):
- Update Results Automatically: results are periodically refreshed approx. each 1.2sec
- Update Results Now: immediately fetches actual data, typically used when automatic refresh is disabled
- Run Garbage Collection: invokes GC in profiled application
- Reset Collected Results Buffer: resets the data collected so far, useful for measuring delta results
- Take Snapshot of Collected Results: saves all the collected data into a persistent snapshot for more detailed analysis
- Save current view to image: saves the results table into a
The most important action is Take Snapshot of Collected Results (available also as Profiler Snapshot in context menu of profiled application in Applications tree). It takes a snapshot of collected profiling results (compatible with NetBeans profiler snapshot) and opens it in a separate tab. This snapshot provides several different views: Call Tree displaying methods call tree starting by threads, Hot Spots displaying a list of all profiled methods sorted by their execution time and Combined view showing both call tree and list of profiled methods. The last view Info displays basic snapshot information and detailed profiling configuration of the snapshot. There's one handy action available in context menu of each method, it's called Show Back Traces and displays all the places from where the method is being called.
Multiple profiler snapshots can be taken for a single profiling session for example to compare performance in various situations / loads / configurations of the application. All the profiler snapshots can be then saved into a single Application Snapshot (use Application Snapshot action in context menu of profiled application in Applications tree) to archive them in one file or to send them to application developers/quality engineers.
When Memory button in Profiler tab is pressed, the profiler attaches to the application and starts profiling its memory consumption. At the beginning the profiler needs to instrument all classes of the application, the actual number of instrumented classes is displayed in the Status area. Because all the application classes need to be instrumented, it takes some time until the profiler starts to collect the data. To lower the profiling overhead, each 10th object allocation is tracked by default (also displayed in Status area). Keep this in mind when evaluating the profiling results. After the profiler is attached and starts collecting the data, the view looks like on the screenshot:
You can see live profiling data for the application, for each class number of live instances and their size is displayed. The rightmost column shows Surviving Generations metrics which is very useful for detecting memory leaks. Detailed explanation of Surviving Generations is available in this article. You can also monitor allocations history of a particular class during time (History subtab at the bottom), to do this invoke the Log Class History action in context menu of the class.
The toolbar of memory profiling results is the same as for CPU profiling results. You can also save the collected results into a snapshot using the Take Snapshot of Collected Results action in Profiling results section toolbar or Profiler Snapshot context menu action. This is especially useful for detecting memory leaks, using the Compare Memory Snapshots action available in File menu you can visually display the difference between two comparable memory results and for example evaluate if/which objects remained on the heap after executing some action.
Note: When stopping the profiling session (both CPU an Memory) the profiler restores original application bytecode. This can take some time and the application and/or the whole system may not respond for a while.
When VisualVM is started for the first time, the profiler performs an initial calibration. During this process the overall system and actual JDK performance is being measured and these data are later used to subtract the profiling overhead from collected performance data. The profiler requires a "stable" performance of the system, this means that any technique for dynamic CPU frequency switching like SpeedStep or PowerNow! should be disabled during both the calibration and profiling.
If the system performance changes or a different JDK than the calibrated one is used for profiling, the collected performance results may become biased and the profiler needs to be re-calibrated. Unfortunately there's no UI action available for recalibration in VisualVM 1.0, the only way to invoke the calibration again is to manually delete calibration data file in
<user_directory>/.nbprofiler/machinedata.jdk1X and restart the VisualVM.
You may also find the NetBeans Profiler 5.5 documentation useful, especially the Profiling Results - Application Performance, Profiling Results - Memory Usage, CPU Snapshot or Memory Snapshot sections.