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

[Will Deacon <will.deacon@arm.com>]

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
> 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!

Cheers,

Will

> Cc: Andrew Morton <akpm@linux-foundation.org>
> Cc: Kay Sievers <kay@vrfy.org>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Signed-off-by: Will Deacon <will.deacon@arm.com>
> ---
>  kernel/printk/printk.c | 9 +++++++++
>  1 file changed, 9 insertions(+)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index a45b50962295..721a7d8fb853 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2033,10 +2033,13 @@ void console_unlock(void)
>  again:
>  	for (;;) {
>  		struct printk_log *msg;
> +		u64 console_end_seq;
>  		size_t len;
>  		int level;
>  
>  		raw_spin_lock_irqsave(&logbuf_lock, flags);
> +		console_end_seq = log_next_seq;
> +again_noirq:
>  		if (seen_seq != log_next_seq) {
>  			wake_klogd = true;
>  			seen_seq = log_next_seq;
> @@ -2081,6 +2084,12 @@ skip:
>  		stop_critical_timings();	/* don't trace print latency */
>  		call_console_drivers(level, text, len);
>  		start_critical_timings();
> +
> +		if (console_seq < console_end_seq) {
> +			raw_spin_lock(&logbuf_lock);
> +			goto again_noirq;
> +		}
> +
>  		local_irq_restore(flags);
>  	}
>  	console_locked = 0;
> -- 
> 1.9.1
>