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

From: Petr Mladek
Date: Fri Dec 09 2016 - 11:46:33 EST


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 ;-)