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

[Joe Perches <joe@perches.com>]

(adding Kay Sievers who wrote most of this)

On Tue, 2016-08-23 at 00:40 +0900, Sergey Senozhatsky wrote:
> Hello,
> 
> 	RFC and POC
> 
> 	Petr, I took a very quick look at your series [1]. I think it
> won't work on some of the setups I'm toying with, where multiple CPUs
> can do a simultaneous pr_cont() output. What do you about the following
> approach?
> 
> (it's not really tested, I just finished writing the code. Will test it
> more tomorrow. But I kinda like that at this point it removes almost
> twice the code it adds, which is probably because I missed some cases).
> 
> ===8<====
> 
> 	This patch changes pr_cont buffer to be a per-cpu variable, so
> CPUs don't compete anymore for a single cont buffer. Thus we minimize
> the possibility of preliminary/forced flushes of incomplete pr_cont
> buffers.
> 	The basic idea is that the first time CPU issues a pr_cont or
> !LOG_NEWLINE output it starts a non-preemptible region which ends when
> CPUs writes a NEW_LINE symbol.
> Schematically:
> 
> 	pr_cont()			/* preempt_disable() */
> 		<< write to this_cpu_ptr cont buffer
> 	pr_cont()
> 		<< write to this_cpu_ptr cont buffer
> 	...
> 	pr_cont("\n")			/* log_store(). preempt_enable() */
> 
> 	The only possible case (unless I'm missing something) for a
> race is when IRQ is issuing a pr_cont() output, interrupting the CPU
> which is already in the middle of pr_cont() printing.
> 
> 
> [1]: http://marc.info/?l=linux-kernel&m=146860197621876
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/printk.c | 193 ++++++++++++++++---------------------------------
>  1 file changed, 64 insertions(+), 129 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 0d3e026..2bf8b85 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,22 @@ asmlinkage int vprintk_emit(int facility, int level,
>  		lflags |= LOG_PREFIX|LOG_NEWLINE;
>  
>  	if (!(lflags & LOG_NEWLINE)) {
> +		if (!this_cpu_read(cont_printing)) {
> +			bool unsafe_pr_cont = preemptible() &&
> +				!rcu_preempt_depth();
> +
> +			if (unsafe_pr_cont) {
> +				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 +1860,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 +1873,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 +2021,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 +2313,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 +2366,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 +2395,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 +2403,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 +2504,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