LKML Archive on lore.kernel.org
help / color / mirror / Atom feed
* printk timestamps jumping back and forth in 2.6.25-rc.
@ 2008-02-28 14:26 Alexey Zaytsev
  2008-02-28 19:21 ` David Miller
  2008-02-28 20:13 ` Ingo Molnar
  0 siblings, 2 replies; 15+ messages in thread
From: Alexey Zaytsev @ 2008-02-28 14:26 UTC (permalink / raw)
  To: Ingo Molnar, Thomas Gleixner; +Cc: lkml

Hello.

Long story short, this is what I see in my dmesg:

http://romomatic.osuosl.org/share/xl0/dmesg-2.6.25-rc3
http://romomatic.osuosl.org/share/xl0/dmesg-2.6.25-rc3-clocksource-acpi_pm
http://romomatic.osuosl.org/share/xl0/dmesg-2.6.25-rc3-clocksource-hpet

Specifying clocksource=acpi_pm and hpet changes nothing.

Apart from the jumpy timestamps, I think the
scheduler is not working well, because the mouse
looses smoothness from time to time during
compilations. Not that noticeble, but definetely
worse than it was in 2.6.23. Probably might be related,
I don't know.

I tried to bisect the problem, but it first lead me to

commit 326e96b92306b7af24a3608ec01156cba17a3fc1
Author: Ingo Molnar <mingo@elte.hu>
Date:   Sun Jan 27 08:03:54 2008 +0100

    printk: revert ktime_get() timestamps

    revert 19ef9309273d26cb005cb23e6a370353dca91099.

    Kevin Winchester reported a lockup during X startup an bisected
    it to this commit.

Reverting this revert kind of worked:
http://romomatic.osuosl.org/share/xl0/dmesg-2.6.25-rc3-reverted
but clearly this was not the right thing. ;)

and after bisecting 2.6.24 - commit before
19ef9309273d26cb005cb23e6a370353dca91099
I got to

commit d713f519332e029d43eca8462629314eee1ded86
Author: Ingo Molnar <mingo@elte.hu>
Date:   Fri Jan 25 21:07:58 2008 +0100

    sched: fix CONFIG_PRINT_TIME's reliance on sched_clock()

    Stefano Brivio reported weird printk timestamp behavior during
    CPU frequency changes:

      http://bugzilla.kernel.org/show_bug.cgi?id=9475

    fix CONFIG_PRINT_TIME's reliance on sched_clock() and use cpu_clock()
    instead.

    Reported-and-bisected-by: Stefano Brivio <stefano.brivio@polimi.it>
    Signed-off-by: Ingo Molnar <mingo@elte.hu>


which sound like "happy debugging, losers" to me. ;)

Anything else I can do?

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-02-28 14:26 printk timestamps jumping back and forth in 2.6.25-rc Alexey Zaytsev
@ 2008-02-28 19:21 ` David Miller
  2008-02-28 20:13 ` Ingo Molnar
  1 sibling, 0 replies; 15+ messages in thread
From: David Miller @ 2008-02-28 19:21 UTC (permalink / raw)
  To: alexey.zaytsev; +Cc: mingo, tglx, linux-kernel

From: "Alexey Zaytsev" <alexey.zaytsev@gmail.com>
Date: Thu, 28 Feb 2008 17:26:38 +0300

> commit d713f519332e029d43eca8462629314eee1ded86
> Author: Ingo Molnar <mingo@elte.hu>
> Date:   Fri Jan 25 21:07:58 2008 +0100
> 
>     sched: fix CONFIG_PRINT_TIME's reliance on sched_clock()
> 
>     Stefano Brivio reported weird printk timestamp behavior during
>     CPU frequency changes:
> 
>       http://bugzilla.kernel.org/show_bug.cgi?id=9475
> 
>     fix CONFIG_PRINT_TIME's reliance on sched_clock() and use cpu_clock()
>     instead.
> 
>     Reported-and-bisected-by: Stefano Brivio <stefano.brivio@polimi.it>
>     Signed-off-by: Ingo Molnar <mingo@elte.hu>
> 
> 
> which sound like "happy debugging, losers" to me. ;)
> 
> Anything else I can do?

FWIW, I've been seeing jumping printk timestamps ever since this
change on SMP sparc64 as well.  Especially on my Niagara boxes.

