linux-kernel - Re: IRQ off latency of printk is very high

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20071026012342.GV19691@waste.org>
Date:	Thu, 25 Oct 2007 20:23:42 -0500
From:	Matt Mackall <mpm@...enic.com>
To:	Tim Bird <tim.bird@...sony.com>
Cc:	Mathieu Desnoyers <mathieu.desnoyers@...ymtl.ca>,
	linux kernel <linux-kernel@...r.kernel.org>,
	Ingo Molnar <mingo@...hat.com>, Jon Smirl <jonsmirl@...oo.com>
Subject: Re: IRQ off latency of printk is very high

On Thu, Oct 25, 2007 at 04:41:55PM -0700, Tim Bird wrote:
> Matt Mackall wrote:
> > On Thu, Oct 25, 2007 at 03:52:28PM -0700, Tim Bird wrote:
> >> Mathieu Desnoyers wrote:
> >>> It might help to read this thread I posted on LKML in January 2006
> >>> explaining the problem, which led to some discussion about the issue.
> >>>
> >>> http://lkml.org/lkml/2006/6/3/48
> >> This is very helpful.  Jon Smirl's answer seems to give the
> >> rationale for supporting printk output in interrupt context.
> >> I'm not sure, however, if extending the interrupt off period
> >> to cover the console output is required.  It didn't until
> >> Ingo changed it in 2.6.17.
> > 
> > Hmm, I see this at the beginning of the post-BK era (2.6.12-rc2):
> > 
> > 	        spin_lock_irqsave(&logbuf_lock, flags);
> > 		...
> > 		spin_unlock(&logbuf_lock);
> > 		call_console_drivers(_con_start, _log_end);
> > 		local_irq_restore(flags);
> > 
> 
> Well, I need to do some more research.  This must be in
> release_console_sem().  I was looking at vprintk, through
> the ages.  At 2.6.16, it looked like this:
> 
>         spin_lock_irqsave(&logbuf_lock, flags);
>         ...
>               spin_unlock_irqrestore(&logbuf_lock, flags);
>               console_may_schedule = 0;
>               release_console_sem();
> 
> but the irq restore has been moving around to different places
> in that function over the last few years.  I suspect that in the
> common case the irqsave in vprintk is the one that disables
> ints.
> 
> It appears that formerly interrupts were enabled in vprintk but
> re-disabled immediately upon entering release_console_sem().
> As it is now, they're held during formatting, buffering,
> and output, which seems excessive.
> 
> It seems draconian to drain the entire buffer with ints disabled.
> Is it possible to break this up and send out smaller chunks
> at a time?  Maybe by putting a chunk loop in release_console_sem()?

Well there are things we can do, yes, but I'd be worried that they've
give up the deterministic behavior we rely on quite heavily for
debugging. If event A happens before event B, we must see the message
from A before the one from B, even if B happens in irq context. 

And if event B is a hard lock up, we'd also like to be sure the
message for A actually gets out. If B happens in the interrupt that
comes in when we re-enable them, that won't happen.

(This is also a problem on unaccelerated video consoles, where
scrolling may actually be slower than 115kbps!)

-- 
Mathematics is the supreme nostalgia of our time.
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/