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

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: <1397734570-12748-1-git-send-email-will.deacon@arm.com>
Date:	Thu, 17 Apr 2014 12:36:09 +0100
From:	Will Deacon <will.deacon@....com>
To:	linux-kernel@...r.kernel.org
Cc:	Will Deacon <will.deacon@....com>,
	Andrew Morton <akpm@...ux-foundation.org>,
	Kay Sievers <kay@...y.org>,
	Peter Zijlstra <peterz@...radead.org>
Subject: [RFC PATCH 1/2] 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.

Cc: Andrew Morton <akpm@...ux-foundation.org>
Cc: Kay Sievers <kay@...y.org>
Cc: Peter Zijlstra <peterz@...radead.org>
Signed-off-by: Will Deacon <will.deacon@....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

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