7

I've a requirement to capture the execution time of some code in iterations. I've decided to use a Map<Integer,Long> for capturing this data where Integer(key) is the iteration number and Long(value) is the time consumed by that iteration in milliseconds.

I've written the below java code to compute the time taken for each iteration. I want to ensure that the time taken by all iterations is zero before invoking actual code. Surprisingly, the below code behaves differently for every execution.

Sometimes, I get the desired output(zero millisecond for all iterations), but at times I do get positive and even negative values for some random iterations.

I've tried replacing System.currentTimeMillis(); with below code:

new java.util.Date().getTime();

System.nanoTime();

org.apache.commons.lang.time.StopWatch

but still no luck.

Any suggestions as why some iterations take additional time and how to eliminate it?

package com.stackoverflow.programmer;

import java.util.HashMap;
import java.util.Map;

public class TestTimeConsumption {

    public static void main(String[] args) {
        Integer totalIterations = 100000;
        Integer nonZeroMilliSecondsCounter = 0;
        Map<Integer, Long> timeTakenMap = new HashMap<>();
        for (Integer iteration = 1; iteration <= totalIterations; iteration++) {
            timeTakenMap.put(iteration, getTimeConsumed(iteration));
            if (timeTakenMap.get(iteration) != 0) {
                nonZeroMilliSecondsCounter++;
                System.out.format("Iteration %6d has taken %d millisecond(s).\n", iteration,
                        timeTakenMap.get(iteration));
            }
        }
        System.out.format("Total non zero entries : %d", nonZeroMilliSecondsCounter);
    }

    private static Long getTimeConsumed(Integer iteration) {
        long startTime = System.currentTimeMillis();
        // Execute code for which execution time needs to be captured
        long endTime = System.currentTimeMillis();
        return (endTime - startTime);
    }
}

Here's the sample output from 5 different executions of the same code:

Execution #1 (NOT OK)

Iteration  42970 has taken 1 millisecond(s).
Total non zero entries : 1

Execution #2 (OK)

Total non zero entries : 0

Execution #3 (OK)

Total non zero entries : 0

Execution #4 (NOT OK)

Iteration  65769 has taken -1 millisecond(s).
Total non zero entries : 1

Execution #5 (NOT OK)

Iteration    424 has taken 1 millisecond(s).
Iteration  33053 has taken 1 millisecond(s).
Iteration  76755 has taken -1 millisecond(s).
Total non zero entries : 3

I am looking for a Java based solution that ensures that all iterations consume zero milliseconds consistently. I prefer to accomplish this using pure Java code without using a profiler.

Note: I was also able to accomplish this through C code.

  • If you have to use parallel collections, then you are doing something wrong... – Boris the Spider Aug 09 '16 at 17:23
  • Yes, I agree. I'll eliminate parallel collections. Still, I need consistent execution time for all iterations. –  Aug 09 '16 at 17:44
  • As you are witnessing here, microbenchmarks in Java are not as easy as they first appear.. see http://stackoverflow.com/questions/504103/how-do-i-write-a-correct-micro-benchmark-in-java – Chris K Oct 09 '16 at 13:46

5 Answers5

4

Your HashMap performance may be dropping if it is resizing. The default capacity is 16 which you are exceeding. If you know the expected capacity up front, create the HashMap with the appropriate size taking into account the default load factor of 0.75

If you rerun iterations without defining a new map and the Integer key does not start again from zero, you will need to resize the map taking into account the total of all possible iterations.

int capacity = (int) ((100000/0.75)+1);
Map<Integer, Long> timeTakenMap = new HashMap<>(capacity);
UserF40
  • 3,129
  • 2
  • 19
  • 31
  • 1
    This appears to work. However, if I repeat this process in another iteration(no HashMap), it fails. –  Oct 09 '16 at 13:58
  • What do you use instead of HashMap? – UserF40 Oct 09 '16 at 14:00
  • Nothing, just a loop and the above code inside that. The main method is moved to another method `code()` and and current code is `while(true){ code();}` –  Oct 09 '16 at 14:03
  • Rerunning the HashMap put iterations like this means you can run into a lot more unknowns which affect performance such as constant object creation and teardowns/ possible GCs so it becomes a lot more of a grey area to optimize. – UserF40 Oct 09 '16 at 14:12
3

As you are starting to learn here, writing microbenchmarks in Java is not as easy as one would first assume. Everybody gets bitten at some point, even the hardened performance experts who have been doing it for years.

A lot is going on within the JVM and the OS that skews the results, such as GC, hotspot on the fly optimisations, recompilations, clock corrections, thread contention/scheduling, memory contention and cache misses. To name just a few. And sadly these skews are not consistent, and they can very easily dominate a microbenchmark.

