We have a situation where a master process writes to a log.
It then spawns multiple worker processes which write to their own logs. (I wanted the workers to log through the master, but there was resistance to this idea for some reason.)
What I want to know is, can I trust that the timestamps that end up in the multiple files are consistent with each other? i.e., if I merge the log files into a single file sorting by instant, will the order of events be true? Across all possible operating systems?
The reason I’m asking this is I have a weird situation where it seems like a worker process has logged an error two seconds after the master has reported that the worker had an error. It’s like the master was able to see into the future. (I guess the master is also a time lord, but uh…)
Advertisement
Answer
The call to System.currentTimeMillis, and its modern replacement Instant.now, both capture the current moment as reported by the host OS and the underlying computer clock hardware. The Javadoc and source code promise a clock “based on the best available system clock”.
So, no, there should be no jumping into the future. Every time you call either of those methods, you capture the current moment.
However, you may see the illusion of jumping into the future. This may happen for these reasons:
- thread scheduling
- clock resetting
- fake clock
Thread scheduling
This illusion may occur because of what happens after the current moment is captured. The split-second after capturing the current moment, that thread’s execution may be paused. Some other thread may then capture a later moment, continue to report that moment. Eventually, that first thread resumes, and reports its earlier captured moment — but note how the reporting of that moment happens later.
Take this example code.
package work.basil.example;
import java.time.Instant;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.Callable;
import java.util.concurrent.Future;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
public class TellTime
{
public static void main ( String[] args )
{
TellTime app = new TellTime();
app.demo();
}
private void demo ( )
{
ExecutorService executorService = Executors.newCachedThreadPool();
int countThreads = 15;
List < Callable < Object > > tasks = new ArrayList <>( countThreads );
for ( int i = 0 ; i < countThreads ; i++ )
{
Runnable tellTimeRunnable = ( ) -> System.out.println( Instant.now() );
tasks.add( Executors.callable( tellTimeRunnable ) );
}
try
{
List < Future < Object > > list = executorService.invokeAll( tasks );
}
catch ( InterruptedException e )
{
e.printStackTrace();
}
}
}
The very first time I ran that code, I found such a jump in the last two lines of output. The 4th line shows a moment earlier than the 3rd. The 5th line shows a moment even earlier.
2020-11-23T01:07:34.305318Z 2020-11-23T01:07:34.305569Z 2020-11-23T01:07:34.305770Z 2020-11-23T01:07:34.305746Z 2020-11-23T01:07:34.305434Z
In my case here, the calls to System.out.println got delayed in their execution, so some earlier moments were reported later. Likewise, I suspect that in your case, the act of logging your captured moments involved various delays so that some earlier moments were logged later.
Clock resetting
As Stephen C points out in comments below, computers are often configured to auto-adjust the hardware clock based on info from a time server. The hardware clocks in many computers are less accurate than you might imagine. So the host computer’s clock may well be reset to an earlier or later time-of-day to correct for time-tracking drift.
Be aware that some computers reset their clock back to an epoch reference point such as 1970-01-01 00:00Z when booted with a faulty or exhausted battery/capacitor backing the hardware clock. That epoch reference moment may be reported as the current moment until the computer gets a chance to check in with the time server.
Or some human could manually adjust the computer clock’s current date and time. 🙁
Your code may capture the current moment on either side of this clock adjustment. Now a later event may appear to have occurred earlier.
Fake clock
In java.time, calls such as Instant.now access the currently-assigned Clock implementation. By “currently assigned”, I refer to the fact that in java.time, the default Clock object can be overridden. Usually that would be for testing purposes only. Various Clock object can report a fixed moment, a shifted moment, or may report with an altered cadence.
So be aware that an alternate Clock may purposely tell a different time, if your testing code specified an alternate Clock object. By default though you always get the current moment at the time that method call executes.
Conclusion
There is a major implication here: Time-tracking cannot be completely trusted. The current moment may be incorrectly captured, and the reporting of captured moments may be out-of-order.
So when debugging or investigating, always keep this thought tucked away in the back of your mind: The timestamps and their ordering may not be telling you whole truth. You ultimately cannot know with 100% certainty what happened when.