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-next>] [day] [month] [year] [list]

Message-ID: <20140502224651.GG23636@quack.suse.cz>
Date:	Sat, 3 May 2014 00:46:51 +0200
From:	Jan Kara <jack@...e.cz>
To:	will.deacon@....com
Cc:	mm-commits@...r.kernel.org, peterz@...radead.org, kay@...y.org,
	jack@...e.cz, 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

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 ;). 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?

								Honza

> Signed-off-by: Will Deacon <will.deacon@....com>
> Acked-by: Peter Zijlstra <peterz@...radead.org>
> Cc: Kay Sievers <kay@...y.org>
> Cc: Jan Kara <jack@...e.cz>
> Signed-off-by: Andrew Morton <akpm@...ux-foundation.org>
> ---
> 
>  kernel/printk/printk.c |    9 +++++++++
>  1 file changed, 9 insertions(+)
> 
> diff -puN kernel/printk/printk.c~printk-print-initial-logbuf-contents-before-re-enabling-interrupts kernel/printk/printk.c
> --- a/kernel/printk/printk.c~printk-print-initial-logbuf-contents-before-re-enabling-interrupts
> +++ a/kernel/printk/printk.c
> @@ -2147,10 +2147,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;
> @@ -2195,6 +2198,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;
> _
> 
> Patches currently in -mm which might be from will.deacon@....com are
> 
> origin.patch
> printk-print-initial-logbuf-contents-before-re-enabling-interrupts.patch
> printk-report-dropping-of-messages-from-logbuf.patch
> documentation-devicetree-bindings-add-documentation-for-the-apm-x-gene-soc-rtc-dts-binding.patch
> drivers-rtc-add-apm-x-gene-soc-rtc-driver.patch
> arm64-add-apm-x-gene-soc-rtc-dts-entry.patch
> linux-next.patch
> 
-- 
Jan Kara <jack@...e.cz>
SUSE Labs, CR
--
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/