The very first time clock_gettime is called, a page fault occurs on the page that contains the instructions of that function. On my system, this is a soft page fault and it takes a few thousands of cycles to handle (up to 10,000 cycles). My CPU is running at 3.4GHz. I think that your CPU is running at a much lower frequency, so handling the page fault on your system would take more time. But the point here is that the first call to clock_gettime will take much more time than later calls, which is what you are observing.

The second major effect that your code is exhibiting is significant stalls due to instruction cache misses. It might appear that you are only calling two functions, namely now and printf, but these functions call other functions and they all compete on the L1 instruction cache. Overall, it depends on how all of these functions are aligned in the physical address space. When the sleep time is zero seconds, the stall time due to instruction cache misses is actually relatively small (you can measure this using the ICACHE.IFETCH_STALL performance counter). However, when the sleep time is larger than zero seconds, this stall time becomes significantly larger because the OS will schedule some other thread to run on the same core and that thread would different instructions and data. This explains why when you sleep, clock_gettime takes more time to execute.

Now regarding the second and later measurements. From the question:

4246711141077496455

I have observed on my system that the second measurement is not necessarily larger than later measurements. I believe this is also true on your system. In fact, this seems to be the case when you sleep for 10 seconds or 1 second. In the outer loop, the two functions now and printf contain thousands of dynamic instructions and they also access the L1 data cache. The variability that you see between the second and later measurements is reproducible. So it's inherent in the functions themselves. Note that the execution time of rdtscp instruction itself may vary by 4 cycles. See also this.

In practice, the clock_gettime is useful when the desired precision is at most a million cycles. Otherwise, it can be misleading.

I could not reproduce your results. Even with large sleep times (10 seconds), and a small number of loops (100), I always get timing of less than 100 clocks (less than 38 ns on my 2.6 GHz system).

For example:

./clockt 10 10 100init run 14896trial 0 took 8870 (88 cycles per call)trial 1 took 8316 (83 cycles per call)trial 2 took 8384 (83 cycles per call)trial 3 took 8796 (87 cycles per call)trial 4 took 9424 (94 cycles per call)trial 5 took 9054 (90 cycles per call)trial 6 took 8394 (83 cycles per call)trial 7 took 8346 (83 cycles per call)trial 8 took 8868 (88 cycles per call)trial 9 took 8930 (89 cycles per call)

Outside of measurement or user-error (always the most likely reason), the most likely explanation is that your system is not using rdtsc as a time source, so a system call is made. You can configure the clock source explicitly yourself, or otherwise some heuristic is used which will select rdtsc-based clock_gettime only if it seems suitable on the current system.

The second most likely reason is that clock_gettime(CLOCK_REALTIME) doesn't go through the VDSO on your system, so is a system call even if rdtsc is ultimately being used. I guess that could be due to an old libc version or something like that.

The third most likely reason is that rdtsc on your system is slow, perhaps because it is virtualized or disabled on your system, and implement via a VM exit or OS trap.

Single Loop Results

Trying with a single clock_gettime call per loop, I still get "fast" results after the first few trials. For example, ./clockt 0 20 1 gives:

init run 15932trial 0 took 352 (352 cycles per call)trial 1 took 196 (196 cycles per call)trial 2 took 104 (104 cycles per call)trial 3 took 104 (104 cycles per call)trial 4 took 104 (104 cycles per call)trial 5 took 104 (104 cycles per call)trial 6 took 102 (102 cycles per call)trial 7 took 104 (104 cycles per call)...

Note that I made one modification to the test program, to print the time per call, which seems more useful than the total time. The printf line was modified to:

printf("trial %d took %lld (%lld cycles per call)\n", t, (y-x), (y-x)/loops);