printk: Softlockup avoidance

From: Jan Kara <[email protected]>

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.

...

kernel/printk/printk.c +2 -0

@@ -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();

kernel/printk/printk.c +6 -0

 	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 */

kernel/printk/printk.c +21 -0

+		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;
+}
 
...

Quoted 40 lines · On Wed, 19 Aug 2015 17:38:28 +0200 Jan Kara <[email protected]> wrote:

From: Jan Kara <[email protected]>

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.

...

kernel/printk/printk.c +2 -0

@@ -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;
 

kernel/printk/printk.c void console_unlock(void) · line 2308

Quoted 7 lines

kernel/printk/printk.c +1 -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?

Quoted 17 lines

kernel/printk/printk.c +5 -0

 	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;
 
...

kernel/printk/printk.c int unregister_console(struct console *console) · line 2750

Quoted 11 lines

kernel/printk/printk.c +11 -0

+/* 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?

Quoted 25 lines

kernel/printk/printk.c +21 -0

+		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;
+}
 
...

From: Jan Kara <[email protected]>

When there are lots of messages accumulated in printk buffer, printing them (especially over serial console) can take a long time (tens of seconds). stop_machine() will effectively make all cpus spin in multi_cpu_stop() waiting for the CPU doing printing to print all the messages which triggers NMI softlockup watchdog and RCU stall detector which add even more to the messages to print. Since machine doesn't do anything (except serving interrupts) during this time, also network connections are dropped and other disturbances may happen.

Paper over the problem by waiting for printk buffer to be empty before starting to stop CPUs. In theory a burst of new messages can be appended to the printk buffer before CPUs enter multi_cpu_stop() so this isn't a 100% solution but it works OK in practice and I'm not aware of a reasonably simple better solution.

kernel/printk/printk.c +9 -0

+		if (!retry || console_suspended)
+			break;
+		/* Cycle console_sem to wait for outstanding printing */
+		console_lock();
+		console_unlock();
+	}
+}
+
+/*
  * Prevent further output on the passed console device so that (for example)
  * serial drivers can disable console output before suspending a port, and can
  * re-enable output afterwards.

kernel/stop_machine.c +1 -0

index fd643d8c4b42..016d34621d2e 100644
@@ -21,6 +21,7 @@
 #include <linux/smpboot.h>
 #include <linux/atomic.h>
 #include <linux/lglock.h>
+#include <linux/console.h>
 
 /*
  * Structure to determine completion condition and record errors.  May

kernel/stop_machine.c +0 -0

 	/* Set the initial state and stop all online cpus. */
 	set_state(&msdata, MULTI_STOP_PREPARE);
 	return stop_cpus(cpu_online_mask, multi_cpu_stop, &msdata);

Quoted 11 lines · On Wed, 19 Aug 2015 17:38:30 +0200 Jan Kara <[email protected]> wrote:

From: Jan Kara <[email protected]>

When there are lots of messages accumulated in printk buffer, printing them (especially over serial console) can take a long time (tens of seconds). stop_machine() will effectively make all cpus spin in multi_cpu_stop() waiting for the CPU doing printing to print all the messages which triggers NMI softlockup watchdog and RCU stall detector which add even more to the messages to print. Since machine doesn't do anything (except serving interrupts) during this time, also network connections are dropped and other disturbances may happen.

Quoted 5 lines

Paper over the problem by waiting for printk buffer to be empty before starting to stop CPUs. In theory a burst of new messages can be appended to the printk buffer before CPUs enter multi_cpu_stop() so this isn't a 100% solution but it works OK in practice and I'm not aware of a reasonably simple better solution.

Confused. Why don't patches 1 and 2 already fix this problem?

Quoted 5 lines

...

(quoted diff) +0 -0

@@ -2489,6 +2489,28 @@ struct tty_driver *console_device(int *index)
 }
 

kernel/printk/printk.c struct tty_driver *console_device(int *index) · line 2496

Quoted 6 lines

kernel/printk/printk.c +5 -0

 /*
+ * Wait until all messages accumulated in the printk buffer are printed to
+ * console. Note that as soon as this function returns, new messages may be
+ * added to the printk buffer by other CPUs.
+ */
+void console_flush(void)

This doesn't seem a very good name. We already have console_cont_flush(), cont_flush(), etc. Can we think of something more specific? printk_log_buf_drain() perhaps.

kernel/printk/printk.c struct tty_driver *console_device(int *index) · line 2504

Quoted 8 lines

kernel/printk/printk.c +8 -0

