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

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

[Jan H. Schönherr]

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

This is the second iteration of my try to clean up and fix some bugs around
printk(). A few things got fixed and improved. But I'm still waiting for the
usual beating, that I changed too much. ;)

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

A summary of changes compared to v1 [3] can be found below the now following
high-level description. This series is currently against v3.7-rc8, but it
applies to next-20121206 as well.

Patches 11 and 12 might require some discussion, see below.

1. printk: drop ambiguous LOG_CONT flag

	This patch started everything [2]. It fixes incorrect merges of
	independent continuation records. With all the other patches on top,
	there is not much left of it, but it still serves as a clean up
	and a backup solution if the changes of patches 9-14 are considered
	over the limit.

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

	These five patches fall mostly into the optimization category. The
	only measurable effect is probably that continuation records are more
	often merged than before (patches 3+4+5). Patch 4 also fixes a
	potential problem resulting in not merged continuation records.

7. printk: let cont_print_text() reuse existing code

	Code clean-up. Fixes a bug when printing multiline message to the 
	console.

8. printk: refactor locking in console_unlock()

	Fix a problem with the order of printed messages due to locking race
	conditions.

9. printk: retain unknown log-level until cont_add()/log_store()
10. printk: track previously logged message in log_store()
11. printk: avoid glitches in console output
12. printk: encode formatting in message flags
13. printk: drop now useless tracking of previous message flags

	Patches 9 and 10 are preparations for patches 11 and 12.

	Patch 11 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.

	Patch 12 also changes behavior, but only in a few corner cases. OTOH,
	it improves source readability by removing some of the historical
	growth (patch 13) that only makes sense when you have actually read
	the history. Comments?

14. printk: refactor continuation buffer handling

	Cure four minor issues with continuation messages by doing some
	code reorganization.


If patches 9-14 are too much, applying just the more straight-forward 
patches 1-8 for now is fine, too. 


Changes of v2 compared to v1 (see per-patch changes for additional details):

- fixed a bug (pointed out by Kay) when a single newline is printed
- fixed two bugs that could mismerge continuation records

- added patch 4 (making patch 3 efficient again after fixing the single
  newline bug)
- added a check for the cont buffer for the retry loop to patch 8
- added patch 14

- realized patch 7 differently, in a more readable way
- reorganized the patches towards the end due to patch 14 and the bug-fixes


Remaining issues (which also existed before applying this series) from my
point of view:

1. console_unlock() could use a rewrite to be more readable. (See comment in
   patch 8.)

2. After patch 14 it would be relatively simple to add support for multiple
   cont buffers. Is someone interested in this?

3. The cont buffer should be flushed automatically after some time, so that
   its contents become available to syslog. Currently flushing can be delayed
   indefinitely. (See comment in patch 14.)

I'll probably do #1 one day. #2 only when someone asks. And I currently don't
know The Right Way to do #3.

Regards
Jan

[1] Joe Perches' printk reorganization: http://lkml.org/lkml/2012/10/24/748
[2] first version of patch 1: http://lkml.org/lkml/2012/9/26/392
[3] v1 of this series: http://lkml.org/lkml/2012/11/13/678



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

 kernel/printk.c | 481 ++++++++++++++++++++++++++++++++++----------------------
 1 file changed, 292 insertions(+), 189 deletions(-)

-- 
1.8.0.1.20.g7c65b2e.dirty

[PATCH v2 01/14] 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 -- and vice versa)

Tested-by: Kay Sievers <kay@vrfy.org>
Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
v2:
- minor commit message clarification
v1b:
- 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.1.20.g7c65b2e.dirty

[PATCH v2 02/14] 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.1.20.g7c65b2e.dirty

[PATCH v2 03/14] 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>
---
v2:
- fixed a bug, where the buffer was considered fully printed although
  a final newline was still pending
---
 kernel/printk.c | 37 ++++++++++++++++++++-----------------
 1 file changed, 20 insertions(+), 17 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 0927068..13af61c 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1400,24 +1400,27 @@ 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.flags & LOG_NEWLINE)))
 		cont.len = 0;
-	}
+	else
+		cont.flushed = true;
 }
 
 static bool cont_add(int facility, int level, enum log_flags flags,
-- 
1.8.0.1.20.g7c65b2e.dirty

[PATCH v2 04/14] printk: do not add unnecessary newlines to the continuation buffer

[Jan H. Schönherr]

Do not add newlines to the continuation buffer just because we can.  (In
some cases, the newlines are even misplaced and prevent a correct syslog
output.) Instead, only if a newline was part of the input, store it
during cont_add().

This makes the previous patch a bit more efficient.

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

diff --git a/kernel/printk.c b/kernel/printk.c
index 13af61c..f6a91ec 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1392,15 +1392,13 @@ static struct cont {
 	bool flushed:1;			/* buffer sealed and committed */
 } cont;
 
-static void cont_flush(enum log_flags flags)
+static void cont_flush(void)
 {
 	if (cont.flushed)
 		return;
 	if (cont.len == 0)
 		return;
 
-	cont.flags |= flags;
-
 	/*
 	 * 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
@@ -1431,7 +1429,7 @@ 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);
+		cont_flush();
 		return false;
 	}
 
@@ -1440,16 +1438,18 @@ static bool cont_add(int facility, int level, enum log_flags flags,
 		cont.level = level;
 		cont.owner = current;
 		cont.ts_nsec = local_clock();
-		cont.flags = flags;
+		cont.flags = 0;
 		cont.cons = 0;
 		cont.flushed = false;
 	}
 
+	cont.flags |= flags;
+
 	memcpy(cont.buf + cont.len, text, len);
 	cont.len += len;
 
 	if (cont.len > (sizeof(cont.buf) * 80) / 100)
-		cont_flush(0);
+		cont_flush();
 
 	return true;
 }
@@ -1585,7 +1585,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 			if (cont.owner != current)
 				lflags |= LOG_PREFIX;
 			if (lflags & LOG_PREFIX)
-				cont_flush(LOG_NEWLINE);
+				cont_flush();
 		}
 
 		/* buffer line if possible, otherwise store it right away */
@@ -1605,7 +1605,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 			if (!(lflags & LOG_PREFIX))
 				stored = cont_add(facility, level, lflags,
 							text, text_len);
-			cont_flush(LOG_NEWLINE);
+			cont_flush();
 		}
 
 		if (!stored)
-- 
1.8.0.1.20.g7c65b2e.dirty

[PATCH v2 05/14] 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 f6a91ec..7328348 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1430,7 +1430,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();
-		return false;
+		if (cont.len)
+			return false;
 	}
 
 	if (!cont.len) {
-- 
1.8.0.1.20.g7c65b2e.dirty

[PATCH v2 06/14] 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 7328348..4f3c355 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -2060,10 +2060,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 */
@@ -2124,6 +2120,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.1.20.g7c65b2e.dirty

[PATCH v2 07/14] 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 major 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 print_text() that can also be used with
the continuation buffer and has the ability to start at a specific
position within the message and to track that position.

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
v2:
- moved an already needed check from a later patch to this patch
- fixed a bug, where a single newline at the end of the buffer might get
  skipped
- realized the utilization of msg_print_text() functionality completely
  different: we now pass lots of parameters instead of restructuring
  struct cont, which results in more readable code
---
 kernel/printk.c | 82 ++++++++++++++++++++++++++++++++-------------------------
 1 file changed, 46 insertions(+), 36 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 4f3c355..b6c4eae 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -853,10 +853,11 @@ static size_t print_time(u64 ts, char *buf)
 		       (unsigned long)ts, rem_nsec / 1000);
 }
 
