start_kernel / local_irq_enable() can be very slow

start_kernel / local_irq_enable() can be very slow

[Pozsar Balazs]

Hi all,

I've noticed that the local_irq_enable() call in 
init/main.c::start_kernel() takes 0.3 .. 3.0 seconds on every boot.
(Measured using printk's around it.)

I am wondering what happens during this call (which is effectively one 
"sti"), why does it take so much time sometimes, and why does it vary so 
much, why isn't it (more) deterministic.


This is a x86 machine, I can give more details if needed.
I've observed this behaviour on a few other machines too.


Anybody any clues?
thanks,

-- 
pozsy

Re: start_kernel / local_irq_enable() can be very slow

[Andrew Morton]

Pozsar Balazs <pozsy@uhulinux.hu> wrote:
>
> I've noticed that the local_irq_enable() call in 
>  init/main.c::start_kernel() takes 0.3 .. 3.0 seconds on every boot.
>  (Measured using printk's around it.)
> 
>  I am wondering what happens during this call (which is effectively one 
>  "sti"), why does it take so much time sometimes, and why does it vary so 
>  much, why isn't it (more) deterministic.

Presumably as soon as it does the sti, the CPU takes one or more interrupts
and runs off and does something.

I wonder what?

You could do something like:

int trace_irqs;

	trace_irqs = 1;
	local_irq_enble();
	trace_irqs = 0;

then, over in handle_IRQ_event():

	if (trace_irqs)
		print_symbol("calling %s\n", (unsigned long)action->handler);

Re: start_kernel / local_irq_enable() can be very slow

[Linus Torvalds]

On Sun, 13 Nov 2005, Andrew Morton wrote:
> 
> You could do something like:
> 
> int trace_irqs;
> 
> 	trace_irqs = 1;
> 	local_irq_enble();
> 	trace_irqs = 0;

Do "trace_irqs = 10" first.

> then, over in handle_IRQ_event():
> 
> 	if (trace_irqs)
> 		print_symbol("calling %s\n", (unsigned long)action->handler);

And decrement it here somewhere.

If it's delayed by up to three seconds, it sounds like there's a _lot_ of 
interrupts happening, and I don't think there's any point in showing all 
of them.

			Linus

Re: start_kernel / local_irq_enable() can be very slow

[Pozsar Balazs]

> > You could do something like:
> > 
> > int trace_irqs;
> > 
> > 	trace_irqs = 1;
> > 	local_irq_enble();
> > 	trace_irqs = 0;
> 
> Do "trace_irqs = 10" first.
> 
> > then, over in handle_IRQ_event():
> > 
> > 	if (trace_irqs)
> > 		print_symbol("calling %s\n", (unsigned long)action->handler);
> 
> And decrement it here somewhere.
> 
> If it's delayed by up to three seconds, it sounds like there's a _lot_ of 
> interrupts happening, and I don't think there's any point in showing all 
> of them.

Well, after using tons of printk's I found that the following is 
happening:
 - irqs get enabled, and the timer interrupt gets handled,
 - arch/i386/kernel/timer.c::timer_interrupt gets called,
 - which in turn calls cur_timer->mark_offset(), which is
 - arch/i386/kernel/timers/timer_pm.c::mark_offset_pmtmr(), where we 
   finally arrive to:
        /* compensate for lost ticks */
        if (lost >= 2)
                jiffies_64 += lost - 1;

So no irq storm here, everything works as it should, the jiffies gets 
updated as it should, that's why it _seems_ from printk's that it takes 
long. (And only 1 irq happens.)


The main question though remains: what takes up seconds on the kernel 
boot, and why is it so undeterministic how long it takes (sometimes just 
0.3s, sometimes even 3s)? (Something before timers get enabled.)


-- 
pozsy