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

[Petr Mladek <pmladek@suse.com>]

On Tue 2016-08-23 14:18:31, Sergey Senozhatsky wrote:
> 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@gmail.com>
> ---
>  kernel/printk/printk.c | 190 ++++++++++++++++---------------------------------
>  1 file changed, 61 insertions(+), 129 deletions(-)

The simplification is nice but...

> 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
> -	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();
> +			}
> +		}

I am afraid that this is not acceptable. It means that printk() will have
an unexpected side effect. The missing "\n" at the end of a printed
string would disable preemption. See below for more.

> +
>  		/*
>  		 * 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 "\n" is missing by mistake. The preemption will not get enabled and
the task would stall.

Note that printk() is heavily used when debugging kernel. People would
hate us if every n-th build is unusable because of forgotten '\n'.

>  		/*
>  		 * If an earlier newline was missing and it was the same task,
>  		 * either merge it with the current buffer and flush, or if
> @@ -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);
> -}

This is a trade off between a "perfect" output and an early output.
I do not feel like deciding about it.

In each case, a buggy line (without \n") would stay "hidden" in
the per-CPU buffer until another line with "\n" is printed
on the given CPU.

>  /**
>   * 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;

I think that cont lines should be a corner case. There should be only
a limited use of them. We should not make too complicated things to
support them. Also printk() must not get harder to use because of them.
I still see a messed output rather as a cosmetic problem in compare with
possible possible deadlocks or hung tasks.

Best Regards,
Petr