Re: [PATCH][RFC] printk: make pr_cont buffer per-cpu

[Sergey Senozhatsky]

On (08/23/16 00:40), Sergey Senozhatsky wrote:
> 	RFC and POC
[..]
>  	if (!(lflags & LOG_NEWLINE)) {
> +		if (!this_cpu_read(cont_printing)) {
> +			bool unsafe_pr_cont = preemptible() &&
> +				!rcu_preempt_depth();

d'oh, how did it get there... this simply disables per-cpu pr_cont(). sorry.
what I wanted to do there is to add a dependency on system_state:

	if (!this_cpu_read(cont_printing) && (system_state == SYSTEM_RUNNING)) {
		....
	}

one of the problems is x86 cpu_up, which does pr_cont()-s in announce_cpu()
and then explicitly calls shedule() in do_boot_cpu(). so we have a

	pr_cont();
		shedule();
	pr_cont();
		shedule();
	...
	pr_cont("\n");

pattern. which is probably OK, given that we are in a non-smp mode yet. thus
I'm enabling per-cpu pr_cont buffers only when the system is SYSTEM_RUNNING.

===8<====

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@xxxxxxxxx>
---
 kernel/printk/printk.c | 190 ++++++++++++++++---------------------------------
 1 file changed, 61 insertions(+), 129 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0d3e026..7f48cbf 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -337,10 +337,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_CONT	= 8,	/* text is a fragment of a continuation line */
+	LOG_NEWLINE	= 1,	/* text ended with a newline */
+	LOG_PREFIX	= 2,	/* text started with a prefix */
+	LOG_CONT	= 4,	/* text is a fragment of a continuation line */
 };
 
 struct printk_log {
@@ -1661,108 +1660,62 @@ static inline void printk_delay(void)
  * though, are printed immediately to the consoles to ensure everything has
  * reached the console in case of a kernel crash.
  */
-static struct cont {
+struct cont {
 	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 facility of first message */
 	enum log_flags flags;		/* prefix, newline flags */
-	bool flushed:1;			/* buffer sealed and committed */
-} cont;
+};
+
+static DEFINE_PER_CPU(struct cont, pcpu_cont);
+static DEFINE_PER_CPU(bool, cont_printing);
 
-static void cont_flush(enum log_flags flags)
+static void cont_flush(struct cont *cont, enum log_flags flags)
 {
-	if (cont.flushed)
-		return;
-	if (cont.len == 0)
+	if (cont->len == 0)
 		return;
 
-	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,
-			  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,
-			  NULL, 0, cont.buf, cont.len);
-		cont.len = 0;
-	}
+	/*
+	 * 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,
+		  NULL, 0, cont->buf, cont->len);
+	cont->len = 0;
 }
 
 static bool cont_add(int facility, int level, const char *text, size_t len)
 {
-	if (cont.len && cont.flushed)
-		return false;
+	struct cont *cont = this_cpu_ptr(&pcpu_cont);
 
 	/*
 	 * If ext consoles are present, flush and skip in-kernel
 	 * continuation.  See nr_ext_console_drivers definition.  Also, if
 	 * the line gets too long, split it up in separate records.
 	 */
-	if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) {
-		cont_flush(LOG_CONT);
+	if (nr_ext_console_drivers || cont->len + len > sizeof(cont->buf)) {
+		cont_flush(cont, LOG_CONT);
 		return false;
 	}
 
-	if (!cont.len) {
-		cont.facility = facility;
-		cont.level = level;
-		cont.owner = current;
-		cont.ts_nsec = local_clock();
-		cont.flags = 0;
-		cont.cons = 0;
-		cont.flushed = false;
+	if (!cont->len) {
+		cont->facility = facility;
+		cont->level = level;
+		cont->ts_nsec = local_clock();
+		cont->flags = 0;
 	}
 
-	memcpy(cont.buf + cont.len, text, len);
-	cont.len += len;
+	memcpy(cont->buf + cont->len, text, len);
+	cont->len += len;
 
-	if (cont.len > (sizeof(cont.buf) * 80) / 100)
-		cont_flush(LOG_CONT);
+	if (cont->len > (sizeof(cont->buf) * 80) / 100)
+		cont_flush(cont, LOG_CONT);
 
 	return true;
 }
 
-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);
-		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.flushed) {
-		if (cont.flags & LOG_NEWLINE)
-			text[textlen++] = '\n';
-		/* got everything, release buffer */
-		cont.len = 0;
-	}
-	return textlen;
-}
-
 asmlinkage int vprintk_emit(int facility, int level,
 			    const char *dict, size_t dictlen,
 			    const char *fmt, va_list args)