The timestamp base seem to be dependant upon which cpu prints the
message.  I guess the per-runqueue timestamps this new scheme is using
are all differently based.

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-02-28 14:26 printk timestamps jumping back and forth in 2.6.25-rc Alexey Zaytsev
  2008-02-28 19:21 ` David Miller
@ 2008-02-28 20:13 ` Ingo Molnar
  2008-02-28 20:16   ` Ingo Molnar
  1 sibling, 1 reply; 15+ messages in thread
From: Ingo Molnar @ 2008-02-28 20:13 UTC (permalink / raw)
  To: Alexey Zaytsev; +Cc: Thomas Gleixner, lkml


* Alexey Zaytsev <alexey.zaytsev@gmail.com> wrote:

>     fix CONFIG_PRINT_TIME's reliance on sched_clock() and use 
>     cpu_clock() instead.
> 
>     Reported-and-bisected-by: Stefano Brivio <stefano.brivio@polimi.it>
>     Signed-off-by: Ingo Molnar <mingo@elte.hu>
> 
> which sound like "happy debugging, losers" to me. ;)

i hope not :)

> Anything else I can do?

yes, please test the patch below - does it fix the problem?

	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.

Bisected-by: Alexey Zaytsev <alexey.zaytsev@gmail.com>
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_clock(time, cpu);
+
+	return time;
+}
 EXPORT_SYMBOL_GPL(cpu_clock);
 
 #ifndef prepare_arch_switch

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-02-28 20:13 ` Ingo Molnar
@ 2008-02-28 20:16   ` Ingo Molnar
  2008-02-28 21:24     ` Alexey Zaytsev
                       ` (2 more replies)
  0 siblings, 3 replies; 15+ messages in thread
From: Ingo Molnar @ 2008-02-28 20:16 UTC (permalink / raw)
  To: Alexey Zaytsev; +Cc: Thomas Gleixner, lkml


* 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.)

	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

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-02-28 20:16   ` Ingo Molnar
@ 2008-02-28 21:24     ` Alexey Zaytsev
  2008-02-29 19:45       ` Ingo Molnar
  2008-02-29 11:11     ` Paul Mackerras
  2008-03-21 18:55     ` Alexey Zaytsev
  2 siblings, 1 reply; 15+ messages in thread
From: Alexey Zaytsev @ 2008-02-28 21:24 UTC (permalink / raw)
  To: Ingo Molnar; +Cc: Thomas Gleixner, lkml

On Thu, Feb 28, 2008 at 11:16 PM, 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?
>

The patch worked well, thanks

I still observe some uneven mouse behaviour during
compilations (linux kernel, make -j 6), like, when I slowly
move the mouse, it would stop for a split of a second every
few seconds (the intervals are not equal). On 2.6.23/24
it works very smooth. Of course, I can't say that the
scheduler is to be blamed. It was only my assumption
because I thought I might be confused by the
non-monotinic time, which I see is not the case.
Any ideas, how to debug this?

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-02-28 20:16   ` Ingo Molnar
  2008-02-28 21:24     ` Alexey Zaytsev
@ 2008-02-29 11:11     ` Paul Mackerras
  2008-02-29 18:42       ` David Miller
  2008-03-21 18:55     ` Alexey Zaytsev
  2 siblings, 1 reply; 15+ messages in thread
From: Paul Mackerras @ 2008-02-29 11:11 UTC (permalink / raw)
  To: Ingo Molnar; +Cc: Alexey Zaytsev, Thomas Gleixner, lkml

Ingo Molnar writes:

> * 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.)

Is this patch going to add overhead?

On powerpc we use the timebase register, which is synchronized across
CPUs, so if this will add unnecessary overhead, we will want to way to
turn it off on powerpc (assuming this ends up going upstream).

Paul.

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-02-29 11:11     ` Paul Mackerras
@ 2008-02-29 18:42       ` David Miller
  2008-02-29 19:44         ` Ingo Molnar
  0 siblings, 1 reply; 15+ messages in thread
From: David Miller @ 2008-02-29 18:42 UTC (permalink / raw)
  To: paulus; +Cc: mingo, alexey.zaytsev, tglx, linux-kernel

From: Paul Mackerras <paulus@samba.org>
Date: Fri, 29 Feb 2008 22:11:26 +1100

> On powerpc we use the timebase register, which is synchronized across
> CPUs, so if this will add unnecessary overhead, we will want to way to
> turn it off on powerpc (assuming this ends up going upstream).

