Message-ID: <1340322723.27036.220.camel@gandalf.stny.rr.com>
Date:	Thu, 21 Jun 2012 19:52:03 -0400
From:	Steven Rostedt <rostedt@...dmis.org>
To:	LKML <linux-kernel@...r.kernel.org>
Cc:	Linus Torvalds <torvalds@...ux-foundation.org>,
	Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
	"kay.sievers" <kay.sievers@...y.org>,
	Fengguang Wu <fengguang.wu@...el.com>,
	Ingo Molnar <mingo@...e.hu>,
	AndrewMorton <akpm@...ux-foundation.org>
Subject: [PATCH] printk: Add printk_flush() to force buffered text to console

Fengguang Wu had a config that caused the system to lockup. It reported:

[    6.086395] type=2000 audit(1339501575.085:1): initialized
[    6.116356] Kprobe smoke test started
[    6.125915] Kprobe smoke test passed successfully
[    6.127478] rcu-torture:--- Start of test: nreaders=2 nfakewriters=4 stat_interval=0 verbose=0 test_no_idle_hz=0 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0
+fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 onoff_interval=0 onoff_holdoff=0

and then froze. So naturally, the suspected bug was with rcu-torture.
Fengguang did a git bisect and discovered that the crash came with a
function trace update. He also noticed that if he reverted that update,
the system got farther and showed:

[    1.611901] Testing tracer function: PASSED

His time was wasted by the fact that the function tracing self test
first prints:

  "Testing tracer function: "

then runs the test, and if it succeeds, it prints "PASSED", giving us
the nice output you see above.

But with the new printk() changes, text without a newline gets buffered
and does not print out to the console at the location of the printk.
This caused the "Testing tracer function: " not to print out and because
the test caused the kernel to lock up, we are clueless to the fact that
the problem was with the function tracer test and not the rcu_torture
test. As it made sense that the rcu_torture test could lock up the
system, many kernel developer hours were wasted chasing the wrong wild
goose.

If the "Testing tracer function: " had printed out in the first place,
we would have caught the correct wild goose and saved precious kernel
developer's time.

Thus a need for the following utility. That is to add a 'printk_flush()'
that acts like a fflush() in userspace to flush out the buffers used by
the printing facility so we don't have unexpected hunts for nature
roaming fowl.

I hooked onto the 'facility' infrastructure and used '0x1ffc' (the max
number) as a way to communicate printk() commands to the msg_print_text()
which is performed at a later time (console_unlock()).

I tested this out, (adding pr_flush() after my printk) and now the
lockup shows:

[    9.018231] Kprobe smoke test passed successfully
[    9.023084] rcu-torture:--- Start of test: nreaders=4 nfakewriters=4 stat_interval=0 verbose=0 test_no_idle_hz=0 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_hold
off=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 onoff_interval=0 onoff_holdoff=0
[    9.066065] Testing tracer function:

To prevent the flush to cause the next printk to have a timestamp that
would produce the following:

[    6.834073] Testing tracer function: [    7.136194] PASSED

I made the KERN_CONT ("<c>") use the facility as well to pass info to
not print the timestamp. This fixes the abve issue to print:

[    1.291025] Testing tracer function: PASSED

Link: http://lkml.kernel.org/r/1339649173.13377.191.camel@gandalf.stny.rr.com

