Multithreading with Java nanoTime

Question

I am currently programming a multithreaded program with Java. At some points different threads log their actions and I'm using nanoTime for this. Every thread has it's own log file and at the end I merge them and sort them based on their time (nanoTime) to see what happened. The thing is that I have erroneous behaviour similar to this where x is a volatile variable:

// logged by thead1
x = true // done at time 0000, time computed & logged after x = true was done

// no events in between

// logged by thread2
read x // reads false while time before reading is 0001

So it seems to me that nanoTime doesn't really time things correctly. In nanoTime documentation it's written:

The values returned by this method become meaningful only when the difference between two such values, obtained within the same instance of a Java virtual machine, is computed.

Is it perhaps possible for threads created by the same process to be executed in different JVMs? This would explain the erroneous behaviour of nanoTime but still it doesn't make too much sense. Any ideas?

Answer 1

This is entirely dependant on the OS, but if you have one CPU socket you will have trouble seeing any error using nanoTime. If you use Wiindows 7+ or a recent version of Linux, nanoTime corrects for the differences between sockets. BTW If you have a multi-socket XP box you can see nanoTime jump backwards and forwards by a few milli-seconds. (In short don't use XP on multi-socket machines and expect a good outcome)

Also note that some OSes have only micro-second resolution. This means you can have many operations performed between threads and they all appear to have the same time stamp. The solution to this is to use an OS with higher resolution timers. This doesn't involve changing your code or even your JVM.

Is it perhaps possible for threads created by the same process to be executed in different JVMs?

I don't know of any way for this to be possible, nor can I think of a reason this would matter. The same system call is made regardless of which thread, JVM or process you are using.

This would explain the erroneous behaviour of nanoTime but still it doesn't make too much sense. Any ideas?

Most likely you only have micro-second resolution for the call nanoTime() calls on your OS.

read x // reads false while time before reading is 0001

If you have better than micro-second timing, every call to nanoTime() is likely to be different. An update to a volatile variable via the cache takes a minimum of 75 clock cycles or ~20 nano-seconds. Nothing is instant, and I have seen delays of closer to 100 nano-second for delays between thread for trivial updates between threads.

Answer 2

I don't know it's valid to expect nanoTime to allow you to order events which happened on different threads in this way. I would reconsider your design with each thread having a separate log file which you merge together based on the time. If you're using log4j, I would just have them write to the same log.

If you are building your own logging implementation, I would have them write their messages to a java.util.concurrent.LinkedBlockingQueue (there will be no contention, which is what I suspect you are trying to avoid by having each thread have its own log), and have another thread that is responsible for periodically draining any messages available in the queue and writing them to the file.