Linux clock_gettime() elapse spikes?

Question

I'm try to get high resolution timestamp on linux. Using clock_gettime(), as below, I got "spike" elapses that looks pretty horrible at almost 26 micro second elapse. Most of the "dt"'s are around 30 ns. I was on linux 2.6.32, Red Hat 4.4.6. 'lscpu' shows CPU MHz=2666.121. I thought that means each each clock tick needs about 2 ns. So, asking for ns resolution didn't see like too unreasonable here.

output of program (sorry wasn't able to post this without making it a list. It thinks it's code some how)

• 1397534268,40823395 1397534268,40827950,dt=4555
• 1397534268,41233555 1397534268,41236716,dt=3161
• 1397534268,41389902 1397534268,41392922,dt=3020
• 1397534268,46488430 1397534268,46491674,dt=3244
• 1397534268,46531297 1397534268,46534279,dt=2982
• 1397534268,46823368 1397534268,46849336,dt=25968
• 1397534268,46915657 1397534268,46918663,dt=3006
• 1397534268,51488643 1397534268,51491791,dt=3148
• 1397534268,51530490 1397534268,51533496,dt=3006
• 1397534268,51823307 1397534268,51826904,dt=3597
• 1397534268,55823359 1397534268,55827826,dt=4467
• 1397534268,60531184 1397534268,60534183,dt=2999
• 1397534268,60823381 1397534268,60844866,dt=21485
• 1397534268,60913003 1397534268,60915998,dt=2995
• 1397534268,65823269 1397534268,65827742,dt=4473
• 1397534268,70823376 1397534268,70835280,dt=11904
• 1397534268,75823489 1397534268,75828872,dt=5383
• 1397534268,80823503 1397534268,80859500,dt=35997
• 1397534268,86823381 1397534268,86831907,dt=8526

Any ideas? thanks

#include <vector>
#include <iostream>
#include <time.h>
long long elapse( const timespec& t1, const timespec& t2 ) 
{
    return ( t2.tv_sec * 1000000000L + t2.tv_nsec ) - 
        t1.tv_sec * 1000000000L + t1.tv_nsec ); 

}
int main()
{
    const unsigned n=30000;
    timespec ts;
    std::vector<timespec> t( n );
    for( unsigned i=0; i < n; ++i )
    {
        clock_gettime( CLOCK_REALTIME, &ts );
        t[i] = ts;
    }
    std::vector<long> dt( n );
    for( unsigned i=1; i < n; ++i )
    {
        dt[i] = elapse( t[i-1], t[i] );
        if( dt[i] > 1000 )
        {
            std::cerr << 
                t[i-1].tv_sec << "," 
                << t[i-1].tv_nsec << " " 
                << t[i].tv_sec << "," 
                << t[i].tv_nsec 
                << ",dt=" << dt[i] << std::endl;
        }
        else 
        { 
            //normally I get dt[i] = approx 30-35 nano secs 
        }
    }
    return 0;
}

Answer 1

The numbers you quoted are in the 3 to 30 microsecond range (3,000 to 30,000 nanoseconds). That is too short a time to be a context switch to another thread/process, let the other thread run, and context switch back to your thread. Most likely the core where your process was running was used by the kernel to service an external interrupt (e.g. network card, disk, timer), then returned to running your process.

You can watch the linux interrupt counters (per CPU core and per source) with this command

watch -d -n 0.2 cat /proc/interrupts

The -n 0.2 will cause the command to be issued at 5Hz, the -d flag will highlight what has changed.

The source of the interrupt could also be a TLB shootdown, which results in an IPI (Inter-Processor Interrupt). You can read more about TLB shootdowns here.

If you want to reduce the number of interrupts serviced by the core running your thread/process, you need to set the interrupt affinity. You can learn more about Red Hat Interrupts and IRQ (Interrupt requests) tuning here, and here.

Worth noting is that you are using CLOCK_REALTIME which isn't guaranteed to be "smooth", it could jump around as the system clock is "disciplined" to keep accurate time by a service like NTP (Network Time Protocol) or PTP (Precision Time Protocol). For your purposes it is better to use CLOCK_MONOTONIC, you can read more about the difference here. When a clock is "disciplined" the clock can jump by a "step" - this is unusual and certainly not the cause of the many spikes you see.

Answer 2

Could you check the resolution with clock_getres()?

Answer 3

I suspect what you are measuring here is called "OS Noise". This is often caused by your program getting pre-empted by the operating system. The operating system then performs other work. There are numerous causes, but commonly it is: other runnable tasks, hardware interrupts, or timer events.

The FTQ/FWQ benchmarks were designed to measure this characteristic and the summary contains some further information: https://asc.llnl.gov/sequoia/benchmarks/FTQ_summary_v1.1.pdf