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 <[email protected]>
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 <[email protected]>
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 <[email protected]>
Signed-off-by: Ingo Molnar <[email protected]>
which sound like "happy debugging, losers" to me. ;)
Anything else I can do?
From: "Alexey Zaytsev" <[email protected]>
Date: Thu, 28 Feb 2008 17:26:38 +0300
> commit d713f519332e029d43eca8462629314eee1ded86
> Author: Ingo Molnar <[email protected]>
> 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 <[email protected]>
> Signed-off-by: Ingo Molnar <[email protected]>
>
>
> 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.
* Alexey Zaytsev <[email protected]> wrote:
> fix CONFIG_PRINT_TIME's reliance on sched_clock() and use
> cpu_clock() instead.
>
> Reported-and-bisected-by: Stefano Brivio <[email protected]>
> Signed-off-by: Ingo Molnar <[email protected]>
>
> 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 <[email protected]>
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 <[email protected]>
Signed-off-by: Ingo Molnar <[email protected]>
---
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
* Ingo Molnar <[email protected]> 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 <[email protected]>
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 <[email protected]>
---
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
On Thu, Feb 28, 2008 at 11:16 PM, Ingo Molnar <[email protected]> wrote:
>
> * Ingo Molnar <[email protected]> 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?
Ingo Molnar writes:
> * Ingo Molnar <[email protected]> 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.
From: Paul Mackerras <[email protected]>
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.
* David Miller <[email protected]> wrote:
> From: Paul Mackerras <[email protected]>
> 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
* Alexey Zaytsev <[email protected]> wrote:
> On Thu, Feb 28, 2008 at 11:16 PM, Ingo Molnar <[email protected]> wrote:
> >
> > * Ingo Molnar <[email protected]> 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
On Fri, Feb 29, 2008 at 10:45 PM, Ingo Molnar <[email protected]> wrote:
>
> * Alexey Zaytsev <[email protected]> wrote:
>
>
>
> > On Thu, Feb 28, 2008 at 11:16 PM, Ingo Molnar <[email protected]> wrote:
> > >
> > > * Ingo Molnar <[email protected]> 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.
On Sat, Mar 1, 2008 at 3:42 AM, Alexey Zaytsev <[email protected]> wrote:
>
> On Fri, Feb 29, 2008 at 10:45 PM, Ingo Molnar <[email protected]> wrote:
> >
> > * Alexey Zaytsev <[email protected]> wrote:
> >
> >
> >
> > > On Thu, Feb 28, 2008 at 11:16 PM, Ingo Molnar <[email protected]> wrote:
> > > >
> > > > * Ingo Molnar <[email protected]> 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.
* Alexey Zaytsev <[email protected]> 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
On Mon, Mar 3, 2008 at 1:45 PM, Ingo Molnar <[email protected]> wrote:
>
> * Alexey Zaytsev <[email protected]> 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
>
* Alexey Zaytsev <[email protected]> wrote:
> On Mon, Mar 3, 2008 at 1:45 PM, Ingo Molnar <[email protected]> wrote:
> >
> > * Alexey Zaytsev <[email protected]> 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 <[email protected]>
Ingo
On 2/28/08, Ingo Molnar <[email protected]> wrote:
>
> * Ingo Molnar <[email protected]> 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 <[email protected]>
> 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 <[email protected]>
> ---
> 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
>