-static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
+static size_t print_prefix(u8 facility, u8 level, u64 ts_nsec, bool syslog,
+			   char *buf)
 {
 	size_t len = 0;
-	unsigned int prefix = (msg->facility << 3) | msg->level;
+	unsigned int prefix = (facility << 3) | level;
 
 	if (syslog) {
 		if (buf) {
@@ -872,25 +873,33 @@ static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
 		}
 	}
 
-	len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
+	len += print_time(ts_nsec, buf ? buf + len : NULL);
 	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 print_text(const char *text, size_t text_size, size_t *offset,
+			 enum log_flags flags, enum log_flags prev,
+			 u8 facility, u8 level, u64 ts_nsec, bool syslog,
+			 char *buf, size_t size)
 {
-	const char *text = log_text(msg);
-	size_t text_size = msg->text_len;
 	bool prefix = true;
 	bool newline = true;
 	size_t len = 0;
+	size_t prefix_len = 0;
 
-	if (!(prev & LOG_NEWLINE) && !(msg->flags & LOG_PREFIX))
+	if (!(prev & LOG_NEWLINE) && !(flags & LOG_PREFIX))
 		prefix = false;
 
-	if (!(msg->flags & LOG_NEWLINE))
+	if (!(flags & LOG_NEWLINE))
 		newline = false;
 
+	if (offset) {
+		text += *offset;
+		text_size -= *offset;
+		if (*offset)
+			prefix = false;
+	}
+
 	if (!(prev & LOG_NEWLINE) && prefix) {
 		if (buf)
 			buf[len] = '\n';
@@ -909,22 +918,25 @@ static size_t msg_print_text(const struct log *msg, enum log_flags prev,
 			text_len = text_size;
 		}
 
+		if (prefix && !prefix_len)
+			prefix_len = print_prefix(facility, level, ts_nsec,
+						  syslog, NULL);
 		if (buf) {
-			if (print_prefix(msg, syslog, NULL) +
-			    text_len + 1 >= size - len)
+			if (prefix_len + text_len + 1 >= size - len)
 				break;
 
 			if (prefix)
-				len += print_prefix(msg, syslog, buf + len);
+				len += print_prefix(facility, level, ts_nsec,
+						    syslog, buf + len);
 			memcpy(buf + len, text, text_len);
 			len += text_len;
+			if (offset)
+				*offset += text_len + (next ? 1 : 0);
 			if (next || newline)
 				buf[len++] = '\n';
 		} else {
 			/* SYSLOG_ACTION_* buffer size only calculation */
-			if (prefix)
-				len += print_prefix(msg, syslog, NULL);
-			len += text_len;
+			len += prefix_len + text_len;
 			if (next || newline)
 				len++;
 		}
@@ -936,6 +948,15 @@ static size_t msg_print_text(const struct log *msg, enum log_flags prev,
 	return len;
 }
 
+static size_t msg_print_text(const struct log *msg,
+			     enum log_flags prev,
+			     bool syslog, char *buf, size_t size)
+{
+	return print_text(log_text(msg), msg->text_len, NULL, msg->flags, prev,
+			  msg->facility, msg->level, msg->ts_nsec, syslog,
+			  buf, size);
+}
+
 static int syslog_print(char __user *buf, int size)
 {
 	char *text;
@@ -1458,31 +1479,20 @@ 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;
 
-	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;
-	}
-
-	len = cont.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;
+	if (cont.len == cont.cons) {
+		/* Not even a newline to print? */
+		if (!(cont.flags & LOG_NEWLINE))
+			goto out;
 	}
 
-	if (cont.flushed) {
-		if (cont.flags & LOG_NEWLINE)
-			text[textlen++] = '\n';
-		/* got everything, release buffer */
+	textlen = print_text(cont.buf, cont.len, &cont.cons, cont.flags,
+			     console_prev, cont.facility, cont.level,
+			     cont.ts_nsec, false, text, size);
+out:
+	if (cont.flushed)
 		cont.len = 0;
-	}
+
 	return textlen;
 }
 
-- 
1.8.0.1.20.g7c65b2e.dirty

[PATCH v2 08/14] 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.

(And, at the end, the retry check must include the continuation buffer.)

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.

v2:
- add cont buffer to retry check
---
 kernel/printk.c | 32 +++++++++++++++++---------------
 1 file changed, 17 insertions(+), 15 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index b6c4eae..075fbd4 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1726,6 +1726,7 @@ static struct cont {
 	size_t cons;
 	u8 level;
 	bool flushed:1;
+	enum log_flags flags;
 } cont;
 static struct log *log_from_idx(u32 idx) { return NULL; }
 static u32 log_next(u32 idx) { return 0; }
@@ -2005,13 +2006,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.len)
-		goto out;
+		return;
 
 	/*
 	 * We still queue earlier records, likely because the console was
@@ -2019,17 +2018,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.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;
 }
 
 /**
@@ -2061,15 +2061,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 */
@@ -2105,12 +2105,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;
 
@@ -2129,7 +2129,9 @@ skip:
 	 * flush, no worries.
 	 */
 	raw_spin_lock(&logbuf_lock);
-	retry = console_seq != log_next_seq;
+	retry = console_seq != log_next_seq ||
+		(cont.len && (cont.cons != cont.len ||
+			      cont.flags & LOG_NEWLINE));
 	if (seen_seq != log_next_seq) {
 		wake_klogd = true;
 		seen_seq = log_next_seq;
-- 
1.8.0.1.20.g7c65b2e.dirty

[PATCH v2 09/14] printk: retain unknown log-level until cont_add()/log_store()

[Jan H. Schönherr]

Retain a value of -1 for messages with an unknown message level and pass
this to cont_add() and log_store(). This way, we can better distinguish
continuation records from non-continuation records and keep the correct
level in more cases than before. (Though, most of this level tracking
will be done in follow-up patches.)

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
v2:
- rephrased commit message to better reflect what the patch is doing
---
 kernel/printk.c | 28 +++++++++++++++++-----------
 1 file changed, 17 insertions(+), 11 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 075fbd4..52ccf93 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -309,6 +309,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);
@@ -375,7 +379,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;
@@ -1453,11 +1457,12 @@ static bool cont_add(int facility, int level, enum log_flags flags,
 		cont_flush();
 		if (cont.len)
 			return false;
+		level = cont.level;
 	}
 
 	if (!cont.len) {
 		cont.facility = facility;
-		cont.level = level;
+		cont.level = level == -1 ? default_message_loglevel : level;
 		cont.owner = current;
 		cont.ts_nsec = local_clock();
 		cont.flags = 0;
@@ -1567,22 +1572,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.1.20.g7c65b2e.dirty

[PATCH v2 10/14] printk: track previously logged message in log_store()

[Jan H. Schönherr]

Centrally track information about the previous message in log_store().

This knowledge allows us to decide immediately whether the current
message is a continuation of the previous message. And if that is so, to
keep the correct log level (continuation records do not have a log level).

Later, this will also allow us to remove the tracking of the previous
message flags throughout the syslog/kmsg formatting code.

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
v2:
- Fixed a bug that could mismerge continuation records, because
  log_store() used "current" as the owner of the message passed in,
  which might be incorrect when used from cont_flush().
- refactored code
- refactored patches
---
 kernel/printk.c | 47 ++++++++++++++++++++++++++++++++++++-----------
 1 file changed, 36 insertions(+), 11 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 52ccf93..151c77a 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -226,6 +226,10 @@ static size_t syslog_partial;
 static u64 log_first_seq;
 static u32 log_first_idx;
 
+/* information about the last stored message */
+static struct log *log_last_msg;
+static struct task_struct *log_last_owner;
+
 /* index and sequence number of the next record to store in the buffer */
 static u64 log_next_seq;
 static u32 log_next_idx;
@@ -300,18 +304,36 @@ static u32 log_next(u32 idx)
 	return idx + msg->len;
 }
 
+/* return correct level for continuation records */
+static int log_infer_level(struct task_struct *owner, int facility, int level,
+			  enum log_flags flags)
+{
+	if (flags & LOG_PREFIX || level != -1 || !log_last_msg ||
+	    log_last_msg->facility != facility || log_last_owner != owner ||
+	    log_last_msg->flags & LOG_NEWLINE)
+		return level;
+	return log_last_msg->level;
+}
+
 /* insert record into the buffer, discard old ones, update heads */
-static void log_store(int facility, int level,
+static void log_store(struct task_struct *owner, int facility, int level,
 		      enum log_flags flags, u64 ts_nsec,
 		      const char *dict, u16 dict_len,
 		      const char *text, u16 text_len)
 {
 	struct log *msg;
 	u32 size, pad_len;
-
-	/* store something meaningful, when no loglevel was given */
-	if (level == -1)
-		level = default_message_loglevel;
+	int inferred_level;
+
+	/* setup flags/level for storage */
+	inferred_level = log_infer_level(owner, facility, -1, flags);
+	if (inferred_level == -1) {
+		flags |= LOG_PREFIX;
+		if (level == -1)
+			level = default_message_loglevel;
+	} else {
+		level = inferred_level;
+	}
 
 	/* number of '\0' padding bytes to next message */
 	size = sizeof(struct log) + text_len + dict_len;
@@ -329,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++;
 	}
@@ -363,6 +385,9 @@ static void log_store(int facility, int level,
 	/* insert message */
 	log_next_idx += msg->len;
 	log_next_seq++;
+
+	log_last_owner = owner;
+	log_last_msg = msg;
 }
 
 /* /dev/kmsg - userspace message inject/listen interface */
@@ -1432,8 +1457,8 @@ static void cont_flush(void)
 	if (cont.cons)
 		cont.flags |= LOG_NOCONS;
 
-	log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec, NULL, 0,
-		  cont.buf, cont.len);
+	log_store(cont.owner, 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
@@ -1550,7 +1575,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		recursion_bug = 0;
 		printed_len += strlen(recursion_msg);
 		/* emit KERN_CRIT message */
-		log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
+		log_store(current, 0, 2, LOG_PREFIX | LOG_NEWLINE, 0,
 			  NULL, 0, recursion_msg, printed_len);
 	}
 
@@ -1607,7 +1632,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 		/* buffer line if possible, otherwise store it right away */
 		if (!cont_add(facility, level, lflags, text, text_len))
-			log_store(facility, level, lflags, 0,
+			log_store(current, facility, level, lflags, 0,
 				  dict, dictlen, text, text_len);
 	} else {
 		bool stored = false;
@@ -1626,7 +1651,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		}
 
 		if (!stored)
-			log_store(facility, level, lflags, 0,
+			log_store(current, facility, level, lflags, 0,
 				  dict, dictlen, text, text_len);
 	}
 	printed_len += text_len;
-- 
1.8.0.1.20.g7c65b2e.dirty

[PATCH v2 11/14] 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.

v2:
- moved a check from this patch to an earlier patch where it is already
  needed
- added logic to avoid empty lines that might arise with concurrent
  printk()s and late newlines
- renamed console_prev to console_printed_flags
- fixed a bug with racing continuation printk()s
---
 kernel/printk.c | 68 +++++++++++++++++++++++++++++++++++++++++++--------------
 1 file changed, 52 insertions(+), 16 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 151c77a..387fc51 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -237,7 +237,8 @@ static u32 log_next_idx;
 /* the next printk record to write to the console */
 static u64 console_seq;
 static u32 console_idx;
-static enum log_flags console_prev;
+static enum log_flags console_printed_flags;
+static u64 console_printed_seq;
 
 /* the next printk record to read after the last 'clear' command */
 static u64 clear_seq;
@@ -925,8 +926,6 @@ static size_t print_text(const char *text, size_t text_size, size_t *offset,
 	if (offset) {
 		text += *offset;
 		text_size -= *offset;
-		if (*offset)
-			prefix = false;
 	}
 
 	if (!(prev & LOG_NEWLINE) && prefix) {
@@ -1435,11 +1434,11 @@ static struct cont {
 	size_t len;			/* length == 0 means unused buffer */
 	size_t cons;			/* bytes written to console */
 	struct task_struct *owner;	/* task of first print*/
+	u64 flushed;			/* sequence number when flushed */
 	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;
 
 static void cont_flush(void)
@@ -1460,6 +1459,9 @@ static void cont_flush(void)
 	log_store(cont.owner, cont.facility, cont.level, cont.flags,
 		  cont.ts_nsec, NULL, 0, cont.buf, cont.len);
 
+	if (console_printed_seq == 0)
+		console_printed_seq = log_next_seq - 1;
+
 	/*
 	 * If no fragment of this line ever reached the console or everything
 	 * has been printed, free the buffer. Otherwise keep it available.
@@ -1468,7 +1470,7 @@ static void cont_flush(void)
 			   !(cont.flags & LOG_NEWLINE)))
 		cont.len = 0;
 	else
-		cont.flushed = true;
+		cont.flushed = log_next_seq - 1;
 }
 
 static bool cont_add(int facility, int level, enum log_flags flags,
@@ -1492,7 +1494,7 @@ static bool cont_add(int facility, int level, enum log_flags flags,
 		cont.ts_nsec = local_clock();
 		cont.flags = 0;
 		cont.cons = 0;
-		cont.flushed = false;
+		cont.flushed = 0;
 	}
 
 	cont.flags |= flags;
@@ -1509,16 +1511,37 @@ 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;
+	enum log_flags flags = cont.flags;
+	u64 seq = cont.flushed ? cont.flushed : log_next_seq;
+	u64 pseq = console_printed_seq ? console_printed_seq : log_next_seq;
 
 	if (cont.len == cont.cons) {
 		/* Not even a newline to print? */
 		if (!(cont.flags & LOG_NEWLINE))
 			goto out;
+		/* Newline already printed due to other messages? */
+		if (seq != pseq)
+			goto out;
 	}
 
-	textlen = print_text(cont.buf, cont.len, &cont.cons, cont.flags,
-			     console_prev, cont.facility, cont.level,
+	/*
+	 * Avoid a break, when we continuously print the same message; and
+	 * force a break, when we do not continue the last printed message.
+	 */
+	if (seq == pseq)
+		flags &= ~LOG_PREFIX;
+	else if (seq != pseq + 1 || cont.cons ||
+		 log_infer_level(cont.owner, cont.facility, -1,
+				 cont.flags) == -1)
+		flags |= LOG_PREFIX;
+
+	textlen = print_text(cont.buf, cont.len, &cont.cons, flags,
+			     console_printed_flags, cont.facility, cont.level,
 			     cont.ts_nsec, false, text, size);
+
+	console_printed_seq = cont.flushed;
+	console_printed_flags = flags;
+
 out:
 	if (cont.flushed)
 		cont.len = 0;
@@ -1747,16 +1770,16 @@ 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 enum log_flags console_printed_flags;
+static u64 console_printed_seq;
 static struct cont {
 	size_t len;
 	size_t cons;
+	u64 flushed;
 	u8 level;
-	bool flushed:1;
 	enum log_flags flags;
 } cont;
 static struct log *log_from_idx(u32 idx) { return NULL; }
@@ -2098,6 +2121,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));
@@ -2106,7 +2130,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)
@@ -2126,16 +2149,30 @@ 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,
+		len = msg_print_text(msg, console_printed_flags, false,
 				     text, sizeof(text));
+
+		console_printed_seq = console_seq;
+		console_printed_flags = msg->flags;
+		msg->flags = lflags;
+
 		console_idx = log_next(console_idx);
 		console_seq++;
-		console_prev = msg->flags;
 
 		raw_spin_unlock(&logbuf_lock);
 		stop_critical_timings();	/* don't trace print latency */
@@ -2404,7 +2441,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.1.20.g7c65b2e.dirty

[PATCH v2 12/14] printk: encode formatting in message flags

[Jan H. Schönherr]

Currently, the formatting code has to look at the previously printed
message in order to determine the correct layout of the current message.
This is rather tedious. But now, that we centrally track information
about the previous message in log_store(), we can encode the necessary
information to correctly format a message within the current message
flags.

The flags have the following meaning during formatting:

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>
---
v2:
- refactored patches
---
 kernel/printk.c | 38 +++++++++++++++++++++++---------------
 1 file changed, 23 insertions(+), 15 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 387fc51..fb54e66 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 {
@@ -330,6 +331,8 @@ static void log_store(struct task_struct *owner, int facility, int level,
 	inferred_level = log_infer_level(owner, facility, -1, flags);
 	if (inferred_level == -1) {
 		flags |= LOG_PREFIX;
+		if (log_last_msg && !(log_last_msg->flags & LOG_NEWLINE))
+			flags |= LOG_NOCONT;
 		if (level == -1)
 			level = default_message_loglevel;
 	} else {
@@ -510,10 +513,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,
@@ -912,23 +915,17 @@ static size_t print_text(const char *text, size_t text_size, size_t *offset,
 			 u8 facility, u8 level, u64 ts_nsec, bool syslog,
 			 char *buf, size_t size)
 {
-	bool prefix = true;
-	bool newline = true;
+	bool prefix = flags & LOG_PREFIX;
+	bool newline = flags & LOG_NEWLINE;
 	size_t len = 0;
 	size_t prefix_len = 0;
 
-	if (!(prev & LOG_NEWLINE) && !(flags & LOG_PREFIX))
-		prefix = false;
-
-	if (!(flags & LOG_NEWLINE))
-		newline = false;
-
 	if (offset) {
 		text += *offset;
 		text_size -= *offset;
 	}
 
-	if (!(prev & LOG_NEWLINE) && prefix) {
+	if (flags & LOG_NOCONT) {
 		if (buf)
 			buf[len] = '\n';
 		len++;
@@ -1535,6 +1532,12 @@ static size_t cont_print_text(char *text, size_t size)
 				 cont.flags) == -1)
 		flags |= LOG_PREFIX;
 
+	/* Translate flags for printing */
+	if (console_printed_flags & LOG_NEWLINE)
+		flags |= LOG_PREFIX;
+	else if (flags & LOG_PREFIX)
+		flags |= LOG_NOCONT;
+
 	textlen = print_text(cont.buf, cont.len, &cont.cons, flags,
 			     console_printed_flags, cont.facility, cont.level,
 			     cont.ts_nsec, false, text, size);
@@ -2160,8 +2163,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_printed_flags & LOG_NEWLINE)
+				msg->flags &= ~LOG_NOCONT;
+			else
+				msg->flags |= LOG_NOCONT;
+		}
 
 		level = msg->level;
 		len = msg_print_text(msg, console_printed_flags, false,
-- 
1.8.0.1.20.g7c65b2e.dirty

[PATCH v2 13/14] 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 | 59 ++++++++++++++++-----------------------------------------
 1 file changed, 16 insertions(+), 43 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index fb54e66..0bacb8a 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 */
@@ -398,7 +397,6 @@ static void log_store(struct task_struct *owner, int facility, int level,
 struct devkmsg_user {
 	u64 seq;
 	u32 idx;
-	enum log_flags prev;
 	struct mutex lock;
 	char buf[8192];
 };
@@ -521,7 +519,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++) {
@@ -911,9 +908,8 @@ static size_t print_prefix(u8 facility, u8 level, u64 ts_nsec, bool syslog,
 }
 
 static size_t print_text(const char *text, size_t text_size, size_t *offset,
-			 enum log_flags flags, enum log_flags prev,
-			 u8 facility, u8 level, u64 ts_nsec, bool syslog,
-			 char *buf, size_t size)
+			 enum log_flags flags, u8 facility, u8 level,
+			 u64 ts_nsec, bool syslog, char *buf, size_t size)
 {
 	bool prefix = flags & LOG_PREFIX;
 	bool newline = flags & LOG_NEWLINE;
@@ -974,10 +970,9 @@ static size_t print_text(const char *text, size_t text_size, size_t *offset,
 }
 
 static size_t msg_print_text(const struct log *msg,
-			     enum log_flags prev,
 			     bool syslog, char *buf, size_t size)
 {
-	return print_text(log_text(msg), msg->text_len, NULL, msg->flags, prev,
+	return print_text(log_text(msg), msg->text_len, NULL, msg->flags,
 			  msg->facility, msg->level, msg->ts_nsec, syslog,
 			  buf, size);
 }
@@ -1001,7 +996,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) {
@@ -1011,13 +1005,11 @@ 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,
-				   LOG_LINE_MAX + PREFIX_MAX);
+		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){
@@ -1060,7 +1052,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 */
@@ -1074,12 +1065,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++;
 		}
@@ -1087,12 +1076,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++;
 		}
@@ -1101,12 +1088,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;
@@ -1114,7 +1100,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))
@@ -1127,7 +1112,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;
 			}
 		}
 	}
