Re: [RFC][PATCH v5 1/2] printk: Make printk() completely async

From: Byungchul Park
Date: Sun Mar 20 2016 - 20:07:07 EST


On Sun, Mar 20, 2016 at 11:13:10PM +0900, Sergey Senozhatsky wrote:
> @@ -1748,13 +1872,42 @@ asmlinkage int vprintk_emit(int facility, int level,
> dict, dictlen, text, text_len);
> }
>
> + /*
> + * By default we print message to console asynchronously so that kernel
> + * doesn't get stalled due to slow serial console. That can lead to
> + * softlockups, lost interrupts, or userspace timing out under heavy
> + * printing load.
> + *
> + * However we resort to synchronous printing of messages during early
> + * boot, when synchronous printing was explicitly requested by
> + * kernel parameter, or when console_verbose() was called to print
> + * everything during panic / oops.
> + */
> + if (!sync_print) {
> + if (in_sched) {
> + /*
> + * @in_sched messages may come too early, when we don't
> + * yet have @printk_kthread. We can't print deferred
> + * messages directly, because this may deadlock, route
> + * them via IRQ context.
> + */
> + __this_cpu_or(printk_pending,
> + PRINTK_PENDING_OUTPUT);
> + irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> + } else if (printk_kthread && !in_panic) {
> + /* Offload printing to a schedulable context. */
> + wake_up_process(printk_kthread);

It will not print the "lockup suspected" message at all, for e.g. rq->lock,
p->pi_lock and any locks which are used within wake_up_process().
Furtheremore, any printk() within wake_up_process() cannot work at all, as
well. It's too bad to use any functions potentially including printk()
inside of this critical section.

> + } else {
> + sync_print = true;
> + }
> + }
> +
> logbuf_cpu = UINT_MAX;
> raw_spin_unlock(&logbuf_lock);
> lockdep_on();
> local_irq_restore(flags);