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

[Peter Zijlstra <peterz@infradead.org>]

On Wed, 2009-11-25 at 10:58 +0100, Peter Zijlstra wrote:
> 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.

To clarify, left to their own devices, cpu_clock() times are monotonic
per cpu, but can drift up to ~1 jiffy between cpus, but explicit
cross-cpu updates should pull them straight.