@@ -1232,7 +1216,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) {
@@ -1245,16 +1228,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;
 		}
@@ -1539,8 +1520,8 @@ static size_t cont_print_text(char *text, size_t size)
 		flags |= LOG_NOCONT;
 
 	textlen = print_text(cont.buf, cont.len, &cont.cons, flags,
-			     console_printed_flags, cont.facility, cont.level,
-			     cont.ts_nsec, false, text, size);
+			     cont.facility, cont.level, cont.ts_nsec, false,
+			     text, size);
 
 	console_printed_seq = cont.flushed;
 	console_printed_flags = flags;
@@ -1788,7 +1769,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; }
 
@@ -2172,8 +2153,7 @@ skip:
 		}
 
 		level = msg->level;
-		len = msg_print_text(msg, console_printed_flags, false,
-				     text, sizeof(text));
+		len = msg_print_text(msg, false, text, sizeof(text));
 
 		console_printed_seq = console_seq;
 		console_printed_flags = msg->flags;
@@ -2740,7 +2720,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++;
@@ -2809,7 +2789,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;
 
@@ -2832,27 +2811,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 */
@@ -2860,14 +2835,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.1.20.g7c65b2e.dirty

[PATCH v2 14/14] printk: refactor continuation buffer handling

[Jan H. Schönherr]