@@ -1779,6 +1732,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 	int printed_len = 0;
 	int nmi_message_lost;
 	bool in_sched = false;
+	struct cont *cont;
 
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
@@ -1789,6 +1743,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 	printk_delay();
 
 	local_irq_save(flags);
+	cont = this_cpu_ptr(&pcpu_cont);
 	this_cpu = smp_processor_id();
 
 	/*
@@ -1878,12 +1833,19 @@ asmlinkage int vprintk_emit(int facility, int level,
 		lflags |= LOG_PREFIX|LOG_NEWLINE;
 
 	if (!(lflags & LOG_NEWLINE)) {
+		if (!this_cpu_read(cont_printing)) {
+			if (system_state == SYSTEM_RUNNING) {
+				this_cpu_write(cont_printing, true);
+				preempt_disable();
+			}
+		}
+
 		/*
 		 * 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 && (lflags & LOG_PREFIX))
+			cont_flush(cont, LOG_NEWLINE);
 
 		/* buffer line if possible, otherwise store it right away */
 		if (cont_add(facility, level, text, text_len))
@@ -1895,6 +1857,11 @@ asmlinkage int vprintk_emit(int facility, int level,
 	} else {
 		bool stored = false;
 
+		if (this_cpu_read(cont_printing)) {
+			this_cpu_write(cont_printing, false);
+			preempt_enable();
+		}
+
 		/*
 		 * If an earlier newline was missing and it was the same task,
 		 * either merge it with the current buffer and flush, or if
@@ -1903,11 +1870,11 @@ asmlinkage int vprintk_emit(int facility, int level,
 		 * If the preceding printk was from a different task and missed
 		 * a newline, flush and append the newline.
 		 */
-		if (cont.len) {
-			if (cont.owner == current && !(lflags & LOG_PREFIX))
+		if (cont->len) {
+			if (!(lflags & LOG_PREFIX))
 				stored = cont_add(facility, level, text,
 						  text_len);
-			cont_flush(LOG_NEWLINE);
+			cont_flush(cont, LOG_NEWLINE);
 		}
 
 		if (stored)
@@ -2051,7 +2018,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; }
@@ -2344,42 +2310,6 @@ static inline int can_use_console(void)
 	return cpu_online(raw_smp_processor_id()) || have_callable_console();
 }
 
-static void console_cont_flush(char *text, size_t size)
-{
-	unsigned long flags;
-	size_t len;
-
-	raw_spin_lock_irqsave(&logbuf_lock, flags);
-
-	if (!cont.len)
-		goto out;
-
-	if (suppress_message_printing(cont.level)) {
-		cont.cons = cont.len;
-		if (cont.flushed)
-			cont.len = 0;
-		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 (console_seq < log_next_seq && !cont.cons)
-		goto out;
-
-	len = cont_print_text(text, size);
-	raw_spin_unlock(&logbuf_lock);
-	stop_critical_timings();
-	call_console_drivers(cont.level, NULL, 0, text, len);
-	start_critical_timings();
-	local_irq_restore(flags);
-	return;
-out:
-	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
-}
-
 /**
  * console_unlock - unlock the console system
  *
@@ -2433,9 +2363,6 @@ again:
 		return;
 	}
 
-	/* flush buffered message fragment immediately to console */
-	console_cont_flush(text, sizeof(text));
-
 	for (;;) {
 		struct printk_log *msg;
 		size_t ext_len = 0;
@@ -2465,8 +2392,7 @@ skip:
 
 		msg = log_from_idx(console_idx);
 		level = msg->level;
-		if ((msg->flags & LOG_NOCONS) ||
-				suppress_message_printing(level)) {
+		if (suppress_message_printing(level)) {
 			/*
 			 * Skip record we have buffered and already printed
 			 * directly to the console when we received it, and
@@ -2474,12 +2400,6 @@ skip:
 			 */
 			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;
 		}
@@ -2581,6 +2501,18 @@ void console_unblank(void)
  */
 void console_flush_on_panic(void)
 {
+	unsigned long flags;
+	unsigned int cpu;
+
+	/*
+	 * Flush the cont messages; no matter complete
+	 * or incomplete.
+	 */
+	local_irq_save(flags);
+	for_each_online_cpu(cpu)
+		cont_flush(per_cpu_ptr(&pcpu_cont, cpu), LOG_NEWLINE);
+	local_irq_restore(flags);
+
 	/*
 	 * If someone else is holding the console lock, trylock will fail
 	 * and may_schedule may be set.  Ignore and proceed to unlock so
-- 
2.9.3