Re: [RFC][PATCH 0/7] perf trace: general-purpose scripting support, v2

[Peter Zijlstra <peterz@infradead.org>]

On Wed, 2009-11-25 at 10:43 +0100, Ingo Molnar wrote:
> * Peter Zijlstra <peterz@infradead.org> wrote:
> 
> > On Wed, 2009-11-25 at 09:28 +0100, Peter Zijlstra wrote:
> > > On Wed, 2009-11-25 at 01:15 -0600, Tom Zanussi wrote:
> > > > sched::sched_wakeup      0 01238.657997033     6183 firefox              comm=firefox, pid=6199, prio=120, success=1, target_cpu=1
> > > > sched::sched_switch      1 01238.657991740     7140 firefox              prev_comm=firefox, prev_pid=7140, prev_prio=120, prev_state=S, next_comm=firefox, next_pid=6199, next_prio=120
> > > > 
> > > > min_wakeup_latency: -5293 
> > > 
> > > Looks like we missed a clock update on the cross cpu wakeup, Mike was
> > > busy plugging those holes -- I've been starting at a patch that might
> > > cure this (amongst other things).
> > 
> > Hmm, current -tip should have that cured as per:
> 
> well, but timestamp inconsistencies are still possible fundamentally, as 
> cpu_clock() is not globally serialized.

No, but the cross-cpu update should have pulled 1 to the same time as 0.

So what we see here is that at wakeup time, cpu0 has 01238.657997033, if
it at that time does a cross-cpu clock update, sched_clock_remote()
should pull cpu1's time to that same time (unless cpu1 is ahead, but
given the situation that's clearly not the case).

The clock update on cpu1's schedule() would then either find a negative
increment, not further updating the time, but refreshing the raw tsc
stamp so that future updates appear monotonic, or find a positive stamp,
resulting in fwd time movement.

In any case, the wakeup latency should appear >= 0.