Re: Interrupts disabled for too long in printk

From: Jon Smirl
Date: Wed Jun 07 2006 - 21:36:19 EST


On 6/3/06, Mathieu Desnoyers <compudj@xxxxxxxxxxxxxxxxxx> 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@xxxxxxxxx
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/