Measure execution time

Question

I want to measure the time it takes to generate DES Key, and I want to compute it several time, so that I can find the average value.

for (int x = 0; x < 10; x++)
{
     long startTime = System.currentTimeMillis();

     SecretKey key = KeyGenerator.getInstance("DES").generateKey();         

     long stopTime = System.currentTimeMillis();
     long elapsedTime = stopTime - startTime;
     System.out.println("Total Time Taken : " + elapsedTime);
}

but the result comes out like

Total Time Taken : 251
Total Time Taken : 0
Total Time Taken : 0
Total Time Taken : 0
Total Time Taken : 0
Total Time Taken : 0
Total Time Taken : 0
Total Time Taken : 0
Total Time Taken : 0
Total Time Taken : 0

I tried to dispose the key object by setting it to null and then calling System.gc(); but it didn't work.

Any suggestion or idea to overcome this problem.

Answer 1

Crank up your counts. The currentTimeMillis() resolution power is limited by hardware and OS capabilities. In particular, it isn't capable of actually resolving down to absolute exact ms. I found that it isn't accurate down in the 300 ms range.

You may also want to try System.nanoTime() if you need better precision on small intervals. Note that again, the accuracy of this function will depend on the operating system. I believe that the last time I tried this Linux would return more accurate results than Windows. May or may not still be true.

Answer 2

If generateKey() is very fast, you might want to run some number of iterations of it between the two timing calls. Timers have error (and there is some overhead in getting the timer's value), and so trying to time things that are as fast or faster than the timer interval (1ms here) will produce very inaccurate results. Try putting a separate loop that runs 1000 times around just the key generation (but still within your outer loop).

Answer 3

Micro bench marking is hard. I suggest you use Google's open source project Caliper for this.

How do I write a correct micro-benchmark in Java?

Answer 4

The 251 ms in the initial call primarily represents the JVM's looking up the correct provider for the "DES" algorithm, and initializing the state associated with it.

DES keys are just random 64-bit values (well, actually 56, but that's a different story). I'd expect that it takes less than a millisecond to do that.

If you want to see exactly how much time, try using System.nanoTime(), which gives time at a nanosecond resolution (though its accuracy might be somewhat less than that) for exactly this type of application.

Answer 5

Use System.nanoTime() to get the time in nanoseconds.

You'll get more accurate times if you use System.nanoTime() rather than System.currentTimeMillis(). Results will look like this:

Total Time Taken : 687562592
Total Time Taken : 51328
Total Time Taken : 33838
Total Time Taken : 25474
Total Time Taken : 22432
Total Time Taken : 29656
Total Time Taken : 23192
Total Time Taken : 28516
Total Time Taken : 22812
Total Time Taken : 21672

Answer 6

It can be hard to measure a really small value - like trying to measure the width of a dime with a ruler. You're better off measuring 10 or 20 of them in a stack and then dividing the measurement by the number of them in the stack.

int iterations = 1000;

long startTime = System.currentTimeMillis();
for (int x = 0; x < iterations; x++) {
     SecretKey key = KeyGenerator.getInstance("DES").generateKey();         
}
long stopTime = System.currentTimeMillis();

long elapsedTime = stopTime - startTime;
double average = elapsedTime/((double) iterations);
System.out.println("Total Time Taken : " + average + " ms");

Answer 7

It can be because of JVM run-time optimisations. So on the first runs it performs profiling, and on subsequent invocations method runs much quicker.

Also it can be the because of the method - the first invocation can do some initialization work, like loading classes, creating objects and so on.

Usually, when doing benchmarking of java code it is recommended to discard first several invocations.

EDIT: And in your case, if you don't use that SecretKey instance anywhere, JVM can decide that it is not needed at all, and that code is not even called in the process.