Java/Profiling

Methods

There are various methods for profiling Java code. Some are covered below.

Hprof

Hprof is a lower-level profiling tool than the Java Mission Control, which makes it both easier and harder. It gives much more useful information than the JMC method of profiling, although the information is a bit too low level.

Compiling

No special compiler flags are needed here.

$ javac NQueens.java

Running

You will need to include the following flags when you call Java:

$ java -agentlib:hprof NQueens

Note that hprof has many options, most covered on the official documentation page for hprof: https://docs.oracle.com/javase/7/docs/technotes/samples/hprof.html

Hprof output

I tested hprof on a Java implementation of a recursive backtracking solution to the N queens problem, which made heavy use of integer arrays to keep track of where various queens had been placed and check what squares were valid for placing the next queen.

The result was a file with over 1 million lines, detailing every single function call that occurred and the trace for each. HUUUUGE amount of information.

At the very end of the file (using tail -n 100) was a summary of what was contained in the lines above:

SITES BEGIN (ordered by live bytes) Sat Mar 18 22:29:07 2017
          percent          live          alloc'ed  stack class
 rank   self  accum     bytes objs     bytes  objs trace name
    1 38.18% 38.18%  14603008 228172  53886464 841976 300465 int[]
    2 19.10% 57.28%   7305056 228283  26946784 842087 300271 java.util.LinkedList
    3 19.09% 76.37%   7301920 228185  26943648 841989 300463 java.util.LinkedList$ListItr
    4 14.50% 90.87%   5545128 231047  20548512 856188 300461 java.util.LinkedList$Node
    5  3.56% 94.43%   1363200 14200   1363200 14200 300470 char[]
    6  1.70% 96.13%    650544 5073   3197984 24586 300010 char[]
    7  0.89% 97.02%    340800 14200    340800 14200 300471 java.util.LinkedList$Node
    8  0.89% 97.91%    340800 14200    340800 14200 300469 java.lang.String
    9  0.36% 98.27%    136080 2835    681600 14200 300467 char[]
   10  0.24% 98.51%     92152 1000     92152  1000 300000 char[]
   11  0.18% 98.69%     68040 2835    340800 14200 300466 java.lang.StringBuilder
   12  0.14% 98.83%     52536  597    348656  3962 300468 char[]
   13  0.07% 98.90%     26312  518     26312   518 300000 java.lang.Object[]
   14  0.07% 98.96%     25504    8     25504     8 300000 byte[]
   15  0.06% 99.03%     24280  990     24280   990 300000 java.lang.String
   16  0.02% 99.04%      6672   97      7184   105 300268 char[]
   17  0.01% 99.05%      4640  257      4640   257 300000 java.lang.Integer
   18  0.01% 99.07%      4288  118      4288   118 300000 java.util.Hashtable$Entry
SITES END

This means FORTY PERCENT of the code was spent on array operations. That's a lot - but not terribly surprising, since this implementation an N queens solution makes heavy use of arrays.

Java Mission Control

Not nearly as useful, since you don't get a method-level breakdown of how much time was spent in various places in the code. Lots and lots of superfluous information, though.

Compiling

Nothing special is required when you compile your code if you are going to profile it with Java Mission Control.

$ javac NQueens.java

Running

You can specify that Java should create an output file for Java Mission Control by using flags:

$ java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder -Dscijava.log.level=error  \
-XX:StartFlightRecording=name=MyRecording,duration=999s,filename=//tmp/my_flight_recording.jfr,settings=profile NQueens

When that's finished, you can run Java Mission Control, which has a GUI interface and can be used to open the /tmp/my_flight_recording.jfr file:

$ jmc

For the recursive backtracking method, this did not reveal anything about where the real time was being spent.

References

List of Java profiling tools: http://imagej.net/Profiling_Java_Code