Re: [PATCH 2/7] printk: Start printing handover kthreads on demand

Re: [PATCH 2/7] printk: Start printing handover kthreads on demand

[Sergey Senozhatsky]

> +static void printk_offload_init(void)
> +{
> +	mutex_lock(&printk_kthread_mutex);
> +	if (num_possible_cpus() <= 1) {
> +		/* Offloading doesn't make sense. Disable print offloading. */
> +		printk_offload_chars = 0;
> +	} else
> +		printk_start_offload_kthreads();
> +	mutex_unlock(&printk_kthread_mutex);
> +}

A silly minor nitpick

+	} else {
		printk_start_offload_kthreads();
+	}

	-ss

Re: [PATCH 2/7] printk: Start printing handover kthreads on demand

[Sergey Senozhatsky]

On (12/10/15 23:56), Sergey Senozhatsky wrote:
>
> A silly minor nitpick
>

ah.. nope, I lied.

this part

>+static int printk_start_offload_kthreads(void)
> {
>-	struct console *con;
> 	int i;
> 	struct task_struct *task;
> 
>+	/* Does handover of printing make any sense? */
>+	if (printk_offload_chars == 0 || num_possible_cpus() <= 1)
>+		return 0;
>+	for (i = 0; i < PRINTING_TASKS; i++) {
>+		if (printing_kthread[i])
>+			continue;
>+		task = kthread_run(printing_task, NULL, "print/%d", i);
>+		if (IS_ERR(task))
>+			goto out_err;
>+		printing_kthread[i] = task;
>+	}
>+	return 0;
>+out_err:
>+	pr_err("printk: Cannot create printing thread: %ld\n", PTR_ERR(task));
>+	/* Disable offloading if creating kthreads failed */
>+	printk_offload_chars = 0;
>+	return PTR_ERR(task);
>+}

we can keep printk_offload_chars if we have created at least one thread,
in theory. if we are in heavy or nearly hevy (which is 'a process will spin in
unlock_console() with preemption_disabled for far too long') printk traffic case
(and that's what I want to fix from my side) then we have at least 1 process doing
printk->console_unlock() very often, so breaking that 'while (1)' console_unlock()
loop is a good thing here. which may be a corner case.


if we want to zero `printk_offload_chars' then how about bringing back Tejun Heo's
"printk: do cond_resched() between lines while outputting to consoles"?


Besides, we need this for !CONFIG_PRINTK_OFFLOAD kernel.

===8<====

if printk_start_offload_kthreads() has failed or if for some
other reason `printk_offload_chars' ended up to be 0, we still
need to try to break up long console_unlock() loops and try to
reschedule.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 27 ++++++++++++++++++++++++++-
 1 file changed, 26 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 21b0fb9..fc8c493 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2285,6 +2285,16 @@ static bool cpu_stop_printing(int printed_chars)
 	return false;
 }
 
+static bool cpu_should_cond_resched(bool do_cond_resched)
+{
+	/* Oops? Print everything now to maximize chances user will see it */
+	if (oops_in_progress)
+		return false;
+	if (!printk_offload_chars && do_cond_resched)
+		return true;
+	return false;
+}
+
 /**
  * console_unlock - unlock the console system
  *
@@ -2309,7 +2319,7 @@ void console_unlock(void)
 	unsigned long flags;
 	bool wake_klogd = false;
 	bool retry;
-	bool hand_over = false;
+	bool hand_over = false, do_cond_resched;
 	int printed_chars = 0;
 
 	if (console_suspended) {
@@ -2317,6 +2327,15 @@ void console_unlock(void)
 		return;
 	}
 
+	/*
+	 * We may end up dumping a lot of lines, for example, if called
+	 * from console registration path, and should invoke cond_resched()
+	 * between lines if allowable.  Not doing so can cause a very long
+	 * scheduling stall on a slow console leading to RCU stall and
+	 * softlockup warnings which exacerbate the issue with more
+	 * messages practically incapacitating the system.
+	 */
+	do_cond_resched = console_may_schedule;
 	console_may_schedule = 0;
 
 	/* flush buffered message fragment immediately to console */
@@ -2397,6 +2416,12 @@ skip:
 		call_console_drivers(level, ext_text, ext_len, text, len);
 		start_critical_timings();
 		printed_chars += len;
+
+		if (unlikely(cpu_should_cond_resched(do_cond_resched))) {
+			raw_spin_unlock_irqrestore(&print_lock, flags);
+			cond_resched();
+			raw_spin_lock_irqsave(&print_lock, flags);
+		}
 	}
 
 	/* Release the exclusive_console once it is used */
-- 
2.6.3

[PATCH 0/6 v2] printk: Softlockup avoidance

[Jan Kara]

From: Jan Kara <jack@suse.cz>

Hello,

here is another posting of the revived patch set to avoid lockups during heavy
printing. 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, so I've decided to revive the patch
set. Patches (their older version) are present in SUSE enterprise kernels for
several years and we didn't observe any issues with them.

Patch set passes my stress testing where serial console is slowed down to print
~1000 chars per second and there are 100 delayed works printing together some
64k of text and in parallel modules are inserted which generates quite some
additional messages, stop_machine() calls etc.

Changes since v1:
* printing kthreads now check for kthread_should_stop()
* printing kthreads are now bound to CPUs so that scheduler cannot decide to
  schedule both kthreads on one CPU which effectively makes it impossible to
  hand over printing between them. This happened relatively frequently in
  virtual machines.
