Aprof
by Devexperts
In this tutorial we will demonstrate how to use Aprof. Note, that this guide is actual for version 19.
Getting Started
First of all, extract aprof.jar from downloaded zip file with AProf binaries. This JAR is the file you will be using.
Note, that you should not rename the aprof.jar file, otherwise it will not work.
Running Aprof
Aprof comes with integrated help explaining all supported options and their default values. Execute the following line from the console to read it:
java -jar aprof.jar
You will see that in order to profile your Java application with Aprof you should start JVM with -javaagent:aprof.jar option. For example, to profile well-known SwingSet2 demo you need to start it this way:
java -javaagent:aprof.jar -jar SwingSet2.jar
That's it! While you are using the demo, Aprof collects its memory allocation statistics and flushes it to aprof.txt file every minute.
Examples
Aforementioned SwingSet2 demo is a complex application, hence its profiling results are not suitable for this tutorial. We will be using a series of specifically designed samples. Some of them make no sense, some are written in non-optimal way, some might even contain bugs. Most likely you will never see them in real applications. However, they help us demonstrate key features of Aprof.
Fibonacci Numbers
Let's take a look at the following program.
package com.devexperts.sample;
public class FibonacciNumbers {
private static Integer fib(int n) {
if (n < 2)
return 1;
return fib(n - 1) + fib(n - 2);
}
public static void main(String[] args) {
int n = Integer.parseInt(args[0]);
System.out.printf("fib(%d)=%d\n", n, fib(n));
}
}
It calculates nth Fibonacci number and prints it to stdout. However, the method returns Integer instead of int which leads to a lot of garbage generated by the program. In large applications it is usually hard to find all such ineffective pieces of code.
Let's run this program under Aprof.
java -javaagent:aprof.jar com.devexperts.sample.FibonacciNumbers 40
And look at generated file aprof.txt.
TOTAL allocation dump for 34,124 ms (0h00m34s)
Allocated 83,091,888 bytes in 2,936,168 objects in 953 locations of 299 classes
-------------------------------------------------------------------------------
java.lang.Integer: 34,953,936 (42%) bytes in 2,184,621 (74%) objects (avg size 16 bytes)
java.lang.Integer.valueOf: 34,926,944 (99%) bytes in 2,182,934 (99%) objects
java.lang.Integer.valueOf: 34,852,928 (99%) bytes in 2,178,308 (99%) objects
com.devexperts.sample.FibonacciNumbers.fib: 34,852,928 (100%) bytes in 2,178,308 (100%) objects
com.devexperts.aprof.AProfAgent.go: 52,816 (0%) bytes in 3,301 (0%) objects
com.devexperts.aprof.AProfRegistry.makeSnapshot: 21,184 (0%) bytes in 1,324 (0%) objects
java.lang.Integer.getInteger: 16 (0%) bytes in 1 (0%) objects
com.intellij.rt.execution.application.AppMain.main: 16 (100%) bytes in 1 (100%) objects
org.objectweb.asm.ClassReader.readConst: 18,112 (0%) bytes in 1,132 (0%) objects
com.devexperts.aprof.AProfAgent.go: 13,696 (75%) bytes in 856 (75%) objects
com.devexperts.aprof.transformer.AProfTransformer.transform: 4,416 (24%) bytes in 276 (24%) objects
org.objectweb.asm.tree.LookupSwitchInsnNode.<init>: 4,736 (0%) bytes in 296 (0%) objects
com.devexperts.aprof.AProfAgent.go: 2,848 (60%) bytes in 178 (60%) objects
com.devexperts.aprof.transformer.AProfTransformer.transform: 1,888 (39%) bytes in 118 (39%) objects
java.lang.Integer$IntegerCache.<clinit>: 4,096 (0%) bytes in 256 (0%) objects
com.devexperts.aprof.AProfAgent.go: 4,096 (100%) bytes in 256 (100%) objects
sun.reflect.UnsafeIntegerFieldAccessorImpl.get: 48 (0%) bytes in 3 (0%) objects
com.devexperts.aprof.AProfAgent.go: 48 (100%) bytes in 3 (100%) objects
...
We see that 42% of all memory allocations were made for Integer objects. And almost all of them were done in method fib of class FibonacciNumbers.
Let's fix the bug with unnecessary boxing/unboxing.
package com.devexperts.sample;
public class FibonacciNumbers {
private static int fib(int n) {
if (n < 2)
return 1;
return fib(n - 1) + fib(n - 2);
}
public static void main(String[] args) {
int n = Integer.parseInt(args[0]);
System.out.printf("fib(%d)=%d\n", n, fib(n));
}
}
And run the program under Aprof again. We will get the following results in aprof.txt file:
TOTAL allocation dump for 26,142 ms (0h00m26s)
Allocated 48,231,592 bytes in 757,741 objects in 953 locations of 299 classes
-------------------------------------------------------------------------------
char[]: 12,568,720 (26%) bytes in 185,155 (24%) objects (avg size 68 bytes)
java.util.Arrays.copyOfRange: 3,392,352 (26%) bytes in 51,144 (27%) objects (avg size 66 bytes)
com.devexperts.aprof.AProfAgent.go: 2,370,320 (69%) bytes in 35,586 (69%) objects (avg size 67 bytes)
com.devexperts.aprof.transformer.AProfTransformer.transform: 1,014,784 (29%) bytes in 15,491 (30%) objects (avg size 66 bytes)
java.lang.StringBuilder.toString: 4,896 (0%) bytes in 49 (0%) objects (avg size 100 bytes)
java.net.URLStreamHandler.parseURL: 1,504 (30%) bytes in 10 (20%) objects (avg size 150 bytes)
sun.net.www.protocol.jar.Handler.parseContextSpec: 624 (12%) bytes in 2 (4%) objects (avg size 312 bytes)
sun.net.www.protocol.jar.Handler.parseURL: 624 (12%) bytes in 2 (4%) objects (avg size 312 bytes)
sun.net.www.ParseUtil.decode: 560 (11%) bytes in 4 (8%) objects (avg size 140 bytes)
java.util.ResourceBundle$Control.toBundleName: 256 (5%) bytes in 3 (6%) objects (avg size 85 bytes)
java.util.ServiceLoader$LazyIterator.hasNext: 256 (5%) bytes in 2 (4%) objects (avg size 128 bytes)
java.io.ObjectStreamClass.getClassSignature: 224 (4%) bytes in 5 (10%) objects (avg size 45 bytes)
java.util.Locale.toString: 112 (2%) bytes in 6 (12%) objects (avg size 19 bytes)
sun.util.resources.LocaleData$LocaleDataResourceBundleControl.getCandidateLocales: 112 (2%) bytes in 4 (8%) objects (avg size 28 bytes)
java.net.URLClassLoader.getPermissions: 104 (2%) bytes in 1 (2%) objects (avg size 104 bytes)
...
There are no suspicious memory allocations here. Note, that often the most garbage is generated for char[] objects.
Overview
Content Tools