Re: [RFC][PATCHv5 3/7] printk: introduce per-cpu safe_print seq buffer

[Petr Mladek]

On Thu 2016-12-01 22:55:42, Sergey Senozhatsky wrote:
> This patch extends the idea of NMI per-cpu buffers to regions
> that may cause recursive printk() calls and possible deadlocks.
> Namely, printk() can't handle printk calls from schedule code
> or printk() calls from lock debugging code (spin_dump() for instance);
> because those may be called with `sem->lock' already taken or any
> other `critical' locks (p->pi_lock, etc.). An example of deadlock
> can be
> 
>  vprintk_emit()
>   console_unlock()
>    up()                        << raw_spin_lock_irqsave(&sem->lock, flags);
>     wake_up_process()
>      try_to_wake_up()
>       ttwu_queue()
>        ttwu_activate()
>         activate_task()
>          enqueue_task()
>           enqueue_task_fair()
>            cfs_rq_of()
>             task_of()
>              WARN_ON_ONCE(!entity_is_task(se))
>               vprintk_emit()
>                console_trylock()
>                 down_trylock()
>                  raw_spin_lock_irqsave(&sem->lock, flags)
>                  ^^^^ deadlock
> 
> and some other cases.
> 
> Just like in NMI implementation, the solution uses a per-cpu
> `printk_func' pointer to 'redirect' printk() calls to a 'safe'
> callback, that store messages in a per-cpu buffer and flushes
> them back to logbuf buffer later.
> 
> Usage example:
> 
>  printk()
>   printk_safe_enter(flags)
>   //
>   //  any printk() call from here will endup in vprintk_safe(),
>   //  that stores messages in a special per-CPU buffer.
>   //
>   printk_safe_exit(flags)
> 
> The 'redirection' mechanism, though, has been reworked, as suggested
> by Petr Mladek. Instead of using a per-cpu @print_func callback we now
> keep a per-cpu printk-context variable and call either default or nmi
> vprintk function depending on its value. printk_nmi_entrer/exit and
> printk_safe_enter/exit, thus, just set/celar corresponding bits in
> printk-context functions.
> 
> The patch only adds printk_safe support, we don't use it yet.
> 
> diff --git a/kernel/printk/printk_safe.c b/kernel/printk/printk_safe.c
> index d5a4b6f..c22e286 100644
> --- a/kernel/printk/printk_safe.c
> +++ b/kernel/printk/printk_safe.c
> @@ -50,27 +49,26 @@ struct printk_safe_seq_buf {
>  	struct irq_work		work;	/* IRQ work that flushes the buffer */
>  	unsigned char		buffer[SAFE_LOG_BUF_LEN];
>  };
> +
> +static DEFINE_PER_CPU(struct printk_safe_seq_buf, safe_print_seq);
> +static DEFINE_PER_CPU(int, printk_context);
> +
> +#ifdef CONFIG_PRINTK_NMI
>  static DEFINE_PER_CPU(struct printk_safe_seq_buf, nmi_print_seq);
> +atomic_t nmi_message_lost;
> +#endif
>  
> -/*
> - * Safe printk() for NMI context. It uses a per-CPU buffer to
> - * store the message. NMIs are not nested, so there is always only
> - * one writer running. But the buffer might get flushed from another
> - * CPU, so we need to be careful.
> - */

We should keep/create a good description here because the function
has a non-trivial code. What about something like?

/*
 * Print a message into the given per-CPU buffer a safe way.
 * We need to be very careful here.
 *
 * First, the buffer might be flushed from another CPU at the same
 * time. This is solved by repeated write if the buffer length
 * is changed in the meantime.
 *
 * Second, the function might be called recursively if there
 * is an error message printed from this code. The recursion
 * will stop once the buffer is full. It is not ideal but it
 * should be enough to debug.
 */
> -static int vprintk_safe_nmi(const char *fmt, va_list args)
> +static int printk_safe_log_store(struct printk_safe_seq_buf *s,
> +		const char *fmt, va_list args)
>  {
> -	struct printk_safe_seq_buf *s = this_cpu_ptr(&nmi_print_seq);
> -	int add = 0;
> +	int add;
>  	size_t len;
>  
>  again:
>  	len = atomic_read(&s->len);
>  
> -	if (len >= sizeof(s->buffer)) {
> -		atomic_inc(&nmi_message_lost);
> -		return 0;
> -	}
> +	if (len >= sizeof(s->buffer))
> +		return -ENOSPC;

I was curious if we would really leave the cycle if the buffer
is full. And the check has to be

	if (len >= sizeof(s->buffer) - 1)

but it is handled in separate patch that I have already sent.

>  	/*
>  	 * Make sure that all old data have been read before the buffer was
> @@ -261,14 +263,95 @@ void printk_safe_flush_on_panic(void)
>  	printk_safe_flush();
>  }
>  
> +#ifdef CONFIG_PRINTK_NMI
> +/*
> + * Safe printk() for NMI context. It uses a per-CPU buffer to
> + * store the message. NMIs are not nested, so there is always only
> + * one writer running. But the buffer might get flushed from another
> + * CPU, so we need to be careful.
> + */

Hmm, I wanted to describe why we need another per-CPU buffer in NMI
and I am not sure that we really need it.

vprintk_safe_nmi() and vprintk_safe() will never run in parallel.
vprintk_safe_nmi() might be nested into vprintk_safe() but
printk_safe_log_store() is able to handle the nesting.

It is Friday evening, so I am not 100% sure. But if this is true,
we might simplify everything even more. Single per-cpu buffer and
single per-CPU nesting counter might be enough. I have to think
about it.

Best Regards,
Petr

PS: Heh, I was sad that all my comments looked like nitpicking.
But I was not able to help myself. And it seems that a good function
description might actually help to get a better code ;-)