Chapter 5. Profiling using the Builder

Table of Contents
Creating a Profile
Using a Profile for Compilation

Creating a Profile

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 2.2 Release 1
Generating code for target 'linux-gnu-i686'
 + HelloWorld__.c
 * C compiling
 * linking
 * stripping
Class file compaction gain: 95.85755% (1722798 ==> 71366)
	
      
    

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_THREADS: 2 Threads used
PROFILE: 70 (0%)        java/io/Writer.<init>()V
PROFILE: 17460 (15%)    java/io/Writer.write(Ljava/lang/String;II)V
PROFILE: 6 (0%)         java/lang/Long.<clinit>()V
PROFILE: 18 (0%)        java/lang/Class.<init>(I)V
PROFILE: 50 (0%)        java/lang/Class.forName(Ljava/lang/String;)...
PROFILE: 120 (0%)       java/lang/Class.forName(Ljava/lang/String;Z...
PROFILE: 240 (0%)       java/lang/Class.forNameSlashes(Ljava/lang/S...
...
	
      
    

To be able to use the profile information later, the output should be saved into a file as in the following call with output redirection to HelloWorld.prof:

      > ./HelloWorld >HelloWorld.prof
    

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:

      > cat HelloWorld.prof | grep "PROFILE:" | sort -n -k 2 -r
          
PROFILE: 29040 (25%)    gnu/java/io/encode/EncoderEightBitLookup....
PROFILE: 17460 (15%)    java/io/Writer.write(Ljava/lang/String;II)V
PROFILE: 12650 (11%)    java/lang/String.substring(II)Ljava/lang/...
PROFILE: 7952 (7%)      gnu/java/io/encode/EncoderEightBitLookup....
PROFILE: 5477 (4%)      java/lang/String.replace(CC)Ljava/lang/St...
PROFILE: 3752 (3%)      java/lang/StringBuffer.append(Ljava/lang/...
PROFILE: 3718 (3%)      java/lang/String.indexOf(II)I
PROFILE: 2578 (2%)      gnu/java/io/encode/Encoder8859_1.<clinit>()V
PROFILE: 2577 (2%)      gnu/java/io/decode/Decoder8859_1.<clinit>()V
PROFILE: 1894 (1%)      java/util/Hashtable.put(Ljava/lang/Object...
PROFILE: 1680 (1%)      java/io/FileDescriptor.write([BII)V
PROFILE: 1592 (1%)      java/lang/String.length()I
PROFILE: 1560 (1%)      gnu/java/io/encode/EncoderEightBitLookup....
PROFILE: 1336 (1%)      HelloWorld.main([Ljava/lang/String;)V
PROFILE: 1281 (1%)      java/lang/System.getProperties()Ljava/uti...
PROFILE: 1040 (0%)      java/lang/String.equals(Ljava/lang/Object;)Z
PROFILE: 1035 (0%)      java/util/Hashtable.rehash()V
PROFILE: 1014 (0%)      java/lang/StringBuffer.ensureCapacity2(I)V
PROFILE: 960 (0%)       java/io/FileOutputStream.write([BII)V
PROFILE: 872 (0%)       java/lang/reflect/AccessibleObject.clazz(...
PROFILE: 792 (0%)       java/lang/StringBuffer.<init>(I)V
PROFILE: 786 (0%)       java/util/Hashtable.hash(Ljava/lang/Objec...
PROFILE: 753 (0%)       java/lang/StringBuffer.needBuffer()V
PROFILE: 648 (0%)       java/lang/StringBuffer.toString()Ljava/la...
PROFILE: 510 (0%)       java/io/PrintWriter.println()V
    
  

It is of little surprise that in this small example program, nearly all of the execution time is spend in the Methods like Writer.write and StringBuffer.append (where the calls to the StringBuffer methods have been generated automatically by the compiler for String-concatenation expressions using the '+'-operator.