[PATCH POC 2/4] printk: Do not block cont buffer by partially flushed lines

[Petr Mladek]

Parts of the line can be preliminary flushed to the console
by console_cont_flush(). When this happen, the cont buffer
could not be used for new lines until the rest of the original
line is flushed. This might cause unnecessary fragmentation
of continuous lines.

But there is always only one partially flushed line. We do not
need any per line LOG_NOCONS flag. Instead, we could simply
remember the related sequence number.

Also we could construct a fake cont structure from the
information stored in the ring buffer.

Therefore, we could always flush the log buffer and make
the whole logic easier.

Finally, it makes perfect sense to use the time stamp
of the first continuous fragment. This is why cont_flush()
can be so trivial now.

Signed-off-by: Petr Mladek <pmladek@xxxxxxxx>
---
 kernel/printk/printk.c | 123 ++++++++++++++++++++-----------------------------
 1 file changed, 49 insertions(+), 74 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 71e96aae98e7..7d93ac263006 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -222,7 +222,6 @@ 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_CONT	= 8,	/* text is a fragment of a continuation line */
@@ -1522,11 +1521,12 @@ struct cont {
 	struct task_struct *owner;	/* task of first print*/
 	struct printk_log *msg;		/* more info about the stored text */
 	char *buf;			/* buffer to the stored text */
-	bool flushed:1;			/* buffer sealed and committed */
 };
 
 /* bytes written to console */
 static size_t cont_console_len;
+/* sequence number related to the partially flushed line */
+static u64 cont_console_seq;
 
 static struct printk_log cont_msg;
 static char cont_buf[LOG_LINE_MAX];
@@ -1538,38 +1538,16 @@ static struct cont cont = {
 
 static void cont_flush(enum log_flags flags)
 {
-	if (cont.flushed)
-		return;
 	if (cont.msg->text_len == 0)
 		return;
 
-	if (cont_console_len) {
-		/*
-		 * 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.msg->facility, cont.msg->level,
-			  flags | LOG_NOCONS, cont.msg->ts_nsec,
-			  NULL, 0, cont.buf, cont.msg->text_len);
-		cont.msg->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.msg->facility, cont.msg->level, flags, 0,
-			  NULL, 0, cont.buf, cont.msg->text_len);
-		cont.msg->text_len = 0;
-	}
+	log_store(cont.msg->facility, cont.msg->level, flags,
+		  cont.msg->ts_nsec, NULL, 0, cont.buf, cont.msg->text_len);
+	cont.msg->text_len = 0;
 }
 
 static bool cont_add(int facility, int level, const char *text, size_t len)
 {
-	if (cont.msg->text_len && cont.flushed)
-		return false;
-
 	/*
 	 * If ext consoles are present, flush and skip in-kernel
 	 * continuation.  See nr_ext_console_drivers definition.  Also, if
@@ -1587,8 +1565,6 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 		cont.msg->level = level;
 		cont.msg->ts_nsec = local_clock();
 		cont.msg->flags = 0;
-		cont.flushed = false;
-		cont_console_len = 0;
 	}
 
 	memcpy(cont.buf + cont.msg->text_len, text, len);
@@ -1600,31 +1576,29 @@ static bool cont_add(int facility, int level, const char *text, size_t len)
 	return true;
 }
 
-static size_t cont_print_text(char *text, size_t size)
+static size_t cont_print_text(struct cont *cont, char *text, size_t size)
 {
 	size_t textlen = 0;
 	size_t len;
 
 	if (cont_console_len == 0 && (console_prev & LOG_NEWLINE)) {
-		textlen += print_time(cont.msg->ts_nsec, text);
+		textlen += print_time(cont->msg->ts_nsec, text);
 		size -= textlen;
 	}
 
-	len = cont.msg->text_len - cont_console_len;
+	len = cont->msg->text_len - cont_console_len;
 	if (len > 0) {
 		if (len+1 > size)
 			len = size-1;
-		memcpy(text + textlen, cont.buf + cont_console_len, len);
+		memcpy(text + textlen, cont->buf + cont_console_len, len);
 		textlen += len;
-		cont_console_len = cont.msg->text_len;
+		cont_console_len = cont->msg->text_len;
+		cont_console_seq = console_seq;
 	}
 
-	if (cont.flushed) {
-		if (cont.msg->flags & LOG_NEWLINE)
-			text[textlen++] = '\n';
-		/* got everything, release buffer */
-		cont.msg->text_len = 0;
-	}
+	if (cont->msg->flags & LOG_NEWLINE)
+		text[textlen++] = '\n';
+
 	return textlen;
 }
 
@@ -1917,7 +1891,6 @@ static struct cont {
 	size_t len;
 	size_t cons;
 	u8 level;
-	bool flushed:1;
 } cont;
 static char *log_text(const struct printk_log *msg) { return NULL; }
 static char *log_dict(const struct printk_log *msg) { return NULL; }
@@ -2215,14 +2188,13 @@ static void console_cont_flush(char *text, size_t size)
 		goto out;
 
 	/*
-	 * We still queue earlier records, likely because the console was
-	 * busy. The earlier ones need to be printed before this one, we
-	 * did not flush any fragment so far, so just let it queue up.
+	 * If the partially printed line is already stored in
+	 * the ring buffer, it will be handled with the other lines.
 	 */
-	if (console_seq < log_next_seq && !cont_console_len)
+	if (console_seq < log_next_seq)
 		goto out;
 
-	len = cont_print_text(text, size);
+	len = cont_print_text(&cont, text, size);
 	raw_spin_unlock(&logbuf_lock);
 	stop_critical_timings();
 	call_console_drivers(cont.msg->level, NULL, 0, text, len);
@@ -2312,40 +2284,43 @@ again:
 		} else {
 			len = 0;
 		}
