2.6.24-rc1: au1xxx and clocksource

2.6.24-rc1: au1xxx and clocksource

[Manuel Lauss]

Hi everyone,

> So time to check how your favorite platform is doing and fix what broke!

I let it loose on my Au1200, but unfortunately the new time code is b0rked
ina way I don't understand.

Following call chain:

start_kernel()
 time_init()
  init_mips_clocksource()
  mips_clockevent_init()
   clockevents_register_device()
    clockevents_do_notify()
     notifier_call_chain():

      It dies here, line 69, in kernel/notifier.c:
      ret = nb->notifier_call(nb, val, v);

Maybe my debug method is faulty (homebrew putstring() with au1200 uart
 banging) but the last debug output is before this line.

Any ideas?

Thanks,
	Manuel Lauss

Re: 2.6.24-rc1: au1xxx and clocksource

[Ralf Baechle]

On Wed, Oct 24, 2007 at 08:31:35PM +0200, Manuel Lauss wrote:

> Hi everyone,
> 
> > So time to check how your favorite platform is doing and fix what broke!
> 
> I let it loose on my Au1200, but unfortunately the new time code is b0rked
> ina way I don't understand.
> 
> Following call chain:
> 
> start_kernel()
>  time_init()
>   init_mips_clocksource()
>   mips_clockevent_init()
>    clockevents_register_device()
>     clockevents_do_notify()
>      notifier_call_chain():
> 
>       It dies here, line 69, in kernel/notifier.c:
>       ret = nb->notifier_call(nb, val, v);

What sort of death?  Please describe all sympthoms of the patient.

> Maybe my debug method is faulty (homebrew putstring() with au1200 uart
>  banging) but the last debug output is before this line.

It is consistent with another bug report on IP27.

The function tick_notify has been installed as notifier, so that is what
I think nb->notifier_call() should be pointing at.  So it should be
called like this:

  tick_notify(&tick_notifier, CLOCK_EVT_NOTIFY_ADD, dev)

So things are likely going wrong somewhere in there.

  Ralf

Re: 2.6.24-rc1: au1xxx and clocksource

[Manuel Lauss]

> > > So time to check how your favorite platform is doing and fix what broke!
> > 
> > I let it loose on my Au1200, but unfortunately the new time code is b0rked
> > ina way I don't understand.
> > 
> > Following call chain:
> > 
> > start_kernel()
> >  time_init()
> >   init_mips_clocksource()
> >   mips_clockevent_init()
> >    clockevents_register_device()
> >     clockevents_do_notify()
> >      notifier_call_chain():
> > 
> >       It dies here, line 69, in kernel/notifier.c:
> >       ret = nb->notifier_call(nb, val, v);
> 
> What sort of death?  Please describe all sympthoms of the patient.

Well it does nothing. Unfortunately the only JTAG probe we have 
is always in use by the WinCE people so can't be more specific than that.
 
> > Maybe my debug method is faulty (homebrew putstring() with au1200 uart
> >  banging) but the last debug output is before this line.
> 
> It is consistent with another bug report on IP27.
> 
> The function tick_notify has been installed as notifier, so that is what
> I think nb->notifier_call() should be pointing at.  So it should be
> called like this:
> 
>   tick_notify(&tick_notifier, CLOCK_EVT_NOTIFY_ADD, dev)

That's a great hint, I'll debug it some more.

Thank you!

	Manuel Lauss

Re: 2.6.24-rc1: au1xxx and clocksource

[Manuel Lauss]

Hi Ralf,

On Thu, Oct 25, 2007 at 06:59:14PM +0100, Ralf Baechle wrote:
> On Wed, Oct 24, 2007 at 08:31:35PM +0200, Manuel Lauss wrote:
> > start_kernel()
> >  time_init()
> >   init_mips_clocksource()
> >   mips_clockevent_init()
> >    clockevents_register_device()
> >     clockevents_do_notify()
> >      notifier_call_chain():
> > 
> >       It dies here, line 69, in kernel/notifier.c:
> >       ret = nb->notifier_call(nb, val, v);

