VisualVM Basics

We recently deployed AppDynamics at work and not to be leaving all the good stuff to the new tools, I thought I’d have a look at VisualVM . I wanted to have a good look at this for a while, it’s shipped with the JDK for the last couple of versions too.

I wrote some bad code and cracked it open to get a feel for it. I made the performance bottleneck obvious so that it will be easy to find in the output of of VisualVM. (Code is below)

Download VisualVM or use the one shipped with your JDK $JAVA_HOME/bin/jvisualvm

Running VisualVM, I see my application in the left hand side (Illustration A 1,2) , double clicking this opens a tabbed pane to the right (Illustration A3).

 

Illustration A

From here I can choose various ‘profiling’ options, I’m going to use Profiler as my program is trivial and I don’t care about instrumentation overhead. Selecting the Profiler tab, I profile Memory, after editing the settings and selecting the option to Profile Stack Traces ((Illustration A 4, 6).

The char allocation here is clearly marked by VisualVM, this is the large String I am building up in badAppend(..) – (Profile the CPU to see the method execution info).

Interestingly here, there is a TreeMap coming in strongly behind the expected char[] array – to investigate the origins of this, I can right click the list item during profiling and select the TakeSnapshot and Show Stack Trace option – in reality I had to take the Snapshot first and then right click – my target program crashes out otherwise. The graph presented identifies the garbage collector (Illustration A 5)  – who would have been working hard … Take a look at the heap/memory allocation rate in the first tab – monitor and you’ll see it’s climbing up to a peak – dropping as the garbage collector reclaims the thousands of unnecessary objects we are allocating in createDataSize

 

 

Illustration B

 

Notice the pattern of the peaks here, I’m wondering is this a sweep of the Eden space, followed by some admin then a sweep of the survivor spaces?

 

I couldn’t find the VM arguments in VisualVM* so I ran jps -v on the command line; giving me this

4529 Main -Xms128m -Xmx750m -XX:MaxPermSize=350m -XX:ReservedCodeCacheSize=96m -XX:+UseCodeCacheFlushing -ea -Dsun.io.useCanonCaches=false -Djava.net.preferIPv4Stack=true -Djb.vmOptionsFile=/home/alan/apps/idea-IU-129.1359/bin/idea64.vmoptions -Xbootclasspath/a:/home/alan/apps/idea-IU-129.1359/bin/../lib/boot.jar -Didea.paths.selector=IntelliJIdea12 -Djb.restart.code=88
11096 Jps -Dapplication.home=/home/alan/apps/jdk1.8.0 -Xms8m

 

* Actually there they are, just below the Heap Tab in Illustration B

 

The Xmx750m is my pool/heap size – when we near this the GC must intervene – next time I’ll investigate the length of these GC runs – in theory it should be quick as we are following the ‘expected’ many short lived objects pattern, meaning that most garbage will be run on the small Eden space – with fewer on the survivor spaces.  To check this I installed the   excellent VisualGC plugin:

Illustration C

VisualGC Plugin

I can see the eden space being GC’d quite often and the survivor spaces what seems to be less often – but climbing. I think I took this screenshot early in the run which would explain the increasing allocation rate.

 

Watching the full animation of the GC Plugin is well worth it. This VM is using a Parallel GC and we can see it in action as the program runs.  When the Eden space fills, a GC occurs,  at about 50% of Max. Eden space on this run , S0 (Survior 0) is populated with a ‘2nd generation’ of objects  – freeing up some room in (the cheapest memory space to GC)  Eden, S1 is often purged at this point too.  This allows the application to optimistically  run on with a ‘healthy’ Eden space available.  The GC people wouldn’t be catering for these intentional heap filling executions!!  When we quickly once again fill Eden, S0 is purged, promoting it’s objects to their 3rd generation and into S1.  My large Heap space / Old Gen fills  far slower relative to the other spaces.   This cycle repeats as the program runs, explaining I believe the shape of the Heap allocation graph in Illustration B

None of this is science, just me passing time!

I’m using Java 1.8 and Visual VM 1.3.8

 

 

package tests;

/**
* Created with IntelliJ IDEA.
* User: alan
* Date: 09/09/14
* Time: 18:54
* To change this template use File | Settings | File Templates.
*/
//http://stackoverflow.com/questions/2474486/create-a-java-variable-string-of-a-specific-size-mbs
public class SimpleStringHogger {

public static void main(String... args) {
new SimpleStringHogger().createDataSize(Integer.valueOf(args[0]));
System.out.println("Done");
}

private StringWrapper createDataSize(int msgSize) {
StringWrapper data = new StringWrapper("a");
while (data.length() < (msgSize * 1024) - 6) {
data = data.badAppend("s");
}
return data;
}

private class StringWrapper {
private String s;

private StringWrapper(String s) {
this.s = s;
}

public StringWrapper badAppend(String s) {
return new StringWrapper(this.s + s);
}

public int length() {
return s.length();
}
}
}