Re: printk timestamps jumping back and forth in 2.6.25-rc.

Alexey Zaytsev
2008-03-21T18:55:59Z

On 2/28/08, Ingo Molnar <mingo@elte.hu> wrote:
>
> * Ingo Molnar <mingo@elte.hu> wrote:
>
> > > Anything else I can do?
> >
> > yes, please test the patch below - does it fix the problem?
>
>
> (assuming you prefer patches that build, here's an updated one below.)
>

The patch was not included into the -rc6 kernel, so I thought maybe
I should remind about it. While the jumping timestamps might
be harmless, they for sure will confuse anyone observing some
unrelated bugs.

As I understand it, the overhead created on the architectures with
synchronous time stamp registers is not something measurable,
and the problem is more with the fact that some unnecessary
operations are performed and the result looks a bit ugly.
In this case, may I suggest to merge the patch for 2.6.25, and
revert it right after the release, until a better solution is found?

>
> Ingo
>
> -------------->
> Subject: sched: make cpu_clock() globally synchronous
> From: Ingo Molnar <mingo@elte.hu>
> Date: Thu Feb 28 21:00:21 CET 2008
>
> Alexey Zaytsev reported (and bisected) that the introduction of
> cpu_clock() in printk made the timestamps jump back and forth.
>
> Make cpu_clock() more reliable while still keeping it fast when it's
> called frequently.
>
>
> Signed-off-by: Ingo Molnar <mingo@elte.hu>
> ---
> kernel/sched.c | 52 +++++++++++++++++++++++++++++++++++++++++++++++++---
> 1 file changed, 49 insertions(+), 3 deletions(-)
>
> Index: linux/kernel/sched.c
> ===================================================================
> --- linux.orig/kernel/sched.c
> +++ linux/kernel/sched.c
> @@ -710,11 +710,39 @@ static inline u64 global_rt_runtime(void
> return (u64)sysctl_sched_rt_runtime * NSEC_PER_USEC;
> }
>
> +static const unsigned long long time_sync_thresh = 100000;
> +
> +static DEFINE_PER_CPU(unsigned long long, time_offset);
> +static DEFINE_PER_CPU(unsigned long long, prev_cpu_time);
> +
> /*
> - * For kernel-internal use: high-speed (but slightly incorrect) per-cpu
> - * clock constructed from sched_clock():
> + * Global lock which we take every now and then to synchronize
> + * the CPUs time. This method is not warp-safe, but it's good
> + * enough to synchronize slowly diverging time sources and thus
> + * it's good enough for tracing:
> */
> -unsigned long long cpu_clock(int cpu)
> +static DEFINE_SPINLOCK(time_sync_lock);
> +static unsigned long long prev_global_time;
> +
> +static unsigned long long __sync_cpu_clock(cycles_t time, int cpu)
> +{
> + unsigned long flags;
> +
> + spin_lock_irqsave(&time_sync_lock, flags);
> +
> + if (time < prev_global_time) {
> + per_cpu(time_offset, cpu) += prev_global_time - time;
> + time = prev_global_time;
> + } else {
> + prev_global_time = time;
> + }
> +
> + spin_unlock_irqrestore(&time_sync_lock, flags);
> +
> + return time;
> +}
> +
> +static unsigned long long __cpu_clock(int cpu)
> {
> unsigned long long now;
> unsigned long flags;
> @@ -735,6 +763,24 @@ unsigned long long cpu_clock(int cpu)
>
> return now;
> }
> +
> +/*
> + * For kernel-internal use: high-speed (but slightly incorrect) per-cpu
> + * clock constructed from sched_clock():
> + */
> +unsigned long long cpu_clock(int cpu)
> +{
> + unsigned long long prev_cpu_time, time, delta_time;
> +
> + prev_cpu_time = per_cpu(prev_cpu_time, cpu);
> + time = __cpu_clock(cpu) + per_cpu(time_offset, cpu);
> + delta_time = time-prev_cpu_time;
> +
> + if (unlikely(delta_time > time_sync_thresh))
>
> + time = __sync_cpu_clock(time, cpu);
>
> +
> + return time;
> +}
> EXPORT_SYMBOL_GPL(cpu_clock);
>
> #ifndef prepare_arch_switch
>