On 11/20/12 4:33 AM, Saumil Merchant wrote:
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?
Perhaps John or Thomas can explain what is going on. cc'ed. Added
Stephane as well given his recent thread on the topic.
David
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
--
To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-perf-users" in
the body of a message to majord...@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
