Re: [PATCH 1/4] printk: Hand over printing to console if printing too long

[Andrew Morton <akpm@linux-foundation.org>]

On Wed, 19 Aug 2015 17:38:28 +0200 Jan Kara <jack@suse.com> wrote:

> From: Jan Kara <jack@suse.cz>
> 
> Currently, console_unlock() prints messages from kernel printk buffer to
> console while the buffer is non-empty. When serial console is attached,
> printing is slow and thus other CPUs in the system have plenty of time
> to append new messages to the buffer while one CPU is printing. Thus the
> CPU can spend unbounded amount of time doing printing in console_unlock().
> This is especially serious problem if the printk() calling
> console_unlock() was called with interrupts disabled.
> 
> In practice users have observed a CPU can spend tens of seconds printing
> in console_unlock() (usually during boot when hundreds of SCSI devices
> are discovered) resulting in RCU stalls (CPU doing printing doesn't
> reach quiescent state for a long time), softlockup reports (IPIs for the
> printing CPU don't get served and thus other CPUs are spinning waiting
> for the printing CPU to process IPIs), and eventually a machine death
> (as messages from stalls and lockups append to printk buffer faster than
> we are able to print). So these machines are unable to boot with serial
> console attached. Also during artificial stress testing SATA disk
> disappears from the system because its interrupts aren't served for too
> long.
> 
> This patch implements a mechanism where after printing specified number
> of characters (tunable as a kernel parameter printk.offload_chars), CPU
> doing printing asks for help by waking up one of dedicated kthreads.  As
> soon as the printing CPU notices kthread got scheduled and is spinning
> on print_lock dedicated for that purpose, it drops console_sem,
> print_lock, and exits console_unlock(). Kthread then takes over printing
> instead. This way no CPU should spend printing too long even if there
> is heavy printk traffic.
> 
> ...
>
> @@ -2230,6 +2292,8 @@ void console_unlock(void)
>  	unsigned long flags;
>  	bool wake_klogd = false;
>  	bool retry;
> +	bool hand_over = false;
> +	int printed_chars = 0;
>  
>  	if (console_suspended) {
>  		up_console_sem();
> @@ -2241,12 +2305,18 @@ void console_unlock(void)
>  	/* flush buffered message fragment immediately to console */
>  	console_cont_flush(text, sizeof(text));
>  again:
> +	spin_lock(&print_lock);

I'm surprised this isn't spin_lock_irqsave().  How come this isn't
deadlockable?

>  	for (;;) {
>  		struct printk_log *msg;
>  		size_t ext_len = 0;
>  		size_t len;
>  		int level;
>  
> +		if (cpu_stop_printing(printed_chars)) {
> +			hand_over = true;
> +			break;
> +		}
> +
>  		raw_spin_lock_irqsave(&logbuf_lock, flags);
>  		if (seen_seq != log_next_seq) {
>  			wake_klogd = true;
>
> ...
>
> +/* Kthread which takes over printing from a CPU which asks for help */
> +static int printing_task(void *arg)
> +{
> +	DEFINE_WAIT(wait);
> +
> +	while (1) {
> +		prepare_to_wait_exclusive(&print_queue, &wait,
> +					  TASK_INTERRUPTIBLE);
> +		schedule();
> +		finish_wait(&print_queue, &wait);
> +		preempt_disable();

I don't understand the preempt_disable().  Code comment, please?

> +		atomic_inc(&printing_tasks_spinning);
> +		/*
> +		 * Store printing_tasks_spinning value before we spin. Matches
> +		 * the barrier in cpu_stop_printing().
> +		 */
> +		smp_mb__after_atomic();
> +		/*
> +		 * Wait for currently printing thread to complete. We spin on
> +		 * print_lock instead of waiting on console_sem since we don't
> +		 * want to sleep once we got scheduled to make sure we take
> +		 * over printing without depending on the scheduler.
> +		 */
> +		spin_lock(&print_lock);
> +		atomic_dec(&printing_tasks_spinning);
> +		spin_unlock(&print_lock);
> +		if (console_trylock())
> +			console_unlock();
> +		preempt_enable();
> +	}
> +	return 0;
> +}
>
> ...
>