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

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

On Mon, 23 Dec 2013 21:39:30 +0100 Jan Kara <jack@suse.cz> wrote:

> 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 setting a 'hand over' state. The CPU
> still keeps printing until another CPU running printk() or a CPU being
> pinged by an IPI comes and takes over printing.  This way no CPU should
> spend printing too long if there is heavy printk traffic.
> 
> ...
>
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -84,6 +84,45 @@ static DEFINE_SEMAPHORE(console_sem);
>  struct console *console_drivers;
>  EXPORT_SYMBOL_GPL(console_drivers);
>  
> +/*
> + * State of printing to console.
> + * 0 - noone is printing
> + * 1 - the CPU doing printing is happy doing so
> + * 2 - the printing CPU wants some other CPU to take over
> + * 3 - some CPU is waiting to take over printing
> + *
> + * Allowed state transitions are:
> + * 0 -> 1, 1 -> 0, 1 -> 2, 2 -> 0, 2 -> 3, 3 -> 0
> + * All state transitions except for 2 -> 3 are done by the holder of
> + * console_sem. Transition 2 -> 3 happens using cmpxchg from a task not owning
> + * console_sem. Thus it can race with other state transitions from state 2.
> + * However these races are harmless since the only transition we can race with
> + * is 2 -> 0. If cmpxchg comes after we have moved from state 2, it does
> + * nothing and we end in state 0. If cmpxchg comes before, we end in state 0 as
> + * desired.
> + */

This comment is great, but would be much better if "0"-"3" were
replaced with their PS_foo representations.

The locking issue is regrettable.  What's the problem with getting full
console_sem coverage?

The mixture of cmpxchg with non-atomic reads and writes makes things
significantly more difficult.

> +static enum {
> +	PS_NONE,
> +	PS_PRINTING,
> +	PS_HANDOVER,
> +	PS_WAITING
> +} printing_state;
> +/* CPU which is handing over printing */
> +static unsigned int hand_over_cpu;
> +/*
> + * Structure for IPI to hand printing to another CPU. We have actually two
> + * structures for the case we need to send IPI from an IPI handler...
> + */
> +static void printk_take_over(void *info);
> +static struct call_single_data hand_over_csd[2] = {
> +	{ .func = printk_take_over, },
> +	{ .func = printk_take_over, }
> +};
> +/* Index of csd to use for sending IPI now */
> +static int current_csd;

Locking for this?

> +/* Set if there is IPI pending to take over printing */
> +static bool printk_ipi_sent;

And this?

