On 11/16/12 6:07 AM, Saumil Merchant wrote:
Hi,
I am trying to understand the origin of the timestamps in the trace output.
Here is an example trace of a sample C code.
/> perf sched record -a ./a.out
/> perf script
[ ... ]
a.out 29311 [000] 1746678.549886: sched_stat_runtime: comm=a.out pid=29311
runtime=310028 [ns] vruntime=159246710291986646 [ns]
a.out 29311 [000] 1746678.550885: sched_stat_runtime: comm=a.out pid=29311
runtime=998470 [ns] vruntime=159246710292985116 [ns]
a.out 29311 [000] 1746678.550895: sched_stat_runtime: comm=a.out pid=29311
runtime=11039 [ns] vruntime=159246710292996155 [ns]
[ ... ]
My original impression was that this timestamp (eg, 1746678.550895) would align
with time reported clk_gettime(MONOTONIC,...) function, but it does not. My C
function above prints out timestamps from clk_gettime(MONOTONIC,..) function
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.
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. My
understanding is that both perf and clk_gettime functions on newer x86 systems
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
