Re: Interrupts disabled for too long in printk

["Jon Smirl" <jonsmirl@gmail.com>]

On 6/3/06, Mathieu Desnoyers <compudj@krystal.dyndns.org> wrote:
> Hi,
>
> I ran some experiments with my kernel tracer (LTTng : http://ltt.polymtl.ca)
> that showed missing interrupts. I wrote a small paper to show how to use my
> tracer to solve this kind of problem which I presented at the CE Linux Form
> last April.
>
> http://tree.celinuxforum.org/CelfPubWiki/ELC2006Presentations?action=AttachFile&do=get&target=celf2006-desnoyers.pdf
>
> It shows that, when the serial console is activated, the following code disables
> interrupts for up to 15ms. On a system configured with a 250HZ timer (each 4ms),
> it means that 3 scheduler ticks are lost.
>
> In the current git :
>
> kernel/printk.c: release_console_sem()
>
>         for ( ; ; ) {
> ----->          spin_lock_irqsave(&logbuf_lock, flags);
>                 wake_klogd |= log_start - log_end;
>                 if (con_start == log_end)
>                         break;                  /* Nothing to print */
>                 _con_start = con_start;
>                 _log_end = log_end;
>                 con_start = log_end;            /* Flush */
>                 spin_unlock(&logbuf_lock);
>                 call_console_drivers(_con_start, _log_end);
> ----->          local_irq_restore(flags);
>         }

You can look at this problem from the other direction too. Why is it
taking 15ms to get between the two points? If IRQs are off how is the
serial driver getting interrupts to be able to display the message? It
is probably worthwhile to take a look and see what the serial console
driver is doing.

> I guess interrupts are disabled for a good reason (to protect this spinlock for
> being taken by a nested interrupt handler. One way I am thinking to fix this
> problem would be to do a spin try lock and fail if it is already taken.

-- 
Jon Smirl
jonsmirl@gmail.com