>  #ifdef CONFIG_LOCKDEP
>  static struct lockdep_map console_lock_dep_map = {
>  	.name = "console_lock"
> 
> ...
>
> @@ -1342,8 +1393,40 @@ static int console_trylock_for_printk(void)
>  {
>  	unsigned int cpu = smp_processor_id();
>  
> -	if (!console_trylock())
> -		return 0;
> +	if (!console_trylock()) {
> +		int state;
> +
> +		if (printing_state != PS_HANDOVER || console_suspended)
> +			return 0;
> +		smp_rmb();	/* Paired with smp_wmb() in cpu_stop_printing */
> +		/*
> +		 * Avoid deadlocks when CPU holding console_sem takes an
> +		 * interrupt which does printk.
> +		 */
> +		if (hand_over_cpu == cpu)
> +			return 0;
> +
> +		state = cmpxchg(&printing_state, PS_HANDOVER, PS_WAITING);
> +		if (state != PS_HANDOVER)
> +			return 0;
> +
> +		/*
> +		 * Since PS_HANDOVER state is set only in console_unlock()
> +		 * we shouldn't spin for long here.

"shouldn't" is ambiguous here.  Suggest replacing it with "won't".

>		    And we cannot sleep because
> +		 * the printk() might be called from atomic context.
> +		 */

console_trylock_for_printk() is called under logbuf_lock, isn't it? 
We're atomic here regardless of the printk() caller's state.  That's
why smp_processor_id() was OK.

> +		while (!console_trylock()) {
> +			if (console_suspended)
> +				return 0;
> +			/*
> +			 * Someone else took console_sem? Exit as we don't want
> +			 * to spin for a long time here.
> +			 */
> +			if (ACCESS_ONCE(printing_state) == PS_PRINTING)

Is this appropriate use of ACCESS_ONCE?  What is the ACCESS_ONCE()
trying to achieve?

> +				return 0;
> +			__delay(1);
> +		}
> +	}
>  	/*
>  	 * If we can't use the console, we need to release the console
>  	 * semaphore by hand to avoid flushing the buffer. We need to hold the
> 
> ...
>
> @@ -2005,15 +2091,77 @@ out:
>  	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
>  }
>  
> +/* Handler for IPI to take over printing from another CPU */
> +static void printk_take_over(void *info)
> +{
> +	/*
> +	 * We have to clear printk_ipi_sent only after we succeed / fail the
> +	 * trylock. That way we make sure there is at most one IPI spinning
> +	 * on console_sem and thus we cannot deadlock on csd_lock
> +	 */
> +	if (console_trylock_for_printk()) {

erk, scared.  We're in interrupt and console_trylock_for_printk() can
loop for arbitrarily long durations.  printk_take_over() is called
asynchronously and the system could be in any state at all.

> +		printk_ipi_sent = false;
> +		/* Switch csd as the current one is locked until we finish */
> +		current_csd ^= 1;

So current_csd is protected by console_sem?  As is printk_ipi_sent?

> +		console_unlock();

So it's via this console_unlock() that the current CPU starts printing?
Within IPI context?  It's worth documenting this a bit.

> +	} else
> +		printk_ipi_sent = false;
> +}
> +
> +/*
> + * Returns true iff there is other cpu waiting to take over printing. This
> + * function also takes are of changing printing_state if we want to hand over

"care"

> + * printing to some other cpu.
> + */
> +static bool cpu_stop_printing(int printed_chars)
> +{
> +	cpumask_var_t mask;
> +
> +	/* Oops? Print everything now to maximize chances user will see it */
> +	if (oops_in_progress)
> +		return false;
> +	/* Someone is waiting. Stop printing. */
> +	if (printing_state == PS_WAITING)
> +		return true;
> +	if (!printk_offload_chars || printed_chars <= printk_offload_chars)

Off-by-one?  Should that be "<"?

> +		return false;
> +	if (printing_state == PS_PRINTING) {
> +		hand_over_cpu = smp_processor_id();
> +		/* Paired with smp_rmb() in console_trylock_for_printk() */
> +		smp_wmb();
> +		printing_state = PS_HANDOVER;

So console_sem must be held by the caller?  Worth documenting this.

Again, the race with cmpxchg is worrisome.  Perhaps document its
(non-)effects here?

> +		return false;
> +	}
> +	/*
> +	 * We ping another CPU with IPI only if noone took over printing for a
> +	 * long time - we prefer other printk() to take over printing since it
> +	 * has chances to happen from a better context than IPI handler.
> +	 */
> +	if (!printk_ipi_sent && printed_chars > 2 * printk_offload_chars) {

What is the "2 *" doing?  I don't recall seeing a description of this.

> +		struct call_single_data *csd = &hand_over_csd[current_csd];

I didn't really understand why we need two call_single_data's.

> +
> +		/* Ping another cpu to take printing from us */
> +		cpumask_copy(mask, cpu_online_mask);
> +		cpumask_clear_cpu(hand_over_cpu, mask);
> +		if (!cpumask_empty(mask)) {

So what happens if this was the only online CPU?  We blow a chunk of
CPU time in cpu_stop_printing() for each printed char?  Not a problem I
guess.

> +			printk_ipi_sent = true;
> +			__smp_call_function_any(mask, csd, 0);

The IPI is sent to all other online CPUs.  I wonder if that was overkill.

> +		}
> +	}
> +	return false;
> +}
> +
> 
> ...
>