Java Management Extensions, Raw profiling, and ThreadMXBeans.

The Java Management Extensions are a hidden gem in the JDK that many plain Java developers ignore- probably because of the deceptively enterprisey name.  These APIs are not just useful for profiling large Java EE apps.  Rather – they give you a precise and unbiased view into any snippet of code, by allowing you to look at CPU time and thread usage in a very direct fashion.

The poor man’s JMX profiling might look something like this: 

long startTime=System.currentTimeInMilliseconds();
doSomething();
long mseconds = System.currentTimeInMilliseconds()-mseconds();
System.out.println(“It took ” + seconds +” milliseconds”);

This might work on a simple machine that is not running any other applications.  But in a multiuser (or worse multithreaded) envioronment, the meaning of a raw time stamp before and after a method is lost.  A better way to do the same test: 


long startTime=ManagementFactory.getThreadMXBean().getCurrentThreadCpuTime()/1000000;
doSomething();
long mseconds =ManagementFactory.getThreadMXBean().getCurrentThreadCpuTime()1000000;
System.out.println(“It took ” + mseconds + ” cpu milliseconds”);

CPU time, if measured in Milliseconds, can have a HUGE standard deviation because of the fact that we run so many different applications on a machine.  The ThreadMXBeans are able to lock down the time, specifically, when your JVM is actually USING the CPU.  

I’m really serious here:  Check out how, in a simple test which adds several elements to a vector, we can see that, as we increase the size of the test the CPU time and real time diverge very rapidly ():

SIZE OF TEST : 10000
raw time:6 milliseconds
cpu time:5 milliseconds

SIZE OF TEST : 19952
raw time:6 milliseconds
cpu time:2 milliseconds

SIZE OF TEST : 39810
raw time:2 milliseconds
cpu time:1 milliseconds

SIZE OF TEST : 79432
raw time:3 milliseconds
cpu time:3 milliseconds

SIZE OF TEST : 158489
raw time:6 milliseconds
cpu time:6 milliseconds

SIZE OF TEST : 316228
raw time:11 milliseconds
cpu time:8 milliseconds

SIZE OF TEST : 630959
raw time:21 milliseconds
cpu time:16 milliseconds

SIZE OF TEST : 1258929
raw time:78 milliseconds
cpu time:33 milliseconds

SIZE OF TEST : 2511895
raw time:204 milliseconds
cpu time:69 milliseconds

The code (RudolF sandbox repository git@github.com:jayunit100/RudolF.git, or just paste this and run it as a main class).

package net.rudolfcode.jvm;

import java.lang.management.ManagementFactory;
import java.util.ArrayList;
import java.util.Collection;
import java.util.Vector;

/**
 * You can use this class to profile insert times for a collection type 

(Vector in the example, but swapping it with an ArrayList is 10X faster at large scale).

 */
public class Example3 {

 public static void main(String[] args) throws Exception{
   profile((int)Math.pow(10, i));
 }

 private static void profile(int nums) {
   
  ManagementFactory.getThreadMXBean().getCurrentThreadCpuTime();
    System.out.println("SIZE OF TEST : " +nums);
    final long cpuStart1=System.currentTimeMillis();
    run(new Vector(),nums);
    final long cpu1=(System.currentTimeMillis()-cpuStart1);
    System.out.println("raw time:"+cpu1 + " milliseconds ");

    final long cpuStart2=ManagementFactory.getThreadMXBean().getCurrentThreadCpuTime()/1000000;
    run(new Vector(),nums);
    final long cpu2=ManagementFactory.getThreadMXBean().getCurrentThreadCpuTime()/1000000;
    System.out.println("cpu time:"+(cpu2-cpuStart2) +" milliseconds");
    System.out.println();
 }
 
 public static float average(Collection<Long> l){
  long value=0;
  for(Long v : l){
   value+=v;
  }
  return ((float)value)/(float)l.size();
 }
  
 /**
  * Add "size" elements into a collection .
  */
 public static void run(Collection impl, int size) {
  impl.clear();
  //add a bunch of stuff to a collection
  for(int x = 10 ; x < size; x++){
   impl.add((short)x);
  }
 }

}