Cc: Linus Torvalds <torvalds@...ux-foundation.org>
Cc: Greg Kroah-Hartman <gregkh@...uxfoundation.org>
Cc: "kay.sievers" <kay.sievers@...y.org>
Cc: "Paul E. McKenney" <paulmck@...ibm.com>
Cc: Fengguang Wu <fengguang.wu@...el.com>
Cc: Ingo Molnar <mingo@...e.hu>
Cc: Andrew Morton <akpm@...ux-foundation.org>
Signed-off-by: Steven Rostedt <rostedt@...dmis.org>
---
 include/linux/printk.h |    8 ++++
 kernel/printk.c        |  104 ++++++++++++++++++++++++++++++++++++++++++-----
 2 files changed, 101 insertions(+), 11 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 1bec2f7..b3317bf3 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -111,6 +111,8 @@ asmlinkage int printk_emit(int facility, int level,
 asmlinkage __printf(1, 2) __cold
 int printk(const char *fmt, ...);
 
+void printk_flush(void);
+
 /*
  * Special printk facility for scheduler use only, _DO_NOT_USE_ !
  */
@@ -158,6 +160,10 @@ static inline bool printk_timed_ratelimit(unsigned long *caller_jiffies,
 	return false;
 }
 
+static inline void printk_flush(void)
+{
+}
+
 static inline void log_buf_kexec_setup(void)
 {
 }
@@ -190,6 +196,8 @@ extern void dump_stack(void) __cold;
 	printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
 #define pr_cont(fmt, ...) \
 	printk(KERN_CONT fmt, ##__VA_ARGS__)
+#define pr_flush() \
+	printk_flush()
 
 /* pr_devel() should produce zero code unless DEBUG is defined */
 #ifdef DEBUG
diff --git a/kernel/printk.c b/kernel/printk.c
index 32462d2..ca1f5ff 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -237,6 +237,24 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
 static char *log_buf = __log_buf;
 static u32 log_buf_len = __LOG_BUF_LEN;
 
+/*
+ * The max number for facility is 0xffff >> 3, or 0x1fff.
+ * As log facilities count upward from 1, we have the kernel
+ * keep the top numbers or itself.
+ *
+ * 0x1ffc is the code for kernel processing in msg->level (facility)
+ * bit 0 - do not print prefix
+ * bit 1 - do not print newline
+ */
+#define LOG_KERNEL		0x1ffc
+#define LOG_NONL_NOPREFIX_MSK	3
+#define LOG_NONL_SET		2
+#define LOG_NOPREFIX_SET	1
+
+#define LOG_NONL_NOPREFIX	(LOG_KERNEL | LOG_NONL_NOPREFIX_MSK)
+#define LOG_NONL		(LOG_KERNEL | LOG_NONL_SET)
+#define LOG_NOPREFIX		(LOG_KERNEL | LOG_NOPREFIX_SET)
+
 /* cpu currently holding logbuf_lock */
 static volatile unsigned int logbuf_cpu = UINT_MAX;
 
@@ -836,14 +854,36 @@ static size_t msg_print_text(const struct log *msg, bool syslog,
 		}
 
 		if (buf) {
-			if (print_prefix(msg, syslog, NULL) +
-			    text_len + 1>= size - len)
-				break;
+			int newline = 1;
+			int prefix = 1;
+			int facility = msg->level >> 3;
+
+			/*
+			 * The kernel sends some commands via the facility.
+			 * To do so, a high number mask is used (LOG_KERNEL)
+			 * and the low bits of the mask hold the command bits
+			 * that the kernel printk() will use to state how the
+			 * msg will be printed.
+			 */
+			if ((facility & LOG_KERNEL) == LOG_KERNEL) {
+				if (facility & LOG_NOPREFIX_SET)
+					prefix = 0;
+				if (facility & LOG_NONL_SET)
+					newline = 0;
+			}
+
+			if (prefix) {
+				if (print_prefix(msg, syslog, NULL) +
+				    text_len + 1 >= size - len)
+					break;
+
+				len += print_prefix(msg, syslog, buf + len);
+			}
 
-			len += print_prefix(msg, syslog, buf + len);
 			memcpy(buf + len, text, text_len);
 			len += text_len;
-			buf[len++] = '\n';
+			if (newline)
+				buf[len++] = '\n';
 		} else {
 			/* SYSLOG_ACTION_* buffer size only calculation */
 			len += print_prefix(msg, syslog, NULL);
@@ -1267,6 +1307,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 	static char cont_buf[LOG_LINE_MAX];
 	static size_t cont_len;
 	static int cont_level;
+	static bool cont_prefix;
 	static struct task_struct *cont_task;
 	static char textbuf[LOG_LINE_MAX];
 	char *text = textbuf;
@@ -1275,6 +1316,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 	int this_cpu;
 	bool newline = false;
 	bool prefix = false;
+	bool flush = false;
 	int printed_len = 0;
 
 	boot_delay_msec();
@@ -1339,18 +1381,37 @@ asmlinkage int vprintk_emit(int facility, int level,
 		case 'c':	/* KERN_CONT */
 			text += 3;
 			text_len -= 3;
+			break;
+		case 'f':	/* KERN_FLUSH - used internally */
+			flush = true;
 		}
 	}
 
-	if (level == -1)
-		level = default_message_loglevel;
+	if (!flush) {
+		if (level == -1)
+			level = default_message_loglevel;
 
-	if (dict) {
-		prefix = true;
-		newline = true;
+		if (dict) {
+			prefix = true;
+			newline = true;
+		}
 	}
 
-	if (!newline) {
+	if (flush) {
+		if (cont_len) {
+			int code = LOG_NONL;
+
+			/*
+			 * If the buffered string was KERN_CONT,
+			 * do not print prefix.
+			 */
+			if (!cont_prefix)
+				code = LOG_NONL_NOPREFIX;
+			log_store(code, cont_level, NULL, 0, cont_buf, cont_len);
+			cont_len = 0;
+		}
+
+	} else if (!newline) {
 		if (cont_len && (prefix || cont_task != current)) {
 			/*
 			 * Flush earlier buffer, which is either from a
@@ -1363,6 +1424,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		if (!cont_len) {
 			cont_level = level;
 			cont_task = current;
+			cont_prefix = prefix;
 		}
 
 		/* buffer or append to earlier buffer from the same thread */
@@ -1395,6 +1457,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 			printed_len = cont_len;
 		} else {
 			/* ordinary single and terminated line */
+			if (!prefix && !facility && cont_task == current)
+				facility = LOG_NOPREFIX;
 			log_store(facility, level,
 				  dict, dictlen, text, text_len);
 			printed_len = text_len;
@@ -1483,6 +1547,24 @@ asmlinkage int printk(const char *fmt, ...)
 }
 EXPORT_SYMBOL(printk);
 
+/**
+ * printk_flush - flush out any buffered text
+ *
+ * printk() will buffer text and not write it out to the console
+ * if the text was missing a newline. If it is required to get text
+ * out to the console without a newline, use printk_flush() and it
+ * will do that. This is useful when running self tests, where you
+ * have a line that prints what is being tested, and then if it
+ * passed or failed after the test, and you want this all done on
+ * a single line. Without flushing, if the test crashes, you may
+ * never see what was being tested.
+ */
+void printk_flush(void)
+{
+	printk("<f>");
+}
+EXPORT_SYMBOL(printk_flush);
+
 #else
 
 #define LOG_LINE_MAX 0
-- 
1.7.3.4



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

Powered by blists - more mailing lists