Chapter 5. Profiling using the Builder

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.