Java on Linux: Measuring elapsed time using System.nanotime() for a thread that blocks

Question

I have a thread that takes an object from an ArrayBlockingQueue() connectionPool. The thread may be blocked if ArrayBlockingQueue() is empty. To measure the time for which the calling thread is blocked, I use the following code:

long start = System.nanoTime();
DataBaseEndPoint dbep = connectionPool.take();
long end = System.nanoTime();
long elapsed = (end - start)/1000000;

Now, my concern is that the unblocked thread may start running on a different processor in a multi-processor machine. In that case, I am not entirely sure if the 'System Timer' used is the same on different processors. This blog-post (http://www.javacodegeeks.com/2012/02/what-is-behind-systemnanotime.html) suggests that Linux uses a different Time-Stamp counter for each processor (also used for System.nanotime()), which can really mess up the elapsed time calculation in the above example.

The value is read from clock_gettime with CLOCK_MONOTONIC flag Which uses either TSC or HPET. The only difference with Windows is that Linux not even trying to sync values of TSC read from different CPUs, it just returns it as it is. It means that value can leap back and jump forward with dependency of CPU where it is read.

This link (http://lwn.net/Articles/209101/) however, suggests that TSC is no longer used for high-resolution timers.

... the recently-updated high-resolution timers and dynamic tick patch set includes a change which disables use of the TSC. It seems that the high-resolution timers and dynamic tick features are incompatible with the TSC...

So, the question is, what is used by a Linux machine to return value to System.nanotime() currently? And, is using System.nanotime() safe for measuring elapsed time in the above case (blocked thread starting on another processor). If it isn't safe, what's the alternative?

Fer Fer · Accepted Answer · 2014-08-27T14:49:26

One thing invaluable about virtual machines (and life in general) is abstraction. The threads' execution time do not differ based on the number of cores; not in Linux, nor in Windows, etc... I hope I am not misunderstanding your question.

(Although I am using currentTimeMillis(), nanotime is the same in a different scale, of course)

Check the following example I crafted:

public class SynchThreads {

    public static void main(String[] args) throws InterruptedException {
        GreedyTask gtA = new GreedyTask("A");
        GreedyTask gtB = new GreedyTask("B");
        Thread a = new Thread(gtA);
        Thread b = new Thread(gtB);
        a.start();
        b.start();
        a.join();
        b.join();
        System.out.println(gtA.toString()+" running time: "+gtA.getRunningTime());
        System.out.println(gtB.toString()+" running time: "+gtB.getRunningTime());
    }

    private static class GreedyTask implements Runnable {

        private long startedTime, finishedTime, totalRunTime;
        private String myName;

        public GreedyTask(String pstrName) {
            myName = pstrName;
        }

        public void run() {
            try {
                startedTime = System.currentTimeMillis();
                randomPowerNap(this);
                finishedTime = System.currentTimeMillis();
                totalRunTime = finishedTime - startedTime;
            } catch (Exception e) { System.err.println(e.getMessage()); }
        }

        public String toString() { return ("Task: " + myName); }
        public long getRunningTime() { return this.totalRunTime; }
    }

    private static synchronized void randomPowerNap(GreedyTask gt) throws       InterruptedException {
        System.out.println("Executing: "+gt.toString());
        long random = Math.round(Math.random()*15000);
        System.out.println("Random time for "+gt+" is: "+random);
        Thread.sleep(random);
    }
}

The following is the output of a run in a 4 cores windows machine:

Executing: Task: A
Random time for Task: A is: 1225
Executing: Task: B
Random time for Task: B is: 4383
Task: A running time: 1226
Task: B running time: 5609 // what's funny about this? this is equal to Btime - Atime

This was run in a 4 cores Linux machine:

Executing: Task: A
Random time for Task: A is: 13577
Executing: Task: B
Random time for Task: B is: 5340
Task: A running time: 13579
Task: B running time: 18920 // same results

Conclusions: B total time adds the time it had to wait while randomPowerNap was blocked by A, hence due to the hardware abstraction of the virtual machine, threads see no difference in their running times since they all run in a 'VIRTUAL BIG CORE', if you know what I meant.

I hope this helped.

Java on Linux: Measuring elapsed time using System.nanotime() for a thread that blocks

1 Answers