Hi guys,
I've been playing with latest perf (tip/perf/core) and I'm hitting the
warning in perf_session_queue_event() "Warning: Timestamp below last
timeslice flush" which means IMHO that the timestamps of each sample are
not monotonically increasing, as expected. But here's what I do, it could very
well be that I'm doing it wrong:
$ perf probe sched_clock_tick
$ perf record -f -e probe:sched_clock_tick -a -g ./nbench
$ perf report -g --stdio
Warning:...
The interesting thing is that dropping the '-a', i.e. "all-cpus" option
from perf record doesn't trigger the warning anymore.
Then, I added some silly debug output to see what happens:
diff --git a/tools/perf/util/session.c b/tools/perf/util/session.c
index a3a871f..79c7184 100644
--- a/tools/perf/util/session.c
+++ b/tools/perf/util/session.c
@@ -622,6 +622,7 @@ static int perf_session_queue_event(struct perf_session *s, union perf_event *ev
if (timestamp < s->ordered_samples.last_flush) {
printf("Warning: Timestamp below last timeslice flush\n");
+ printf("ts: %lu <-> %lu (last_flush), cpu: %d\n", timestamp, s->ordered_samples.last_flush, sample->cpu)
return -EINVAL;
}
Result:
...
Warning: Timestamp below last timeslice flush
ts: 10304235947415373581 <-> 18446744069414589173 (last_flush), cpu: -8321639
Warning: Timestamp below last timeslice flush
ts: 72057594029606669 <-> 18446744069414589173 (last_flush), cpu: 0
Warning: Timestamp below last timeslice flush
ts: 18446744069414584320 <-> 18446744069414589173 (last_flush), cpu: 0
Warning: Timestamp below last timeslice flush
ts: 6052837899177642039 <-> 18446744069414589173 (last_flush), cpu: -8323025
Warning: Timestamp below last timeslice flush
ts: 8502796096467174809 <-> 18446744069414589173 (last_flush), cpu: -8321142
Warning: Timestamp below last timeslice flush
ts: 648518346358128639 <-> 18446744069414589173 (last_flush), cpu: 16777216
Warning: Timestamp below last timeslice flush
ts: 11 <-> 18446744069414589173 (last_flush), cpu: -128
Warning: Timestamp below last timeslice flush
ts: 4755801206503243774 <-> 18446744069414589173 (last_flush), cpu: 16441
Warning: Timestamp below last timeslice flush
ts: 4294967295 <-> 18446744069414589173 (last_flush), cpu: 9
Warning: Timestamp below last timeslice flush
ts: 17654401922121072640 <-> 18446744069414589173 (last_flush), cpu: -16777198
Warning: Timestamp below last timeslice flush
ts: 2017612633061998649 <-> 18446744069414589173 (last_flush), cpu: -637534208
...
so this looks like some of the samples do not belong in the perf.data
output with that garbled cpu field. It lets me also assume that the
sample->time field is also crap so the timestamp check is falsely
tripped.
But this is all I got, now you can tell me how much I suck :).
Thanks.
--
Regards/Gruss,
Boris.
Advanced Micro Devices GmbH
Einsteinring 24, 85609 Dornach
General Managers: Alberto Bozzo, Andrew Bowd
Registration: Dornach, Gemeinde Aschheim, Landkreis Muenchen
Registergericht Muenchen, HRB Nr. 43632
On Thu, 2011-02-17 at 19:26 +0100, Borislav Petkov wrote:
>
> so this looks like some of the samples do not belong in the perf.data
> output with that garbled cpu field. It lets me also assume that the
> sample->time field is also crap so the timestamp check is falsely
> tripped.
Most interesting, I haven't tried to reproduce, but it does sound
smelly.
I did have a quick peek at some code I suspected but that all seems in
order. I guess someone will have to sit down and figure this out proper,
if nobody steps up I guess it'll have to be me, but that also means it
might take a while since I've got some other pending stuff to stare at
before this :/
Em Wed, Feb 23, 2011 at 11:21:48AM +0100, Peter Zijlstra escreveu:
> On Thu, 2011-02-17 at 19:26 +0100, Borislav Petkov wrote:
> > so this looks like some of the samples do not belong in the perf.data
> > output with that garbled cpu field. It lets me also assume that the
> > sample->time field is also crap so the timestamp check is falsely
> > tripped.
>
> Most interesting, I haven't tried to reproduce, but it does sound
> smelly.
>
> I did have a quick peek at some code I suspected but that all seems in
> order. I guess someone will have to sit down and figure this out proper,
> if nobody steps up I guess it'll have to be me, but that also means it
> might take a while since I've got some other pending stuff to stare at
> before this :/
I'll look at it today.
- Arnaldo
On Wed, Feb 23, 2011 at 05:21:48AM -0500, Peter Zijlstra wrote:
> On Thu, 2011-02-17 at 19:26 +0100, Borislav Petkov wrote:
> >
> > so this looks like some of the samples do not belong in the perf.data
> > output with that garbled cpu field. It lets me also assume that the
> > sample->time field is also crap so the timestamp check is falsely
> > tripped.
>
> Most interesting, I haven't tried to reproduce, but it does sound
> smelly.
>
> I did have a quick peek at some code I suspected but that all seems in
> order. I guess someone will have to sit down and figure this out proper,
> if nobody steps up I guess it'll have to be me, but that also means it
> might take a while since I've got some other pending stuff to stare at
> before this :/
Same here, I'll try to play with this a bit more when I get a free
window. I think the first step should be if someone else tries
reproducing this to see whether it really is reproducible or there's
something wrong with my setup.
Thanks.
--
Regards/Gruss,
Boris.
Advanced Micro Devices GmbH
Einsteinring 24, 85609 Dornach
General Managers: Alberto Bozzo, Andrew Bowd
Registration: Dornach, Gemeinde Aschheim, Landkreis Muenchen
Registergericht Muenchen, HRB Nr. 43632