1

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?

insumity
  • 5,311
  • 8
  • 36
  • 64
  • "Is it perhaps possible for threads created by the same process to be executed in different JVMs?" not unless you explicitly create a separate jvm first. Is your code above in the same thread? – Taylor Nov 19 '13 at 22:09
  • I see. No `x = true` is done in a different thread from `read x` – insumity Nov 19 '13 at 22:10
  • Show us more of your code. It's hard to find a potential synchronization bug with just two lines of code. – JB Nizet Nov 19 '13 at 22:14
  • @JBNizet the code is pretty large to be able to put in a SO question. I just tried to reduce it ... :s. So you cannot have any idea of why is this happening from my described behaviour? – insumity Nov 19 '13 at 22:16
  • To be clear, x is declared as volatile? If so, my bet is you have some other synchronization issue going on. – Taylor Nov 19 '13 at 22:30

2 Answers2

3

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.

Peter Lawrey
  • 525,659
  • 79
  • 751
  • 1,130
  • I have no reason to doubt, because I know you know these low-level functions very well. But why doesn't the javadoc of nanoTime mention this? It explicitely says: *The same origin is used by all invocations of this method in an instance of a Java virtual machine; other virtual machine instances are likely to use a different origin.*, which is in contradiction with the multi-socket problems you're talking about in your answer. – JB Nizet Nov 19 '13 at 22:29
  • @JBNizet I would read this as meaning; it is not required. I don't know of any OS/JVM where different processes on the same machine have different origins. It is an added complexity I don't see any value in an OS or JVM adding. – Peter Lawrey Nov 19 '13 at 22:31
  • @JBNizet On the other hand, on Windows XP, one thread can see the time jump forward and backwards. This is the only example of a problem I have seen. – Peter Lawrey Nov 19 '13 at 22:32
  • Thanks for answering. May I ask what "multi-socket XP" is? Does it mean multiprocessor? Or how do I find out if my processor is multi-socket? About the micro-second resolution I think my processor has better time resolution since all the times are different (even two consequent `nanoTime` calls give me different number). In my example the numbers `000` and `001` were arbitrary. Usually the difference is more than 1000ns. – insumity Nov 20 '13 at 00:34
  • I remember reading about `nanoTime` being implemented by calls to [`QueryPerformanceCounter`](http://stackoverflow.com/questions/1723629/what-happens-when-queryperformancecounter-is-called) in XP. – Ralf H Nov 20 '13 at 16:55
  • I assume you know whether you have XP or not. I am not sure how to check the number of sockets without `Sandra` on Windows. – Peter Lawrey Nov 20 '13 at 19:34
0

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.

David Conrad
  • 15,432
  • 2
  • 42
  • 54