title: Understanding the output of -XX:+PrintCompilation
body: <p>I am running some micro benchmarks on Java list iteration code. I have used -XX:+PrintCompilation, and -verbose:gc flags to ensure that nothing is happening in the background when the timing is being run. However, I see something in the output which I cannot understand.</p>
  
  <p><strong>Here's the code, I am running the benchmark on:</strong></p>
  
  <pre><code>import java.util.ArrayList;
  import java.util.List;
  
  public class PerformantIteration {
  
      private static int theSum = 0;
  
      public static void main(String[] args) {
          System.out.println("Starting microbenchmark on iterating over collections with a call to size() in each iteration");
          List&lt;Integer&gt; nums = new ArrayList&lt;Integer&gt;();
          for(int i=0; i&lt;50000; i++) {
              nums.add(i);
          }
  
          System.out.println("Warming up ...");
          //warmup... make sure all JIT comliling is done before the actual benchmarking starts
          for(int i=0; i&lt;10; i++) {
              iterateWithConstantSize(nums);
              iterateWithDynamicSize(nums);
          }
  
          //actual        
          System.out.println("Starting the actual test");
          long constantSizeBenchmark = iterateWithConstantSize(nums);
          long dynamicSizeBenchmark = iterateWithDynamicSize(nums);
          System.out.println("Test completed... printing results");
  
          System.out.println("constantSizeBenchmark : " + constantSizeBenchmark);
          System.out.println("dynamicSizeBenchmark : " + dynamicSizeBenchmark);
          System.out.println("dynamicSizeBenchmark/constantSizeBenchmark : " + ((double)dynamicSizeBenchmark/(double)constantSizeBenchmark));
      }
  
      private static long iterateWithDynamicSize(List&lt;Integer&gt; nums) {
          int sum=0;
          long start = System.nanoTime();        
          for(int i=0; i&lt;nums.size(); i++) {
              // appear to do something useful
              sum += nums.get(i);
          }       
          long end = System.nanoTime();
          setSum(sum);
          return end-start;
      }
  
      private static long iterateWithConstantSize(List&lt;Integer&gt; nums) {
          int count = nums.size();
          int sum=0;
          long start = System.nanoTime();        
          for(int i=0; i&lt;count; i++) {
              // appear to do something useful
              sum += nums.get(i);
          }
          long end = System.nanoTime();
          setSum(sum);
          return end-start;
      }
  
      // invocations to this method simply exist to fool the VM into thinking that we are doing something useful in the loop
      private static void setSum(int sum) {
          theSum = sum;       
      }
  
  }
  </code></pre>
  
  <p><br/>
  <strong>Here's the output.</strong></p>
  
  <pre><code>    152   1       java.lang.String::charAt (33 bytes)
      160   2       java.lang.String::indexOf (151 bytes)
      165   3Starting microbenchmark on iterating over collections with a call to size() in each iteration       java.lang.String::hashCode (60 bytes)
      171   4       sun.nio.cs.UTF_8$Encoder::encodeArrayLoop (490 bytes)
      183   5
         java.lang.String::lastIndexOf (156 bytes)
      197   6       java.io.UnixFileSystem::normalize (75 bytes)
      200   7       java.lang.Object::&lt;init&gt; (1 bytes)
      205   8       java.lang.Number::&lt;init&gt; (5 bytes)
      206   9       java.lang.Integer::&lt;init&gt; (10 bytes)
      211  10       java.util.ArrayList::add (29 bytes)
      211  11       java.util.ArrayList::ensureCapacity (58 bytes)
      217  12       java.lang.Integer::valueOf (35 bytes)
      221   1%      performance.api.PerformantIteration::main @ 21 (173 bytes)
  Warming up ...
      252  13       java.util.ArrayList::get (11 bytes)
      252  14       java.util.ArrayList::rangeCheck (22 bytes)
      253  15       java.util.ArrayList::elementData (7 bytes)
      260   2%      performance.api.PerformantIteration::iterateWithConstantSize @ 19 (59 bytes)
      268   3%      performance.api.PerformantIteration::iterateWithDynamicSize @ 12 (57 bytes)
      272  16       performance.api.PerformantIteration::iterateWithConstantSize (59 bytes)
      278  17       performance.api.PerformantIteration::iterateWithDynamicSize (57 bytes)
  Starting the actual test
  Test completed... printing results
  constantSizeBenchmark : 301688
  dynamicSizeBenchmark : 782602
  dynamicSizeBenchmark/constantSizeBenchmark : 2.5940773249184588
  </code></pre>
  
  <p><br/>
  <strong>I don't understand these four lines from the output.</strong></p>
  
  <pre><code>260   2%      performance.api.PerformantIteration::iterateWithConstantSize @ 19 (59 bytes)
  268   3%      performance.api.PerformantIteration::iterateWithDynamicSize @ 12 (57 bytes)
  272  16       performance.api.PerformantIteration::iterateWithConstantSize (59 bytes)
  278  17       performance.api.PerformantIteration::iterateWithDynamicSize (57 bytes)
  </code></pre>
  
  <p><br/></p>
  
  <ul>
  <li>Why are both these methods being compiled twice ?</li>
  <li>How do I read this output... what do the various numbers mean ?</li>
  </ul>