It's time to talk about Nano Time. Not Nanoo Nanoo people. NANO NANO.
I have had a lot of trouble finding info on the new JDK 1.5 System.nanoTime(). I read that it is not synchronized with UTC which is not an issue if you are profiling.
From Wikipedia:
A nanosecond (ns) is equal to 10-9 of a second.
- It is only infrequently put into everyday use. In technical situations it is however a very common unit, especially in computers, telecommunications, pulsed lasers, and some areas of electronics.
- In 1 ns, light travels exactly 299.792458 mm in a vacuum (via the definition of the metre). But the speed of light is slower in materials, indicated by an index of refraction n greater than 1. Thus in air (n = 1.003), light travels about 298.9 mm in 1 ns, but it travels only about 225.4 mm in water (n = 1.33) each nanosecond.
Wow! That is short. So a nanosecond is 1 millionth of a millisecond. Multiply it by 1000 and you are operating with microseconds, which is usually a little more useful. A microsecond is 1 millionth of a second.
But how is this implemented on Linux?
First a little java program:
public class NanoTest
{
public static void main( String[] p_args )
{
System.out.println( "TRACE 1 - nanos = " + System.nanoTime() );
System.out.println( "TRACE 2 - nanos = " + System.nanoTime() );
}
}
Next up, compile it:
sfraser@tennessee:~/Source/NanoTest$ java -version
java version "1.5.0_04"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_04-b05)
Java HotSpot(TM) Client VM (build 1.5.0_04-b05, mixed mode, sharing)
sfraser@tennessee:~/Source/NanoTest$ javac NanoTest.java
Run it under the control of strace so that we can log how it interacts with the linux kernel:
sfraser@tennessee:~/Source/NanoTest$ strace -ff -o NanoTest.log java NanoTest
TRACE 1 - nanos = 1126744308394574000
TRACE 2 - nanos = 1126744308395374000
sfraser@tennessee:~/Source/NanoTest$
After some comparisons of the strace output with and without the calls to System.nanoTime(), the main difference I noticed (not easy - there are MANY calls to gettimeofday in strace output!) was there appeared to be some extra calls to gettimeofday() in my code that used System.nanoTime():
gettimeofday({1126744308, 394574}, NULL) = 0
write(1, "TRACE 1 - nanos = 11267443083945"..., 37) = 37
write(1, "\n", 1) = 1
gettimeofday({1126744308, 395374}, NULL) = 0
write(1, "TRACE 2 - nanos = 11267443083953"..., 37) = 37
write(1, "\n", 1)
So it would appear that Sun's JDK on Linux calls gettimeofday to get
the, uh, time of day. "gettimeofday" is what is known as a "syscall" in
Linux - a part of the API that the Linux kernel presents to your
application. In Linux the "syscalls" are usually implemented as a
function called "sys_*", which frequently calls another function called
"do_*" that actually does the real work.
So let's do some digging - this is Linux, let's look at the source! First of all, make sure you have the kernel sources actually installed. I am on Kubuntu linux, which uses APT as its package management technology (you may be familiar with RPM on Redhat), so installing the sources is as easy as this (really):
sudo apt-get install linux-source-2.6.10
Next up, let's search the source and figure out where our gettimeofday is implemented:
find /usr/src/linux-source-2.6.10/ -name *.c -exec grep "gettimeofday" '{}' \; -ls > ~/scratch/GetTimeOfDay.txt
Now... search through the text file and figure out where gettimeofday is defined, used, etc... WAIT A MINUTE. There has to be an easier way, right? OK OK, I know there are easier ways... instead of the brutality above, how about you just check out LXR, it's SWEET. For instance, click here for access to the 2.6.10 source code.
After a little digging, you would stumble across this interesting source file:
1 /*
2 * linux/kernel/time.c
3 *
4 * Copyright (C) 1991, 1992 Linus Torvalds
5 *
6 * This file contains the interface functions for the various
7 * time related system calls: time, stime, gettimeofday, settimeofday,
8 * adjtime
9 */
A little searching in it will find the syscall here in linux/kernel/time.c, which as expected calls a "do_gettimeofday":
100 asmlinkage long sys_gettimeofday(struct timeval __user *tv, struct timezone __user *tz)
101 {
102 if (likely(tv != NULL)) {
103 struct timeval ktv;
104 do_gettimeofday(&ktv);
105 if (copy_to_user(tv, &ktv, sizeof(ktv)))
106 return -EFAULT;
107 }
108 if (unlikely(tz != NULL)) {
109 if (copy_to_user(tz, &sys_tz, sizeof(sys_tz)))
110 return -EFAULT;
111 }
112 return 0;
113 }
Finally, the smoking gun, do_gettimeofday, is implemented for the Intel architecture in linux/arch/i386/kernel/time.c:
90 /*
91 * This version of gettimeofday has microsecond resolution
92 * and better than microsecond precision on fast x86 machines with TSC.
93 */
94 void do_gettimeofday(struct timeval *tv)
Note the comment!!! So do_gettimeofday basically fills in a "timeval" struct which is defined in time.h:
18 struct timeval {
19 time_t tv_sec; /* seconds */
20 suseconds_t tv_usec; /* microseconds */
21 };
A ha!!! Microseconds! However if you dig further you will find accommodations in the code made to handle time in nanoseconds. In fact, the struct being copied from is meant to handle nanosecond resolution:
12 struct timespec {
13 time_t tv_sec; /* seconds */
14 long tv_nsec; /* nanoseconds */
15 };
So if do_gettimeofday is starting with a struct that records time to the nanosecond, where does it round this up to microseconds? Here:
124 usec += (xtime.tv_nsec / 1000);
So it is all starting to come together. If you go back and look really closely at the strace output, you can see the two parameters coming
back from the gettimeofday call being combined and multiplied by 1000
to produce the output our program generated. In other words this call:
gettimeofday({1126744308, 394574}, NULL) = 0
Resulted in this output from the Java program:
TRACE 1 - nanos = 1126744308394574000
So the 1126744308 must have been the number of seconds, the 3974574 was microseconds, and Java 1.5 on my desktop simply did this:
((seconds * 1000000) + microseconds) * 1000 = nanoseconds
So that's the end of the road for today, hope you enjoyed this trek into the wonders of the Linux kernel!
I gave a presentation titled "Secure Java Programming" on November 14, 2007 to the most excellent Philadelphia Area Java Users' Group at the Unisys East Coast Development Center in Malvern, PA. This is a great JUG - every time I have gone to one of their meetings the turnout has been huge and the speakers first-class. If you are interested in Java and work in the Greater Philadelphia area, it's definitely worth making an effort to attend. 
