Wrong Time with System.currentTimeMillis () (Java)

Question

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

OS : Debian 4.0, Java : 6_17. Code : while (true) {setLog (System.currentTimeMillis ())}; — bill0ute, Dec 26 '09 at 21:30
(Not sure if this is relevant in your case but) also check out this post by Kevin Bourrillion about the differences of `currentTimeMillis` and `nanoTime`: http://stackoverflow.com/questions/1770010/how-do-i-measure-time-elapsed-in-java/1776053#1776053 — Jonik, Dec 26 '09 at 21:30
@bill0ute: Please don't add clarifications as comments. Edit your question and add the new info. — MAK, Dec 26 '09 at 21:45
I wonder what the first part of your logs is using to get the time... since it's nearly impossible to get the time in Java without calling System.currentTimeMillis() or making native calls. Something else is going on here that has not been provided to us. — PSpeed, Dec 26 '09 at 21:46
I find a "solution" : I make 2 times the System.currentTimeMillis () and take the min. — bill0ute, Dec 26 '09 at 21:56
This has been incorrectly edited - the time difference is 4,398 seconds. — Pool, Dec 27 '09 at 14:59

score 7 · Answer 1 · answered Dec 26 '09 at 22:46

7

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.

answered Dec 26 '09 at 22:46

Pool

11,999
14
68
78

NTP wouldn't adjust the time forward and then back again. Also, the formatted time remained the same. Agree with you on avoiding the clock for elapsed time, but I'd use one of the StopWatch implementations (such as from Apache). – NVRAM Feb 16 '12 at 18:12

score 0 · Answer 2 · answered Dec 26 '09 at 21:33

0

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);

answered Dec 26 '09 at 21:33

moritz

2,448
1
20
25

Hum, I'm pretty sure it's 73 seconds because the difference between line 3 and 4 is roughly 4300000 milliseconds. – bill0ute Dec 26 '09 at 21:36
but the log timestamps indicate something different, anyhow, it seems like there are unwanted side effects somewhere. Have you tried my approach above? – moritz Dec 26 '09 at 21:48
I don't understand what is "the method in question". – bill0ute Dec 26 '09 at 21:54
2

4,300,000 milliseconds is 4,300 seconds. – Pool Dec 26 '09 at 22:58
1

You can get 73 seconds shift with NTP as well ;), but not up and down like this. – Peter Lawrey Dec 27 '09 at 09:27

score 0 · Answer 3 · answered Dec 26 '09 at 21:37

0

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.

answered Dec 26 '09 at 21:37

Paul Wagland

27,756
10
52
74

My program is on a VPS, and I can't find the chip of it. – bill0ute Dec 26 '09 at 21:44
2

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 Dec 26 '09 at 21:50
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 Dec 26 '09 at 22:31

Steve Emmerson · Answer 4 · 2009-12-27T02:05:46.257

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.

Wrong Time with System.currentTimeMillis () (Java)

4 Answers4

Linked