Re: Interrupts disabled for too long in printk

[Steven Rostedt <rostedt@goodmis.org>]

On Sat, 2006-06-03 at 07:19 -0400, Mathieu Desnoyers 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);
>         }
> 
> 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.

So what's the problem?

printk is more for debugging. If you don't like the latency then disable
printks.  But turning the spin_lock_irqsave into a spin_lock means you
need to do a trylock every time in printk.  Since printk can be called
from interrupt handlers.  So what do you do when you fail? just return?
So you just lost your printk that you needed, which could be of
importance.

Actually, the spin_lock is not your problem, since it is not held when
the console drivers are being called. But...

There may be console drivers that grab spin_locks without turning off
interrupts, which mean that you can again deadlock if an interrupt that
calls printk happens in one of those drivers.

If latency is your worry, then try out Ingo Molnar's -rt patch
http://people.redhat.com/mingo/realtime-preempt/
It isn't affected by this problem.

-- Steve