-skip:
+
 		if (console_seq == log_next_seq)
 			break;
 
 		msg = log_from_idx(console_idx);
-		if (msg->flags & LOG_NOCONS) {
-			/*
-			 * Skip record we have buffered and already printed
-			 * directly to the console when we received it.
-			 */
-			console_idx = log_next(console_idx);
-			console_seq++;
-			/*
-			 * We will get here again when we register a new
-			 * CON_PRINTBUFFER console. Clear the flag so we
-			 * will properly dump everything later.
-			 */
-			msg->flags &= ~LOG_NOCONS;
-			console_prev = msg->flags;
-			goto skip;
-		}
-
 		level = msg->level;
-		len += msg_print_text(msg, console_prev, false,
-				      text + len, sizeof(text) - len);
-		if (nr_ext_console_drivers) {
-			ext_len = msg_print_ext_header(ext_text,
-						sizeof(ext_text),
-						msg, console_seq, console_prev);
-			ext_len += msg_print_ext_body(ext_text + ext_len,
-						sizeof(ext_text) - ext_len,
-						log_dict(msg), msg->dict_len,
-						log_text(msg), msg->text_len);
+
+		/*
+		 * The line might be already partially printed from the cont
+		 * buffer. In this case, flush the rest using a fake
+		 * cont buffer.
+		 */
+		if (cont_console_len && cont_console_seq == console_seq) {
+			struct cont fake_cont;
+
+			fake_cont.owner = NULL;
+			fake_cont.msg = msg;
+			fake_cont.buf = log_text(msg);
+
+			len += cont_print_text(&fake_cont, text + len, sizeof(text) - len);
+
+			cont_console_len = 0;
+			cont_console_seq = 0;
+		} else {
+			len += msg_print_text(msg, console_prev, false,
+					      text + len, sizeof(text) - len);
+			if (nr_ext_console_drivers) {
+				ext_len = msg_print_ext_header(ext_text,
+							       sizeof(ext_text),
+							       msg, console_seq, console_prev);
+				ext_len += msg_print_ext_body(ext_text + ext_len,
+							      sizeof(ext_text) - ext_len,
+							      log_dict(msg), msg->dict_len,
+							      log_text(msg), msg->text_len);
+			}
 		}
+
 		console_idx = log_next(console_idx);
 		console_seq++;
 		console_prev = msg->flags;
-- 
1.8.5.6