Re: perf trace timestamps

[John Stultz <john.stultz@linaro.org>]

On 11/21/2012 07:54 AM, David Ahern wrote:
> 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.

I suspect this is expected behavior, as to my understanding perf uses 
sched_clock, not CLOCK_MONOTONIC for its timestamps.

CLOCK_MONOTONIC is frequency corrected for accuracy by NTP (thus after 
NTP converges, one second is really one second long), sched_clock has no 
such correction.

So if you either disable NTP or compare with CLOCK_MONOTONIC_RAW (which 
also has no frequency correction, so one second may not be actually one 
second, given any initial calibration error or hardware drift), I 
suspect you'll not see the linear slope.

Another possible source for this slope/drift could be if the clocksource 
hardware being used for time (CLOCK_MONOTONIC) is different the the 
hardware used for sched_clock.  For instance, on x86 sched_clock is 
usually based on the TSC (which is calibrated at boot, which introduces 
accuracy errors). The TSC may not be stable on the cpu, so it could halt 
or may not be consistent between cores, so we may use something like the 
HPET or ACPI PM hardware (which we are given the freq by the hardware) 
for the timekeeping clocksource. Thus there may be either calibration or 
hardware drift (or both) between the different clocks.

There was some discussion recently on lkml about either exposing the 
perf clock to userland, or possibly reworking perf so the timestamps is 
exports are based on CLOCK_MONOTONIC instead, but that hasn't come to 
any resolution yet.

thanks
-john