Similarly on sparc64, all of our TSCs are fully synchronized so
this complexity is completely unnecessary.

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-02-29 18:42       ` David Miller
@ 2008-02-29 19:44         ` Ingo Molnar
  0 siblings, 0 replies; 15+ messages in thread
From: Ingo Molnar @ 2008-02-29 19:44 UTC (permalink / raw)
  To: David Miller; +Cc: paulus, alexey.zaytsev, tglx, linux-kernel


* David Miller <davem@davemloft.net> wrote:

> From: Paul Mackerras <paulus@samba.org>
> Date: Fri, 29 Feb 2008 22:11:26 +1100
> 
> > On powerpc we use the timebase register, which is synchronized across
> > CPUs, so if this will add unnecessary overhead, we will want to way to
> > turn it off on powerpc (assuming this ends up going upstream).
> 
> Similarly on sparc64, all of our TSCs are fully synchronized so this 
> complexity is completely unnecessary.

i suspect for them the easiest way is to expose time_sync_thresh and let 
them set it to ULONG_MAX - which skips all synchronization overhead and 
complexity.

	Ingo

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-02-28 21:24     ` Alexey Zaytsev
@ 2008-02-29 19:45       ` Ingo Molnar
  2008-03-01  0:42         ` Alexey Zaytsev
  0 siblings, 1 reply; 15+ messages in thread
From: Ingo Molnar @ 2008-02-29 19:45 UTC (permalink / raw)
  To: Alexey Zaytsev; +Cc: Thomas Gleixner, lkml


* Alexey Zaytsev <alexey.zaytsev@gmail.com> wrote:

> On Thu, Feb 28, 2008 at 11:16 PM, 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?
> 
> The patch worked well, thanks
> 
> I still observe some uneven mouse behaviour during compilations (linux 
> kernel, make -j 6), like, when I slowly move the mouse, it would stop 
> for a split of a second every few seconds (the intervals are not 
> equal). On 2.6.23/24 it works very smooth. Of course, I can't say that 
> the scheduler is to be blamed. It was only my assumption because I 
> thought I might be confused by the non-monotinic time, which I see is 
> not the case. Any ideas, how to debug this?

could you try latencytop, what does it say, what type of scheduler (and 
other) delays are there?

	Ingo

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-02-29 19:45       ` Ingo Molnar
@ 2008-03-01  0:42         ` Alexey Zaytsev
  2008-03-01  0:59           ` Alexey Zaytsev
  0 siblings, 1 reply; 15+ messages in thread
From: Alexey Zaytsev @ 2008-03-01  0:42 UTC (permalink / raw)
  To: Ingo Molnar; +Cc: Thomas Gleixner, lkml, Arjan van de Ven

On Fri, Feb 29, 2008 at 10:45 PM, Ingo Molnar <mingo@elte.hu> wrote:
>
>  * Alexey Zaytsev <alexey.zaytsev@gmail.com> wrote:
>
>
>
> > On Thu, Feb 28, 2008 at 11:16 PM, 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?
>  >
>  > The patch worked well, thanks
>  >
>  > I still observe some uneven mouse behaviour during compilations (linux
>  > kernel, make -j 6), like, when I slowly move the mouse, it would stop
>  > for a split of a second every few seconds (the intervals are not
>  > equal). On 2.6.23/24 it works very smooth. Of course, I can't say that
>  > the scheduler is to be blamed. It was only my assumption because I
>  > thought I might be confused by the non-monotinic time, which I see is
>  > not the case. Any ideas, how to debug this?
>
>  could you try latencytop, what does it say, what type of scheduler (and
>  other) delays are there?
>

I'm not sure I fully understand how to use this tool.
There are clearly two possible options to the utility,
--unknown and -d, but I still have no idea what they do..

Does the latencytop-0.3 actually work? I my case the upper half of the
window is always empty. The lower half shows always one line, like

Scheduler: waiting for cpu \t \t \t \t $some_val $some_val

The two values are always identical.

In the 2.6.24 case, the values for Xorg are always around 20 ms
when a make -j 6 is runig in parallel. For the 2.6.25 the
values jump from 100 ms to over 1000 ms.

Later I mounted a tmpfs and run the compilation (from root) there
(swap turned off). This time the Xorg latency was usually less then
30 ms, but the gnome-terminal (running from an other user) was not
that lucky with latencies around 500-1000 ms. Now I ran the same compilation
from user, and the latencies came back to what I observed before, with
gnome-terminal being about 30-50 and Xorg jumping from 100 to now
over 2000. The latencytop and some daemons runnig as different users
also had comparable latencyes.

