I'm a software architect/consultant in Boulder, Colorado. I started blogging at: http://wayne-adams.blogspot.com/, but have since started the new blog, Data Sceintist in Training which will cover the areas I am learning as part of my own "big data" training, including the Hadoop family, frameworks like OpenStack, the R programming language, column-oriented databases and the art of examining data sets for useful patterns. The original blog will be kept alive with Java-specific posts. Wayne is a DZone MVB and is not an employee of DZone and has posted 35 posts at DZone. You can read more from them at their website. View Full User Profile

Java Profiling with MonkeyWrench

02.09.2010
| 23557 views |
  • submit to reddit

CPU & Memory Profiling

Once you have started CPU and Memory profiling, information accumulates in the “CPU” and “Memory” tabs at each display update interval. The “CPU” tab is designed to track the time spent in methods and constructors, while the “Memory” tab is designed to track the allocation of objects specified by your regular expressions. Note that if you instrument only on method names, you will not get any output in the “Memory” tab, as no constructors will be instrumented.

Figure 4 shows the CPU tab while profiling an NWIS-based water quality web service. A few selections have been made to highlight most of the features of this tab. As method and constructor‐call signatures accumulate in the display, the table in the top half of the screen displays the CPU time and wall‐clock time for each method, as well as the percentages of total CPU and wall‐clock time, and the number of invocations. Note that the totals are based on the total time accumulated for all methods being instrumented (not for all methods in the target application). There are only a few methods in the table in this example, but the number of entries can of course run into the hundreds or thousands. For this reason, a search window is provided, with “find next” and “find previous” buttons.

The StreamMonitor’s getSiteName() method is selected in the constructor/method table. When you select an entry in this table, the site‐summary table in the lower‐left corner is populated with a list of unique stack‐trace signatures associated with this method call (the term “site” is taken from the profiling utility hprof). In this case, there is only one site identified; clicking on that entry will populate the lower‐right text area with the stack trace itself.

Figure 4 -- The CPU Screen

Both tables in this screen can be sorted on all columns, ascending or descending. You will typically sort the upper table by “% Total CPU Time”, descending, and the site‐summary table by the “Occurrences” column, descending. The two percentage columns in the upper table render a proportional green bar to display the percentage, as well as displaying the amount.

Note there are two “View Threads” buttons. When you select “View Threads” on the upper table, containing the method signature data, you will open a small dialog listing the threads used to invoke that method, with a count of the number of times each thread called that method or constructor. When you select the “View Threads” button above the stack‐trace text area, you display only the threads used to call the method or constructor through the selected site or stack trace. In this example, the thread “pool‐1‐thread‐1” (a naming convention used by the Java SE webservice implementation) is the thread that has called this method for all of the occurrences (10, in this case) since we started profiling or cleared the data.

In a more‐complex or more heavily‐used application, there may in fact be many sites, or stack‐trace signatures, for a particular constructor or method call, and there may be several threads involved. These may be just different threads from a pool, but in some cases the thread display can reveal potential issues. For example, it may show that on a number of occasions, a highly compute‐intensive method is being called on the AWT event thread. Having the stack trace associated with this thread would then simplify the job of determining how such a call got scheduled on the thread responsible for GUI updates.

Finally, note the two “Clear...” buttons on this screen. Every screen (except the Configuration screen) in the MonkeyWrench contains these two buttons; one to clear the profiling data in the current screen, and one to clear the profiling data in all screens. This feature is provided as a convenience to allow you to clear the profiling data just before an important event occurs in your target application.

Figure 5 shows the “Memory” screen of the MonkeyWrench profiler, this time for the popular “jEdit” Java file editor, after a couple of files have been opened, parsed and displayed. As you might expect, a lot of objects get constructed by an editor during this type of activity, so the memory usage table (similar to the method/constructor table in the CPU screen, but in this case, showing objects instantiated) has quite a few entries. This application is an example of a case where the search window (identical in operation to the one in the CPU screen) can be quite useful.

Figure 5 -- The Memory Screen

In this case, we have selected jEdit’s ServiceManager’s inner class Descriptor. We see that there are 34 instances of this class for a total of 1088 bytes (note that the object size, as returned by the instrumentation hooks of the JVM, is a shallow size). We selected the “View Threads” button above the upper table, which displays the threads for all 34 occurrences of this object instantiation (unlike the lower “View Threads” button, which would just show the 4 occurrences for the selected site summary) and can see that 32 times, the Descriptor was instantiated on the AWT event thread, but 2 times it was instantiated on one of jEdit’s I/O threads.

Working our way down the list in the site summary table, we could find the one (or at most two) sites where the jEdit I/O thread was used to instantiate one of these objects. In fact, if we scroll down through the list of sites (practical in this case only because there are not that many sites) we would see that it is stack trace #15 which was used by this particular thread, as seen in Figure 6. Matching a thread with a stack trace can help you find errors in applications, especially those that spawn a chain of thread‐start operations (in some cases, handing over to the AWT event thread) in the process of handling a request.

Figure 6 -- Memory Screen Detail View

As with the CPU screen, the Memory screen has fully sortable tables and buttons to clear the CPU and Memory profiling data, or to clear all profiling data. While the sizes reported by the JVM for each object are probably not that useful, it can be revealing to see just how many instances of a class are being created by an application, particularly if the relevant constructor involves some resource‐intensive activity. In this case, you should also be seeing large CPU‐time numbers for the constructor on the MonkeyWrench’s CPU screen.

Published at DZone with permission of Wayne Adams, author and DZone MVB.

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)

Tags:

Comments

Bhabho Sharma replied on Thu, 2010/02/11 - 1:43am

Felt motivated reading this. I am a Java developer and i am very eager to create some new, innovative application some day. That is why i am going to attend Sun Tech Days 2010 conference in Hyderabad. Experts are going to share ideas on new technologies there. lets see what happens.

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.