linux-kernel - Re: + printk-print-initial-logbuf-contents-before-re-enabling-interrupts.patch added to -mm tree

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: <20140506120648.GA30234@arm.com>
Date:	Tue, 6 May 2014 13:06:48 +0100
From:	Will Deacon <will.deacon@....com>
To:	Jan Kara <jack@...e.cz>
Cc:	"mm-commits@...r.kernel.org" <mm-commits@...r.kernel.org>,
	"peterz@...radead.org" <peterz@...radead.org>,
	"kay@...y.org" <kay@...y.org>, LKML <linux-kernel@...r.kernel.org>,
	Andrew Morton <akpm@...ux-foundation.org>
Subject: Re: +
 printk-print-initial-logbuf-contents-before-re-enabling-interrupts.patch
 added to -mm tree

Hello,

On Fri, May 02, 2014 at 11:46:51PM +0100, Jan Kara wrote:
> On Fri 02-05-14 14:22:20, Andrew Morton wrote:
> > From: Will Deacon <will.deacon@....com>
> > Subject: printk: print initial logbuf contents before re-enabling interrupts
> > 
> > When running on a hideously slow system (~10Mhz FPGA) with a bunch of
> > debug printk invocations on the timer interrupt path, we end up filling
> > the log buffer faster than we can drain it.
> > 
> > The reason is that console_unlock (which is responsible for moving
> > messages out of logbuf to hand over to the console driver) removes one
> > message at a time, briefly re-enabling interrupts between each of them. 
> > If the interrupt path prints more than a single message, then we can
> > easily generate more messages than we can print for a regular, recurring
> > interrupt (e.g.  a 1khz timer).  This results in messages getting silently
> > dropped, leading to counter-intuitive, incomplete printk traces on the
> > console.
> > 
> > Rather than run the console_unlock loop with interrupts disabled (which
> > has obvious latency problems), this patch records the sequence number of
> > the last message in the log buffer after taking the logbuf_lock.  We can
> > then print this fixed amount of work before re-enabling interrupts again,
> > making sure we keep up with ourself.  Other CPUs could still potentially
> > flood the buffer, but there's little that we can do to protect against
> > that.
>   I really dislike this patch. It goes completely against my efforts of
> lowering irq latency caused by printing to console (which are the
> problems I have observed ;).

Hmmm, what makes you think that? Interrupts only remain disabled whilst we
process the backlog, which in the usual case should be pretty small. We also
hold the logbuf_lock during this time, so we can't get stuck in an unbounded
loop.

Can you elaborate a bit more on the problems you've observed, please?

> My opinion is that when you are printing from each and every interrupt
> which happens so often, then you have a problem and disabling IRQs in
> printk so that your interrupt doesn't happen that often seems like a poor
> solution to me. You could as well just ratelimit your debug messages,
> couldn't you?

My use-case was basically using printk as a debug trace during early boot
when bringing up Linux on a new CPU core. I don't think ratelimiting would
be the right thing there, since I really did want as many messages to
reach the console as possible (which is also why I wrote this patch, not
just the other one in the series).

Cheers,

Will
--
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/