Aprof
by Devexperts
In this tutorial we will demonstrate how to use Aprof. Note, that this guide is actual for version 21.
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.
Understanding Statistics
In order to understand aprof.txt file you should be aware of the following specifics of Aprof.
Imagine we are interested in allocations of char[]. Aprof will collect all locations where these allocations take place. Naturally, some of them occur in constructor of String object. However, it is not enough to know that, for instance, 3 char[] with total size of 120 bytes were allocated at location java.lang.String.<init>. We are also interested in locations from which we called constructor of class String. In order to collect such additional information without taking stack-traces the following method is used.
In Aprof configuration some constructors/methods are marked as tracked. What exactly does that mean? When we mark the method as tracked, we tell Aprof that we are interested in occurrences of the method on stack-trace taken at the moment of memory allocation. The trick we use is the fact that knowledge of the outermost tracked method and location from which it was called is enough to pinpoint the problem. Hence, for each memory allocation the following data is collected by Aprof:
- type of allocated object;
- location where the allocation took place;
- the outermost tracked method (if any) on stack-trace of the allocation;
- location where the tracked method was called from.
These data is organized in a tree structure with types of objects being tree roots. Here is the example of how it might look like in the actual output:
...
java.util.LinkedHashMap$Entry: 18,880 (0%) bytes in 590 (0%) objects (avg size 32 bytes)
java.util.LinkedHashMap.createEntry: 18,560 (98%) bytes in 580 (98%) objects
com.devexperts.aprof.AProfAgent.go: 18,432 (99%) bytes in 576 (99%) objects
java.util.HashMap.put: 128 (0%) bytes in 4 (0%) objects
java.io.ExpiringCache.put: 128 (100%) bytes in 4 (100%) objects
java.util.LinkedHashMap.init: 320 (1%) bytes in 10 (1%) objects
com.devexperts.aprof.AProfAgent.go: 128 (40%) bytes in 4 (40%) objects
java.util.HashMap.<init>: 128 (40%) bytes in 4 (40%) objects
java.util.LinkedHashMap.<init>: 128 (100%) bytes in 4 (100%) objects
java.util.HashSet.<init>: 64 (20%) bytes in 2 (20%) objects
java.util.LinkedHashSet.<init>: 64 (100%) bytes in 2 (100%) objects
java.lang.Long: 18,336 (0%) bytes in 1,146 (0%) objects (avg size 16 bytes)
org.objectweb.asm.ClassReader.readConst: 18,304 (99%) bytes in 1,144 (99%) objects
com.devexperts.aprof.AProfAgent.go: 16,992 (92%) bytes in 1,062 (92%) objects
com.devexperts.aprof.transformer.AProfTransformer.transform: 1,312 (7%) bytes in 82 (7%) objects
java.lang.Long.valueOf: 16 (0%) bytes in 1 (0%) objects
java.lang.Long.valueOf: 16 (100%) bytes in 1 (100%) objects
com.devexperts.sample.FibonacciNumbers.main: 16 (100%) bytes in 1 (100%) objects
sun.reflect.UnsafeLongFieldAccessorImpl.get: 16 (0%) bytes in 1 (0%) objects
com.devexperts.aprof.AProfAgent.go: 16 (100%) bytes in 1 (100%) objects
...
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)
...
There are no suspicious memory allocations here. Note, that for many programs it is normal to have the most garbage generated for char[] objects.
Overview
Content Tools