Re: perf trace timestamps

[David Ahern <dsahern@gmail.com>]

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