This tests how accurate the CodeTimer is compared to manually timing the code using System.nanoTime(). Run the main method to test.
import static CodeTimer.*;
import java.text.DecimalFormat;
import java.util.*;
/**
*
* @author Keith
*/
public class CodeTimerTest {
public static void main(String[] args){
// Test to see if the manual profiling method using System.nanoTime()'s gives
// the same results as the convenience class CodeTimer.
// The first test does manual profiling and prints the results,
// the second test uses the CodeTimer.
long testRunningTimeNanos = 11*NANOS_IN_A_SECOND; // run each test for 11 seconds.
Random random = new Random(0);
// warm the JIT compiler
for (int i = 0; i < 1024; i++){
float randomAngle = random.nextFloat();
long t0 = System.nanoTime();
// the calculation being timed:
double sine = Math.sin(randomAngle);
double cosine = Math.cos(randomAngle+1);
double tan = Math.tan(randomAngle+2);
double calc = Math.sqrt(Math.pow(Math.pow(sine, cosine), tan));
long t1 = System.nanoTime();
}
System.out.println(CodeTimer.class.getSimpleName()+": starting test 1.");
long startNanos = System.nanoTime();
random = new Random(0);
long nanoSelfTime = calibrateNanoTime(10000);
System.out.println(CodeTimer.class.getSimpleName()+": System.nanoTime() selfTime == "+nanoSelfTime);
long totalNanos = 0;
double lastPrintOutNanos = System.nanoTime();
float maxSecondsBeforePrintOut = 5;
long count = 0;
while (true){
float randomAngle = random.nextFloat();
long t0 = System.nanoTime();
// the calculation being timed:
double sine = Math.sin(randomAngle);
double cosine = Math.cos(randomAngle+1);
double tan = Math.tan(randomAngle+2);
double calc = Math.sqrt(Math.pow(Math.pow(sine, cosine), tan));
long t1 = System.nanoTime();
totalNanos += t1 - t0 - nanoSelfTime;
count++;
if (System.nanoTime() - lastPrintOutNanos > maxSecondsBeforePrintOut*NANOS_IN_A_SECOND){
double avTotalNanos = (double)totalNanos/(count);
System.out.println(CodeTimer.class.getSimpleName()+": avTotalNanos == "+decimalFormat.format(avTotalNanos));
totalNanos = 0;
count = 0;
lastPrintOutNanos = System.nanoTime();
}
if (System.nanoTime() - startNanos > testRunningTimeNanos){
break;
}
}
System.out.println(CodeTimer.class.getSimpleName()+": starting test 2.");
startNanos = System.nanoTime();
random = new Random(1000);
CodeTimer codeTimer = new CodeTimer(NANOS, false, NONE);
System.out.println(CodeTimer.class.getSimpleName()+": CodeTimer.SELF_TIME == "+CodeTimer.SELF_TIME);
while (true){
float randomAngle = random.nextFloat();
codeTimer.click();
// the calculation being timed:
double sine = Math.sin(randomAngle);
double cosine = Math.cos(randomAngle+1);
double tan = Math.tan(randomAngle+2);
double calc = Math.sqrt(Math.pow(Math.pow(sine, cosine), tan));
codeTimer.lastClick();
if (System.nanoTime() - startNanos > testRunningTimeNanos){
break;
}
}
System.out.println(CodeTimer.class.getSimpleName()+": finished.");
}
// This is only used in the testing of the manual method.
protected static long calibrateNanoTime(int numTests){
boolean print = false;
// warm the JIT
for(int i=0; i<1024; i++){
System.nanoTime();
}
// find how out long it takes to call click(), so that time can be accounted for
ArrayList<Long> selfTimeObservations = new ArrayList<Long>(numTests);
for (int i = 0; i < numTests; i++){
long nanoSelfTime = -(System.nanoTime() - System.nanoTime());
if (print){
System.out.println(CodeTimer.class.getSimpleName()+": nanoSelfTime == "+nanoSelfTime);
}
selfTimeObservations.add(nanoSelfTime);
}
// sort the times
Collections.sort(selfTimeObservations);
if (print){
for (int i = 0; i < selfTimeObservations.size(); i++){
System.out.println(CodeTimer.class.getSimpleName()+": selfTimeObservations.get(i) == "+selfTimeObservations.get(i));
}
}
// cut out the slowest 5% which are assumed to be outliers
for (int i = 0; i < (int)(numTests*0.05); i++){
selfTimeObservations.remove(0);
}
// cut out the fastest 5% which are assumed to be outliers
for (int i = 0; i < (int)(numTests*0.05); i++){
selfTimeObservations.remove(selfTimeObservations.size()-1);
}
if (print){
System.out.println(CodeTimer.class.getSimpleName()+": Slimmed list: selfTimeObservations.size() == "+selfTimeObservations.size());
for (int i = 0; i < selfTimeObservations.size(); i++){
System.out.println(CodeTimer.class.getSimpleName()+": selfTimeObservations.get(i) == "+selfTimeObservations.get(i));
}
}
// find the average
long sumOfSelfTimes = 0;
for (int i = 0; i < selfTimeObservations.size(); i++){
sumOfSelfTimes += selfTimeObservations.get(i);
}
long nanoSelfTime = sumOfSelfTimes/selfTimeObservations.size();
return nanoSelfTime;
}
}
This was my output on Windows Vista, java 6 update 17:
CodeTimer: starting test 1.
CodeTimer: System.nanoTime() selfTime == 1381
CodeTimer: avTotalNanos == 1,276.9695 <— 1st manual method measurement of average nanoseconds to do the calc’s
CodeTimer: avTotalNanos == 1,253.9743 <— 2nd manual method measurement of average nanoseconds to do the calc’s
CodeTimer: starting test 2.
CodeTimer: CodeTimer.SELF_TIME == 1375
CodeTimer: avTotalNanos == 1,270.8229 <— 1st convenience class measurement of average nanoseconds to do the calc’s
CodeTimer: avTotalNanos == 1,260.9276 <— 2nd convenience class measurement of average nanoseconds to do the calc’s
CodeTimer: finished.
Which shows that the manual method and the convenience class give pretty similar results. Phew!
CodeTimer sounds fine to me.