Yes, fair group scheduler enabled, the config can be seen here:
http://romomatic.osuosl.org/share/xl0/config-2.6.25-rc3

I"ll now recompile with fair group scheduler disabled, just to be sure.

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-03-01  0:42         ` Alexey Zaytsev
@ 2008-03-01  0:59           ` Alexey Zaytsev
  2008-03-03 10:45             ` Ingo Molnar
  0 siblings, 1 reply; 15+ messages in thread
From: Alexey Zaytsev @ 2008-03-01  0:59 UTC (permalink / raw)
  To: Ingo Molnar; +Cc: Thomas Gleixner, lkml, Arjan van de Ven

On Sat, Mar 1, 2008 at 3:42 AM, Alexey Zaytsev <alexey.zaytsev@gmail.com> wrote:
>
> On Fri, Feb 29, 2008 at 10:45 PM, Ingo Molnar <mingo@elte.hu> wrote:
>  >
>  >  * Alexey Zaytsev <alexey.zaytsev@gmail.com> wrote:
>  >
>  >
>  >
>  > > On Thu, Feb 28, 2008 at 11:16 PM, 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?
>  >  >
>  >  > The patch worked well, thanks
>  >  >
>  >  > I still observe some uneven mouse behaviour during compilations (linux
>  >  > kernel, make -j 6), like, when I slowly move the mouse, it would stop
>  >  > for a split of a second every few seconds (the intervals are not
>  >  > equal). On 2.6.23/24 it works very smooth. Of course, I can't say that
>  >  > the scheduler is to be blamed. It was only my assumption because I
>  >  > thought I might be confused by the non-monotinic time, which I see is
>  >  > not the case. Any ideas, how to debug this?
>  >
>  >  could you try latencytop, what does it say, what type of scheduler (and
>  >  other) delays are there?
>  >
>
>  I'm not sure I fully understand how to use this tool.
>  There are clearly two possible options to the utility,
>  --unknown and -d, but I still have no idea what they do..
>
>  Does the latencytop-0.3 actually work? I my case the upper half of the
>  window is always empty. The lower half shows always one line, like
>
>  Scheduler: waiting for cpu \t \t \t \t $some_val $some_val
>
>  The two values are always identical.
>
>  In the 2.6.24 case, the values for Xorg are always around 20 ms
>  when a make -j 6 is runig in parallel. For the 2.6.25 the
>  values jump from 100 ms to over 1000 ms.
>
>  Later I mounted a tmpfs and run the compilation (from root) there
>  (swap turned off). This time the Xorg latency was usually less then
>  30 ms, but the gnome-terminal (running from an other user) was not
>  that lucky with latencies around 500-1000 ms. Now I ran the same compilation
>  from user, and the latencies came back to what I observed before, with
>  gnome-terminal being about 30-50 and Xorg jumping from 100 to now
>  over 2000. The latencytop and some daemons runnig as different users
>  also had comparable latencyes.
>
>  Yes, fair group scheduler enabled, the config can be seen here:
>  http://romomatic.osuosl.org/share/xl0/config-2.6.25-rc3
>
>  I"ll now recompile with fair group scheduler disabled, just to be sure.
>

Yes, with the group scheduler disabled, the latencies for both Xorg and
gnome-terminal do net exceed 15 ms. And the mouse is also smooth.

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-03-01  0:59           ` Alexey Zaytsev
@ 2008-03-03 10:45             ` Ingo Molnar
  2008-03-03 22:16               ` Alexey Zaytsev
  0 siblings, 1 reply; 15+ messages in thread
From: Ingo Molnar @ 2008-03-03 10:45 UTC (permalink / raw)
  To: Alexey Zaytsev; +Cc: Thomas Gleixner, lkml, Arjan van de Ven


* Alexey Zaytsev <alexey.zaytsev@gmail.com> wrote:

> >  I"ll now recompile with fair group scheduler disabled, just to be 
> >  sure.
> 
> Yes, with the group scheduler disabled, the latencies for both Xorg 
> and gnome-terminal do net exceed 15 ms. And the mouse is also smooth.

could you also try the current scheduler fixes lineup in 
sched-devel.git:

   http://people.redhat.com/mingo/sched-devel.git/README