Clean up the code in vprintk_emit(), and move the continuation buffer
handling completely into cont_*() functions. Also, make continuation
decisions a bit more intelligient.

Due to the cleanup, we can now draw a nice picture of the design:

      | | |
      | | | various ways to store messages,
      | | | e. g., printk(), kmsg, ...
      | | |
      v v v
Kernel Logging Interface
	|
	| forward preprocessed message
	| via cont_add()
	|
	v		forward message
Continuation Buffer  --------------------->  Syslog Buffer
Management		via log_store()	     Management
	^					^ ^ ^
	| get message via	get message via | | |
	| cont_print_text()    msg_print_text() | | |
	|					| | |
	| +-------------------------------------+ | |
	| |					  | |
      Console				    Syslog + Others

The continuation buffer management works now as follows:

Every message or message fragment is passed via cont_add(). cont_add()
either buffers the message internally or forwards the message directly
to the syslog buffer management via log_store(). Buffering is only done
when it seems beneficial, i. e., the fragment in question might be
continued later -- and then only when it does not conflict with the
buffer's contents. Additionally, program order of messages is ensured.

Compared to the previous behavior, there are the following changes:
* A message fragment with a different facility or level can no longer
  continue a previous fragment from the same task.
* The unknown log level of a continuation fragment is inferred in more
  cases.
