visualgc plugin for visualvm
By klichong on Apr 17, 2009
Did you know that visualvm has a visualgc plugin? Maybe I'm just late to the game. The following example hopefully will illustrate how useful this plugin in conjunction with visualvm.
I am debugging a problem where after starting the GlassFish application server, it seems to hang and become unresponsive. (Note that this was occurring because my particular instance had several composite applications already deployed to it which seemed to be causing an issue) This manifests when the server log indicates that the server did indeed startup, but when I tried login to the administration page, it just hangs. Usually at this point, it is useful to get a thread dump to investigate what is going on. However, in this case I had a suspicion that this was memory related so I was curious to see how the memory usage was in the heap.
I added some JVM options to find some garbage collection (GC) details
-XX:+PrintGCDetails and -Xloggc:gclog.txt.
These two options, when added to the domain.xml will reveal the garbage collection details. Restarting the application server and tailing this gclog.txt while trying to duplicate the issue revealed the following logs:
<snip> 386.522: [GC [PSYoungGen: 188796K->102397K(204800K)] 903386K->830907K(985856K), 0.2852612 secs]</snip>
What does this mean?
386.522 - this collection happened at 386.522 seconds from when the application server was started.
188796K->102397K(204800K) this indicates that the memory usage after GC went from 188,796K to 102,397K. In other words, this is the size of the live objects before and after GC.
Adding the flag -XX:+PrintGCDetails gives us additional information. The overall heap went from 903,386K to 830,907K and this collection took 0.2852612 seconds. OK, nothing new yet. If you have read http://java.sun.com/docs/hotspot/gc1.4.2/, this is standard stuff.
After this, the gclog reveals a series a full GC after which the server becomes unresponsive:
Admittedly, parsing through the gclog can be tedious although it is full of information. The visualgc plugin gives us the ability to view each generation of the heap behaves during GC cycles. So go to the visualvm website and install it along with the visualgc plugin. The links provide instructions on how to download, install and run the application.
After you start GlassFish, double-clicking on the GlassFish pid gives you the monitoring information for your instance.
Click on the VisualGC tab (this should appear if you have installed the plugin correctly). This will give us specific information about our heap:
[NOTE: The astute observer will observe the pid of GlassFish changing from the 1st screenshot to the 2nd. The blame goes to my poor skill in taking a screenshot but the points being illustrated still apply to the new pid]
The heap is divided into several spaces as indicated by the figure. Objects are initially allocated in the Eden generation, and its size is indicated by the height of the orange bar in the Eden section. When you are viewing this real time, it can be rising and shrinking indicating how objects are instantiated (rising) then garbage collected (shrinking) depending what your application server is doing at the present moment. S0 and S1 indicate the two survivor spaces. All three of these comprise the young generation space. Objects are copied between survivor spaces until they are old enough to be part of the tenured, or Old generation, indicated by the middle green bar. The third space, indicated by Perm space, is the permanent generation. This space holds data needed by the virtual machine that do not have a Java equivalent, like metadata about objects describing classes and methods. You can find more details about the spaces and garbage collection in this excellent reference.
Recall in my particular issue, the server does startup but becomes unresponsive. The snapshot above shows the heap just after starting GlassFish. There has already been 7 GC collections in the Eden space and some objects have already been promoted to the tenured space.
The server log shows that the components of the composite applications were still being deployed which was causing many object creation and destruction. The second snapshot below shows how much larger the tenured generation has grown while the Eden graph shows spiky behavior, typical of many GC cycles.
The third snapshot below was taken when the gclog indicates continuous GC cycles. The tenured space is full now and the GC cycles are continuously happening for both the Eden space and tenured.
Is this a memory leak? Unwise object management? The next step would involve taking a heap dump (also possible with visualvm under the "Memory Sampler" tab) and taking a histogram of the objects in this dump. Note that the dump can also be viewed conveniently within visualvm.
For the purpose of this entry, I just wanted to highlight the use of visualgc plugin in visualvm and how you can see GC and object promotion in your heap as they occur in real time.