+{
+	bool retry;
+	unsigned long flags;
+
+	while (1) {
+		raw_spin_lock_irqsave(&logbuf_lock, flags);
+		retry = console_seq != log_next_seq;
+		raw_spin_unlock_irqrestore(&logbuf_lock, flags);

Does this lock/unlock do anything useful?

Quoted 25 lines

kernel/printk/printk.c +9 -0

+		if (!retry || console_suspended)
+			break;
+		/* Cycle console_sem to wait for outstanding printing */
+		console_lock();
+		console_unlock();
+	}
+}
+
+/*
  * Prevent further output on the passed console device so that (for example)
  * serial drivers can disable console output before suspending a port, and can
  * re-enable output afterwards.

kernel/stop_machine.c +1 -0

index fd643d8c4b42..016d34621d2e 100644
@@ -21,6 +21,7 @@
 #include <linux/smpboot.h>
 #include <linux/atomic.h>
 #include <linux/lglock.h>
+#include <linux/console.h>
 
 /*
  * Structure to determine completion condition and record errors.  May

kernel/stop_machine.c int __stop_machine(int (*fn)(void *), void *data, const struct cpumask *cpus) · line 553

Quoted 10 lines

kernel/stop_machine.c +7 -0

@@ -543,6 +544,14 @@ int __stop_machine(int (*fn)(void *), void *data, const struct cpumask *cpus)
 		return ret;
 	}
 
+	/*
+	 * If there are lots of outstanding messages, printing them can take a
+	 * long time and all cpus would be spinning waiting for the printing to
+	 * finish thus triggering NMI watchdog, RCU lockups etc. Wait for the
+	 * printing here to avoid these.
+	 */
+	console_flush();

This is pretty pointless if num_possible_cpus==1. I'd suggest setting printk_offload_chars=0 in this case, add some early bale-out into console_flush(). Or something along those lines.

And make console_flush() go away altogether if CONFIG_SMP=n - it's pointless bloat.

Quoted 10 lines

kernel/printk/printk.c struct tty_driver *console_device(int *index) · line 2504

Quoted 8 lines

kernel/printk/printk.c +8 -0

+{
+	bool retry;
+	unsigned long flags;
+
+	while (1) {
+		raw_spin_lock_irqsave(&logbuf_lock, flags);
+		retry = console_seq != log_next_seq;
+		raw_spin_unlock_irqrestore(&logbuf_lock, flags);

Does this lock/unlock do anything useful?

Quoted 40 lines

Quoted 25 lines

kernel/printk/printk.c +9 -0

+		if (!retry || console_suspended)
+			break;
+		/* Cycle console_sem to wait for outstanding printing */
+		console_lock();
+		console_unlock();
+	}
+}
+
+/*
  * Prevent further output on the passed console device so that (for example)
  * serial drivers can disable console output before suspending a port, and can
  * re-enable output afterwards.

kernel/stop_machine.c +1 -0

index fd643d8c4b42..016d34621d2e 100644
@@ -21,6 +21,7 @@
 #include <linux/smpboot.h>
 #include <linux/atomic.h>
 #include <linux/lglock.h>
+#include <linux/console.h>
 
 /*
  * Structure to determine completion condition and record errors.  May

kernel/stop_machine.c int __stop_machine(int (*fn)(void *), void *data, const struct cpumask *cpus) · line 553

Quoted 10 lines

kernel/stop_machine.c +7 -0

@@ -543,6 +544,14 @@ int __stop_machine(int (*fn)(void *), void *data, const struct cpumask *cpus)
 		return ret;
 	}
 
+	/*
+	 * If there are lots of outstanding messages, printing them can take a
+	 * long time and all cpus would be spinning waiting for the printing to
+	 * finish thus triggering NMI watchdog, RCU lockups etc. Wait for the
+	 * printing here to avoid these.
+	 */
+	console_flush();

This is pretty pointless if num_possible_cpus==1. I'd suggest setting printk_offload_chars=0 in this case, add some early bale-out into console_flush(). Or something along those lines.

Quoted 2 lines

And make console_flush() go away altogether if CONFIG_SMP=n - it's pointless bloat.

Sure, I'll do that.

From: Jan Kara <[email protected]>

Necessity for offloading of printing was observed only for large systems. So add a config option (disabled by default)

which removes most
of the overhead added by this functionality.

...

kernel/printk/printk.c +9 -0