* If a message is long enough to trigger a flush, it bypasses the
  buffer.
* The buffer is _not_ flushed for a continuation fragment of a different
  task if the buffer cannot be used directly afterwards for said
  fragment.

Most of the changes help racing printk()s, especially the last one
helps when two threads do continuation printk()s and the console is
busy. Then, instead of having alternating fragments in syslog, one
message will be accumulated in the cont buffer, while the others
fragments are stored (still one by one) in the syslog buffer.

(If the console is fast enough, the cont buffer is always immediately
reclaimable, thus, we still end up with alternating fragments in
syslog. I considered to add a delay before the cont buffer is flushed,
but it did not seem worth the effort.)

Signed-off-by: Jan H. Schönherr <schnhrr@cs.tu-berlin.de>
---
new in v2

We still need a timer, but for a different purpose: Currently the
contents of the cont buffer are kept indefinitely if nothing else
is logged. That is, the last message (without newline) is not
going to be visible in syslog, until something else causes a flush.
Any idea where to put this?
---
 kernel/printk.c | 149 ++++++++++++++++++++++++++++++++++----------------------
 1 file changed, 90 insertions(+), 59 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 0bacb8a..aa698cd 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1419,12 +1419,28 @@ static struct cont {
 	enum log_flags flags;		/* prefix, newline flags */
 } cont;
 