>   tick_notify(&tick_notifier, CLOCK_EVT_NOTIFY_ADD, dev)
> 
> So things are likely going wrong somewhere in there.

starting in nb->notifier_call:
tick_notify()
 tick_check_new_device()
  tick_setup_device()
   tick_setup_periodic():

   it seems to enternally loop in here:

123                 for (;;) {
124                         if (!clockevents_program_event(dev, next, ktime_get()))
125                                 return;
126                         next = ktime_add(next, tick_period);
127                 }

I think it's waiting for a timer irq which never happens.  The code in
cevt-r4k.c assigns IRQ 7 as the timer irq which is a GPIO according to
the manual. Actually, there is no real requestable() timer irq mentioned
in the manual (RTC and TOY aside).

Thanks!
	Manuel Lauss

Re: 2.6.24-rc1: au1xxx and clocksource

[Manuel Lauss]

On Fri, Oct 26, 2007 at 08:18:35AM +0200, Manuel Lauss wrote:
> Hi Ralf,
> 
> On Thu, Oct 25, 2007 at 06:59:14PM +0100, Ralf Baechle wrote:
> > On Wed, Oct 24, 2007 at 08:31:35PM +0200, Manuel Lauss wrote:
> > > start_kernel()
> > >  time_init()
> > >   init_mips_clocksource()
> > >   mips_clockevent_init()
> > >    clockevents_register_device()
> > >     clockevents_do_notify()
> > >      notifier_call_chain():
> > > 
> > >       It dies here, line 69, in kernel/notifier.c:
> > >       ret = nb->notifier_call(nb, val, v);
> 
> >   tick_notify(&tick_notifier, CLOCK_EVT_NOTIFY_ADD, dev)
> > 
> > So things are likely going wrong somewhere in there.
> 
> starting in nb->notifier_call:
> tick_notify()
>  tick_check_new_device()
>   tick_setup_device()
>    tick_setup_periodic():
> 
>    it seems to enternally loop in here:
> 
> 123                 for (;;) {
> 124                         if (!clockevents_program_event(dev, next, ktime_get()))
> 125                                 return;
> 126                         next = ktime_add(next, tick_period);
> 127                 }
> 
> I think it's waiting for a timer irq which never happens.  The code in
> cevt-r4k.c assigns IRQ 7 as the timer irq which is a GPIO according to
> the manual. Actually, there is no real requestable() timer irq mentioned
> in the manual (RTC and TOY aside).

That's wrong of course :(

The real reason is that mips_hpt_frequency is zero, the whole min/max delta
is therefore 2^31-1 and the loop above never exits because mips_next_event()
is called with zero for the 'delta' parameter.

Setting mips_hpt_frequency to processor speed gives me a booting kernel.

Sorry for the noise!

Thanks,
	Manuel Lauss

Re: 2.6.24-rc1: au1xxx and clocksource

[Sergei Shtylyov]

Hello.

Manuel Lauss wrote:

> Setting mips_hpt_frequency to processor speed gives me a booting kernel.

    I thought it's done in arch/mips/au1000/common/time.c...

> Sorry for the noise!

WBR, Sergei

Re: 2.6.24-rc1: au1xxx and clocksource

[Ralf Baechle]

On Fri, Oct 26, 2007 at 03:56:22PM +0400, Sergei Shtylyov wrote:

> >Setting mips_hpt_frequency to processor speed gives me a booting kernel.
> 
>    I thought it's done in arch/mips/au1000/common/time.c...

The function plat_timer_setup which does it is not getting invoked anymore.
So there will be a similar issue in the following:

