tags:

views:

568

answers:

4

Hi,

I made a little program to test the System.currentTimeMillis (). And I have a strange result. This is my logs :

1    26-12-09 20:48:21 - [Log] lTime = 1261860501009
2    26-12-09 20:48:21 - [Log] lTime = 1261860501012
3    26-12-09 20:48:21 - [Log] lTime = 1261864899078
4    26-12-09 20:48:21 - [Log] lTime = 1261860501033
5    26-12-09 20:48:21 - [Log] lTime = 1261860501069

As you can see, there is a problem on line 3. The time millis is wrong. It should be between 1261860501012 and 1261860501033. There is an error of, roughly, 73 milli seconds.

Somebody knows where the problem come from ?

Thanks a lot

bill0ute

Edit : OS : Debian 4.0, Java : 6_17.

My code :

while (true) 
    setLog (System.currentTimeMillis ());

Edit : The program run on a Linux based VPS

+1  A: 

First of all, you have a little typo, it's 73 milliseconds, not seconds ( would be disturbing then :-) ).

To get to the point, you should be aware that Java is a very high-level language with access to system functions only provided to you through native function calls. These calls are implemented by your Virtual Machine, and there are quite a few ( Sun, Open, Dalvik.. ), so general advice can't be given, but the return time currentTimeMillis is depending on a lot of stuff, like Threading ( in the VM as well as native threads ), the resolution of the onboard timer etc. I admit that the results are strange, but unless you are highly dependent on their correct order, I wouldn't bother and just live with an anomaly in the range of a tenth of a second.

If you need more specific advice, please paste some of your source code!

Edit:

After having seen your source, I'm quite sure that your Log function uses some kind of priority processing, or threading, that leads to false results. Just try to assign the return value of the method in question and pass that variable to your log:

long foo = System.currentTimeMillis();
setLog(foo);
moritz
Hum, I'm pretty sure it's 73 seconds because the difference between line 3 and 4 is roughly 4300000 milliseconds.
bill0ute
but the log timestamps indicate something different, anyhow, it seems like there are unwanted side effects somewhere. Have you tried my approach above?
moritz
I don't understand what is "the method in question".
bill0ute
System.currentTimeMillis();
moritz
4,300,000 milliseconds is 4,300 seconds.
Pool
You can get 73 seconds shift with NTP as well ;), but not up and down like this.
Peter Lawrey
A: 

We once saw a similar thing, running on Ubuntu with AMD64x2 chips. If you also have the chip that is where I would start looking.

Paul Wagland
My program is on a VPS, and I can't find the chip of it.
bill0ute
VPS may lead us to the answer. Xen and VMWare both tinker around with the CPU timers they emulate ( or manipulate ) for the guest machines, so the values given are everything but reliable. Certain versions are known for having bugs where CPU time ( ticks ) even moves backwards..
moritz
Still you have to wonder what the logging system is doing if it is consistently getting good times. Though maybe it has already done a min() work-around.
PSpeed
+1  A: 

System.currentTimeMillis() is dependent on System clock. It looks like the system clock has been micro-corrected by an external programme, for Linux that's probably NTP.

Note you shouldn't use System.currentTimeMillis() to measure elapsed time. It's better to use System.nanoTime() but even that isn't guaranteed to be monotonic.

Pool
A: 

The method in question depends on the system clock and system clocks can have problems. See http://support.ntp.org/bin/view/Support/KnownOsIssues for a discussion of issues keeping the system clock accurate via the ntpd(8) daemon.

I also recommend http://www.vmware.com/pdf/vmware_timekeeping.pdf for a discussion on the accuracy of the system clock in VMWare. It also has as excellent discussion on system clocks in general.

Steve Emmerson