-static void cont_flush(void)
+static inline bool cont_is_reclaimable(void)
+{
+	/*
+	 * If no fragment of this line ever reached the console or everything
+	 * has been printed, the buffer will be freed. Otherwise it will be
+	 * kept available for printing.
+	 */
+	return !cont.cons || (cont.cons == cont.len &&
+			      !(cont.flags & LOG_NEWLINE));
+}
+
+static inline bool cont_would_flush(enum log_flags flags, size_t len)
+{
+	return flags & LOG_NEWLINE || len > (sizeof(cont.buf) * 80) / 100;
+}
+
+static bool cont_flush(void)
 {
-	if (cont.flushed)
-		return;
 	if (cont.len == 0)
-		return;
+		return true;
+	if (cont.flushed)
+		return false;
 
 	/*
 	 * If a fragment of this line was directly flushed to the console, the
@@ -1440,29 +1456,80 @@ static void cont_flush(void)
 	if (console_printed_seq == 0)
 		console_printed_seq = log_next_seq - 1;
 
-	/*
-	 * 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.flags & LOG_NEWLINE)))
+	if (cont_is_reclaimable()) {
 		cont.len = 0;
-	else
-		cont.flushed = log_next_seq - 1;
+		return true;
+	}
+
+	cont.flushed = log_next_seq - 1;
+	return false;
 }
 
-static bool cont_add(int facility, int level, enum log_flags flags,
+static void cont_add(int facility, int level, enum log_flags flags,
+		     const char *dict, u16 dict_len,
 		     const char *text, size_t len)
 {
-	if (cont.len && cont.flushed)
-		return false;
+	bool use_buffer = true;
 
-	if (cont.len + len > sizeof(cont.buf)) {
-		/* the line gets too long, split it up in separate records */
-		cont_flush();
-		if (cont.len)
-			return false;
+	if (!cont.len) {
+		/*
+		 * Buffer is empty. If message is self-contained or too long
+		 * in itself, then bypass buffer.
+		 */
+		if (cont_would_flush(flags, len))
+			use_buffer = false;
+		else
+			level = log_infer_level(current, facility, level,
+						flags);
+	} else if (cont.flushed) {
+		/* Buffer is still in use and cannot be used. */
+		use_buffer = false;
+	} else if (cont.owner != current) {
+		/*
+		 * Buffer contains data from someone else. Only use the buffer
+		 * when this message might be continued _and_ the buffer is
+		 * immediately reclaimable. Otherwise bypass buffer.
+		 */
+		if (cont_would_flush(flags, len) || !cont_is_reclaimable()) {
+			use_buffer = false;
+		} else {
+			/*
+			 * Try to infer level from last stored message before
+			 * cont_flush().
+			 */
+			level = log_infer_level(current, facility, level,
+						flags);
+			/*
+			 * Due to the check above, cont_flush() should always
+			 * reclaim the buffer, but be extra defensive.
+			 */
+			use_buffer = cont_flush();
+		}
+	} else if (cont.facility != facility || flags & LOG_PREFIX ||
+		   (level != -1 && level != cont.level)) {
+		/*
+		 * The data in the buffer belongs to the same owner, but this
+		 * message is no continuation. Flush buffer to ensure program
+		 * order of messages.
+		 */
+		use_buffer = cont_flush();
+		if (cont_would_flush(flags, len))
+			use_buffer = false;
+	} else if (cont.len + len > sizeof(cont.buf)) {
+		/*
+		 * This message continues the data in the buffer, but it gets
+		 * too long, split it up in separate records.
+		 */
 		level = cont.level;
+		use_buffer = cont_flush();
+		if (cont_would_flush(flags, len))
+			use_buffer = false;
+	}
+
+	if (!use_buffer) {
+		log_store(current, facility, level, flags, 0, dict, dict_len,
+			  text, len);
+		return;
 	}
 
 	if (!cont.len) {
@@ -1480,10 +1547,8 @@ static bool cont_add(int facility, int level, enum log_flags flags,
 	memcpy(cont.buf + cont.len, text, len);
 	cont.len += len;
 
-	if (cont.len > (sizeof(cont.buf) * 80) / 100)
+	if (cont_would_flush(cont.flags, cont.len))
 		cont_flush();
-
-	return true;
 }
 
 static size_t cont_print_text(char *text, size_t size)
@@ -1623,44 +1688,10 @@ asmlinkage int vprintk_emit(int facility, int level,
 		lflags |= LOG_PREFIX;
 
 	if (dict)
-		lflags |= LOG_PREFIX|LOG_NEWLINE;
+		lflags |= LOG_PREFIX | LOG_NEWLINE;
 
-	if (!(lflags & LOG_NEWLINE)) {
-		/*
-		 * Flush the conflicting buffer. An earlier newline was missing,
-		 * or another task also prints continuation lines.
-		 */
-		if (cont.len && !cont.flushed) {
-			if (cont.owner != current)
-				lflags |= LOG_PREFIX;
-			if (lflags & LOG_PREFIX)
-				cont_flush();
-		}
+	cont_add(facility, level, lflags, dict, dictlen, text, text_len);
 
-		/* buffer line if possible, otherwise store it right away */
-		if (!cont_add(facility, level, lflags, text, text_len))
-			log_store(current, facility, level, lflags, 0,
-				  dict, dictlen, text, text_len);
-	} else {
-		bool stored = false;
-
-		/*
-		 * If an earlier newline was missing and it was the same task,
-		 * either merge it with the current buffer and flush, or if
-		 * 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 (!(lflags & LOG_PREFIX))
-				stored = cont_add(facility, level, lflags,
-							text, text_len);
-			cont_flush();
-		}
-
-		if (!stored)
-			log_store(current, facility, level, lflags, 0,
-				  dict, dictlen, text, text_len);
-	}
 	printed_len += text_len;
 
 	/*
-- 
1.8.0.1.20.g7c65b2e.dirty

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

[Joe Perches]

On Thu, 2012-12-06 at 13:39 -0800, Andrew Morton wrote:
> On Thu,  6 Dec 2012 18:05:57 +0100
> Jan H. Sch__nherr <schnhrr@cs.tu-berlin.de> wrote:
> 
> > This is the second iteration of my try to clean up and fix some bugs around
> > printk().
> 
> We're a few days away from 3.7, which is not a good time to be sending
> large patchsets.  Please resend after -rc1 and I'll take a look.

Hi Andrew, 

I'm pretty sure this isn't for 3.7 but is for 3.8.

> But be aware that Joe is also planning on sending a large
> printk patchset at that time, and the two patchsets will conflict
> massively.

Can you please pick this up for -next now and I'll
redo my patches against -next for -rc1 so I'm not
delayed until 3.9?

cheers, Joe

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

[Joe Perches]

On Thu, 2012-12-06 at 16:19 -0800, Andrew Morton wrote:
> On Thu, 06 Dec 2012 15:37:30 -0800
> Joe Perches <joe@perches.com> wrote:
> > Can you please pick this up for -next now and I'll
> > redo my patches against -next for -rc1 so I'm not
> > delayed until 3.9?
> 
> It would be better to do things in the other order.
> 
> a) Your patches perform mainly code-movement which doesn't cause
>    functional changes.  Jan's patches are functional changes which
>    require more thought and testing and possible fixups.

Fine by me.  Jan?

Jan's patches also correct garbled output with the relatively
infrequent use of printk with only a newline like printk("\n");

$ git grep -E "\b(printk|pr_cont)\s*\(\s*\"\\\\n\""|wc -l
890

I think that's not too serious a dmesg problem for now.

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

["Jan H. Schönherr"]

Am 07.12.2012 03:51, schrieb Joe Perches:
> On Thu, 2012-12-06 at 16:19 -0800, Andrew Morton wrote:
>> On Thu, 06 Dec 2012 15:37:30 -0800
>> Joe Perches <joe@perches.com> wrote:
>>> Can you please pick this up for -next now and I'll
>>> redo my patches against -next for -rc1 so I'm not
>>> delayed until 3.9?
>>
>> It would be better to do things in the other order.
>>
>> a) Your patches perform mainly code-movement which doesn't cause
>>    functional changes.  Jan's patches are functional changes which
>>    require more thought and testing and possible fixups.
> 
> Fine by me.  Jan?

No problem.

I agree with Andrew, that patches 9 to 14 could use indeed some
more eyeballs.

Patches 1 to 8 are more straight-forward, and I would consider
these ready. However, they are also those, where I probably won't
have any trouble rebasing them on top of your changes.


Anyway. Until now I always thought my patches will end up in the
queue of some maintainer, so that I don't have to bother about
_when_ posting my patches. Therefore: when should I repost a
version rebased on top of Joe's changes?

(If I'd get some opinions on 9 to 14 until then, all the better.)

Regards
Jan

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

[Greg Kroah-Hartman]

On Fri, Dec 07, 2012 at 12:47:36PM +0100, "Jan H. Schönherr" wrote:
> Am 07.12.2012 03:51, schrieb Joe Perches:
> > On Thu, 2012-12-06 at 16:19 -0800, Andrew Morton wrote:
> >> On Thu, 06 Dec 2012 15:37:30 -0800
> >> Joe Perches <joe@perches.com> wrote:
> >>> Can you please pick this up for -next now and I'll
> >>> redo my patches against -next for -rc1 so I'm not
> >>> delayed until 3.9?
> >>
> >> It would be better to do things in the other order.
> >>
> >> a) Your patches perform mainly code-movement which doesn't cause
> >>    functional changes.  Jan's patches are functional changes which
> >>    require more thought and testing and possible fixups.
> > 
> > Fine by me.  Jan?
> 
> No problem.
> 
> I agree with Andrew, that patches 9 to 14 could use indeed some
> more eyeballs.
> 
> Patches 1 to 8 are more straight-forward, and I would consider
> these ready. However, they are also those, where I probably won't
> have any trouble rebasing them on top of your changes.
> 
> 
> Anyway. Until now I always thought my patches will end up in the
> queue of some maintainer, so that I don't have to bother about
> _when_ posting my patches. Therefore: when should I repost a
> version rebased on top of Joe's changes?

You are correct, I'll end up queuing these up to my tree when 3.8-rc1 is
out, they will live in linux-next until 3.8-final is out, and then go to
Linus for 3.9-rc1.  Right now, my trees are frozen due to the merge
window about to open up.  Your patience is appreciated.

thanks,

greg k-h

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

[Joe Perches]

On Fri, 2012-12-07 at 07:04 -0800, Greg Kroah-Hartman wrote:
> On Fri, Dec 07, 2012 at 12:47:36PM +0100, "Jan H. Schönherr" wrote:
> > Am 07.12.2012 03:51, schrieb Joe Perches:
> > > On Thu, 2012-12-06 at 16:19 -0800, Andrew Morton wrote:
> > >> On Thu, 06 Dec 2012 15:37:30 -0800
> > >> Joe Perches <joe@perches.com> wrote:
> > >>> Can you please pick this up for -next now and I'll
> > >>> redo my patches against -next for -rc1 so I'm not
> > >>> delayed until 3.9?
> > >>
> > >> It would be better to do things in the other order.
> > >>
> > >> a) Your patches perform mainly code-movement which doesn't cause
> > >>    functional changes.  Jan's patches are functional changes which
> > >>    require more thought and testing and possible fixups.
> > > 
> > > Fine by me.  Jan?
> > 
> > No problem.
> > 
> > I agree with Andrew, that patches 9 to 14 could use indeed some
> > more eyeballs.
> > 
> > Patches 1 to 8 are more straight-forward, and I would consider
> > these ready. However, they are also those, where I probably won't
> > have any trouble rebasing them on top of your changes.
> > 
> > Anyway. Until now I always thought my patches will end up in the
> > queue of some maintainer, so that I don't have to bother about
> > _when_ posting my patches. Therefore: when should I repost a
> > version rebased on top of Joe's changes?
> 
> You are correct, I'll end up queuing these up to my tree when 3.8-rc1 is
> out,

Andrew suggested I send my patches at -rc2.

> they will live in linux-next until 3.8-final is out, and then go to
> Linus for 3.9-rc1.  Right now, my trees are frozen due to the merge
> window about to open up.  Your patience is appreciated.

I think it'd be easier for a single downstream
maintainer to coordinate these patch sets sequencing.

You or Andrew might be better than you and Andrew.

There is a small patch to printk that should likely
be applied in some form for -rc1 or earlier:

Sylvain Munaut's (cc'd) print_time fix:
https://patchwork.kernel.org/patch/1845971/

I don't know of anything else that likely will
or should be applied before -rc1.

Frederic Weisbecker (also cc'd) has a printk nohz
patch series that merits some consideration too.
https://lkml.org/lkml/2012/10/20/94
https://lkml.org/lkml/2012/11/14/646
I don't know if Ingo pulled it in somewhere or not.

cheers, Joe

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

[Frederic Weisbecker]

2012/12/7 Joe Perches <joe@perches.com>:
> On Fri, 2012-12-07 at 07:04 -0800, Greg Kroah-Hartman wrote:
>> On Fri, Dec 07, 2012 at 12:47:36PM +0100, "Jan H. Schönherr" wrote:
>> > Am 07.12.2012 03:51, schrieb Joe Perches:
>> > > On Thu, 2012-12-06 at 16:19 -0800, Andrew Morton wrote:
>> > >> On Thu, 06 Dec 2012 15:37:30 -0800
>> > >> Joe Perches <joe@perches.com> wrote:
>> > >>> Can you please pick this up for -next now and I'll
>> > >>> redo my patches against -next for -rc1 so I'm not
>> > >>> delayed until 3.9?
>> > >>
>> > >> It would be better to do things in the other order.
>> > >>
>> > >> a) Your patches perform mainly code-movement which doesn't cause
>> > >>    functional changes.  Jan's patches are functional changes which
>> > >>    require more thought and testing and possible fixups.
>> > >
>> > > Fine by me.  Jan?
>> >
>> > No problem.
>> >
>> > I agree with Andrew, that patches 9 to 14 could use indeed some
>> > more eyeballs.
>> >
>> > Patches 1 to 8 are more straight-forward, and I would consider
>> > these ready. However, they are also those, where I probably won't
>> > have any trouble rebasing them on top of your changes.
>> >
>> > Anyway. Until now I always thought my patches will end up in the
>> > queue of some maintainer, so that I don't have to bother about
>> > _when_ posting my patches. Therefore: when should I repost a
>> > version rebased on top of Joe's changes?
>>
>> You are correct, I'll end up queuing these up to my tree when 3.8-rc1 is
>> out,
>
> Andrew suggested I send my patches at -rc2.
>
>> they will live in linux-next until 3.8-final is out, and then go to
>> Linus for 3.9-rc1.  Right now, my trees are frozen due to the merge
>> window about to open up.  Your patience is appreciated.
>
> I think it'd be easier for a single downstream
> maintainer to coordinate these patch sets sequencing.
>
> You or Andrew might be better than you and Andrew.
>
> There is a small patch to printk that should likely
> be applied in some form for -rc1 or earlier:
>
> Sylvain Munaut's (cc'd) print_time fix:
> https://patchwork.kernel.org/patch/1845971/
>
> I don't know of anything else that likely will
> or should be applied before -rc1.
>
> Frederic Weisbecker (also cc'd) has a printk nohz
> patch series that merits some consideration too.
> https://lkml.org/lkml/2012/10/20/94
> https://lkml.org/lkml/2012/11/14/646
> I don't know if Ingo pulled it in somewhere or not.

He has not yet pulled. But it's ready to be pulled and is on linux-next.