arch/mips/basler/excite/excite_setup.c:void __init plat_timer_setup(struct irqaction *irq)
arch/mips/dec/time.c:void __init plat_timer_setup(struct irqaction *irq)
arch/mips/gt64120/wrppmc/time.c:void __init plat_timer_setup(struct irqaction *irq)
arch/mips/kernel/smtc.c:         * plat_timer_setup has already have been invoked by init/main
arch/mips/kernel/time.c: * 3) plat_timer_setup() -
arch/mips/kernel/time.c:void __init __weak plat_timer_setup(struct irqaction *irq)
arch/mips/lasat/setup.c:void __init plat_timer_setup(struct irqaction *irq)
arch/mips/mips-boards/generic/time.c:void __init plat_timer_setup(struct irqaction *irq)
arch/mips/mipssim/sim_time.c:void __init plat_timer_setup(struct irqaction *irq)
arch/mips/philips/pnx8550/common/time.c:void __init plat_timer_setup(struct irqaction *irq)
arch/mips/pmc-sierra/msp71xx/msp_time.c:void __init plat_timer_setup(struct irqaction *irq)
arch/mips/sni/time.c:void __init plat_timer_setup(struct irqaction *irq)
include/asm-mips/time.h:extern void plat_timer_setup(struct irqaction *irq);

I'll turn the weak definition of plat_timer_setup() in time.c into a strong
one to force people to look at it when there is a linker error.

  Ralf

Re: 2.6.24-rc1: au1xxx and clocksource

[Ralf Baechle]

On Fri, Oct 26, 2007 at 01:24:55PM +0200, Manuel Lauss wrote:

> On Fri, Oct 26, 2007 at 08:18:35AM +0200, Manuel Lauss wrote:
> > Hi Ralf,
> > 
> > On Thu, Oct 25, 2007 at 06:59:14PM +0100, Ralf Baechle wrote:
> > > On Wed, Oct 24, 2007 at 08:31:35PM +0200, Manuel Lauss wrote:
> > > > start_kernel()
> > > >  time_init()
> > > >   init_mips_clocksource()
> > > >   mips_clockevent_init()
> > > >    clockevents_register_device()
> > > >     clockevents_do_notify()
> > > >      notifier_call_chain():
> > > > 
> > > >       It dies here, line 69, in kernel/notifier.c:
> > > >       ret = nb->notifier_call(nb, val, v);
> > 
> > >   tick_notify(&tick_notifier, CLOCK_EVT_NOTIFY_ADD, dev)
> > > 
> > > So things are likely going wrong somewhere in there.
> > 
> > starting in nb->notifier_call:
> > tick_notify()
> >  tick_check_new_device()
> >   tick_setup_device()
> >    tick_setup_periodic():
> > 
> >    it seems to enternally loop in here:
> > 
> > 123                 for (;;) {
> > 124                         if (!clockevents_program_event(dev, next, ktime_get()))
> > 125                                 return;
> > 126                         next = ktime_add(next, tick_period);
> > 127                 }
> > 
> > I think it's waiting for a timer irq which never happens.  The code in
> > cevt-r4k.c assigns IRQ 7 as the timer irq which is a GPIO according to
> > the manual. Actually, there is no real requestable() timer irq mentioned
> > in the manual (RTC and TOY aside).
> 
> That's wrong of course :(
> 
> The real reason is that mips_hpt_frequency is zero, the whole min/max delta
> is therefore 2^31-1 and the loop above never exits because mips_next_event()
> is called with zero for the 'delta' parameter.
> 
> Setting mips_hpt_frequency to processor speed gives me a booting kernel.

So you found that while I was composing my other mail, good.  It basically
confirms my starring at the code, so I'm going to commit my patch now.

  Ralf

Re: 2.6.24-rc1: au1xxx and clocksource

[Ralf Baechle]

On Fri, Oct 26, 2007 at 08:18:35AM +0200, Manuel Lauss wrote:

> On Thu, Oct 25, 2007 at 06:59:14PM +0100, Ralf Baechle wrote:
> > On Wed, Oct 24, 2007 at 08:31:35PM +0200, Manuel Lauss wrote:
> > > start_kernel()
> > >  time_init()
> > >   init_mips_clocksource()
> > >   mips_clockevent_init()
> > >    clockevents_register_device()
> > >     clockevents_do_notify()
> > >      notifier_call_chain():
> > > 
> > >       It dies here, line 69, in kernel/notifier.c:
> > >       ret = nb->notifier_call(nb, val, v);
> 
> >   tick_notify(&tick_notifier, CLOCK_EVT_NOTIFY_ADD, dev)
> > 
> > So things are likely going wrong somewhere in there.
> 
> starting in nb->notifier_call:
> tick_notify()
>  tick_check_new_device()
>   tick_setup_device()
>    tick_setup_periodic():
> 
>    it seems to enternally loop in here:
> 
> 123                 for (;;) {
> 124                         if (!clockevents_program_event(dev, next, ktime_get()))
> 125                                 return;
> 126                         next = ktime_add(next, tick_period);
> 127                 }
> 
> I think it's waiting for a timer irq which never happens.  The code in
> cevt-r4k.c assigns IRQ 7 as the timer irq which is a GPIO according to
> the manual. Actually, there is no real requestable() timer irq mentioned
> in the manual (RTC and TOY aside).

