[PATCH 00/12] printk() fixes, optimizations, and clean ups

[PATCH 00/12] printk() fixes, optimizations, and clean ups

[Jan H. Schönherr]

Hi Greg, hi Kay, and all other interested people.

This series aims at cleaning up and fixing some bugs around printk().
Patches 9 and 11 might require some discussion, see below.

(This is not to be confused with the printk.c reorganization that Joe 
Perches currently does [1]. This series is really focused around printk().)

Let's get straight to the individual patches (series is currently against
v3.7-rc5, but applies to next-20121113 as well):

1. printk: drop ambiguous LOG_CONT flag

	This is the only patch that was previously posted [2]. Compared to
	the previous version, a small bug got fixed. With this patch,
	independent continuation records are no longer incorrectly merged.

2. printk: use saved timestamp for temporarily buffered message
3. printk: reclaim cont buffer immediately for fully printed messages
4. printk: reuse reclaimed continuation buffer immediately
5. printk: move wake_klogd-check out of the loop

	These four patches fall into the optimization category. The only
	measurable effect is probably that continuation records are more often
	merged than before (patches 3+4).

6. printk: reorganize storage of continuation buffer
7. printk: let cont_print_text() reuse existing code

  	These two reduce replicated code within printk.c and fix an actual bug
	in the console output of logged messages.

8. printk: refactor locking in console_unlock()

  	Another bugfix. And due to the refactored locking, I hopefully closed
	all the smaller time-windows where the same race could have happened.
	(This patch does not fix all issues within console_unlock() that I am
	aware of, see patch description.) 

9. printk: avoid glitches in console output

	This one has a notable effect on the console output when there are
	concurrent printk()s. Personally, I think it improves the readability,
	but there could be a reason I'm not aware of why such a change is
	not acceptable. Please discuss.

10. printk: retain unknown log-level until log_store()
11. printk: track previously logged message in log_store()
12. printk: drop now useless tracking of previous message flags

	The change due to these three patches is only noticeable for a user in
	a few corner cases. OTOH, it improves source readability by removing
	some of the historical growth (patch 12) that only makes sense when
	you have actually read the history.


Regards
Jan

[1] http://lkml.org/lkml/2012/10/24/748
[2] http://lkml.org/lkml/2012/9/26/392

Jan H. Schönherr (12):
  printk: drop ambiguous LOG_CONT flag
  printk: use saved timestamp for temporarily buffered message
  printk: reclaim cont buffer immediately for fully printed messages
  printk: reuse reclaimed continuation buffer immediately
  printk: move wake_klogd-check out of the loop
  printk: reorganize storage of continuation buffer
  printk: let cont_print_text() reuse existing code
  printk: refactor locking in console_unlock()
  printk: avoid glitches in console output
  printk: retain unknown log-level until log_store()
  printk: track previously logged message in log_store()
  printk: drop now useless tracking of previous message flags

 kernel/printk.c | 368 ++++++++++++++++++++++++++++++++------------------------
 1 file changed, 209 insertions(+), 159 deletions(-)

-- 
1.8.0.316.g291341c.dirty

[PATCH 01/12] printk: drop ambiguous LOG_CONT flag

[Jan H. Schönherr]

The meaning of LOG_CONT is unclear, i. e., whether a message is a starting,
ending, or middle fragment. Unfortunately, this cannot be inferred from
the LOG_PREFIX and LOG_NEWLINE flags, as they are not always kept.
Furthermore, in some cases LOG_CONT is set, although it is unknown if
there will be a continuation. This leads to wrongly concatenated output.

Fix this by dropping LOG_CONT and rely on LOG_PREFIX and LOG_NEWLINE to
distinguish the type of fragment. That is, if LOG_PREFIX is set, this
fragment does not continue the previous fragment. And if LOG_NEWLINE is
set, this fragment is not continued by the next fragment.

(Unfortunately, we still have to look at the previous fragment to catch the
case of an unset LOG_PREFIX on this fragment, but a set LOG_NEWLINE on
the previous fragment.)

