Collecting method-level execution statistics
Of the three profiling agents discussed in this tutorial, likely the most commonly-used agent is the method-level execution analysis agent, which provides a variety of statistics on method execution. The following example should provide a straightforward explanation of the available execution statistics' functionality.
- First, select a Java application to profile.
- Right click the Java project and select Profile as.
- If this is the first time that you are profiling this project, the Profiling dialog is displayed. Otherwise it will automatically revert to the last saved profile configuration for the selected project.
- To modify the previous profile configuration, use the Profile configurations dialog, as described previously.
Profiling options include Execution Time Analysis, Memory Analysis, and Thread Analysis, as shown in Figure 2.
Figure 2. Options in the Edit configuration and launch dialog
In the profile dialog you will see several profiling options: the previously-mentioned profiling options under Java Profiling are the subject of this tutorial. The fourth item, Probe Insertion, describes an additional functionality using the Probekit tool to instrument applications with custom probes, but is outside the scope of this tutorial.
- From here, click the Edit Options button.
Execution Time Analysis has three options:
- Execution Flow provides a greater variety of profiling data views, but increases profiling overhead, profiling data volume, and workbench memory usage. This may be unsuitable for applications with large profiling data sets.
- Execution Statistics has a significantly reduced overhead, and workbench memory usage, but at the expensive of some profiling functionality. Only the Execution Statistics and Method Invocation Details will be available.
- Collect method CPU time information: In either of the above modes, the profiler can collect the time the CPU spends executing profiled methods. This will differ from the above, because I/O and wait times will not be included in the CPU time.
The best course of action is to begin with Execution Flow, and then switch to Execution Statistics (or the adjust filter set) if the data volume becomes too great.
- For this example, select Execution Flow, because this provides an example of all of the available profiling views.
Before selecting the profile button, it is important that the proper filters are in place. A large amount of profiling data is generated as part of the profiling process, because every single method call, object allocation, or thread event requires an event to be generated, transmitted, and processed.
The sheer volume of profiling data can sometimes be overwhelming, both to the application under execution and to the workbench itself. However, only a fraction of it will be useful for analysis purposes. Fortunately, the profiling tool provides a way to filter out irrelevant information so that you can reduce the agent data volume for the profiled application.
For instance, in profiling a Java application, you are likely only concerned for the methods of your application, and not in the execution time of the standard Java language packages like java.*, sun.*, and so on. It is important to use filters that are specifically targeted to the classes of your application, so as to reduce profiling overhead from external classes as much as possible.
- To set filters, double click the Java profiling – JRE 1.5 or newer entry. You will see a window similar to the one shown in Figure 3. Filters specify which packages and classes to profile; filters are themselves contained in configurable filter sets.
Figure 3. Select filter sets and their contents
In this dialog, you define new filters or modify existing filters. A few filters that are useful in the most common profiling scenarios are provided, as shown in Figure 3. Filter sets are listed in the top pane, and the filters themselves are listed on the bottom. Filter precedence is from top to bottom, meaning that filters higher on the list will override any conflicting filters lower on the list. Filters and filter sets can be added and removed using the buttons on the right of the dialog box.
- For this example, you are content with the default filter and select Finish to return to the profiling dialog box.
- From here, select Execution Analysis, and click the Profile button. The workbench will confirm a switch to the Profiling and Logging perspective, and the profiled application will begin running in the Profiling Monitor view.
- Click Execution Time Analysis to open the Execution Statistics view shown in Figure 4.
Figure 4. A small data set for a class being profiled in the Execution Statistics view
The Session summary tab provides an overview of the top ten methods with the highest base time. However, it's the Execution Statistics tab from which all of the data is made fully available. Here you will find details on methods invocations and their statistics: the number of times called, average time spent, cumulative time, and so forth.
A few key definitions should help clarify the columns in this view:
- Base Time: The time to execute the contents of the method itself, excluding calls to other methods. (In the table, the Base Time field sums together all of the calls of that method.)
- Average Base Time: The average time that a particular method took to complete, excluding the time of method calls to other methods. (In the table, this is the Base Time divided by the number of Calls)
- Cumulative Time: The time to execute the method contents itself, including calls to other methods.
These statistics can help locate the performance bottlenecks in a program.
Based on these definitions, there are three important considerations:
- Average Base Time: This is the average time that a method took to complete. So, on average, this is how long a single invocation of that method took to finish (as noted above, this excludes the time taken by child methods called by this method or, more specifically, excluding the time of unfiltered child methods)
- Base Time: This is the total amount of time that a method took to complete. This is an amalgamation of all of the time that was spent in this method (excluding calls to other unfiltered methods.)
- Cumulative CPU Time: Cumulative CPU Time represents the amount of CPU time spent executing a specified method. However, the granularity of the data provided by the JVM in this regard is coarser then might be desirable. Consequently, CPU time maybe reported as zero if the time is less than a single platform-specific unit as reported by the JVM. Also, CPU time will not take into account other types of performance bottlenecks, such as those involving communication type and I/O access time. As a result, base time is often favored as a metric for performance bottleneck reduction.
At first glance, average base time would seem to be a key data point in determining which methods are slowing down the system. However, while average base time will pinpoint methods that take a long time to execute, it does not take into account the number of times a method is called. You can ask yourself which is worse: a method that runs once and takes 5.0 seconds, or a method that runs 1000 times and takes 0.5 seconds? Average base time for the first would be 5.0 seconds, while average base time for the second would be 0.5 seconds.
However, the base time for the first method would be 5.0 seconds, while the base time for the second would be 500 seconds. Reducing 500 seconds from an application run time is tremendously more impactful than merely reducing 5. Thus you can say unequivocally that the second method is a greater concern than the first, due to base time difference. Base time is therefore a primary concern for reducing the performance bottlenecks in an application. Because base time represents an amalgamation of the entire application run, generally speaking reducing base time is equivalent to reducing run time.
While base time only represents time spent executing the method itself (excluding calls to other methods), cumulative time represents the total time spent executing a method, including child calls. So, for instance, in a single-threaded application, the cumulative time of the
main(…) method is equivalent to the sum of all of the base times for all other methods in the application, because the
main(…) method is the starting point of the application, and thus is the starting point for all methods calls. Therefore, it is equivalent to the total application run time.
With an understanding of the details of execution statistics in mind, let's look at ways to further drill down to analyze performance problems. To get a better idea of what specific methods are invoking, and from where specific methods are being called, double-click the desired method in the Execution Statistics tab. This will open the Method Invocation Details tab, as shown in Figure 5.
Figure 5. Drill down into finer detail of specific methods
The Method Invocation Details tab is a fairly straightforward presentation of those execution statistics that are directly related to the selected method. The second table in the tab is Selected method is invoked by, which will list all of the methods that called the selected method during the application run.
The third table, Selected method invokes, will list all of the methods that the selected method calls. The same statistics from the Execution Statistics tab are reproduced here, and selecting a method from any of these tables will update the selected method at the top of the view.
The next tab of note here is the Call Tree tab, which is only available when you are profiling with the Execution Flow profiling option. The Call Tree tab breaks down method calls for all of the methods that are called for a specific thread. The first-level items in the table are all of the threads that have spawned during the application run. Below this is an amalgamation of each of the method calls that are made, with methods on a subsequent level being called by methods from the previous level of the tree.
Figure 6. The Call Tree tab presents method invocations from a more thread-centric perspective
At the top-most level, the Cumulative Time for each thread represents the total time that the thread spent running in the application. Those threads with a higher cumulative time are candidates for analysis and optimization.
The Percent Per Thread field represents the total time spent executing a method as expressed as a percentage of the total time spent executing the thread. It is represented as a total of the cumulative time of the top-most method call for that thread (which is the total time spent executing the thread). Additional statistics are provided, such as the maximum, minimum, and average time that it took to complete a method execution on the thread, as well as the total number of calls.
Below the top call tree table is a table of method call stacks, which display the contents of the stack of every method call for the presently selected item in the call tree table. The number of stacks available will be equal to the number of calls listed. This can prove useful for analyzing particular method invocation instances.
Finally, you can right-click on the method entry and select Open Source from any of the views. If the related Java file is present in the workspace, the workbench file will be opened and the method definition will be located. When performance bottlenecks are identified, you can modify them and then profile again to see the difference.