As I said before, I've renumbered interrupts on Alchemy.  0 ... 7 are now
the processor's built-in interrupt controller (see the IE bits in the
CPU status and cause register).  The Alchemy SOC's interrupt controller
has moved to interrupts 8 ... 71.

So what must be happening is that clockevents_program_event is returning
a non-zero value, that's the only thing that can make above loop going
forever.  Now looking at clockevents_program_event:

int clockevents_program_event(struct clock_event_device *dev, ktime_t expires,
                              ktime_t now)
{
        unsigned long long clc;
        int64_t delta;

        delta = ktime_to_ns(ktime_sub(expires, now));

        if (delta <= 0)
                return -ETIME;

        dev->next_event = expires;

        if (dev->mode == CLOCK_EVT_MODE_SHUTDOWN)
                return 0;

        if (delta > dev->max_delta_ns)
                delta = dev->max_delta_ns;
        if (delta < dev->min_delta_ns)
                delta = dev->min_delta_ns;

        clc = delta * dev->mult;
        clc >>= dev->shift;

        return dev->set_next_event((unsigned long) clc, dev);
}

So you either must be hitting the "delta <= 0" check.  Or ->set_next_event
is returning an error.  So as your earlier calltrace of the hang shows
you are using cevt-r4k.c for the clockevent device so the function getting
called would be arch/mips/kernel/cevt-r4k.c:mips_next_event().  With the
#ifdefery removed this function looks like this:

static int mips_next_event(unsigned long delta,
                           struct clock_event_device *evt)
{
        unsigned int cnt;
        int res;

        cnt = read_c0_count();
        cnt += delta;
        write_c0_compare(cnt);
        res = ((long)(read_c0_count() - cnt ) > 0) ? -ETIME : 0;

        return res;
}

So this would return an error if by the time the compare register has
been programmed the timer has already expired which would happen for
exmaple if it was programmed for an extremly short time into the future.

The timer clock initialization code in cevt-r4k.c:

        /* Calculate the min / max delta */
        cd->mult        = div_sc((unsigned long) mips_freq, NSEC_PER_SEC, 32);
        cd->shift               = 32;
        cd->max_delta_ns        = clockevent_delta2ns(0x7fffffff, cd);
        cd->min_delta_ns        = clockevent_delta2ns(0x300, cd);

Looks a little oldfashioned but okay otherwise - if mips_freq is sane.
So let's see.  mips_freq is initialized from mips_hpt_frequency which the
platform code should have initialized in plat_time_init() which happens
in arch/mips/au1000/common/time.c: cal_r4koff() which is getting called
from plat_timer_setup which is called from ...  nowhere anymore whoops.

I could restore the call easily but that function is on the way out and
any user of plat_timer_setup has likely other bugs in the new time code.

Can you try below patch?

  Ralf

Signed-off-by: Ralf Baechle <ralf@linux-mips.org>

 arch/mips/au1000/common/time.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/arch/mips/au1000/common/time.c b/arch/mips/au1000/common/time.c
index 0673fc0..f113b51 100644
--- a/arch/mips/au1000/common/time.c
+++ b/arch/mips/au1000/common/time.c
@@ -228,7 +228,7 @@ unsigned long cal_r4koff(void)
 	return (cpu_speed / HZ);
 }
 
-void __init plat_timer_setup(struct irqaction *irq)
+void __init plat_time_init(void)
 {
 	unsigned int est_freq;