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
--
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