+#ifdef CONFIG_PRINTK_OFFLOAD
 /*
  * Returns true iff there is other cpu waiting to take over printing. This
  * function also takes are of setting PRINTK_HANDOVER_B if we want to hand over

@@ -2278,6 +2283,14 @@ static bool cpu_stop_printing(int printed_chars)
 
 	return false;
 }
+#else
+
+static bool cpu_stop_printing(int printed_chars, bool *woken)
+{
+	return false;
+}
+
+#endif
 
 /**
  * console_unlock - unlock the console system

kernel/printk/printk.c +4 -0

 	for (;;) {
 		struct printk_log *msg;
 		size_t ext_len = 0;

@@ -2399,12 +2414,14 @@ skip:
 
 	console_locked = 0;
 	up_console_sem();
+#ifdef CONFIG_PRINTK_OFFLOAD
 	/*
 	 * Release print_lock after console_sem so that printing_task()
 	 * succeeds in getting console_sem (unless someone else takes it and
 	 * then he'll be responsible for printing).
          */
 	spin_unlock(&print_lock);
+#endif
 
 	/*
 	 * Subtlety: We have interrupts disabled iff hand_over == false (to

@@ -2770,6 +2787,7 @@ int unregister_console(struct console *console)
 }
 EXPORT_SYMBOL(unregister_console);
 
+#ifdef CONFIG_PRINTK_OFFLOAD
 /* Kthread which takes over printing from a CPU which asks for help */
 static int printing_task(void *arg)
 {

@@ -2838,6 +2856,7 @@ static int offload_chars_set(const char *val, const struct kernel_param *kp)
 	mutex_unlock(&printk_kthread_mutex);
 	return 0;
 }
