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

From: Andrew Morton
Date: Fri Sep 18 2015 - 18:15:07 EST


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

> From: Jan Kara <jack@xxxxxxx>
>
> 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@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/