Aprof
by Devexperts
...
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.
...
Let's take a look at the following program.
No Format |
---|
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.
No Format |
---|
java -javaagent:aprof.jar com.devexperts.sample.FibonacciNumbers 40 |
And look at generated file aprof.txt.
No Format |
---|
TOTAL allocation dump for 36,706 ms (0h00m36s)
Allocated 83,088,072 bytes in 2,936,099 objects in 953 locations of 299 classes
-------------------------------------------------------------------------------
java.lang.Integer: 34,953,904 (42%) bytes in 2,184,619 (74%) objects (avg size 16 bytes)
java.lang.Integer.valueOf: 34,926,912 (99%) bytes in 2,182,932 (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,152 (0%) bytes in 1,322 (0%) objects
java.lang.Integer.decode: 16 (0%) bytes in 1 (0%) objects
java.lang.Integer.getInteger: 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.
No Format |
---|
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:
No Format |
---|
TOTAL allocation dump for 24,267 ms (0h00m24s)
Allocated 48,231,872 bytes in 757,672 objects in 953 locations of 299 classes
-------------------------------------------------------------------------------
char[]: 12,568,176 (26%) bytes in 185,145 (24%) objects (avg size 68 bytes)
java.util.Arrays.copyOfRange: 3,392,160 (26%) bytes in 51,140 (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,592 (29%) bytes in 15,487 (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 usually the most garbage is generated on char[] objects.