+#endif	/* CONFIG_PRINTK_OFFLOAD */
 
 static int __init printk_late_init(void)
 {

Quoted 4 lines · On Wed, 19 Aug 2015 17:38:31 +0200 Jan Kara <[email protected]> wrote:

From: Jan Kara <[email protected]>

Necessity for offloading of printing was observed only for large systems. So add a config option (disabled by default)

The Kconfig has "default y"?

Quoted 22 lines

which removes most
of the overhead added by this functionality.

...

kernel/printk/printk.c +9 -0

+#ifdef CONFIG_PRINTK_OFFLOAD
 /*
  * Returns true iff there is other cpu waiting to take over printing. This
  * function also takes are of setting PRINTK_HANDOVER_B if we want to hand over

@@ -2278,6 +2283,14 @@ static bool cpu_stop_printing(int printed_chars)
 
 	return false;
 }
+#else
+
+static bool cpu_stop_printing(int printed_chars, bool *woken)
+{
+	return false;
+}
+
+#endif
 

kernel/printk/printk.c void console_unlock(void) · line 2334

Quoted 9 lines

kernel/printk/printk.c +2 -0

 /**
  * console_unlock - unlock the console system

@@ -2316,7 +2329,9 @@ void console_unlock(void)
 	/* flush buffered message fragment immediately to console */
 	console_cont_flush(text, sizeof(text));
 again:
+#ifdef CONFIG_PRINTK_OFFLOAD
 	spin_lock(&print_lock);
+#endif

You could nuke a couple of ugly ifdefs by adding spin_[un]lock_printk_lock() wrappers into that ifdef/else/endif block which holds cpu_stop_printing().

Quoted 38 lines

kernel/printk/printk.c +4 -0

 	for (;;) {
 		struct printk_log *msg;
 		size_t ext_len = 0;

@@ -2399,12 +2414,14 @@ skip:
 
 	console_locked = 0;
 	up_console_sem();
+#ifdef CONFIG_PRINTK_OFFLOAD
 	/*
 	 * Release print_lock after console_sem so that printing_task()
 	 * succeeds in getting console_sem (unless someone else takes it and
 	 * then he'll be responsible for printing).
          */
 	spin_unlock(&print_lock);
+#endif
 
 	/*
 	 * Subtlety: We have interrupts disabled iff hand_over == false (to

@@ -2770,6 +2787,7 @@ int unregister_console(struct console *console)
 }
 EXPORT_SYMBOL(unregister_console);
 
+#ifdef CONFIG_PRINTK_OFFLOAD
 /* Kthread which takes over printing from a CPU which asks for help */
 static int printing_task(void *arg)
 {

@@ -2838,6 +2856,7 @@ static int offload_chars_set(const char *val, const struct kernel_param *kp)
 	mutex_unlock(&printk_kthread_mutex);
 	return 0;
 }
+#endif	/* CONFIG_PRINTK_OFFLOAD */
 
 static int __init printk_late_init(void)
 {

@@ -2850,9 +2869,11 @@ static int __init printk_late_init(void)
 	}
 	hotcpu_notifier(console_cpu_notify, 0);
 

kernel/printk/printk.c static int __init printk_late_init(void) · line 2876

Quoted 5 lines

kernel/printk/printk.c +2 -0

+#ifdef CONFIG_PRINTK_OFFLOAD
 	mutex_lock(&printk_kthread_mutex);
 	printk_start_offload_kthreads();
 	mutex_unlock(&printk_kthread_mutex);
+#endif

Possibly ditto here. Maybe move the mutex_lock() into printk_start_offload_kthreads() too?

-----Original Message-----
From: Jan Kara [mailto:[email protected]]
Sent: Wednesday, August 19, 2015 8:38 AM
To: Andrew Morton <[email protected]>
Cc: LKML <[email protected]>; [email protected]; [email protected]; Gavin Hu <[email protected]>; KY Srinivasan <[email protected]>; Jan Kara <[email protected]>
Subject: [PATCH 0/4] printk: Softlockup avoidance

From: Jan Kara <[email protected]>

Hello,

since lately there were several attempts at dealing with softlockups due to heavy printk traffic [1] [2] and I've been also privately pinged by couple of people about the state of the patch set, I've decided to respin the patch set.

To remind the original problem:

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 when printk() gets called under some critical spinlock or 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 series addresses the problem in the following way: If CPU has printed more that printk_offload (defaults to 1000) characters, it wakes up one of dedicated printk kthreads (we don't use workqueue because that has deadlock potential if printk was called from workqueue code). Once we find out kthread is spinning on a lock, we stop printing, drop console_sem, and let kthread continue printing. Since there are two printing kthreads, they will pass printing between them and thus no CPU gets hogged by printing.

Changes since the last posting [3]:
* I have replaced the state machine to pass printing and spinning on console_sem with a simple spinlock which makes the code somewhat easier to read and verify.
* Some of the patches were merged so I dropped them.

Honza

[1]
https://na01.safelinks.protection.outlook.com/?url=https%3a%2f%2flkml.or
g%2flkml%2f2015%2f7%2f8%2f215&data=01%7c01%7ckys%40microsoft.com %7c0be64449b7734417b58e08d2a8ac4215%7c72f988bf86f141af91ab2d7cd011 db47%7c1&sdata=tIGC5%2bms890etIzVbaj3x3B3XUrgC54C79vaniZzRIY%3d
[2]
https://na01.safelinks.protection.outlook.com/?url=http%3a%2f%2fmarc.inf
o%2f%3fl%3dlinux- kernel%26m%3d143929238407816%26w%3d2&data=01%7c01%7ckys%40micr osoft.com%7c0be64449b7734417b58e08d2a8ac4215%7c72f988bf86f141af91a b2d7cd011db47%7c1&sdata=DFEq8NILXnLGTo%2fscI5zjzWrX9%2buJlj9lmo8r ahuIt0%3d
[3]
https://na01.safelinks.protection.outlook.com/?url=https%3a%2f%2flkml.or
g%2flkml%2f2014%2f3%2f17%2f68&data=01%7c01%7ckys%40microsoft.com %7c0be64449b7734417b58e08d2a8ac4215%7c72f988bf86f141af91ab2d7cd011 db47%7c1&sdata=j9uJalk7Cup0q78gl8rgIIjySU0l7HIwk1AhYJ5cAd4%3d

From: Jan Kara <[email protected]>

Hello,

since lately there were several attempts at dealing with softlockups due to heavy printk traffic [1] [2] and I've been also privately pinged by couple of people about the state of the patch set, I've decided to respin the patch set.

To remind the original problem:

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 when printk() gets called under some critical spinlock or 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 series addresses the problem in the following way: If CPU has printed more that printk_offload (defaults to 1000) characters, it wakes up one of dedicated printk kthreads (we don't use workqueue because that has deadlock potential if printk was called from workqueue code). Once we find out kthread is spinning on a lock, we stop printing, drop console_sem, and let kthread continue printing. Since there are two printing kthreads, they will pass printing between them and thus no CPU gets hogged by printing.

Quoted 31 lines · On Wed, 19 Aug 2015 17:38:27 +0200 Jan Kara <[email protected]> wrote:

From: Jan Kara <[email protected]>

Hello,

since lately there were several attempts at dealing with softlockups due to heavy printk traffic [1] [2] and I've been also privately pinged by couple of people about the state of the patch set, I've decided to respin the patch set.

To remind the original problem:

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 when printk() gets called under some critical spinlock or 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.

Quoted 7 lines

This series addresses the problem in the following way: If CPU has printed more that printk_offload (defaults to 1000) characters, it wakes up one of dedicated printk kthreads (we don't use workqueue because that has deadlock potential if printk was called from workqueue code). Once we find out kthread is spinning on a lock, we stop printing, drop console_sem, and let kthread continue printing. Since there are two printing kthreads, they will pass printing between them and thus no CPU gets hogged by printing.

I still hate your patchset ;)

But nothing better suggests itself. I have a few review comments - please let's work through that stuff, get a fresh version out and we'll see how it goes.

Is this patchset being used in the field? Perhaps in the suse kernel? If so, a mention of that in the changelog would help things along.