Logging of method execution time

Question

In java/groovy application I am using org.slf4j.Logger I like to log method execution time and proposing to use following code

def startTime
LOGGER.isDebugEnabled() {
    startTime = System.currentTimeMillis()
}

doSomething()

LOGGER.debug("Execution took {}ms", (System.currentTimeMillis() - startTime))

I think this code is 'ugly'. Can anyone suggest something more elegant ?

Answer 1

You can probably use this class to calculate elapsed time.

public class StopWatch {

    /* Private Instance Variables */
    /** Stores the start time when an object of the StopWatch class is initialized. */
    private long startTime;

    /**
     * Custom constructor which initializes the {@link #startTime} parameter.
     */
    public StopWatch() {
        startTime = System.currentTimeMillis();
    }

    /**
     * Gets the elapsed time (in seconds) since the time the object of StopWatch was initialized.
     * 
     * @return Elapsed time in seconds.
     */
    public double getElapsedTime() {
        long endTime = System.currentTimeMillis();
        return (double) (endTime - startTime) / (1000);
    }
}

And use it like this:

public class SWTest {

    public static void main(String[] args) {
        StopWatch stopWatch = new StopWatch();

        doSomething();

        LOGGER.debug("Execution took in seconds: ", (stopWatch.getElapsedTime());
    }
}

Answer 2

When measuring a difference between 2 points in time, you should use System.nanoTime(), the millis variant should be used when you are actually interested in measuring the time (from the epoch value) but not when you want to measure a difference in time as precisely as possible.

Also see http://docs.oracle.com/javase/7/docs/api/java/lang/System.html#nanoTime()

Returns the current value of the running Java Virtual Machine's high-resolution time source, in nanoseconds.