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

Your process is scheduled by the kernel. So it cannot always run. — Basile Starynkevitch, Apr 15 '14 at 04:56
@Basile - thanks. Is there anyways for it to always run? I actually tried modified the code to use pthread_setaffinity_np to tie that to a cpu. But doesn't seem to affect the result too much. — surfcode, Apr 15 '14 at 05:38
No, the kernel is in charge of scheduling processes (but you could make your process a real time one). — Basile Starynkevitch, Apr 15 '14 at 06:45

score 2 · Accepted Answer · edited May 23 '17 at 11:57

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.

score 1 · Answer 2 · answered Apr 15 '14 at 04:55

1

Could you check the resolution with clock_getres()?

answered Apr 15 '14 at 04:55

Jason Lewis

147
11

it returns 0 for tv_sec, and 1 for tv_nsec. – surfcode Apr 15 '14 at 05:37

score 1 · Answer 3 · answered Apr 15 '14 at 05:29

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

Linux clock_gettime() elapse spikes?

3 Answers3