Messages in this thread | | | Date | Wed, 15 Jan 2014 14:23:47 -0800 | From | Andrew Morton <> | Subject | Re: [PATCH 9/9] printk: Hand over printing to console if printing too long |
| |
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; > +} > + > > ... >
| |