Re: perf trace timestamps

[Saumil Merchant <msaumil@gmail.com>]

David Ahern <dsahern <at> gmail.com> writes:

> 
> >
> > My original impression was that this timestamp (eg, 1746678.550895) would
> > with time reported clk_gettime(MONOTONIC,...) function, but it does not. My
> > function above prints out timestamps from clk_gettime(MONOTONIC,..)  
> > and there is a delta of >15 mins.
> >
> > Here is the printout on console:
> > CLKTIME (MONOTONIC):  1748132.102228068
> 
> At one time many, many releases ago perf timestamps did align with the 
> monotonic clock. I have tried (unsuccessfully) to get an option into 
> perf to correlate perf events with time-of-day stamps.
> 


Since clk_gettime and perf timestamps do not align, I tried synchronizing 
timestamps at start my code. I used a syscall that I can track in the perf
trace.  I can then normalize perf trace output timestamps using the delta 
between perf timestamp and clk_gettime timestamp for the syscall.  I chose to 
use nanosleep for this.  While doing this I realized that this normalizing 
delta between the perf and clk_gettime timestamps linearly increases with 
time.  Here is a simple C code that I used to check this behavior:

#include <stdio.h>
#include <stdlib.h>
#include <time.h>

int ITERATIONS=600;
struct timespec sleepy, t1, t2;

int main(int argc, char **argv) {
    int i;

    sleepy.tv_sec=0;
    sleepy.tv_nsec=1000000;

    for(i=0; i<ITERATIONS; i++) {
        clock_gettime(CLOCK_MONOTONIC,&t1);
        nanosleep(&sleepy,NULL);
        clock_gettime(CLOCK_MONOTONIC,&t2);
        printf("%d.%09d, %d.%09d\n",
               t1.tv_sec,t1.tv_nsec,t2.tv_sec,t2.tv_nsec);
    }

    return(0);
}

I correlated entry (t1) clk_gettime timestamps with entry nanosleep timestamps
from perf.  Same with he exit timestamps.  
i.e. two arrays of "entry_clk_gettime - entry_perf" and 
"exit_clk_gettime - exit_perf". 

On plotting these two arrays against the iterations I got a plot which is
straight line linearly increasing with slope 0.00000095.  The difference 
between the first and the last sample of these arrays is almost 0.6 msecs over
just 600 iterations.  I was expecting variations when I plotted these two
arrays, but was expecting random variations and not a linearly increasing 
straight line.  This tells me that perf is inflating the timestamps over time 
with probably a constant value. 

Is this an expected behavior or a bug?

I didn't want to bombard the list with a big spreadsheet file detailing the
experiment outcomes, but I can email it separately to whoever wants to take a
look at it.



> >
> > This delta has been varying from 5 mins to 15+ mins.  My objective is to
> > correlate events in a kernel trace with the execution of our user program.  
> > understanding is that both perf and clk_gettime functions on newer x86 
> > use TSC as the clock source and hence I was confused why they do not align.
> >
> > Can someone please help?
> 
> See John's explanations in this thread:
> https://lkml.org/lkml/2012/10/16/173
> 
> David
>