* use printk buffer draining code in panic() to force all messages out when
  the system is dying
* better naming of logbuf flushing functions suggested by AKPM
* fixed irq safety of printing lock as pointed out by AKMP
* fixed various smaller issues pointed by AKPM


Changes since the the old patch set [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.

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.

								Honza

[1] https://lkml.org/lkml/2015/7/8/215
[2] http://marc.info/?l=linux-kernel&m=143929238407816&w=2
[3] https://lkml.org/lkml/2014/3/17/68

[PATCH 2/7] printk: Start printing handover kthreads on demand

[Jan Kara]

From: Jan Kara <jack@suse.cz>

Start kthreads for handing over printing only when printk.offload_chars
is set to value > 0 (i.e., when print offloading gets enabled).

Signed-off-by: Jan Kara <jack@suse.cz>
---
 kernel/printk/printk.c | 78 +++++++++++++++++++++++++++++++++++++++++---------
 1 file changed, 64 insertions(+), 14 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1b26263edfa7..b9bb4a7a6dff 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -98,6 +98,10 @@ static atomic_t printing_tasks_spinning = ATOMIC_INIT(0);
  * CPUs.
  */
 #define PRINTING_TASKS 2
+/* Pointers to printing kthreads */
+static struct task_struct *printing_kthread[PRINTING_TASKS];
+/* Serialization of changes to printk_offload_chars and kthread creation */
+static DEFINE_MUTEX(printk_kthread_mutex);
 
 /* Wait queue printing kthreads sleep on when idle */
 static DECLARE_WAIT_QUEUE_HEAD(print_queue);
@@ -303,6 +307,13 @@ static u32 clear_idx;
 static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
 static char *log_buf = __log_buf;
 static u32 log_buf_len = __LOG_BUF_LEN;
+
+static int offload_chars_set(const char *val, const struct kernel_param *kp);
+static struct kernel_param_ops offload_chars_ops = {
+	.set = offload_chars_set,
+	.get = param_get_uint,
+};
+
 /*
  * How many characters can we print in one call of printk before asking
  * other cpus to continue printing. 0 means infinity. Tunable via
@@ -311,7 +322,7 @@ static u32 log_buf_len = __LOG_BUF_LEN;
  */
 static unsigned int __read_mostly printk_offload_chars = 1000;
 
-module_param_named(offload_chars, printk_offload_chars, uint,
+module_param_cb(offload_chars, &offload_chars_ops, &printk_offload_chars,
 		   S_IRUGO | S_IWUSR);
 MODULE_PARM_DESC(offload_chars, "offload printing to console to a different"
 	" cpu after this number of characters");
@@ -2778,12 +2789,61 @@ static int printing_task(void *arg)
 	return 0;
 }
 
-static int __init printk_late_init(void)
+static int printk_start_offload_kthreads(void)
 {
-	struct console *con;
 	int i;
 	struct task_struct *task;
 
+	/* Does handover of printing make any sense? */
+	if (printk_offload_chars == 0 || num_possible_cpus() <= 1)
+		return 0;
+	for (i = 0; i < PRINTING_TASKS; i++) {
+		if (printing_kthread[i])
+			continue;
+		task = kthread_run(printing_task, NULL, "print/%d", i);
+		if (IS_ERR(task))
+			goto out_err;
+		printing_kthread[i] = task;
+	}
+	return 0;
+out_err:
+	pr_err("printk: Cannot create printing thread: %ld\n", PTR_ERR(task));
+	/* Disable offloading if creating kthreads failed */
+	printk_offload_chars = 0;
+	return PTR_ERR(task);
+}
+
+static int offload_chars_set(const char *val, const struct kernel_param *kp)
+{
+	int ret;
+
+	/* Protect against parallel change of printk_offload_chars */
+	mutex_lock(&printk_kthread_mutex);
+	ret = param_set_uint(val, kp);
+	if (ret) {
+		mutex_unlock(&printk_kthread_mutex);
+		return ret;
+	}
+	ret = printk_start_offload_kthreads();
+	mutex_unlock(&printk_kthread_mutex);
+	return ret;
+}
+
+static void printk_offload_init(void)
+{
+	mutex_lock(&printk_kthread_mutex);
+	if (num_possible_cpus() <= 1) {
+		/* Offloading doesn't make sense. Disable print offloading. */
+		printk_offload_chars = 0;
+	} else
+		printk_start_offload_kthreads();
+	mutex_unlock(&printk_kthread_mutex);
+}
+
+static int __init printk_late_init(void)
+{
+	struct console *con;
+
 	for_each_console(con) {
 		if (!keep_bootcon && con->flags & CON_BOOT) {
 			unregister_console(con);
@@ -2791,17 +2851,7 @@ static int __init printk_late_init(void)
 	}
 	hotcpu_notifier(console_cpu_notify, 0);
 
-	/* Does any handover of printing have any sence? */
-	if (num_possible_cpus() <= 1)
-		return 0;
-
-	for (i = 0; i < PRINTING_TASKS; i++) {
-		task = kthread_run(printing_task, NULL, "print/%d", i);
-		if (IS_ERR(task)) {
-			pr_err("printk: Cannot create printing thread: %ld\n",
-			       PTR_ERR(task));
-		}
-	}
+	printk_offload_init();
 
 	return 0;
 }
-- 
2.1.4