[patch] fix for sched_clock() when using jiffies

[patch] fix for sched_clock() when using jiffies

[Ron]

Hi,

I'm in the process of updating a port for an ARM based chip we've been
working on, from 2.6.22-rc4'ish to the current HEAD of Linus' tree, and
I started seeing the following:

[    0.000000] PID hash table entries: 512 (order: 9, 2048 bytes)
[42949372.970000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)

The reason appears to be that printk_clock() has been replaced with a
call to cpu_clock, which in our case currently falls back to the default
(weak) implementation of sched_clock() that uses jiffies -- but doesn't
account for the initial offset of the jiffy count.  The following simple
patch fixes it for me, in line with what printk_clock used to do.

Cheers,
Ron

diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
index 8178724..d76814e 100644
--- a/kernel/sched_clock.c
+++ b/kernel/sched_clock.c
@@ -37,7 +37,7 @@
  */
 unsigned long long __attribute__((weak)) sched_clock(void)
 {
-       return (unsigned long long)jiffies * (NSEC_PER_SEC / HZ);
+       return (unsigned long long)(jiffies - INITIAL_JIFFIES) * (NSEC_PER_SEC / HZ);
 }
 

Re: [patch] fix for sched_clock() when using jiffies

[Peter Zijlstra]

On Thu, 2008-11-27 at 01:36 +1030, Ron wrote:
> Hi,
> 
> I'm in the process of updating a port for an ARM based chip we've been
> working on, from 2.6.22-rc4'ish to the current HEAD of Linus' tree, and
> I started seeing the following:
> 
> [    0.000000] PID hash table entries: 512 (order: 9, 2048 bytes)
> [42949372.970000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
> 
> The reason appears to be that printk_clock() has been replaced with a
> call to cpu_clock, which in our case currently falls back to the default
> (weak) implementation of sched_clock() that uses jiffies -- but doesn't
> account for the initial offset of the jiffy count.  The following simple
> patch fixes it for me, in line with what printk_clock used to do.
> 

Looks good, except I suspect this line will now be longer than 80
characters and you forgot to provide your signed-off-by line.

> 
> diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
> index 8178724..d76814e 100644
> --- a/kernel/sched_clock.c
> +++ b/kernel/sched_clock.c
> @@ -37,7 +37,7 @@
>   */
>  unsigned long long __attribute__((weak)) sched_clock(void)
>  {
> -       return (unsigned long long)jiffies * (NSEC_PER_SEC / HZ);
> +       return (unsigned long long)(jiffies - INITIAL_JIFFIES) * (NSEC_PER_SEC / HZ);
>  }
>  
> 

Re: [patch] fix for sched_clock() when using jiffies

[Ron]

On Wed, Nov 26, 2008 at 04:16:38PM +0100, Peter Zijlstra wrote:
> On Thu, 2008-11-27 at 01:36 +1030, Ron wrote:
> > Hi,
> > 
> > I'm in the process of updating a port for an ARM based chip we've been
> > working on, from 2.6.22-rc4'ish to the current HEAD of Linus' tree, and
> > I started seeing the following:
> > 
> > [    0.000000] PID hash table entries: 512 (order: 9, 2048 bytes)
> > [42949372.970000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
> > 
> > The reason appears to be that printk_clock() has been replaced with a
> > call to cpu_clock, which in our case currently falls back to the default
> > (weak) implementation of sched_clock() that uses jiffies -- but doesn't
> > account for the initial offset of the jiffy count.  The following simple
> > patch fixes it for me, in line with what printk_clock used to do.
> > 
> 
> Looks good, except I suspect this line will now be longer than 80
> characters and you forgot to provide your signed-off-by line.

diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
index 8178724..1ce2e53 100644
--- a/kernel/sched_clock.c
+++ b/kernel/sched_clock.c
@@ -37,7 +37,8 @@
  */
 unsigned long long __attribute__((weak)) sched_clock(void)
 {
-       return (unsigned long long)jiffies * (NSEC_PER_SEC / HZ);
+       return (unsigned long long)(jiffies - INITIAL_JIFFIES)
+                                  * (NSEC_PER_SEC / HZ);
 }
 
 static __read_mostly int sched_clock_running;


 Signed-off-by: Ron Lee <ron@debian.org>


Thanks!

Re: [patch] fix for sched_clock() when using jiffies

[Ingo Molnar]

* Ron <ron@debian.org> wrote:

> On Wed, Nov 26, 2008 at 04:16:38PM +0100, Peter Zijlstra wrote:
> > On Thu, 2008-11-27 at 01:36 +1030, Ron wrote:
> > > Hi,
> > > 
> > > I'm in the process of updating a port for an ARM based chip we've been
> > > working on, from 2.6.22-rc4'ish to the current HEAD of Linus' tree, and
> > > I started seeing the following:
> > > 
> > > [    0.000000] PID hash table entries: 512 (order: 9, 2048 bytes)
> > > [42949372.970000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
> > > 
> > > The reason appears to be that printk_clock() has been replaced with a
> > > call to cpu_clock, which in our case currently falls back to the default
> > > (weak) implementation of sched_clock() that uses jiffies -- but doesn't
> > > account for the initial offset of the jiffy count.  The following simple
> > > patch fixes it for me, in line with what printk_clock used to do.
> > > 
> > 
> > Looks good, except I suspect this line will now be longer than 80
> > characters and you forgot to provide your signed-off-by line.
> 
> diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
> index 8178724..1ce2e53 100644
> --- a/kernel/sched_clock.c
> +++ b/kernel/sched_clock.c
> @@ -37,7 +37,8 @@
>   */
>  unsigned long long __attribute__((weak)) sched_clock(void)
>  {
> -       return (unsigned long long)jiffies * (NSEC_PER_SEC / HZ);
> +       return (unsigned long long)(jiffies - INITIAL_JIFFIES)
> +                                  * (NSEC_PER_SEC / HZ);
>  }
>  
>  static __read_mostly int sched_clock_running;
> 
> 
>  Signed-off-by: Ron Lee <ron@debian.org>

whitespace damage: all tabs are space.

please see Documentation/email-clients.txt for how to send patches.

Also, when you resend a patch, do it without quotes and by including the 
fill commit log again - to make it easier to apply it. (and not forcing 
me to cut&paste various emails - it's fundamentall error-prone)

	Ingo

[PATCH] fix for sched_clock() when using jiffies

[Ron]

Account for the initial offset to the jiffy count.
---
 kernel/sched_clock.c |    3 ++-
 1 files changed, 2 insertions(+), 1 deletions(-)

diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
index a0b0852..a1567b1 100644
--- a/kernel/sched_clock.c
+++ b/kernel/sched_clock.c
@@ -37,7 +37,8 @@
  */
 unsigned long long __attribute__((weak)) sched_clock(void)
 {
-	return (unsigned long long)jiffies * (NSEC_PER_SEC / HZ);
+	return (unsigned long long)(jiffies - INITIAL_JIFFIES)
+					* (NSEC_PER_SEC / HZ);
 }
 
 static __read_mostly int sched_clock_running;
-- 
1.6.1.3

[PATCH] fix for sched_clock() when using jiffies

[Ron]

 
Account for the initial offset to the jiffy count.

Signed-off-by: Ron Lee <ron@debian.org>

---
 kernel/sched_clock.c |    3 ++-
 1 files changed, 2 insertions(+), 1 deletions(-)

diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
index a0b0852..a1567b1 100644
--- a/kernel/sched_clock.c
+++ b/kernel/sched_clock.c
@@ -37,7 +37,8 @@
  */
 unsigned long long __attribute__((weak)) sched_clock(void)
 {
-	return (unsigned long long)jiffies * (NSEC_PER_SEC / HZ);
+	return (unsigned long long)(jiffies - INITIAL_JIFFIES)
+					* (NSEC_PER_SEC / HZ);
 }
 
 static __read_mostly int sched_clock_running;
-- 
1.6.1.3

Re: [PATCH] fix for sched_clock() when using jiffies

[Andrew Morton]

On Sat, 9 May 2009 05:34:44 +0930
Ron <ron@debian.org> wrote:

>  
> Account for the initial offset to the jiffy count.
> 
> Signed-off-by: Ron Lee <ron@debian.org>
> 
> ---
>  kernel/sched_clock.c |    3 ++-
>  1 files changed, 2 insertions(+), 1 deletions(-)
> 
> diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
> index a0b0852..a1567b1 100644
> --- a/kernel/sched_clock.c
> +++ b/kernel/sched_clock.c
> @@ -37,7 +37,8 @@
>   */
>  unsigned long long __attribute__((weak)) sched_clock(void)
>  {
> -	return (unsigned long long)jiffies * (NSEC_PER_SEC / HZ);
> +	return (unsigned long long)(jiffies - INITIAL_JIFFIES)
> +					* (NSEC_PER_SEC / HZ);
>  }
>  
>  static __read_mostly int sched_clock_running;

Why?  I assume that you encountered some problem which was fixed
by this patch.  What was that problem?

Re: [PATCH] fix for sched_clock() when using jiffies

[Ron]

On Fri, May 08, 2009 at 04:01:42PM -0700, Andrew Morton wrote:
> On Sat, 9 May 2009 05:34:44 +0930
> Ron <ron@debian.org> wrote:
> 
> >  
> > Account for the initial offset to the jiffy count.
> > 
> > Signed-off-by: Ron Lee <ron@debian.org>
> > 
> > ---
> >  kernel/sched_clock.c |    3 ++-
> >  1 files changed, 2 insertions(+), 1 deletions(-)
> > 
> > diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
> > index a0b0852..a1567b1 100644
> > --- a/kernel/sched_clock.c
> > +++ b/kernel/sched_clock.c
> > @@ -37,7 +37,8 @@
> >   */
> >  unsigned long long __attribute__((weak)) sched_clock(void)
> >  {
> > -	return (unsigned long long)jiffies * (NSEC_PER_SEC / HZ);
> > +	return (unsigned long long)(jiffies - INITIAL_JIFFIES)
> > +					* (NSEC_PER_SEC / HZ);
> >  }
> >  
> >  static __read_mostly int sched_clock_running;
> 
> Why?  I assume that you encountered some problem which was fixed
> by this patch.  What was that problem?

This was a resend of a patch that seemed to get a thumbs up, except
for whitespace damage in what I originally sent, but which apparently
then didn't get applied.  The original context to it was:

 I'm in the process of updating a port for an ARM based chip we've been
 working on, from 2.6.22-rc4'ish to the current HEAD of Linus' tree, and
 I started seeing the following:

 [    0.000000] PID hash table entries: 512 (order: 9, 2048 bytes)
 [42949372.970000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)

 The reason appears to be that printk_clock() has been replaced with a
 call to cpu_clock, which in our case currently falls back to the default
 (weak) implementation of sched_clock() that uses jiffies -- but doesn't
 account for the initial offset of the jiffy count.  The following simple
 patch fixes it for me, in line with what printk_clock used to do.

I've since created a 'real' implementation of sched_clock for our port,
so it's no longer an issue for us, but someone else reported this on
#kernelnewbies yesterday, so I figured it was worth forwarding a clean
patch for it once again.

Cheers,
Ron

Re: [PATCH] fix for sched_clock() when using jiffies

[Andrew Morton]

On Sat, 9 May 2009 10:10:09 +0930 Ron <ron@debian.org> wrote:

> On Fri, May 08, 2009 at 04:01:42PM -0700, Andrew Morton wrote:
> > On Sat, 9 May 2009 05:34:44 +0930
> > Ron <ron@debian.org> wrote:
> > 
> > >  
> > > Account for the initial offset to the jiffy count.
> > > 
> > > Signed-off-by: Ron Lee <ron@debian.org>
> > > 
> > > ---
> > >  kernel/sched_clock.c |    3 ++-
> > >  1 files changed, 2 insertions(+), 1 deletions(-)
> > > 
> > > diff --git a/kernel/sched_clock.c b/kernel/sched_clock.c
> > > index a0b0852..a1567b1 100644
> > > --- a/kernel/sched_clock.c
> > > +++ b/kernel/sched_clock.c
> > > @@ -37,7 +37,8 @@
> > >   */
> > >  unsigned long long __attribute__((weak)) sched_clock(void)
> > >  {
> > > -	return (unsigned long long)jiffies * (NSEC_PER_SEC / HZ);
> > > +	return (unsigned long long)(jiffies - INITIAL_JIFFIES)
> > > +					* (NSEC_PER_SEC / HZ);
> > >  }
> > >  
> > >  static __read_mostly int sched_clock_running;
> > 
> > Why?  I assume that you encountered some problem which was fixed
> > by this patch.  What was that problem?
> 
> This was a resend of a patch that seemed to get a thumbs up, except
> for whitespace damage in what I originally sent, but which apparently
> then didn't get applied.  The original context to it was:
> 
>  I'm in the process of updating a port for an ARM based chip we've been
>  working on, from 2.6.22-rc4'ish to the current HEAD of Linus' tree, and
>  I started seeing the following:
> 
>  [    0.000000] PID hash table entries: 512 (order: 9, 2048 bytes)
>  [42949372.970000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
> 
>  The reason appears to be that printk_clock() has been replaced with a
>  call to cpu_clock, which in our case currently falls back to the default
>  (weak) implementation of sched_clock() that uses jiffies -- but doesn't
>  account for the initial offset of the jiffy count.  The following simple
>  patch fixes it for me, in line with what printk_clock used to do.

Removing printk_clock() always seemed a mildly wrong idea to me.

I'm sure we fixed this printk-timestamping ages and ages ago.  Maybe it
came back, or maybe it's somehow specific to your setup?

It's trivial to test, but I don't have the time to build and boot a
kernel right now :(

If the printk oddity is indeed being seen on all kernels then I'd
suggest that it be fixed right there in vprintk().  Because changing
sched_clock() adds unneeded overhead and partially defeats the intent
of INITIAL_JIFFIES, which is to catch code which is incorrectly
handling jiffy wrapping.

Re: [PATCH] fix for sched_clock() when using jiffies

[Ron]

On Fri, May 08, 2009 at 06:15:59PM -0700, Andrew Morton wrote:
> On Sat, 9 May 2009 10:10:09 +0930 Ron <ron@debian.org> wrote:
> 
> >  I'm in the process of updating a port for an ARM based chip we've been
> >  working on, from 2.6.22-rc4'ish to the current HEAD of Linus' tree, and
> >  I started seeing the following:
> > 
> >  [    0.000000] PID hash table entries: 512 (order: 9, 2048 bytes)
> >  [42949372.970000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
> > 
> >  The reason appears to be that printk_clock() has been replaced with a
> >  call to cpu_clock, which in our case currently falls back to the default
> >  (weak) implementation of sched_clock() that uses jiffies -- but doesn't
> >  account for the initial offset of the jiffy count.  The following simple
> >  patch fixes it for me, in line with what printk_clock used to do.
> 
> Removing printk_clock() always seemed a mildly wrong idea to me.
> 
> I'm sure we fixed this printk-timestamping ages and ages ago.  Maybe it
> came back, or maybe it's somehow specific to your setup?

I presume it's just gone unnoticed because nobody actually uses this
default implementation, they all have one based on a real clocksource.

> It's trivial to test, but I don't have the time to build and boot a
> kernel right now :(

I can confirm for our ARM port that if I revert to using this default
sched_clock, then I still see the same result.  That's rebased against
Linus' tree as of yesterday.

> If the printk oddity is indeed being seen on all kernels then I'd
> suggest that it be fixed right there in vprintk().

Looking at the code again, it seems pretty straightforward that it
should be (for anything actually using this default sched_clock,
which is probably not much, except people fleshing out new ports).

vprintk() calls cpu_clock(), which calls sched_clock().  All 'real'
sched_clock implementations (empirically) count from 0, except this
default one.

> Because changing sched_clock() adds unneeded overhead and partially
> defeats the intent of INITIAL_JIFFIES, which is to catch code which
> is incorrectly handling jiffy wrapping.

I agree with the general spirit of that thinking, but in this particular
case, I'm not sure that it's entirely applicable:

The overhead of subtracting INITIAL_JIFFIES is only incurred for people
who actually use this default sched_clock -- which should be almost
nobody for a 'mature' port, they mostly all should implement their own
specialisation with a better clock source.  So at worst it's a tax on
'lazy people' right now.

Actually having a real hires timer for the printk output is nice, so
reverting to a printk_clock() that _only_ counts in jiffies seems
suboptimal -- except in this one case, that nobody should be using.

Which means trying to 'fix' vprintk for only this one anomalous case
where sched_clock does not start at zero, which nobody should be using
anyhow, starts to look a bit messy in its own right.

Unless there is some other reason for having this one implementation
of sched_clock start from something other than zero, making it behave
like the others seems like the 'simplest' correct thing to do here.
That doesn't totally invalidate the use of INITIAL_JIFFIES for other
things counting by jiffies, it just makes it explicit that sched_clock
should count from 0, regardless of the underlying clock values.

OTOH, having it start with a bogus value may also be a useful hint
to people that they need to provide their own sched_clock (which is
what I recommended the reporter yesterday do, rather than applying
this patch :)

I'm happy to defer to wiser minds on what the best thing to do here
really is, there are surely subtleties that I'm missing, but given
that nobody should be using this particular function implementation,
and it's the only one showing this symptom, it doesn't seem too
unreasonable to make it behave like the ones people are actually
using do...  unless that's an invalid constraint to place on all
sched_clock implementations for some other reason.  If it's not,
that seems preferable to having ports provide _both_ a sched_clock
and a hires 'zero based clock' for printk ...  but there might still
be a better existing clock that printk could use instead ...

Cheers,
Ron

Re: [PATCH] fix for sched_clock() when using jiffies

[Andrew Morton]

On Sat, 9 May 2009 13:35:37 +0930 Ron <ron@debian.org> wrote:

>  All 'real'
> sched_clock implementations (empirically) count from 0, except this
> default one.

Well you live and learn.

Yup, we should make the toy sched_clock() match the fancy ones.


otoh, sched_clock() should do the INTITAL_JIFFIES offsetting as well,
because there are probably callers of sched_clock() who are buggy in
the presence of sched_clock()-return-value wraparound.

otooh, sched_clock() wraparound takes nearly 500 years so we can
afford to wait until linux-2.7.x to fix this.


I'll go off and find your original patch.  This was all a difficult way of
writing the changelog ;)

Re: [PATCH] fix for sched_clock() when using jiffies

[Paul Mundt]

On Fri, May 08, 2009 at 06:15:59PM -0700, Andrew Morton wrote:
> On Sat, 9 May 2009 10:10:09 +0930 Ron <ron@debian.org> wrote:
> > This was a resend of a patch that seemed to get a thumbs up, except
> > for whitespace damage in what I originally sent, but which apparently
> > then didn't get applied.  The original context to it was:
> > 
> >  I'm in the process of updating a port for an ARM based chip we've been
> >  working on, from 2.6.22-rc4'ish to the current HEAD of Linus' tree, and
> >  I started seeing the following:
> > 
> >  [    0.000000] PID hash table entries: 512 (order: 9, 2048 bytes)
> >  [42949372.970000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
> > 
> >  The reason appears to be that printk_clock() has been replaced with a
> >  call to cpu_clock, which in our case currently falls back to the default
> >  (weak) implementation of sched_clock() that uses jiffies -- but doesn't
> >  account for the initial offset of the jiffy count.  The following simple
> >  patch fixes it for me, in line with what printk_clock used to do.
> 
> Removing printk_clock() always seemed a mildly wrong idea to me.
> 
> I'm sure we fixed this printk-timestamping ages and ages ago.  Maybe it
> came back, or maybe it's somehow specific to your setup?
> 
FWIW, I just ran in to this yesterday on a board with a single timer
channel (which is assigned over to clockevents so we can still do
tickless), using the jiffies clocksource. With printk_clock() gone, it
seems like anything using the jiffies clocksource ought to have this
problem.

Re: [PATCH] fix for sched_clock() when using jiffies

[Ron]

On Sat, May 09, 2009 at 12:04:06AM -0700, Andrew Morton wrote:
> otoh, sched_clock() should do the INTITAL_JIFFIES offsetting as well,
> because there are probably callers of sched_clock() who are buggy in
> the presence of sched_clock()-return-value wraparound.

I had pondered that too ...

FWIW, that probably could be added fairly trivially as an explicit
debug mode.  Since the only effect should be the visible anomaly in
the printk timestamp, and that would be a Good Thing in this mode
because you'd get to see exactly when it wrapped relative to when
things do go pear shaped and start barking to kernel log about it.