Re: [RFC PATCH 1/2] printk: print initial logbuf contents before re-enabling interrupts

[Peter Zijlstra]

On Fri, Apr 25, 2014 at 02:29:37PM +0100, Will Deacon wrote:
> Hi all,
> 
> On Thu, Apr 17, 2014 at 12:36:09PM +0100, Will Deacon wrote:
> > When running on a hideously slow system (~10Mhz FPGA) with a bunch of

Hey, still faster then the 4.77 MHz 8088 chips I started with :-)

> > 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.
> 
> Any thoughts on these two patches? I can understand the reluctance to make
> changes to printk, but I had a horrible time debugging timers without these
> patches!

They look fine to me.
--
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/