To answer your immediate question of why the timings can some times go negative, it is because currentTimeMillis is designed to capture wall clock time and not elapsed time. No wall clock is accurate on a computer and there are times when the clock will be adjusted.. very possibly backwards. More detail on Java's clocks can be read on the following Oracle Blog Inside the Oracle Hotspot VM clocks.

Further details and support of nanoTime verses currentTimeMillis can be read here.

Before continuing with your own benchmark, I strongly recommend that you read how do I write a currect micro benchmark in java. The quick synopses is to 1) warm up the JVM before taking results, 2) jump through hoops to avoid dead code elimination, 3) ensure that nothing else is running on the same machine but accept that there will be thread scheduling going on.. you may even want to pin threads to cores, depends on how far you want to take this, 4) use a framework specifically designed for microbenchmarking such as JMH or for quick light weight spikes JUnitMosaic gives good results.

Community
  • 1
  • 1
Chris K
  • 10,844
  • 1
  • 29
  • 45
1

You hint it right... System.currentTimeMillis(); is the way to go in this case.

There is no warranty that increasing the value of the integer object i represent either a millisecond or a Cycle-Time in no system...

you should take the System.currentTimeMillis() and calculated the elapsed time

Example:

public static void main(String[] args) {
    long lapsedTime = System.currentTimeMillis();
    doFoo();
    lapsedTime -= System.currentTimeMillis();
    System.out.println("Time:" + -lapsedTime);
}
Community
  • 1
  • 1
ΦXocę 웃 Пepeúpa ツ
  • 43,054
  • 16
  • 58
  • 83
  • 3
    `System.nanoTime()` is preferable for benchmarking. It is even more preferable not to do it yourself. – Boris the Spider Aug 09 '16 at 17:26
  • Is it not possible to get a consistent output from this code? –  Aug 09 '16 at 17:45
  • Is that part of Java or an external library? I prefer doing this in pure Java. –  Aug 09 '16 at 18:21
  • 2
    [JMH](http://openjdk.java.net/projects/code-tools/jmh/) is part of OpenJDK, but is packaged as a separate project. Due to the nature of Java, JIT-compiled JVM language, it is almost impossible so get useable benchmarking results without some very extensive test harnessing. – Boris the Spider Aug 09 '16 at 18:57
1

I'm not sure if I understand your question. You're trying to execute a certain set of statements S, and expect the execution time to be zero. You then test this premise by executing it a number of times and verifying the result.

That is a strange expectation to have: anything consumes some time, and possibly even more. Hence, although it would be possible to test successfully, that does not prove that no time has been used, since your program is save_time();execute(S);compare_time(). Even if execute(S) is nothing, your timing is discrete, and as such, it is possible that the 'tick' of your wallclock just happens to happen just between save_time and compare_time, leading to some time having been visibly past.
As such, I'd expect your C program to behave exactly the same. Have you run that multiple times? What happens when you increase the iterations to over millions? If it still does not occur, then apparently your C compiler has optimized the code in such a way that no time is measured, and apparently, Java doesn't.

Or am I understanding you wrong?

Koos Gadellaa
  • 1,124
  • 6
  • 15
  • Sorry, am also having problem in understanding your post. What am basically trying is that the time consumption I measure should include only that of my computational logic, but not anything that is external to my logic(memory allocation overheads etc.,.). –  Oct 09 '16 at 14:02
  • And since time is discrete, at an arbitrary moment the time will go from 1 to 2, from 2 to 3, etc. (for any discernible moment and preciseness). So think about what happens when you have a clock which is almost ready to go from 1 to 2. How can you measure the time without any measurement error, when the following sequence can occur: 1) Measurement starts. 2) clock goes tick. 3) your code executes. 4. Your measurement ends. And also the same measurement, where 2) does not occur. Those two measurements will differ. And that is only because you cannot measure time infinitely precise. – Koos Gadellaa Oct 09 '16 at 14:10
0

I am also not sure exactly, You're trying to execute a certain code, and try to get the execution for each iteration of execution.

I hope I understand correct, if that so than i would suggest please use System.nanoTime() instead of System.currentTimeMillis(); because if your statement of block has very small enough you always get Zero in Millisecond.

Simple Ex could be:

public static void main(String[] args) {
    long lapsedTime = System.nanoTime();
    //do your stuff here.  
    lapsedTime -= System.nanoTime();
    System.out.println("Time Taken" + -lapsedTime);
}

If System.nanoTime() and System.currentTimeMillis(); are nothing much difference. But its just how much accurate result you need and some time difference in millisecond you may get Zero in case if you your set of statement are not more in each iteration.

Tam
  • 3,153
  • 3
  • 30
  • 50