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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-Id: <20150918151459.a73804a65137f3e1049b8dd7@linux-foundation.org>
Date:	Fri, 18 Sep 2015 15:14:59 -0700
From:	Andrew Morton <akpm@...ux-foundation.org>
To:	Jan Kara <jack@...e.com>
Cc:	LKML <linux-kernel@...r.kernel.org>, pmladek@...e.com,
	rostedt@...dmis.org, Gavin Hu <gavin.hu.2010@...il.com>,
	KY Srinivasan <kys@...rosoft.com>, Jan Kara <jack@...e.cz>
Subject: Re: [PATCH 1/4] printk: Hand over printing to console if printing
 too long

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

> From: Jan Kara <jack@...e.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;
> +}
>
> ...
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/