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.

Sounds like the result is cached, Java compiler/VM being too "smart". Perhaps you can fool it by placing the code in a function that takes a dummy argument that you vary? It's sometimes amazing how little obfuscation is needed to disable inlining and caching optimizations. Cheers, — Cheers and hth. - Alf, Jan 24 '11 at 04:12
milliseconds may be too large a unit to effectively measure. If a smaller unit is still 0 then make sure your method generates different keys each call. Otherwise it could be optimized to return a constant if it always returns the same value. — EnabrenTane, Jan 24 '11 at 04:13
Do you really think it takes a whole millisecond to generate a DES key (after initialization)??? You're doing a LOT of things wrongly. I canceled my answer, because of Pangea being faster. — maaartinus, Jan 24 '11 at 04:16

score 4 · Accepted Answer · answered Jan 24 '11 at 04:12

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.

score 2 · Answer 2 · answered Jan 24 '11 at 04:12

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).

score 2 · Answer 3 · edited May 23 '17 at 12:11

2

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?

edited May 23 '17 at 12:11

Community

1
1

answered Jan 24 '11 at 04:13

Aravind Yarram

78,777
46
231
327

score 1 · Answer 4 · answered Jan 24 '11 at 04:18

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.

score 1 · Answer 5 · answered Jan 24 '11 at 04:23

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

score 1 · Answer 6 · answered Jan 24 '11 at 04:32

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");

Rogach · Answer 7 · 2011-01-24T04:15:17.150

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.

Measure execution time

7 Answers7