Tested-by: Kay Sievers <kay@vrfy.org>
Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
Changes since last posting:
- fixed check for flushed buffer
- minor code adjustment
- coding style fixes
---
 kernel/printk.c | 58 ++++++++++++++++++++++++++++++++-------------------------
 1 file changed, 33 insertions(+), 25 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 2d607f4..857ff7c 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -197,7 +197,6 @@ enum log_flags {
 	LOG_NOCONS	= 1,	/* already flushed, do not print to console */
 	LOG_NEWLINE	= 2,	/* text ended with a newline */
 	LOG_PREFIX	= 4,	/* text started with a prefix */
-	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
 };
 
 struct log {
@@ -481,10 +480,9 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 	 * better readable output. 'c' in the record flags mark the first
 	 * fragment of a line, '+' the following.
 	 */
-	if (msg->flags & LOG_CONT && !(user->prev & LOG_CONT))
+	if (!(msg->flags & LOG_NEWLINE) && msg->flags & LOG_PREFIX)
 		cont = 'c';
-	else if ((msg->flags & LOG_CONT) ||
-		 ((user->prev & LOG_CONT) && !(msg->flags & LOG_PREFIX)))
+	else if (!(user->prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
 		cont = '+';
 
 	len = sprintf(user->buf, "%u,%llu,%llu,%c;",
@@ -887,15 +885,16 @@ static size_t msg_print_text(const struct log *msg, enum log_flags prev,
 	bool newline = true;
 	size_t len = 0;
 
-	if ((prev & LOG_CONT) && !(msg->flags & LOG_PREFIX))
+	if (!(prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
 		prefix = false;
 
-	if (msg->flags & LOG_CONT) {
-		if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
-			prefix = false;
+	if (!(msg->flags & LOG_NEWLINE))
+		newline = false;
 
-		if (!(msg->flags & LOG_NEWLINE))
-			newline = false;
+	if (!(prev & LOG_NEWLINE) && prefix) {
+		if (buf)
+			buf[len] = '\n';
+		len++;
 	}
 
 	do {
@@ -1400,35 +1399,36 @@ static void cont_flush(enum log_flags flags)
 	if (cont.len == 0)
 		return;
 
+	cont.flags |= flags;
 	if (cont.cons) {
 		/*
 		 * If a fragment of this line was directly flushed to the
 		 * console; wait for the console to pick up the rest of the
 		 * line. LOG_NOCONS suppresses a duplicated output.
 		 */
-		log_store(cont.facility, cont.level, flags | LOG_NOCONS,
+		log_store(cont.facility, cont.level, cont.flags | LOG_NOCONS,
 			  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
-		cont.flags = flags;
 		cont.flushed = true;
 	} else {
 		/*
 		 * If no fragment of this line ever reached the console,
 		 * just submit it to the store and free the buffer.
 		 */
-		log_store(cont.facility, cont.level, flags, 0,
+		log_store(cont.facility, cont.level, cont.flags, 0,
 			  NULL, 0, cont.buf, cont.len);
 		cont.len = 0;
 	}
 }
 
-static bool cont_add(int facility, int level, const char *text, size_t len)
+static bool cont_add(int facility, int level, enum log_flags flags,
+		     const char *text, size_t len)
 {
 	if (cont.len && cont.flushed)
 		return false;
 
 	if (cont.len + len > sizeof(cont.buf)) {
 		/* the line gets too long, split it up in separate records */
-		cont_flush(LOG_CONT);
+		cont_flush(0);
 		return false;
 	}
 
@@ -1437,7 +1437,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 		cont.level = level;
 		cont.owner = current;
 		cont.ts_nsec = local_clock();
-		cont.flags = 0;
+		cont.flags = flags;
 		cont.cons = 0;
 		cont.flushed = false;
 	}
@@ -1446,7 +1446,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 	cont.len += len;
 
 	if (cont.len > (sizeof(cont.buf) * 80) / 100)
-		cont_flush(LOG_CONT);
+		cont_flush(0);
 
 	return true;
 }
@@ -1456,8 +1456,11 @@ static size_t cont_print_text(char *text, size_t size)
 	size_t textlen = 0;
 	size_t len;
 
-	if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
-		textlen += print_time(cont.ts_nsec, text);
+	if (cont.cons == 0 && (console_prev & LOG_NEWLINE ||
+			       cont.flags & LOG_PREFIX)) {
+		if (!(console_prev & LOG_NEWLINE))
+			text[textlen++] = '\n';
+		textlen += print_time(cont.ts_nsec, text + textlen);
 		size -= textlen;
 	}
 
@@ -1575,12 +1578,16 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 * Flush the conflicting buffer. An earlier newline was missing,
 		 * or another task also prints continuation lines.
 		 */
-		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
-			cont_flush(LOG_NEWLINE);
+		if (cont.len && !cont.flushed) {
+			if (cont.owner != current)
+				lflags |= LOG_PREFIX;
+			if (lflags & LOG_PREFIX)
+				cont_flush(LOG_NEWLINE);
+		}
 
 		/* buffer line if possible, otherwise store it right away */
-		if (!cont_add(facility, level, text, text_len))
-			log_store(facility, level, lflags | LOG_CONT, 0,
+		if (!cont_add(facility, level, lflags, text, text_len))
+			log_store(facility, level, lflags, 0,
 				  dict, dictlen, text, text_len);
 	} else {
 		bool stored = false;
@@ -1591,9 +1598,10 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 * there was a race with interrupts (prefix == true) then just
 		 * flush it out and store this line separately.
 		 */
-		if (cont.len && cont.owner == current) {
+		if (cont.len && !cont.flushed && cont.owner == current) {
 			if (!(lflags & LOG_PREFIX))
-				stored = cont_add(facility, level, text, text_len);
+				stored = cont_add(facility, level, lflags,
+							text, text_len);
 			cont_flush(LOG_NEWLINE);
 		}
 
-- 
1.8.0.316.g291341c.dirty

[PATCH 02/12] printk: use saved timestamp for temporarily buffered message

[Jan H. Schönherr]

If a message has been buffered, always use the saved timestamp reflecting
the actual occurrence of the message. (There is no reason to use a
possibly later timestamp.)

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
This is a rather small change that could be folded into the next patch
which changes cont_flush() a bit more. However, this way we have one
patch per logical change.
---
 kernel/printk.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 857ff7c..0927068 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1414,7 +1414,7 @@ static void cont_flush(enum log_flags flags)
 		 * If no fragment of this line ever reached the console,
 		 * just submit it to the store and free the buffer.
 		 */
-		log_store(cont.facility, cont.level, cont.flags, 0,
+		log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec,
 			  NULL, 0, cont.buf, cont.len);
 		cont.len = 0;
 	}
-- 
1.8.0.316.g291341c.dirty

[PATCH 03/12] printk: reclaim cont buffer immediately for fully printed messages

[Jan H. Schönherr]

We only need to keep the contents of the cont buffer, when there is a
partly printed message in it. In both other cases, not yet printed as
well as fully printed messages, we can reclaim the buffer immediately.

Currently, we do not reclaim the cont buffer when it contains a fully
printed message. This commit restructures the logic to achieve that.
(Note, that LOG_NOCONS must still be set for partly _and_ fully printed
messages, making it a bit more complicated than just changing the
if-condition.)

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
 kernel/printk.c | 36 +++++++++++++++++++-----------------
 1 file changed, 19 insertions(+), 17 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 0927068..ba9494b 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1400,24 +1400,26 @@ static void cont_flush(enum log_flags flags)
 		return;
 
 	cont.flags |= flags;
-	if (cont.cons) {
-		/*
-		 * If a fragment of this line was directly flushed to the
-		 * console; wait for the console to pick up the rest of the
-		 * line. LOG_NOCONS suppresses a duplicated output.
-		 */
-		log_store(cont.facility, cont.level, cont.flags | LOG_NOCONS,
-			  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
-		cont.flushed = true;
-	} else {
-		/*
-		 * If no fragment of this line ever reached the console,
-		 * just submit it to the store and free the buffer.
-		 */
-		log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec,
-			  NULL, 0, cont.buf, cont.len);
+
+	/*
+	 * If a fragment of this line was directly flushed to the console, the
+	 * whole line is/was directly printed. Use LOG_NOCONS to suppress a
+	 * duplicated output later -- see console_unlock().
+	 */
+	if (cont.cons)
+		cont.flags |= LOG_NOCONS;
+
+	log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec, NULL, 0,
+		  cont.buf, cont.len);
+
+	/*
+	 * If no fragment of this line ever reached the console or everything
+	 * has been printed, free the buffer. Otherwise keep it available.
+	 */
+	if (!cont.cons || cont.cons == cont.len)
 		cont.len = 0;
-	}
+	else
+		cont.flushed = true;
 }
 
 static bool cont_add(int facility, int level, enum log_flags flags,
-- 
1.8.0.316.g291341c.dirty

[PATCH 04/12] printk: reuse reclaimed continuation buffer immediately

[Jan H. Schönherr]

cont_add() might flush the continuation buffer before appending
anything. If that happens, the function returns immediately, forcing the
calling function to store the message elsewhere. This is not always
necessary.

When the continuation buffer was reclaimed (and not just marked as
"flushed"), then we can reuse it immediately instead of returning false.

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
 kernel/printk.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index ba9494b..42e5eaf 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1431,7 +1431,8 @@ static bool cont_add(int facility, int level, enum log_flags flags,
 	if (cont.len + len > sizeof(cont.buf)) {
 		/* the line gets too long, split it up in separate records */
 		cont_flush(0);
-		return false;
+		if (cont.len)
+			return false;
 	}
 
 	if (!cont.len) {
-- 
1.8.0.316.g291341c.dirty

[PATCH 05/12] printk: move wake_klogd-check out of the loop

[Jan H. Schönherr]

The checked criterion is loop-independent and we hold the lock necessary
to do the check also outside the loop. So, move that piece of code more
towards the end where the result is used.

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
 kernel/printk.c | 8 ++++----
 1 file changed, 4 insertions(+), 4 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 42e5eaf..2939683 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -2059,10 +2059,6 @@ again:
 		int level;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
-		if (seen_seq != log_next_seq) {
-			wake_klogd = true;
-			seen_seq = log_next_seq;
-		}
 
 		if (console_seq < log_first_seq) {
 			/* messages are gone, move to first one */
@@ -2123,6 +2119,10 @@ skip:
 	 */
 	raw_spin_lock(&logbuf_lock);
 	retry = console_seq != log_next_seq;
+	if (seen_seq != log_next_seq) {
+		wake_klogd = true;
+		seen_seq = log_next_seq;
+	}
 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
 
 	if (retry && console_trylock())
-- 
1.8.0.316.g291341c.dirty

[PATCH 06/12] printk: reorganize storage of continuation buffer

[Jan H. Schönherr]

Many fields of struct cont are similar to those in struct log.
Reorganize struct cont and embed a struct log in it. This allows us
to use regular struct log functions also for continuation records,
without having to create a copy first.

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
This is a prerequisite for the cont_print_text() rewrite.

An alternative would be to pass most of the struct log fields as
parameters to msg_print_text(): msg->text_len, msg->flags,
log_text(msg), msg->facility, msg->level, msg->ts_nsec. So that we can
use the function also with the continuation buffer.
---
 kernel/printk.c | 69 ++++++++++++++++++++++++++++-----------------------------
 1 file changed, 34 insertions(+), 35 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 2939683..988a8f5 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1381,14 +1381,10 @@ static inline void printk_delay(void)
  * reached the console in case of a kernel crash.
  */
 static struct cont {
+	struct log msg;
 	char buf[LOG_LINE_MAX];
-	size_t len;			/* length == 0 means unused buffer */
 	size_t cons;			/* bytes written to console */
 	struct task_struct *owner;	/* task of first print*/
-	u64 ts_nsec;			/* time of first print */
-	u8 level;			/* log level of first message */
-	u8 facility;			/* log level of first message */
-	enum log_flags flags;		/* prefix, newline flags */
 	bool flushed:1;			/* buffer sealed and committed */
 } cont;
 
@@ -1396,10 +1392,10 @@ static void cont_flush(enum log_flags flags)
 {
 	if (cont.flushed)
 		return;
-	if (cont.len == 0)
+	if (cont.msg.text_len == 0)
 		return;
 
-	cont.flags |= flags;
+	cont.msg.flags |= flags;
 
 	/*
 	 * If a fragment of this line was directly flushed to the console, the
@@ -1407,17 +1403,17 @@ static void cont_flush(enum log_flags flags)
 	 * duplicated output later -- see console_unlock().
 	 */
 	if (cont.cons)
-		cont.flags |= LOG_NOCONS;
+		cont.msg.flags |= LOG_NOCONS;
 
-	log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec, NULL, 0,
-		  cont.buf, cont.len);
+	log_store(cont.msg.facility, cont.msg.level, cont.msg.flags,
+		  cont.msg.ts_nsec, NULL, 0, cont.buf, cont.msg.text_len);
 
 	/*
 	 * If no fragment of this line ever reached the console or everything
 	 * has been printed, free the buffer. Otherwise keep it available.
 	 */
-	if (!cont.cons || cont.cons == cont.len)
-		cont.len = 0;
+	if (!cont.cons || cont.cons == cont.msg.text_len)
+		cont.msg.text_len = 0;
 	else
 		cont.flushed = true;
 }
@@ -1425,30 +1421,30 @@ static void cont_flush(enum log_flags flags)
 static bool cont_add(int facility, int level, enum log_flags flags,
 		     const char *text, size_t len)
 {
-	if (cont.len && cont.flushed)
+	if (cont.msg.text_len && cont.flushed)
 		return false;
 
-	if (cont.len + len > sizeof(cont.buf)) {
+	if (cont.msg.text_len + len > sizeof(cont.buf)) {
 		/* the line gets too long, split it up in separate records */
 		cont_flush(0);
-		if (cont.len)
+		if (cont.msg.text_len)
 			return false;
 	}
 
-	if (!cont.len) {
-		cont.facility = facility;
-		cont.level = level;
+	if (!cont.msg.text_len) {
+		cont.msg.facility = facility;
+		cont.msg.level = level;
 		cont.owner = current;
-		cont.ts_nsec = local_clock();
-		cont.flags = flags;
+		cont.msg.ts_nsec = local_clock();
+		cont.msg.flags = flags;
 		cont.cons = 0;
 		cont.flushed = false;
 	}
 
-	memcpy(cont.buf + cont.len, text, len);
-	cont.len += len;
+	memcpy(cont.buf + cont.msg.text_len, text, len);
+	cont.msg.text_len += len;
 
-	if (cont.len > (sizeof(cont.buf) * 80) / 100)
+	if (cont.msg.text_len > (sizeof(cont.buf) * 80) / 100)
 		cont_flush(0);
 
 	return true;
@@ -1460,27 +1456,27 @@ static size_t cont_print_text(char *text, size_t size)
 	size_t len;
 
 	if (cont.cons == 0 && (console_prev & LOG_NEWLINE ||
-			       cont.flags & LOG_PREFIX)) {
+			       cont.msg.flags & LOG_PREFIX)) {
 		if (!(console_prev & LOG_NEWLINE))
 			text[textlen++] = '\n';
-		textlen += print_time(cont.ts_nsec, text + textlen);
+		textlen += print_time(cont.msg.ts_nsec, text + textlen);
 		size -= textlen;
 	}
 
-	len = cont.len - cont.cons;
+	len = cont.msg.text_len - cont.cons;
 	if (len > 0) {
 		if (len+1 > size)
 			len = size-1;
 		memcpy(text + textlen, cont.buf + cont.cons, len);
 		textlen += len;
-		cont.cons = cont.len;
+		cont.cons = cont.msg.text_len;
 	}
 
 	if (cont.flushed) {
-		if (cont.flags & LOG_NEWLINE)
+		if (cont.msg.flags & LOG_NEWLINE)
 			text[textlen++] = '\n';
 		/* got everything, release buffer */
-		cont.len = 0;
+		cont.msg.text_len = 0;
 	}
 	return textlen;
 }
@@ -1581,7 +1577,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 * Flush the conflicting buffer. An earlier newline was missing,
 		 * or another task also prints continuation lines.
 		 */
-		if (cont.len && !cont.flushed) {
+		if (cont.msg.text_len && !cont.flushed) {
 			if (cont.owner != current)
 				lflags |= LOG_PREFIX;
 			if (lflags & LOG_PREFIX)
@@ -1601,7 +1597,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 * there was a race with interrupts (prefix == true) then just
 		 * flush it out and store this line separately.
 		 */
-		if (cont.len && !cont.flushed && cont.owner == current) {
+		if (cont.msg.text_len && !cont.flushed &&
+		    cont.owner == current) {
 			if (!(lflags & LOG_PREFIX))
 				stored = cont_add(facility, level, lflags,
 							text, text_len);
@@ -1711,9 +1708,11 @@ static u32 log_first_idx;
 static u64 log_next_seq;
 static enum log_flags console_prev;
 static struct cont {
-	size_t len;
+	struct {
+		size_t text_len;
+		u8 level;
+	} msg;
 	size_t cons;
-	u8 level;
 	bool flushed:1;
 } cont;
 static struct log *log_from_idx(u32 idx) { return NULL; }
@@ -1999,7 +1998,7 @@ static void console_cont_flush(char *text, size_t size)
 
 	raw_spin_lock_irqsave(&logbuf_lock, flags);
 
-	if (!cont.len)
+	if (!cont.msg.text_len)
 		goto out;
 
 	/*
@@ -2013,7 +2012,7 @@ static void console_cont_flush(char *text, size_t size)
 	len = cont_print_text(text, size);
 	raw_spin_unlock(&logbuf_lock);
 	stop_critical_timings();
-	call_console_drivers(cont.level, text, len);
+	call_console_drivers(cont.msg.level, text, len);
 	start_critical_timings();
 	local_irq_restore(flags);
 	return;
-- 
1.8.0.316.g291341c.dirty

[PATCH 07/12] printk: let cont_print_text() reuse existing code

[Jan H. Schönherr]

The functionality of cont_print_text() also exists within
msg_print_text(). The only difference is that cont_print_text()
currently fails to print timestamps for multi-line strings from the
second line on.

In order to be able to use msg_print_text() from cont_print_text(),
create a more general version msg_print_text_from() with the ability to
start at a specific position within the message and to track the
position.

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
 kernel/printk.c | 54 ++++++++++++++++++++++++++++--------------------------
 1 file changed, 28 insertions(+), 26 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 988a8f5..7a961d4 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -876,8 +876,9 @@ static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
 	return len;
 }
 
-static size_t msg_print_text(const struct log *msg, enum log_flags prev,
-			     bool syslog, char *buf, size_t size)
+static size_t msg_print_text_from(const struct log *msg, size_t *from,
+				  enum log_flags prev,
+				  bool syslog, char *buf, size_t size)
 {
 	const char *text = log_text(msg);
 	size_t text_size = msg->text_len;
@@ -891,6 +892,13 @@ static size_t msg_print_text(const struct log *msg, enum log_flags prev,
 	if (!(msg->flags & LOG_NEWLINE))
 		newline = false;
 
+	if (from) {
+		text += *from;
+		text_size -= *from;
+		if (*from)
+			prefix = false;
+	}
+
 	if (!(prev & LOG_NEWLINE) && prefix) {
 		if (buf)
 			buf[len] = '\n';
@@ -933,9 +941,23 @@ static size_t msg_print_text(const struct log *msg, enum log_flags prev,
 		text = next;
 	} while (text);
 
+	if (from) {
+		if (text)
+			*from = text - log_text(msg);
+		else
+			*from = msg->text_len;
+	}
+
 	return len;
 }
 
+static size_t msg_print_text(const struct log *msg,
+			     enum log_flags prev,
+			     bool syslog, char *buf, size_t size)
+{
+	return msg_print_text_from(msg, NULL, prev, syslog, buf, size);
+}
+
 static int syslog_print(char __user *buf, int size)
 {
 	char *text;
@@ -1452,32 +1474,12 @@ static bool cont_add(int facility, int level, enum log_flags flags,
 
 static size_t cont_print_text(char *text, size_t size)
 {
-	size_t textlen = 0;
-	size_t len;
+	size_t textlen = msg_print_text_from(&cont.msg, &cont.cons,
+					     console_prev, false, text, size);
 
-	if (cont.cons == 0 && (console_prev & LOG_NEWLINE ||
-			       cont.msg.flags & LOG_PREFIX)) {
-		if (!(console_prev & LOG_NEWLINE))
-			text[textlen++] = '\n';
-		textlen += print_time(cont.msg.ts_nsec, text + textlen);
-		size -= textlen;
-	}
-
-	len = cont.msg.text_len - cont.cons;
-	if (len > 0) {
-		if (len+1 > size)
-			len = size-1;
-		memcpy(text + textlen, cont.buf + cont.cons, len);
-		textlen += len;
-		cont.cons = cont.msg.text_len;
-	}
-
-	if (cont.flushed) {
-		if (cont.msg.flags & LOG_NEWLINE)
-			text[textlen++] = '\n';
-		/* got everything, release buffer */
+	if (cont.flushed)
 		cont.msg.text_len = 0;
-	}
+
 	return textlen;
 }
 
-- 
1.8.0.316.g291341c.dirty

[PATCH 08/12] printk: refactor locking in console_unlock()

[Jan H. Schönherr]

Currently, console_unlock() acquires and releases the logbuf_lock quite
often, including saving and restoring the interrupt state. While we can
do only so much about the former, because we should not block logging
while writing to the console, the latter is unnecessary and can be
avoided.

Still, whenever we released the logbuf_lock for a moment, other threads
might have added new data that we must process. This might include the
continuation buffer. That means, after we reacquire the lock, we must
check the continuation buffer again. And, equally important, if the
continuation buffer turns out to be empty, we must proceed to the
check for remaining logged messages without dropping the lock.

This resolves an issue where console message are output in the wrong order,
because after the retry jump at the bottom the continuation buffer is not
checked again, but left until another call to console_unlock().

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
This is not yet the final state I envision for this function, but it is
a working middle step. That is, the loop in console_cont_flush() is
rather ugly, and call_console_drivers() is still called from two places
with the same code around. This calls for even more refactoring.

Also, one issue still remains: we should check the continuation buffer
also after printing all log messages, as we postpone printing the
continuation buffer in certain situations. So there could possibly
be something left.

And one more: the retry check at the bottom should also include the
continuation buffer.
---
 kernel/printk.c | 27 +++++++++++++--------------
 1 file changed, 13 insertions(+), 14 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 7a961d4..e78bbd9 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1995,13 +1995,11 @@ void wake_up_klogd(void)
 
 static void console_cont_flush(char *text, size_t size)
 {
-	unsigned long flags;
 	size_t len;
 
-	raw_spin_lock_irqsave(&logbuf_lock, flags);
-
+again:
 	if (!cont.msg.text_len)
-		goto out;
+		return;
 
 	/*
 	 * We still queue earlier records, likely because the console was
@@ -2009,17 +2007,18 @@ static void console_cont_flush(char *text, size_t size)
 	 * did not flush any fragment so far, so just let it queue up.
 	 */
 	if (console_seq < log_next_seq && !cont.cons)
-		goto out;
+		return;
 
 	len = cont_print_text(text, size);
+	if (!len)
+		return;
+
 	raw_spin_unlock(&logbuf_lock);
 	stop_critical_timings();
 	call_console_drivers(cont.msg.level, text, len);
 	start_critical_timings();
-	local_irq_restore(flags);
-	return;
-out:
-	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
+	raw_spin_lock(&logbuf_lock);
+	goto again;
 }
 
 /**
@@ -2051,15 +2050,15 @@ void console_unlock(void)
 
 	console_may_schedule = 0;
 
-	/* flush buffered message fragment immediately to console */
-	console_cont_flush(text, sizeof(text));
 again:
+	raw_spin_lock_irqsave(&logbuf_lock, flags);
 	for (;;) {
 		struct log *msg;
 		size_t len;
 		int level;
 
-		raw_spin_lock_irqsave(&logbuf_lock, flags);
+		/* flush buffered message fragment immediately to console */
+		console_cont_flush(text, sizeof(text));
 
 		if (console_seq < log_first_seq) {
 			/* messages are gone, move to first one */
@@ -2095,12 +2094,12 @@ skip:
 		console_idx = log_next(console_idx);
 		console_seq++;
 		console_prev = msg->flags;
-		raw_spin_unlock(&logbuf_lock);
 
+		raw_spin_unlock(&logbuf_lock);
 		stop_critical_timings();	/* don't trace print latency */
 		call_console_drivers(level, text, len);
 		start_critical_timings();
-		local_irq_restore(flags);
+		raw_spin_lock(&logbuf_lock);
 	}
 	console_locked = 0;
 
-- 
1.8.0.316.g291341c.dirty

[PATCH 09/12] printk: avoid glitches in console output

[Jan H. Schönherr]

Let console_prev not track the previously logged message, but the
previously printed message. Add some additional code to get all
transitions between printing the continuation buffer and printing
already logged messages right.

With this, even racing printk()s no longer mess up console output.
Instead, whenever printing continues with a different message, it starts
on a new line:

[  243.344417] printk test init
[  243.344473] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[  243.344666] (CC
[  243.346020] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[  243.346030] C
[  243.348047] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[  243.346030] CC
[  243.351190] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)

Instead of:

[   25.736925] printk test init
[   25.737560] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
[   25.739101] (CCC[   25.740802] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
C[   25.743846] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
CC[   25.746816] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)
C[   25.748770] (AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA)

(A-lines are printed with a single printk(), C-lines are printed
char-wise with KERN_CONT.)

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
This definitely causes a notable change in the output that might go
beyond fixing the current output, depending on one's point of view.
Therefore, this is RFC for the moment.
---
 kernel/printk.c | 57 +++++++++++++++++++++++++++++++++++++++++++++------------
 1 file changed, 45 insertions(+), 12 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index e78bbd9..42ecdb0 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -234,6 +234,7 @@ static u32 log_next_idx;
 static u64 console_seq;
 static u32 console_idx;
 static enum log_flags console_prev;
+static u64 console_printed_seq;
 
 /* the next printk record to read after the last 'clear' command */
 static u64 clear_seq;
@@ -895,8 +896,6 @@ static size_t msg_print_text_from(const struct log *msg, size_t *from,
 	if (from) {
 		text += *from;
 		text_size -= *from;
-		if (*from)
-			prefix = false;
 	}
 
 	if (!(prev & LOG_NEWLINE) && prefix) {
@@ -1407,7 +1406,7 @@ static struct cont {
 	char buf[LOG_LINE_MAX];
 	size_t cons;			/* bytes written to console */
 	struct task_struct *owner;	/* task of first print*/
-	bool flushed:1;			/* buffer sealed and committed */
+	u64 flushed;			/* sequence number when flushed */
 } cont;
 
 static void cont_flush(enum log_flags flags)
@@ -1437,7 +1436,7 @@ static void cont_flush(enum log_flags flags)
 	if (!cont.cons || cont.cons == cont.msg.text_len)
 		cont.msg.text_len = 0;
 	else
-		cont.flushed = true;
+		cont.flushed = log_next_seq - 1;
 }
 
 static bool cont_add(int facility, int level, enum log_flags flags,
@@ -1460,7 +1459,7 @@ static bool cont_add(int facility, int level, enum log_flags flags,
 		cont.msg.ts_nsec = local_clock();
 		cont.msg.flags = flags;
 		cont.cons = 0;
-		cont.flushed = false;
+		cont.flushed = 0;
 	}
 
 	memcpy(cont.buf + cont.msg.text_len, text, len);
@@ -1474,8 +1473,29 @@ static bool cont_add(int facility, int level, enum log_flags flags,
 
 static size_t cont_print_text(char *text, size_t size)
 {
-	size_t textlen = msg_print_text_from(&cont.msg, &cont.cons,
-					     console_prev, false, text, size);
+	size_t textlen;
+	enum log_flags flags = cont.msg.flags;
+	u64 seq = cont.flushed ? cont.flushed : log_next_seq;
+
+	if (cont.msg.text_len == cont.cons) {
+		if (cont.flushed)
+			cont.msg.text_len = 0;
+		return 0;
+	}
+
+	/* Avoid a break, when we continuously print the cont buffer */
+	if (console_printed_seq == 0 && cont.cons)
+		cont.msg.flags &= ~LOG_PREFIX;
+
+	/* Force a break, when we do not continue the last printed message */
+	if (console_printed_seq != 0 && console_printed_seq + 1 != seq)
+		cont.msg.flags |= LOG_PREFIX;
+
+	textlen = msg_print_text_from(&cont.msg, &cont.cons, console_prev,
+				      false, text, size);
+	cont.msg.flags = flags;
+	console_prev = cont.msg.flags;
+	console_printed_seq = cont.flushed;
 
 	if (cont.flushed)
 		cont.msg.text_len = 0;
@@ -1704,18 +1724,18 @@ static u64 syslog_seq;
 static u32 syslog_idx;
 static u64 console_seq;
 static u32 console_idx;
-static enum log_flags syslog_prev;
 static u64 log_first_seq;
 static u32 log_first_idx;
 static u64 log_next_seq;
 static enum log_flags console_prev;
+static u64 console_printed_seq;
 static struct cont {
 	struct {
 		size_t text_len;
 		u8 level;
 	} msg;
 	size_t cons;
-	bool flushed:1;
+	u64 flushed;
 } cont;
 static struct log *log_from_idx(u32 idx) { return NULL; }
 static u32 log_next(u32 idx) { return 0; }
@@ -2056,6 +2076,7 @@ again:
 		struct log *msg;
 		size_t len;
 		int level;
+		enum log_flags lflags;
 
 		/* flush buffered message fragment immediately to console */
 		console_cont_flush(text, sizeof(text));
@@ -2064,7 +2085,6 @@ again:
 			/* messages are gone, move to first one */
 			console_seq = log_first_seq;
 			console_idx = log_first_idx;
-			console_prev = 0;
 		}
 skip:
 		if (console_seq == log_next_seq)
@@ -2084,13 +2104,27 @@ skip:
 			 * will properly dump everything later.
 			 */
 			msg->flags &= ~LOG_NOCONS;
-			console_prev = msg->flags;
 			goto skip;
 		}
 
+		lflags = msg->flags;
+
+		/*
+		 * If we do not continue the previously logged message (i. e.,
+		 * the last printed message was either the cont buffer or
+		 * another logged message), then force a break in the output.
+		 */
+		if (console_printed_seq == 0 ||
+		    console_printed_seq + 1 != console_seq)
+			msg->flags |= LOG_PREFIX;
+
 		level = msg->level;
 		len = msg_print_text(msg, console_prev, false,
 				     text, sizeof(text));
+
+		msg->flags = lflags;
+		console_printed_seq = console_seq;
+
 		console_idx = log_next(console_idx);
 		console_seq++;
 		console_prev = msg->flags;
@@ -2360,7 +2394,6 @@ void register_console(struct console *newcon)
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
 		console_seq = syslog_seq;
 		console_idx = syslog_idx;
-		console_prev = syslog_prev;
 		raw_spin_unlock_irqrestore(&logbuf_lock, flags);
 		/*
 		 * We're about to replay the log buffer.  Only do this to the
-- 
1.8.0.316.g291341c.dirty

[PATCH 10/12] printk: retain unknown log-level until log_store()

[Jan H. Schönherr]

Retain a value of -1 for messages with an unknown message level and pass
this to log_store(). This way, we can later distinguish continuation
records from non-continuation records in log_store().

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
 kernel/printk.c | 28 +++++++++++++++++-----------
 1 file changed, 17 insertions(+), 11 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 42ecdb0..6daa7cc 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -310,6 +310,10 @@ static void log_store(int facility, int level,
 	struct log *msg;
 	u32 size, pad_len;
 
+	/* store something meaningful, when no loglevel was given */
+	if (level == -1)
+		level = default_message_loglevel;
+
 	/* number of '\0' padding bytes to next message */
 	size = sizeof(struct log) + text_len + dict_len;
 	pad_len = (-size) & (LOG_ALIGN - 1);
@@ -376,7 +380,7 @@ static ssize_t devkmsg_writev(struct kiocb *iocb, const struct iovec *iv,
 {
 	char *buf, *line;
 	int i;
-	int level = default_message_loglevel;
+	int level = -1;
 	int facility = 1;	/* LOG_USER */
 	size_t len = iov_length(iv, count);
 	ssize_t ret = len;
@@ -1450,11 +1454,12 @@ static bool cont_add(int facility, int level, enum log_flags flags,
 		cont_flush(0);
 		if (cont.msg.text_len)
 			return false;
+		level = cont.msg.level;
 	}
 
 	if (!cont.msg.text_len) {
 		cont.msg.facility = facility;
-		cont.msg.level = level;
+		cont.msg.level = level == -1 ? default_message_loglevel : level;
 		cont.owner = current;
 		cont.msg.ts_nsec = local_clock();
 		cont.msg.flags = flags;
@@ -1574,22 +1579,23 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 		if (kern_level) {
 			const char *end_of_header = printk_skip_level(text);
-			switch (kern_level) {
-			case '0' ... '7':
-				if (level == -1)
+			if (level == -1) {
+				switch (kern_level) {
+				case '0' ... '7':
 					level = kern_level - '0';
-			case 'd':	/* KERN_DEFAULT */
-				lflags |= LOG_PREFIX;
-			case 'c':	/* KERN_CONT */
-				break;
+					break;
+				case 'd':	/* KERN_DEFAULT */
+					level = default_message_loglevel;
+					break;
+				}
 			}
 			text_len -= end_of_header - text;
 			text = (char *)end_of_header;
 		}
 	}
 
-	if (level == -1)
-		level = default_message_loglevel;
+	if (level != -1)
+		lflags |= LOG_PREFIX;
 
 	if (dict)
 		lflags |= LOG_PREFIX|LOG_NEWLINE;
-- 
1.8.0.316.g291341c.dirty

[PATCH 11/12] printk: track previously logged message in log_store()

[Jan H. Schönherr]

Centrally track information about the previous message in log_store()
instead of doing it from formatting code spread over various places.
To be able to format the current message correctly, encode the necessary
information within the current message's flags:

LOG_NOCONT:  Print a newline before the prefix.
LOG_PREFIX:  Print a prefix before the message.
LOG_NEWLINE: Print a newline after the message.

We do not always know in time, whether we should store a message with a
newline at the end or not. However, a missing newline is addressed by a
LOG_NOCONT stored with the next message.

Thus, when logged messages are processed in order without any skips,
we generate an nicely formatted output.

(When there are skips, e. g., the log buffer overflowed before the next
message in sequence was retrieved, the output might end up with a
missing newline and/or header or an additional newline. OTOH, the
current code just silently ignores skipped messages...)

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
 kernel/printk.c | 60 +++++++++++++++++++++++++++++++++++++++++----------------
 1 file changed, 43 insertions(+), 17 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 6daa7cc..4ad2bb4 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -195,8 +195,9 @@ static int console_may_schedule;
 
 enum log_flags {
 	LOG_NOCONS	= 1,	/* already flushed, do not print to console */
-	LOG_NEWLINE	= 2,	/* text ended with a newline */
-	LOG_PREFIX	= 4,	/* text started with a prefix */
+	LOG_NEWLINE	= 2,	/* fragment ends with a newline */
+	LOG_PREFIX	= 4,	/* fragment starts with a prefix */
+	LOG_NOCONT	= 8,	/* previous fragment missed a newline */
 };
 
 struct log {
@@ -307,9 +308,29 @@ static void log_store(int facility, int level,
 		      const char *dict, u16 dict_len,
 		      const char *text, u16 text_len)
 {
-	struct log *msg;
+	static struct log *msg;
+	static struct task_struct *msgowner;
 	u32 size, pad_len;
 
+	/* setup flags for storage */
+	if (msg && !(msg->flags & LOG_NEWLINE)) {
+		/*
+		 * If previous message did not end with a newline, this record
+		 * either continues the previously logged record, or the
+		 * previous one missed a newline.
+		 */
+		if (msgowner == current && msg->facility == facility &&
+		    !(flags & LOG_PREFIX) &&
+		    (level == -1 || level == msg->level))
+			level = msg->level;
+		else
+			flags |= LOG_NOCONT | LOG_PREFIX;
+	} else {
+		flags |= LOG_PREFIX;
+	}
+
+	msgowner = current;
+
 	/* store something meaningful, when no loglevel was given */
 	if (level == -1)
 		level = default_message_loglevel;
@@ -330,7 +351,7 @@ static void log_store(int facility, int level,
 		if (free > size + sizeof(struct log))
 			break;
 
-		/* drop old messages until we have enough contiuous space */
+		/* drop old messages until we have enough continuous space */
 		log_first_idx = log_next(log_first_idx);
 		log_first_seq++;
 	}
@@ -485,10 +506,10 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 	 * better readable output. 'c' in the record flags mark the first
 	 * fragment of a line, '+' the following.
 	 */
-	if (!(msg->flags & LOG_NEWLINE) && msg->flags & LOG_PREFIX)
-		cont = 'c';
-	else if (!(user->prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
+	if (!(msg->flags & LOG_PREFIX))
 		cont = '+';
+	else if (!(msg->flags & LOG_NEWLINE))
+		cont = 'c';
 
 	len = sprintf(user->buf, "%u,%llu,%llu,%c;",
 		      (msg->facility << 3) | msg->level,
@@ -887,22 +908,16 @@ static size_t msg_print_text_from(const struct log *msg, size_t *from,
 {
 	const char *text = log_text(msg);
 	size_t text_size = msg->text_len;
-	bool prefix = true;
-	bool newline = true;
+	bool prefix = msg->flags & LOG_PREFIX;
+	bool newline = msg->flags & LOG_NEWLINE;
 	size_t len = 0;
 
-	if (!(prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
-		prefix = false;
-
-	if (!(msg->flags & LOG_NEWLINE))
-		newline = false;
-
 	if (from) {
 		text += *from;
 		text_size -= *from;
 	}
 
-	if (!(prev & LOG_NEWLINE) && prefix) {
+	if (msg->flags & LOG_NOCONT) {
 		if (buf)
 			buf[len] = '\n';
 		len++;
@@ -1496,6 +1511,12 @@ static size_t cont_print_text(char *text, size_t size)
 	if (console_printed_seq != 0 && console_printed_seq + 1 != seq)
 		cont.msg.flags |= LOG_PREFIX;
 
+	/* Translate flags for printing */
+	if (console_prev & LOG_NEWLINE)
+		cont.msg.flags |= LOG_PREFIX;
+	else if (cont.msg.flags & LOG_PREFIX)
+		cont.msg.flags |= LOG_NOCONT;
+
 	textlen = msg_print_text_from(&cont.msg, &cont.cons, console_prev,
 				      false, text, size);
 	cont.msg.flags = flags;
@@ -2121,8 +2142,13 @@ skip:
 		 * another logged message), then force a break in the output.
 		 */
 		if (console_printed_seq == 0 ||
-		    console_printed_seq + 1 != console_seq)
+		    console_printed_seq + 1 != console_seq) {
 			msg->flags |= LOG_PREFIX;
+			if (console_prev & LOG_NEWLINE)
+				msg->flags &= ~LOG_NOCONT;
+			else
+				msg->flags |= LOG_NOCONT;
+		}
 
 		level = msg->level;
 		len = msg_print_text(msg, console_prev, false,
-- 
1.8.0.316.g291341c.dirty

[PATCH 12/12] printk: drop now useless tracking of previous message flags

[Jan H. Schönherr]

With the introduction of LOG_NOCONT, the layout decision can now be made
without explicit knowledge of the flags of the previous message. Drop
the code associated with this tracking.

Note, that the console is an exception due to the immediate flushing of
incoming log fragments: the printing order differs generally from the
order in which the message are stored. Therefore, it still keeps track
of the previously printed message.

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
This could be folded into the previous patch.
---
 kernel/printk.c | 54 ++++++++++++++----------------------------------------
 1 file changed, 14 insertions(+), 40 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 4ad2bb4..d27da0a 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -220,7 +220,6 @@ static DEFINE_RAW_SPINLOCK(logbuf_lock);
 /* the next printk record to read by syslog(READ) or /proc/kmsg */
 static u64 syslog_seq;
 static u32 syslog_idx;
-static enum log_flags syslog_prev;
 static size_t syslog_partial;
 
 /* index and sequence number of the first record stored in the buffer */
@@ -391,7 +390,6 @@ static void log_store(int facility, int level,
 struct devkmsg_user {
 	u64 seq;
 	u32 idx;
-	enum log_flags prev;
 	struct mutex lock;
 	char buf[8192];
 };
@@ -514,7 +512,6 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
 	len = sprintf(user->buf, "%u,%llu,%llu,%c;",
 		      (msg->facility << 3) | msg->level,
 		      user->seq, ts_usec, cont);
-	user->prev = msg->flags;
 
 	/* escape non-printable characters */
 	for (i = 0; i < msg->text_len; i++) {
@@ -903,7 +900,6 @@ static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
 }
 
 static size_t msg_print_text_from(const struct log *msg, size_t *from,
-				  enum log_flags prev,
 				  bool syslog, char *buf, size_t size)
 {
 	const char *text = log_text(msg);
@@ -970,10 +966,9 @@ static size_t msg_print_text_from(const struct log *msg, size_t *from,
 }
 
 static size_t msg_print_text(const struct log *msg,
-			     enum log_flags prev,
 			     bool syslog, char *buf, size_t size)
 {
-	return msg_print_text_from(msg, NULL, prev, syslog, buf, size);
+	return msg_print_text_from(msg, NULL, syslog, buf, size);
 }
 
 static int syslog_print(char __user *buf, int size)
@@ -995,7 +990,6 @@ static int syslog_print(char __user *buf, int size)
 			/* messages are gone, move to first one */
 			syslog_seq = log_first_seq;
 			syslog_idx = log_first_idx;
-			syslog_prev = 0;
 			syslog_partial = 0;
 		}
 		if (syslog_seq == log_next_seq) {
@@ -1005,13 +999,12 @@ static int syslog_print(char __user *buf, int size)
 
 		skip = syslog_partial;
 		msg = log_from_idx(syslog_idx);
-		n = msg_print_text(msg, syslog_prev, true, text,
+		n = msg_print_text(msg, true, text,
 				   LOG_LINE_MAX + PREFIX_MAX);
 		if (n - syslog_partial <= size) {
 			/* message fits into buffer, move forward */
 			syslog_idx = log_next(syslog_idx);
 			syslog_seq++;
-			syslog_prev = msg->flags;
 			n -= syslog_partial;
 			syslog_partial = 0;
 		} else if (!len){
@@ -1054,7 +1047,6 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 		u64 next_seq;
 		u64 seq;
 		u32 idx;
-		enum log_flags prev;
 
 		if (clear_seq < log_first_seq) {
 			/* messages are gone, move to first available one */
@@ -1068,12 +1060,10 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 		 */
 		seq = clear_seq;
 		idx = clear_idx;
-		prev = 0;
 		while (seq < log_next_seq) {
 			struct log *msg = log_from_idx(idx);
 
-			len += msg_print_text(msg, prev, true, NULL, 0);
-			prev = msg->flags;
+			len += msg_print_text(msg, true, NULL, 0);
 			idx = log_next(idx);
 			seq++;
 		}
@@ -1081,12 +1071,10 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 		/* move first record forward until length fits into the buffer */
 		seq = clear_seq;
 		idx = clear_idx;
-		prev = 0;
 		while (len > size && seq < log_next_seq) {
 			struct log *msg = log_from_idx(idx);
 
-			len -= msg_print_text(msg, prev, true, NULL, 0);
-			prev = msg->flags;
+			len -= msg_print_text(msg, true, NULL, 0);
 			idx = log_next(idx);
 			seq++;
 		}
@@ -1095,12 +1083,11 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 		next_seq = log_next_seq;
 
 		len = 0;
-		prev = 0;
 		while (len >= 0 && seq < next_seq) {
 			struct log *msg = log_from_idx(idx);
 			int textlen;
 
-			textlen = msg_print_text(msg, prev, true, text,
+			textlen = msg_print_text(msg, true, text,
 						 LOG_LINE_MAX + PREFIX_MAX);
 			if (textlen < 0) {
 				len = textlen;
@@ -1108,7 +1095,6 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 			}
 			idx = log_next(idx);
 			seq++;
-			prev = msg->flags;
 
 			raw_spin_unlock_irq(&logbuf_lock);
 			if (copy_to_user(buf + len, text, textlen))
@@ -1121,7 +1107,6 @@ static int syslog_print_all(char __user *buf, int size, bool clear)
 				/* messages are gone, move to next one */
 				seq = log_first_seq;
 				idx = log_first_idx;
-				prev = 0;
 			}
 		}
 	}
@@ -1226,7 +1211,6 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
 			/* messages are gone, move to first one */
 			syslog_seq = log_first_seq;
 			syslog_idx = log_first_idx;
-			syslog_prev = 0;
 			syslog_partial = 0;
 		}
 		if (from_file) {
@@ -1239,16 +1223,14 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
 		} else {
 			u64 seq = syslog_seq;
 			u32 idx = syslog_idx;
-			enum log_flags prev = syslog_prev;
 
 			error = 0;
 			while (seq < log_next_seq) {
 				struct log *msg = log_from_idx(idx);
 
-				error += msg_print_text(msg, prev, true, NULL, 0);
+				error += msg_print_text(msg, true, NULL, 0);
 				idx = log_next(idx);
 				seq++;
-				prev = msg->flags;
 			}
 			error -= syslog_partial;
 		}
@@ -1517,8 +1499,8 @@ static size_t cont_print_text(char *text, size_t size)
 	else if (cont.msg.flags & LOG_PREFIX)
 		cont.msg.flags |= LOG_NOCONT;
 
-	textlen = msg_print_text_from(&cont.msg, &cont.cons, console_prev,
-				      false, text, size);
+	textlen = msg_print_text_from(&cont.msg, &cont.cons, false, text, size);
+
 	cont.msg.flags = flags;
 	console_prev = cont.msg.flags;
 	console_printed_seq = cont.flushed;
@@ -1767,7 +1749,7 @@ static struct cont {
 static struct log *log_from_idx(u32 idx) { return NULL; }
 static u32 log_next(u32 idx) { return 0; }
 static void call_console_drivers(int level, const char *text, size_t len) {}
-static size_t msg_print_text(const struct log *msg, enum log_flags prev,
+static size_t msg_print_text(const struct log *msg,
 			     bool syslog, char *buf, size_t size) { return 0; }
 static size_t cont_print_text(char *text, size_t size) { return 0; }
 
@@ -2151,8 +2133,7 @@ skip:
 		}
 
 		level = msg->level;
-		len = msg_print_text(msg, console_prev, false,
-				     text, sizeof(text));
+		len = msg_print_text(msg, false, text, sizeof(text));
 
 		msg->flags = lflags;
 		console_printed_seq = console_seq;
@@ -2717,7 +2698,7 @@ bool kmsg_dump_get_line_nolock(struct kmsg_dumper *dumper, bool syslog,
 		goto out;
 
 	msg = log_from_idx(dumper->cur_idx);
-	l = msg_print_text(msg, 0, syslog, line, size);
+	l = msg_print_text(msg, syslog, line, size);
 
 	dumper->cur_idx = log_next(dumper->cur_idx);
 	dumper->cur_seq++;
@@ -2786,7 +2767,6 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 	u32 idx;
 	u64 next_seq;
 	u32 next_idx;
-	enum log_flags prev;
 	size_t l = 0;
 	bool ret = false;
 
@@ -2809,27 +2789,23 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 	/* calculate length of entire buffer */
 	seq = dumper->cur_seq;
 	idx = dumper->cur_idx;
-	prev = 0;
 	while (seq < dumper->next_seq) {
 		struct log *msg = log_from_idx(idx);
 
-		l += msg_print_text(msg, prev, true, NULL, 0);
+		l += msg_print_text(msg, true, NULL, 0);
 		idx = log_next(idx);
 		seq++;
-		prev = msg->flags;
 	}
 
 	/* move first record forward until length fits into the buffer */
 	seq = dumper->cur_seq;
 	idx = dumper->cur_idx;
-	prev = 0;
 	while (l > size && seq < dumper->next_seq) {
 		struct log *msg = log_from_idx(idx);
 
-		l -= msg_print_text(msg, prev, true, NULL, 0);
+		l -= msg_print_text(msg, true, NULL, 0);
 		idx = log_next(idx);
 		seq++;
-		prev = msg->flags;
 	}
 
 	/* last message in next interation */
@@ -2837,14 +2813,12 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 	next_idx = idx;
 
 	l = 0;
-	prev = 0;
 	while (seq < dumper->next_seq) {
 		struct log *msg = log_from_idx(idx);
 
-		l += msg_print_text(msg, prev, syslog, buf + l, size - l);
+		l += msg_print_text(msg, syslog, buf + l, size - l);
 		idx = log_next(idx);
 		seq++;
-		prev = msg->flags;
 	}
 
 	dumper->next_seq = next_seq;
-- 
1.8.0.316.g291341c.dirty

Re: [PATCH 00/12] printk() fixes, optimizations, and clean ups

[Kay Sievers]

On Wed, 2012-11-14 at 00:12 +0100, Jan H. Schönherr wrote:
> Hi Greg, hi Kay, and all other interested people.
> 
> This series aims at cleaning up and fixing some bugs around printk().
> Patches 9 and 11 might require some discussion, see below.

This is how current git looks like:
[    1.062953] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input2
[    1.090595] List of all partitions:
[    1.091703] 0800       117220824 sda  driver: sd
[    1.093054]   0801         1048576 sda1 1fcbc57f-4bfc-4c2b-91a3-9c84fbcd9af1
[    1.094662]   0802        30720000 sda2 084917b7-8be2-4e86-838d-f771a9902e08
[    1.096624]   0803        15360000 sda3 180053b6-6697-4f4c-b331-4925773197ff
[    1.098624]   0804        54730752 sda4 b67dfc6e-d06f-4b11-bd52-96c09163aca9
[    1.100304]   0805        15360000 sda5 6d0d537c-3107-4057-a57b-5379a0cd8e31
[    1.101918] No filesystem could mount root, tried:  btrfs
[    1.103633] Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(8,1)


This with all your patches applied:
[    1.032804] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input2
[    1.063915] List of all partitions:
[    1.065521] 0800       117220824 sda  driver: sd
[    1.067444]   0801         1048576 sda1 1fcbc57f-4bfc-4c2b-91a3-9c84fbcd9af1  0802        30720000 sda2 084917b7-8be2-4e86-838d-f771a9902e08  0803        15360000 sda3 180053b6-6697-4f4c-b331-4925773197ff  0804        54730752 sda4 b67dfc6e-d06f-4b11-bd52-96c09163aca9  0805        15360000 sda5 6d0d537c-3107-4057-a57b-5379a0cd8e31No filesystem could mount root, tried:  btrfs
[    1.077120] Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(8,1)


Something seems broken in the patches regarding the console or newline logic.

Thanks,
Kay

Re: [PATCH 00/12] printk() fixes, optimizations, and clean ups

["Jan H. Schönherr"]

Am 15.11.2012 17:05, schrieb Kay Sievers:
> This with all your patches applied:
> [    1.032804] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input2
> [    1.063915] List of all partitions:
> [    1.065521] 0800       117220824 sda  driver: sd
> [    1.067444]   0801         1048576 sda1 1fcbc57f-4bfc-4c2b-91a3-9c84fbcd9af1  0802        30720000 sda2 084917b7-8be2-4e86-838d-f771a9902e08  0803        15360000 sda3 180053b6-6697-4f4c-b331-4925773197ff  0804        54730752 sda4 b67dfc6e-d06f-4b11-bd52-96c09163aca9  0805        15360000 sda5 6d0d537c-3107-4057-a57b-5379a0cd8e31No filesystem could mount root, tried:  btrfs
> [    1.077120] Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(8,1)
> 
> 
> Something seems broken in the patches regarding the console or newline logic.

(Just to mention it: I did do quite some testing, but this case must have
escaped me.)

Hmm... the code in question does only continuation prints, without any PREFIX.
Especially, it issues a single

	printk("\n");

at the end of each line (and does not start the next line with a KERN_ prefix).

This newline gets lost on the console.

This is due to patch 3, which reclaims a fully printed cont buffer
immediately. It does only a length check, without considering the LOG_NEWLINE
flag. So we never come around to print it. (And then, patch 9 has a similar
check -- which, btw, is necessary already in patch 7 I think...)

Please, try the patch below on top of everything. If this works, I'll prepare
a -v2 where everything is sorted into the correct patches.

(Though that makes patch 3 less efficient as we add newlines very late in two 
places via cont_flush(). OTOH, the newlines are not strictly needed, I think.)
(And another note: the longer I look at all the code, the more I want to try 
the alternative mentioned in patch 6, might be easier to read overall.)

Regards
Jan

diff --git a/kernel/printk.c b/kernel/printk.c
index d27da0a..51da981 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1434,7 +1434,8 @@ static void cont_flush(enum log_flags flags)
 	 * If no fragment of this line ever reached the console or everything
 	 * has been printed, free the buffer. Otherwise keep it available.
 	 */
-	if (!cont.cons || cont.cons == cont.msg.text_len)
+	if (!cont.cons || (cont.cons == cont.msg.text_len &&
+			   !(cont.msg.flags & LOG_NEWLINE)))
 		cont.msg.text_len = 0;
 	else
 		cont.flushed = log_next_seq - 1;
@@ -1475,14 +1476,17 @@ static bool cont_add(int facility, int level, enum log_flags flags,
 
 static size_t cont_print_text(char *text, size_t size)
 {
-	size_t textlen;
+	size_t textlen = 0;
 	enum log_flags flags = cont.msg.flags;
 	u64 seq = cont.flushed ? cont.flushed : log_next_seq;
 
 	if (cont.msg.text_len == cont.cons) {
-		if (cont.flushed)
-			cont.msg.text_len = 0;
-		return 0;
+		/* Not even a newline to print? */
+		if (!(cont.msg.flags & LOG_NEWLINE))
+			goto out;
+		/* Newline already printed due to other messages? */
+		if (console_printed_seq != 0)
+			goto out;
 	}
 
 	/* Avoid a break, when we continuously print the cont buffer */
@@ -1505,6 +1509,7 @@ static size_t cont_print_text(char *text, size_t size)
 	console_prev = cont.msg.flags;
 	console_printed_seq = cont.flushed;
 
+out:
 	if (cont.flushed)
 		cont.msg.text_len = 0;
 

Re: [PATCH 00/12] printk() fixes, optimizations, and clean ups

[Kay Sievers]

On Thu, Nov 15, 2012 at 10:22 PM, "Jan H. Schönherr"
<schnhrr@cs.tu-berlin.de> wrote:
> Am 15.11.2012 17:05, schrieb Kay Sievers:
>> This with all your patches applied:
>> [    1.032804] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input2
>> [    1.063915] List of all partitions:
>> [    1.065521] 0800       117220824 sda  driver: sd
>> [    1.067444]   0801         1048576 sda1 1fcbc57f-4bfc-4c2b-91a3-9c84fbcd9af1  0802        30720000 sda2 084917b7-8be2-4e86-838d-f771a9902e08  0803        15360000 sda3 180053b6-6697-4f4c-b331-4925773197ff  0804        54730752 sda4 b67dfc6e-d06f-4b11-bd52-96c09163aca9  0805        15360000 sda5 6d0d537c-3107-4057-a57b-5379a0cd8e31No filesystem could mount root, tried:  btrfs
>> [    1.077120] Kernel panic - not syncing: VFS: Unable to mount root fs on unknown-block(8,1)
>>
>> Something seems broken in the patches regarding the console or newline logic.
>
> (Just to mention it: I did do quite some testing, but this case must have
> escaped me.)

Yeah, don't tell me, it was not really fun to discover all the weird
edges here because nobody wants to have rules. :)

> Please, try the patch below on top of everything. If this works, I'll prepare
> a -v2 where everything is sorted into the correct patches.

Looks all fine now.

Kay