Re: start_kernel / local_irq_enable() can be very slow

[Pozsar Balazs <pozsy@uhulinux.hu>]

> > 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
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/