Through the option -profile the builder provides a simple means to profile an application. To enable profiling, the option -profile has to be set, and, if the target systems requires a manual linking process, the profiling version of the Jamaica object files needs to be used.
During profiling, the Jamaica Virtual Machine counts the number of bytecode instructions executed within every method of the application. The number of instructions can be used as a measure for the time spent in each method.
At the end of the execution, the total number of bytecode instructions executed by each method is printed to the standard output stream, so that it can be used for further processing. It allows determination of 'hot spots' in the application that are the most likely sources for further performance enhancements by optimization.
The compilation technology of Jamaica is able to use the data generated when using the -profile option to guide the compilation process, to get optimial performance with lowest increase in code size.
Example:
To demonstrate the profiler, we use the HelloWorld example presented above. First, it needs to be built using the option -profile:
> jamaica -smart -profile HelloWorld Jamaica Builder Tool + HelloWorld.c + HelloWorld.makefile Classfile compaction gain: 91.086945% (125232 ==> 11162) gcc -o HelloWorld.o -c HelloWorld.c -I /Jamaica/Target/include/ -I /Jamaica/JamaicaVM/include/ -I /Jamaica/JamaicaGC/include/ gcc -o HelloWorld HelloWorld.o /Jamaica/obj/jamaica_vm.op /Jamaica/obj/jamaica_gc.op /Jamaica/obj/classes.op /Jamaica/obj/interpreter.op /Jamaica/obj/nativecode.op /Jamaica/obj/jamaica_threads.op /Jamaica/obj/jamaica_thread.op /Jamaica/obj/jamaica_target.op -lm -lpthread strip HelloWorld |
The generated executable HelloWorld now prints the profiling information after execution. The output may look like this:
> ./HelloWorld Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! Hello World! ... PROFILE: PROFILE: 3 (0%) java/lang/VirtualMachineError.<init>()V PROFILE: 3 (0%) java/lang/OutOfMemoryError.<init>()V PROFILE: 18 (0%) java/io/FilterOutputStream.<init>(Ljava/io/OutputStream;)V PROFILE: 12 (0%) java/io/FileOutputStream.<init>(Ljava/io/FileDescriptor;)V PROFILE: 360 (0%) java/io/FileOutputStream.write([BII)V PROFILE: 6 (0%) java/io/FileInputStream.<init>(Ljava/io/FileDescriptor;)V PROFILE: 600 (1%) java/lang/StringBuffer.<init>(I)V PROFILE: 720 (1%) java/lang/StringBuffer.<init>(Ljava/lang/String;)V PROFILE: 300 (0%) java/lang/StringBuffer.allocSize(I)I PROFILE: 2458 (5%) java/lang/StringBuffer.append(Ljava/lang/String;)Ljava/lang/StringBuffer; PROFILE: 30 (0%) java/lang/StringBuffer.cast2string([CI)Ljava/lang/String; PROFILE: 124 (0%) java/lang/StringBuffer.copyChars(Ljava/lang/Object;Ljava/lang/Object;II)V PROFILE: 176 (0%) java/lang/StringBuffer.ensureCapacity2(I)V PROFILE: 582 (1%) java/lang/StringBuffer.needBuffer()V PROFILE: 540 (1%) java/lang/StringBuffer.toString()Ljava/lang/String; PROFILE: 16 (0%) java/io/FileDescriptor.<clinit>()V ... |
To find the methods of the application in which most of the execution time is spend, we can sort the profiling output. In a Unix environment, a command line like this gives the 25 methods that require the biggest part of the execution time:
> HelloWorld | grep PROFILE | sort -n -k 2 -r | head -n 25 PROFILE: 23340 (51%) java/io/PrintStream.print(Ljava/lang/String;)V PROFILE: 9060 (20%) java/lang/String.substring(II)Ljava/lang/String; PROFILE: 2458 (5%) java/lang/StringBuffer.append(Ljava/lang/String;)Ljava/lang/StringBuffer; PROFILE: 1650 (3%) java/lang/String.charAt(I)C PROFILE: 1337 (2%) HelloWorld.main([Ljava/lang/String;)V PROFILE: 1320 (2%) java/lang/String.length()I PROFILE: 1020 (2%) java/io/FileDescriptor.write([BII)V PROFILE: 720 (1%) java/lang/StringBuffer.<init>(Ljava/lang/String;)V PROFILE: 600 (1%) java/lang/StringBuffer.<init>(I)V PROFILE: 582 (1%) java/lang/StringBuffer.needBuffer()V PROFILE: 540 (1%) java/lang/StringBuffer.toString()Ljava/lang/String; PROFILE: 360 (0%) java/lang/String.substring(I)Ljava/lang/String; PROFILE: 360 (0%) java/io/FileOutputStream.write([BII)V PROFILE: 300 (0%) java/lang/StringBuffer.allocSize(I)I PROFILE: 180 (0%) java/io/PrintStream.println(Ljava/lang/String;)V PROFILE: 180 (0%) java/io/PrintStream.println()V PROFILE: 176 (0%) java/lang/StringBuffer.ensureCapacity2(I)V PROFILE: 150 (0%) java/lang/String.valueOf(Ljava/lang/Object;)Ljava/lang/String; PROFILE: 124 (0%) java/lang/StringBuffer.copyChars(Ljava/lang/Object;Ljava/lang/Object;II)V PROFILE: 63 (0%) java/io/FileDescriptor.<init>(I)V PROFILE: 62 (0%) java/lang/Object.getClass()Ljava/lang/Class; PROFILE: 60 (0%) java/lang/String.toString()Ljava/lang/String; PROFILE: 60 (0%) java/lang/String.cast2string([CI)Ljava/lang/String; PROFILE: 60 (0%) java/io/FileDescriptor.fwrite(I[BII)Z PROFILE: 42 (0%) java/lang/Object.<init>()V |
It is of little surprise that in this small example program, nearly all of the execution time is spend in the Methods like PrintStream.print and StringBuffer.append (where the calls to the StringBuffer methods have been generated automatically by the compiler for String-concatenation expressions using the '+'-operator.