is the mouse smooth with the group scheduler _enabled_ too?

	Ingo

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-03-03 10:45             ` Ingo Molnar
@ 2008-03-03 22:16               ` Alexey Zaytsev
  2008-03-04 12:44                 ` Ingo Molnar
  0 siblings, 1 reply; 15+ messages in thread
From: Alexey Zaytsev @ 2008-03-03 22:16 UTC (permalink / raw)
  To: Ingo Molnar; +Cc: Thomas Gleixner, lkml, Arjan van de Ven

On Mon, Mar 3, 2008 at 1:45 PM, Ingo Molnar <mingo@elte.hu> wrote:
>
>  * Alexey Zaytsev <alexey.zaytsev@gmail.com> wrote:
>
>
> > >  I"ll now recompile with fair group scheduler disabled, just to be
>  > >  sure.
>  >
>  > Yes, with the group scheduler disabled, the latencies for both Xorg
>  > and gnome-terminal do net exceed 15 ms. And the mouse is also smooth.
>
>  could you also try the current scheduler fixes lineup in
>  sched-devel.git:
>
>    http://people.redhat.com/mingo/sched-devel.git/README
>
>  is the mouse smooth with the group scheduler _enabled_ too?
>

Works fine. The latencies of both Xorg and gnome-terminal are
reported to be about 5-20 ms, and the mouse is smooth too.

Thanks for the fast response to the ptoblem.

>         Ingo
>

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-03-03 22:16               ` Alexey Zaytsev
@ 2008-03-04 12:44                 ` Ingo Molnar
  0 siblings, 0 replies; 15+ messages in thread
From: Ingo Molnar @ 2008-03-04 12:44 UTC (permalink / raw)
  To: Alexey Zaytsev; +Cc: Thomas Gleixner, lkml, Arjan van de Ven


* Alexey Zaytsev <alexey.zaytsev@gmail.com> wrote:

> On Mon, Mar 3, 2008 at 1:45 PM, Ingo Molnar <mingo@elte.hu> wrote:
> >
> >  * Alexey Zaytsev <alexey.zaytsev@gmail.com> wrote:
> >
> >
> > > >  I"ll now recompile with fair group scheduler disabled, just to be
> >  > >  sure.
> >  >
> >  > Yes, with the group scheduler disabled, the latencies for both Xorg
> >  > and gnome-terminal do net exceed 15 ms. And the mouse is also smooth.
> >
> >  could you also try the current scheduler fixes lineup in
> >  sched-devel.git:
> >
> >    http://people.redhat.com/mingo/sched-devel.git/README
> >
> >  is the mouse smooth with the group scheduler _enabled_ too?
> >
> 
> Works fine. The latencies of both Xorg and gnome-terminal are reported 
> to be about 5-20 ms, and the mouse is smooth too.

great - if you dont mind i'll add your:

  Tested-by: Alexey Zaytsev <alexey.zaytsev@gmail.com>

	Ingo

^ permalink raw reply	[flat|nested] 15+ messages in thread

* Re: printk timestamps jumping back and forth in 2.6.25-rc.
  2008-02-28 20:16   ` Ingo Molnar
  2008-02-28 21:24     ` Alexey Zaytsev
  2008-02-29 11:11     ` Paul Mackerras
@ 2008-03-21 18:55     ` Alexey Zaytsev
  2 siblings, 0 replies; 15+ messages in thread
From: Alexey Zaytsev @ 2008-03-21 18:55 UTC (permalink / raw)
  To: Ingo Molnar; +Cc: Thomas Gleixner, lkml, Paul Mackerras, David Miller

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
>

^ permalink raw reply	[flat|nested] 15+ messages in thread

end of thread, other threads:[~2008-03-21 18:55 UTC | newest]

Thread overview: 15+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2008-02-28 14:26 printk timestamps jumping back and forth in 2.6.25-rc Alexey Zaytsev
2008-02-28 19:21 ` David Miller
2008-02-28 20:13 ` Ingo Molnar
2008-02-28 20:16   ` Ingo Molnar
2008-02-28 21:24     ` Alexey Zaytsev
2008-02-29 19:45       ` Ingo Molnar
2008-03-01  0:42         ` Alexey Zaytsev
2008-03-01  0:59           ` Alexey Zaytsev
2008-03-03 10:45             ` Ingo Molnar
2008-03-03 22:16               ` Alexey Zaytsev
2008-03-04 12:44                 ` Ingo Molnar
2008-02-29 11:11     ` Paul Mackerras
2008-02-29 18:42       ` David Miller
2008-02-29 19:44         ` Ingo Molnar
2008-03-21 18:55     ` Alexey Zaytsev

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).