How to accurately measure Java method's running time?

Question

I had to report the mean running time of a java method. I do it the following way

//method start
long startTime = System.nanoTime();
//method body here ...
long estimationTime = System.nanoTime() - startTime; 
//method end

I run the method many many times, log the results and then report the mean and variance of running time in microseconds.

Here is the problem I got the following values (very large spikes exist)

note that other values are not zeros (zoom in reveals it)

My Questions:

1. What the main cause of these outliers (spikes)?
2. How to report the running time accurately in a case like this?

Take a look at the method body (For the curious)

TraceRecord resultRecord = new TraceRecord();
    resultRecord.setTimeStamp(timeStamp);
    resultRecord.setUserID(userID);

    if (sensorValue.getSensorType() == SensorType.WIFI) {
        ArrayList<WifiBaseStation> wifiAPsInRange = new ArrayList<WifiBaseStation>();

        for (int i = 0; i < sensorValue.getBaseStationsIdentifiers().length; i++) {

            WifiBaseStation wifiAP = new WifiBaseStation(sensorValue.getRepresentativeName(i),
                    sensorValue.getBaseStationsIdentifier(i));
            wifiAP.getSignalStrengthsList().add(sensorValue.getSignalValue(i));
            wifiAPsInRange.add(wifiAP);
        }
        if (wifiAPsInRange.size() > 0) {

            double averageLong = 0;
            double averageLat = 0;
            int matchedCount = 0;

            for (WifiBaseStation bs : wifiAPsInRange) {
                WifiBaseStation bsFromTable = WiFiUniqueWarDrivingTable.Get(bs.getMacAddress());
                if (bsFromTable != null) {
                    GPSLocation locationFromTable = bsFromTable.getBaseStationLocationUsingAverage();
                    if (locationFromTable != null) {
                        averageLong += locationFromTable.getLongitude();
                        averageLat += locationFromTable.getLatitude();
                        matchedCount++;
                    }else{
                        averageLong++;
                        averageLong--;
                    }
                }else{
                    averageLong++;
                    averageLong--;
                }

            }

            if (averageLong != 0) {
                averageLong /= matchedCount;
            }
            if (averageLat != 0) {
                averageLat /= matchedCount;
            }

            if (averageLat != 0 && averageLong != 0) {
                resultRecord.setLocationPoint(new GPSLocation(averageLong, averageLat, 0));
            } else {
                return null;
            }
        }

    }

Answer 1

The likeliest cause for these spikes are "stop the world" breaks caused by the GC. There isn't much you can do to prevent this from happening. The best try is calling System.gc() once before taking the first measurement.

Answer 2

You need to track what the program is doing in those times. For example, there are some lines in your code that your a call to another service (probably not controlled by you) is done. You need to profile this service as well.

You can do it by your self adding a lot of this time control measurements, or use a profile tool like jVisualVM, or new Relic.

This last one you can analyse graphics and receive feedback in a online platform.

After analyse all the data, you can start to change some features on your program, or even in you JVM if necessary. For example, if the problem is related to a full GC process, you can change the GC algorithm that your JVM is using at startup.

Answer 3

For very fast operations, there is a big chance of "something" happens. It can be GC, it can be another process which takes your processor time (like your antivir decide to check something right now).

But there is an easy solution. If you want to know "true" processing time, you just have to run your method body several times and count average time from it. It assures that even if "something" happens, it would have minimal impact on your results.

Here is very simple example :

    int count = 0;
    long start = System.nanoTime();
    for (int i = 0; i < 1000000; i++) {
        count++;
    }
    long end = System.nanoTime();
    long totalTime = end - start;
    System.out.println("Incrementing int variable cost you + " + (totalTime/(double) 1000000) + " nanoseconds");

You can try to run this and as you can see, if you run it again and again, totalTime will be almost the same.

Answer 4

Trying to measure time spans in the microsecond range is hard (or practically impossible). The resolution of the timer that is used in the System.nanoTime() call is limited, and depends on the operating system (more details can easily be found, e.g. at System.currentTimeMillis vs System.nanoTime )

Additionally, there may be arbitrary interferences, ranging from the ones that are bound to the JVM (namely, a garbage collection run), over the user-generated ones (some additional thread that you have running somewhere else in your program), to the "external" ones, like your mail client popping up the "You have mail" window, or a delay that is caused by the MP3 player that is running in the background as an amusement during the boring, boring benchmarking run ;-)

A profiler is obviously the first choice for identifying bottlenecks in a complex system. And in this case, a profiler may be helpful in order to "zoom" into the method: Any method call that is done from this method could be the reason for the "spikes". For example, a call like sensorValue.getSignalValue(i) or bs.getMacAddress() could do some weird hardware interrupt accesses via a native library... or maybe randomly launch "MineSweeper" in the background, who knows.

An interesting question would also be what you actually want to measure. Given the question, it may sound naive, but: Why do the spikes matter? Is the spike itself really a problem, or just an artifact that attracted your curiosity? I can not imagine that it is relevant in practice wheter whether the execution time of this method for 100 calls is 100x1ms or 99x1ms+1x2ms. If this is intended for some sort of "microbenchmarking", you should at least compute the average time over 100 calls anyhow (and preferably use a microbenchmarking framework).