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

[Petr Mladek <pmladek@suse.com>]

On Tue 2016-03-22 02:25:29, Sergey Senozhatsky wrote:
> From: Jan Kara <jack@suse.cz>
> 
> This patch makes printk() completely asynchronous (similar to what
> printk_deferred() did until now). It appends message to the kernel
> printk buffer and wake_up()s a special dedicated kthread to do the
> printing to console. This has the advantage that printing always happens
> from a schedulable contex and thus we don't lockup any particular CPU or
> even interrupts. Also it has the advantage that printk() is fast and
> thus kernel booting is not slowed down by slow serial console.
> Disadvantage of this method is that in case of crash there is higher
> chance that important messages won't appear in console output (we may
> need working scheduling to print message to console). We somewhat
> mitigate this risk by switching printk to the original method of
> immediate printing to console if oops is in progress.  Also for
> debugging purposes we provide printk.synchronous kernel parameter which
> resorts to the original printk behavior.
> 
> printk() is expected to work under different conditions and in different
> scenarios, including corner cases of OOM when all of the workers are busy
> (e.g. allocating memory), thus printk() uses its own dedicated printing
> kthread, rather than relying on workqueue (even with WQ_MEM_RECLAIM bit
> set we potentially can receive delays in printing until workqueue
> declares a ->mayday, as noted by Tetsuo Handa). Another thing to mention,
> is that deferred printk() messages may appear before printing kthread
> created, so in the very beginning we have to print deferred messages
> the old way -- via IRQs.
> 
> Signed-off-by: Jan Kara <jack@suse.cz>
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  Documentation/kernel-parameters.txt |  10 ++
>  kernel/printk/printk.c              | 209 ++++++++++++++++++++++++++----------
>  2 files changed, 161 insertions(+), 58 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index e38579d..99c105d6 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> +/*
> + * Delayed printk version, for scheduler-internal messages:
> + */
> +#define PRINTK_PENDING_WAKEUP	(1<<0)
> +#define PRINTK_PENDING_OUTPUT	(1<<1)
> +
> +static DEFINE_PER_CPU(int, printk_pending);
> +
> +static void wake_up_klogd_work_func(struct irq_work *irq_work)
> +{
> +	int pending = __this_cpu_xchg(printk_pending, 0);
> +
> +	if (pending & PRINTK_PENDING_OUTPUT) {
> +		/* If trylock fails, someone else is doing the printing */
> +		if (console_trylock())
> +			console_unlock();

This is called from IRQ context and thus keeps the original problem
for printk_deferred(). We should try to
wake_up_process(printk_kthread) when allowed.

	if (pending & PRINTK_PENDING_OUTPUT) {
		if (printk_sync || !printk_kthread) {
			/* If trylock fails, someone else is printing. */
			if (console_trylock())
				console_unlock();
		} else {
			wake_up_process(printk_kthread);
		}
	}


> @@ -1609,6 +1709,8 @@ asmlinkage int vprintk_emit(int facility, int level,
>  			    const char *dict, size_t dictlen,
>  			    const char *fmt, va_list args)
>  {
> +	/* cpu currently holding logbuf_lock in this function */
> +	static unsigned int logbuf_cpu = UINT_MAX;
>  	static bool recursion_bug;
>  	static char textbuf[LOG_LINE_MAX];
>  	char *text = textbuf;
> @@ -1619,12 +1721,21 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	int printed_len = 0;
>  	int nmi_message_lost;
>  	bool in_sched = false;
> -	/* cpu currently holding logbuf_lock in this function */
> -	static unsigned int logbuf_cpu = UINT_MAX;
> +	bool in_panic = console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH;
> +	bool sync_print = printk_sync;

I still think that this local variable adds more mess than good.
Please, rename it to do_printk_sync at least. It will a poor human
to distinguish it from the global one ;-)

I still hope that we could get rid if it, see below.

> +
> +	/* disable async printk */
> +	if (in_panic)
> +		printk_sync = true;
>  
>  	if (level == LOGLEVEL_SCHED) {
>  		level = LOGLEVEL_DEFAULT;
> +		/*
> +		 * Deferred sched messages must not be printed
> +		 * synchronously regardless the @printk_sync or @in_panic.
> +		 */
>  		in_sched = true;
> +		sync_print = false;
>  	}
>  
>  	boot_delay_msec(level);
> @@ -1657,6 +1768,14 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	raw_spin_lock(&logbuf_lock);
>  	logbuf_cpu = this_cpu;
>  
> +	/*
> +	 * Set printing_func() sleep condition early, under the @logbuf_lock.
> +	 * So printing kthread (if RUNNING) will go to console_lock() and spin
> +	 * on @logbuf_lock.
> +	 */
> +	if (!printk_sync)
> +		need_flush_console = true;

We set this variable for each call and also when printk_kthread is
NULL or when sync_printk is false.

We migth want to clear it also from console_unlock(). I think that
a good place would be in the check:

	raw_spin_lock(&logbuf_lock);
	retry = console_seq != log_next_seq;
	raw_spin_unlock_irqrestore(&logbuf_lock, flags);


>  	if (unlikely(recursion_bug)) {
>  		static const char recursion_msg[] =
>  			"BUG: recent printk recursion!";
> @@ -1762,10 +1881,38 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	logbuf_cpu = UINT_MAX;
>  	raw_spin_unlock(&logbuf_lock);
>  	lockdep_on();
> +	/*
> +	 * 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);
> +		} else {
> +			sync_print = true;
> +		}
> +	}
>  	local_irq_restore(flags);

Please, what is the exact reason to call the above stuff before
we release IRQs here? I guess that it is related to the discussions
about possible lock debugging, infinite loops, ...

I wonder how the disabled IRQs help here. It is very likely that I
miss something.

In each case, irq_work_queue() is lock-less and was used with IRQs
enabled before.

So, it might be related to wake_up_process(). It takes a lock but
using

       raw_spin_lock_irqsave(&p->pi_lock, flags);

, so it disables IRQs in the critical section. Do we need to guard
it in between?

I think that you actually wanted to disable lockdep or any other lock
debugging, instead.

I wonder if the following code would do the job and is better readable
to others.

	/*
	 * 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 (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));
		goto out;
	}

	/* Avoid printk recursion */
	lockdep_off();

	if  (printk_kthread && !in_panic) {
		/* Offload printing to a schedulable context. */
		wake_up_process(printk_kthread);
		goto out_lockdep;
	} else {
		/*
		 * Try to acquire and then immediately release the console
		 * semaphore.  The release will print out buffers and wake up
		 * /dev/kmsg and syslog() users.
		 */
		if (console_trylock())
			console_unlock();
	}

	lockdep_on();


I do not say that it is a "dream-of-like" code. One important thing for
me is that it does not use "sync_printk" variable.

You original code modified "sync_printk" according to "in_sched" and
"in_panic" variables earlier in vprintk_emit. Then it again checked
all three variables here which produced strange twists in my head ;-)


Best regards,
Petr