A Java class for use in creating time traces in tests when tracking down performance problems. It prints the time between each call to the trace() method, as well as logging when methods are entered and exited. Use it by instantiating a new TestTimeTracer as a field and then calling .trace() on the tracer between each line of code of a test. Whe…

TestTimeTracer.java

public class TestTimeTracer {

    public static final int MILLIS_PER_NANO = 1000000;

    private final Stack<Pair<String, Integer>> traceCounts = new Stack<>();
    private final NumberFormat numberFormat = NumberFormat.getIntegerInstance();

    private String methodName = null;
    private int methodTraceCount = 0;
    private int lastStackDepth = 0;
    private long lastCallTime = System.nanoTime();

    public void trace() {
        StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
        int currentStackDepth = stackTrace.length;

        if (currentStackDepth > lastStackDepth) {
            if (lastStackDepth != 0) {
                traceCounts.push(new ImmutablePair<>(methodName, methodTraceCount));
            }
            methodTraceCount = 0;
            methodName = stackTrace[2].getMethodName();
            System.out.println(">>> " + methodName);
        } else {
            methodTraceCount++;
            long timeSinceLastCallMillis = (System.nanoTime() - lastCallTime) / MILLIS_PER_NANO;
            System.out.printf("%3d - %3d: %8s ms\n", methodTraceCount - 1, methodTraceCount, numberFormat.format(timeSinceLastCallMillis));

            if (currentStackDepth < lastStackDepth) {
                System.out.println("<<< " + methodName);
                Pair<String, Integer> traceCount = traceCounts.pop();
                methodName = traceCount.getLeft();
                methodTraceCount = traceCount.getRight();
            }
        }

        lastStackDepth = currentStackDepth;
        lastCallTime = System.nanoTime();
    }

}