Getting negative duration time between two long actions?

Question

I'm querying a server URL using a Thread and I'm calculating the time taken to query this server and get a response to be used as a response time but sometimes, the time returned is negative, and this shouldn't occurs!

I could suppose it's when the connection fails and this happens so quickly, but for me, calling two consecutire System.nanoTime() should never be lower than, at least, 0 !

Here's my code :

final long startTime = System.nanoTime();
ExecutorService executor = Executors.newFixedThreadPool(1);

Connector connector = new Connector(url);
String response = null;
Long duration = null;

try {
   Future<String> future = executor.submit(connector);
   response = future.get(Connector.timeout, TimeUnit.MILLISECONDS);

   duration = Long.valueOf(System.nanoTime() - startTime);
}
catch (Exception e) {}

executor.shutdown();

// Here, duration is sometimes negative !

And the Connector.java :

public class Connector implements Callable<String> {
    public final static int timeout = 2500; // WE use a timeout of 2.5s, which should be enough

    private String urlStr;

    public Connector(String url) {
        this.urlStr = url;
    }

    @Override
    public String call() throws Exception {
        URL url = new URL(urlStr);

        HttpURLConnection connection = (HttpURLConnection)url.openConnection();
        connection.setConnectTimeout(timeout - 50);
        connection.setRequestMethod("GET");
        connection.setRequestProperty("User-Agent", "Mozilla/5.0 (X11; Linux i686; rv:21.0) Gecko/20100101 Firefox/21.0");
        connection.connect();

        int code = connection.getResponseCode();
        connection.disconnect();
        return String.valueOf(code);
    }
}

Do you have any idea why ?

Update : On this S.O. question, the first comment (by @gustafc) of the first answer (by david-johnstone) is very interesting :

One gotcha (on Windows w. Sun JDK6, in any case) with nanoTime is that the value returned depends on the CPU core executing the thread. If the thread starts executing on one core and finishes on another core, your numbers will be somewhat off. I had code like long start = System.nanoTime(); doIt(); long elapsedNanos = System.nanoTime() - start; and wound up with elapsedNanos being negative. –

I'm running my machine under a Linux Fedora release, but maybe this is what's happening.

Clearly, the problem is with System.nanoTime() but I wasn't able to find a better alternative :/

"Long actions" - how long? if I recall correctly `.nanoTime()` overflows after some 300 years... :-) — Anders R. Bystrup, Nov 13 '13 at 10:24
I don't think it's the problem but could you try to eliminate autoboxing by making `duration` a `long` instead? — Anders R. Bystrup, Nov 13 '13 at 10:31
duration can be null if the Thread is killed after running too long :/ — Cyril N., Nov 13 '13 at 10:32
Instead, I do a `duration = Long.valueOf(System.nanoTime() - startTime);` for avoiding auto boxing — Cyril N., Nov 13 '13 at 10:33

score 1 · Answer 1 · answered Nov 13 '13 at 12:10

So I took your code, added a System.out.println("Time: " + (duration == null ? "aborted" : duration)); to the end and run it a few thousand times... it never returned anything even remotely negative. I even tried to comment out the connection part and again the minimum time was close to 120,000ns.

If you ever got a negative time, there is either something in your code that you did not post, or it is the fault of your operating system/JVM implementation. Java and System.nanoTime()is doing its job perfectly fine.

Your comment about negative time differences when calculating time in different threads is interesting, but even if this was happening, the "somewhat off" part would be more like +/- 10 or 100 ns and definitely not >100,000ns.

That what I'm supposing, it CAN NOT be under 0ns. Now I switched to `ThreadMXBean` for getting the `CurrentThreadCpuTime` and run it a moment. The lower I get is 0. Now I'm calling this checking from an Akka actor that also use a `ThreadPool` (via an `ExecutorService`). That mean I have 10 threads (I defined as 10 for now) that generate a 1 Thread (the code above). Maybe it's too thread-ceptionned ? — Cyril N., Nov 13 '13 at 13:37

score 0 · Answer 2 · answered May 20 '14 at 18:00

The javadoc for nanoTime says

The value returned represents nanoseconds since some fixed but arbitrary origin time (perhaps in the future, so values may be negative).

So you would need to take the absolute value of the difference between the start and end times.

Getting negative duration time between two long actions?

2 Answers2