perf trace timestamps

[Saumil Merchant <msaumil@gmail.com>]

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

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?

Regards,
Saumil