[RFC][PATCHv4 0/7] printk: introduce printing kernel threads

[RFC][PATCHv4 0/7] printk: introduce printing kernel threads

[Sergey Senozhatsky]

Hello,

	RFC

	This patch set adds a printk() SMP kernel threads which let us
to print kernel messages to the console from a non-atomic/schedule-able
context, avoiding different sort of lockups, stalls, etc.

	A completely reworked version, for more details please
see 0003 commit message and code comments/documentation.

	I've managed to reproduce some of the issues with a single printk
kthread solution that Jan Kara talked about. Sometimes scheduler decides
sometimes scheduler decides that printk kthread should run on the same CPU
as the process that is doing printing, so printk kthread never takes over
and systems eventually lockups. With SMP threads we can wake up printk
kthread on a remote CPU (and we know that it will be woken up on a remote
CPU), so per my tests SMP thread-ed version of printing offloading works
much better. But more tests are needed.

	The patch set is in RFC stage. I think I'll move the whole
offloading thing under CONFIG_PRINTK_OFFLOAD (e.g.) at some point.

	As a side note, seems that with the SMP threaded implementation
we can do (there are some constraints (!!), of course) some sort of less
deadlock prone printk. Instead of calling into the scheduler, console_sem,
console_unlock(), we can wake_up printk_kthread on a foreign CPU. So we will
not take scheduler locks or console locks from this CPU. (very-very
schematically):

int vprintk_emit(....)
{
	logbuf_lock_irqsave(flags);

	[..]
	printed_len += log_output(facility, level, lflags, dict, dictlen, text, text_len);

	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);

	for_each_cpu_and(cpu, cpu_online_mask, &printk_cpumask) {
		if (cpu != smp_processor_id())
			wake_up_process(per_cpu(printk_kthread, cpu));
	}

	logbuf_unlock_irqrestore(flags);
	return printed_len;
}

but, well, there are constraints and limitations.



v3->v4 (Petr, Jan)
-- use SMP kthreads. so every CPU has printk kthread now
-- add syscore notifiers
-- fix 0001 compilation warnings
-- use proper CPU notifiers return values

v2->v3 (Petr, Pavel, Andreas):
-- rework offloading
-- use PM notifiers
-- dropped some patches, etc. etc.

v1->v2:
-- introduce printk_emergency mode and API to switch it on/off
-- move printk_pending out of per-CPU memory
-- add printk emergency_mode sysfs node
-- switch sysrq handlers (some of them) to printk_emergency
-- cleanus/etc.


Sergey Senozhatsky (7):
  printk: move printk_pending out of per-cpu
  printk: introduce printing kernel SMP threads
  printk: add enforce_emergency parameter
  printk: enable printk offloading
  printk: register PM notifier
  printk: register syscore notifier
  printk: add printk cpumask sysctl

 include/linux/console.h |   3 +
 include/linux/printk.h  |   4 +
 kernel/printk/printk.c  | 385 +++++++++++++++++++++++++++++++++++++++++++++---
 kernel/sysctl.c         |   7 +
 4 files changed, 379 insertions(+), 20 deletions(-)

-- 
2.13.0

[RFC][PATCHv4 1/7] printk: move printk_pending out of per-cpu

[Sergey Senozhatsky]

Do not keep `printk_pending' in per-CPU area. We set the following bits
of printk_pending:
a) PRINTK_PENDING_WAKEUP
	when we need to wakeup klogd
b) PRINTK_PENDING_OUTPUT
	when there is a pending output from deferred printk and we need
	to call console_unlock().

So none of the bits control/represent a state of a particular CPU and,
basically, they should be global instead.

Besides we will use `printk_pending' to control printk kthread, so this
patch is also a preparation work.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Suggested-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 26 ++++++++++++--------------
 1 file changed, 12 insertions(+), 14 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e782e9049e73..45fe90ca8f87 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -402,6 +402,14 @@ DEFINE_RAW_SPINLOCK(logbuf_lock);
 	} while (0)
 
 #ifdef CONFIG_PRINTK
+/*
+ * Delayed printk version, for scheduler-internal messages:
+ */
+#define PRINTK_PENDING_WAKEUP	0x01
+#define PRINTK_PENDING_OUTPUT	0x02
+
+static unsigned long printk_pending;
+
 DECLARE_WAIT_QUEUE_HEAD(log_wait);
 /* the next printk record to read by syslog(READ) or /proc/kmsg */
 static u64 syslog_seq;
@@ -2709,25 +2717,15 @@ static int __init printk_late_init(void)
 late_initcall(printk_late_init);
 
 #if defined CONFIG_PRINTK
-/*
- * Delayed printk version, for scheduler-internal messages:
- */
-#define PRINTK_PENDING_WAKEUP	0x01
-#define PRINTK_PENDING_OUTPUT	0x02
-
-static DEFINE_PER_CPU(int, printk_pending);
-
 static void wake_up_klogd_work_func(struct irq_work *irq_work)
 {
-	int pending = __this_cpu_xchg(printk_pending, 0);
-
-	if (pending & PRINTK_PENDING_OUTPUT) {
+	if (test_and_clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending)) {
 		/* If trylock fails, someone else is doing the printing */
 		if (console_trylock())
 			console_unlock();
 	}
 
-	if (pending & PRINTK_PENDING_WAKEUP)
+	if (test_and_clear_bit(PRINTK_PENDING_WAKEUP, &printk_pending))
 		wake_up_interruptible(&log_wait);
 }
 
@@ -2740,7 +2738,7 @@ void wake_up_klogd(void)
 {
 	preempt_disable();
 	if (waitqueue_active(&log_wait)) {
-		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
+		set_bit(PRINTK_PENDING_WAKEUP, &printk_pending);
 		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
 	}
 	preempt_enable();
@@ -2753,7 +2751,7 @@ int vprintk_deferred(const char *fmt, va_list args)
 	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
 
 	preempt_disable();
-	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
+	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
 	preempt_enable();
 
-- 
2.13.0

[RFC][PATCHv4 2/7] printk: introduce printing kernel SMP threads

[Sergey Senozhatsky]

printk() is quite complex internally and, basically, it does two
slightly independent things:
 a) adds a new message to a kernel log buffer (log_store())
 b) prints kernel log messages to serial consoles (console_unlock())

while (a) is guaranteed to be executed by printk(), (b) is not, for a
variety of reasons, and, unlike log_store(), it comes at a price:

 1) console_unlock() attempts to flush all pending kernel log messages
to the console and it can loop indefinitely.

 2) while console_unlock() is executed on one particular CPU, printing
pending kernel log messages, other CPUs can simultaneously append new
messages to the kernel log buffer.

 3) the time it takes console_unlock() to print kernel messages also
depends on the speed of the console -- which may not be fast at all.

 4) console_unlock() is executed in the same context as printk(), so
it may be non-preemptible/atomic, which makes 1)-3) dangerous.

As a result, nobody knows how long a printk() call will take, so
it's not really safe to call printk() in a number of situations,
including atomic context, RCU critical sections, interrupt context,
etc.

This patch introduces a '/sys/module/printk/parameters/atomic_print_limit'
sysfs param, which sets the limit on number of lines a process can print
from console_unlock(). Value 0 corresponds to the current behavior (no
limitation). The printing offloading is happening from console_unlock()
function and, briefly, looks as follows:
	as soon as process prints more than `atomic_print_limit' lines it
attempts to offload printing to another process.

Since nothing guarantees that there will another process sleeping on the
console_sem or calling printk() on another CPU simultaneously, the patch
also introduces auxiliary SMP kernel thread - printk kthreads, the main
purpose of which is to take over printing duty. The workflow is, thus,
turns into:
	as soon as process prints more than `atomic_print_limit' lines
it wakes up printk_kthread and unlocks the console_sem.

The reason we have SMP printk kthreads is because single printk_kthread
is not reliable. Scheduler may decide that printk_kthread should run on
the same CPU with the process that is currently doing printing. This
means that offloading will not take place as long as current process
has pending messages to print, which results in lockup. SMP threads let
us to wake up printk_kthread on foreign CPU so printing take over has
much greater chances to succeed.

So in the best case at this point there will be at least 1 processes
trying to lock the console_sem: this CPU's printk_kthread. (There can
also be a process that was sleeping on the console_sem and that was
woken up by console semaphore up(); concurrent printk() invocations
from other CPUs and, besides, we wake up all printk_kthreads for
offloading).

But in the worst case there won't be any processes ready to take
over the printing duty: it may take printk_kthread some time to become
running; or printk_kthread may even never become running (a misbehaving
scheduler, or other critical condition). That's why after we wake_up()
printk_kthread we can't immediately leave the printing loop, we must
ensure that the console_sem has a new owner before we do so.

In other words, `atomic_print_limit' is a soft limit, not the hard one:
we let task to overrun `atomic_print_limit'. But, at the same time, the
console_unlock() printing loop behaves differently for tasks that have
exceeded `atomic_print_limit': after every printed logbuf entry
(call_console_drivers()) such a process wakes up printk_kthread, unlocks
the console_sem and attempts to console_trylock() a bit later (if there
any are pending messages in the logbuf, of course). In the best case
scenario either printk_kthread or some other tasks will lock the
console_sem, so current printing task will see failed console_trylock(),
which will indicate a successful printing offloading. In the worst
case, however, current will successfully console_trylock(), which will
indicate that offloading did not take place and we can't return from
console_unlock(), so the printing task will print one more line from
the logbuf and attempt to offload printing once again; and it will
continue doing so until another process locks the console_sem or
until there are pending messages in the logbuf.

So if everything goes wrong - we can't wakeup printk_kthread and there
are no other processes sleeping on the console_sem or trying to down()
it - then we will have the existing console_unlock() behavior: print
all pending messages in one shot.

We track the number of unsuccessful offloading attempts and after some
point we declare a `printk_emergency' condition and give up trying to
offload. `printk_emergency' is a new name for printk mode in which
printk does not attempt to offload printing, but instead flushes all
the pending logbuf messages (basically, the existing behaviour).

There also other cases when we can't (or should avoid) offloading.
For example, we can't call into the scheduler from panic(), because
this may cause deadlock. Therefore printk() has some additional places
where it switches to printk_emergency mode: for instance, once a EMERG
log level message appears in the log buffer. We also provide two new
functions that can be used when a path needs to declare a temporal
`printk_emergency' mode:

 -- printk_emergency_begin()
    Disables printk offloading. All printk() calls will attempt
    to lock the console_sem and, if successful, flush kernel log
    messages.

 -- printk_emergency_end()
    Enables printk offloading.

Offloading is not possible yet, it will be enabled in a later patch.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 include/linux/console.h |   3 +
 kernel/printk/printk.c  | 220 ++++++++++++++++++++++++++++++++++++++++++++++--
 2 files changed, 214 insertions(+), 9 deletions(-)

diff --git a/include/linux/console.h b/include/linux/console.h
index b8920a031a3e..07005db4c788 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -187,6 +187,9 @@ extern bool console_suspend_enabled;
 extern void suspend_console(void);
 extern void resume_console(void);
 
+extern void printk_emergency_begin(void);
+extern void printk_emergency_end(void);
+
 int mda_console_init(void);
 void prom_con_init(void);
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 45fe90ca8f87..45e585624ced 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -48,6 +48,8 @@
 #include <linux/sched/clock.h>
 #include <linux/sched/debug.h>
 #include <linux/sched/task_stack.h>
+#include <linux/kthread.h>
+#include <linux/smpboot.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -401,15 +403,16 @@ DEFINE_RAW_SPINLOCK(logbuf_lock);
 		printk_safe_exit_irqrestore(flags);	\
 	} while (0)
 
-#ifdef CONFIG_PRINTK
 /*
- * Delayed printk version, for scheduler-internal messages:
+ * Used both for deferred printk version (scheduler-internal messages)
+ * and printk_kthread control.
  */
 #define PRINTK_PENDING_WAKEUP	0x01
 #define PRINTK_PENDING_OUTPUT	0x02
 
 static unsigned long printk_pending;
 
+#ifdef CONFIG_PRINTK
 DECLARE_WAIT_QUEUE_HEAD(log_wait);
 /* the next printk record to read by syslog(READ) or /proc/kmsg */
 static u64 syslog_seq;
@@ -445,6 +448,145 @@ 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 struct cpumask printk_cpumask __read_mostly;
+static DEFINE_PER_CPU(struct task_struct *, printk_kthread);
+/*
+ * We can't call into the scheduler (wake_up() printk kthread) during
+ * suspend/kexec/etc. This temporarily switches printk to old behaviour.
+ */
+static atomic_t printk_emergency __read_mostly;
+/*
+ * Disable printk_kthread permanently. Unlike `oops_in_progress'
+ * it doesn't go back to 0.
+ */
+static bool printk_enforce_emergency __read_mostly;
+/*
+ * The number of lines a task can print before offloading printing
+ * job to printk_kthread. 0 indicates 'no limit'.
+ */
+static unsigned int atomic_print_limit;
+
+module_param_named(atomic_print_limit, atomic_print_limit, uint, 0644);
+MODULE_PARM_DESC(atomic_print_limit,
+		 "max lines to print before offloading to printk kthread");
+
+/* Must be called with preemption disabled. */
+static inline bool printk_offloading_enabled(void)
+{
+	return atomic_print_limit &&
+		!printk_enforce_emergency &&
+		__this_cpu_read(printk_kthread) &&
+		atomic_read(&printk_emergency) == 0;
+}
+
+/*
+ * This disables printing offloading and instead attempts
+ * to do the usual console_trylock()->console_unlock().
+ *
+ * Note, this does not stop the printk_kthread if it's already
+ * printing logbuf messages.
+ */
+void printk_emergency_begin(void)
+{
+	atomic_inc(&printk_emergency);
+}
+
+/* This re-enables printk_kthread offloading. */
+void printk_emergency_end(void)
+{
+	atomic_dec(&printk_emergency);
+}
+
+/*
+ * Under heavy printing load or with a slow serial console (or both)
+ * console_unlock() can stall CPUs, which can result in soft/hard-lockups,
+ * lost interrupts, RCU stalls, etc. Therefore we attempt to limit the
+ * number of lines a process can print from console_unlock().
+ *
+ * There is one more reason to do offloading - there might be other processes
+ * (including user space tasks) sleeping on the console_sem in uninterruptible
+ * state; and keeping the console_sem locked for long time may have a negative
+ * impact on them.
+ *
+ * This function must be called from 'printk_safe' context under
+ * console_sem lock.
+ */
+static inline bool console_offload_printing(void)
+{
+	static struct task_struct *printing_task;
+	static unsigned long long lines_printed;
+	static unsigned long saved_csw;
+	int cpu;
+
+	if (!printk_offloading_enabled())
+		return false;
+
+	if (system_state != SYSTEM_RUNNING || oops_in_progress)
+		return false;
+
+	/* A new task - reset the counters. */
+	if (printing_task != current) {
+		lines_printed = 0;
+		printing_task = current;
+		saved_csw = current->nvcsw + current->nivcsw;
+		return false;
+	}
+
+	lines_printed++;
+	if (lines_printed < atomic_print_limit)
+		return false;
+
+	if (current == __this_cpu_read(printk_kthread)) {
+		/*
+		 * Do not reset `lines_printed' counter and do not let it to
+		 * pass the emergency watermark, but at the same time keep it
+		 * above `atomic_print_limit', which forces `printk_kthread'
+		 * to offload printing. Keep in mind that `printk_kthread'
+		 * might be the only process left that would down() console_sem
+		 * and call console_unlock().
+		 */
+		lines_printed--;
+		return true;
+	}
+
+	/*
+	 * A trivial emergency enforcement - give up on printk_kthread if
+	 * we can't wake it up. This assumes that `atomic_print_limit' is
+	 * reasonably and sufficiently large.
+	 */
+	if (lines_printed > 10 * (unsigned long long)atomic_print_limit &&
+			saved_csw == (current->nvcsw + current->nivcsw)) {
+		printk_enforce_emergency = true;
+		pr_crit("Declaring printk emergency mode.\n");
+		return false;
+	}
+
+	/*
+	 * Wakeup `printk_kthread' but don't reset the `lines_printed'
+	 * counter, let task overrun the limit. The idea is that
+	 *
+	 *   a) woken up printk_kthread (if succeeded)
+	 * or
+	 *   b) concurrent printk from another CPU or a task from console_sem
+	 *      wait list (if any)
+	 *
+	 * will take over, change `printing_task' and reset the counter.
+	 * If neither a) nor b) happens - we continue printing from
+	 * current process. Which is bad and can be risky, but since
+	 * we couldn't wake_up() printk_kthread, the things already
+	 * don't look normal.
+	 *
+	 * Here we wake_up() every available `printk_kthread'. We probably
+	 * don't really need to wake_up() it on the current CPU, but
+	 * `printk_cpumask' may be quite restrictive and the only available
+	 * `printk_kthread' could be the one that was created on this CPU.
+	 */
+	for_each_cpu_and(cpu, cpu_online_mask, &printk_cpumask)
+		wake_up_process(per_cpu(printk_kthread, cpu));
+
+	return true;
+}
+
 /* Return log buffer address */
 char *log_buf_addr_get(void)
 {
@@ -1765,6 +1907,15 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	printed_len += log_output(facility, level, lflags, dict, dictlen, text, text_len);
 
+	/*
+	 * Emergency level indicates that the system is unstable and, thus,
+	 * we better stop relying on wake_up(printk_kthread) and try to do
+	 * a direct printing.
+	 */
+	if (level == LOGLEVEL_EMERG)
+		printk_enforce_emergency = true;
+
+	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
@@ -1882,6 +2033,10 @@ static size_t msg_print_text(const struct printk_log *msg,
 			     bool syslog, char *buf, size_t size) { return 0; }
 static bool suppress_message_printing(int level) { return false; }
 
+void printk_emergency_begin(void) {}
+void printk_emergency_end(void) {}
+static inline bool console_offload_printing(void) { return false; }
+
 #endif /* CONFIG_PRINTK */
 
 #ifdef CONFIG_EARLY_PRINTK
@@ -2177,8 +2332,17 @@ void console_unlock(void)
 	unsigned long flags;
 	bool wake_klogd = false;
 	bool do_cond_resched, retry;
+	bool did_offload;
 
 	if (console_suspended) {
+		/*
+		 * Here and later, we need to clear the PENDING_OUTPUT bit
+		 * in order to avoid an infinite loop in printk_kthread
+		 * function when console_unlock() cannot flush messages
+		 * because we suspended consoles. Someone else will print
+		 * the messages from resume_console().
+		 */
+		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 		up_console_sem();
 		return;
 	}
@@ -2200,6 +2364,7 @@ void console_unlock(void)
 	do_cond_resched = console_may_schedule;
 again:
 	console_may_schedule = 0;
+	did_offload = 0;
 
 	/*
 	 * We released the console_sem lock, so we need to recheck if
@@ -2207,6 +2372,7 @@ void console_unlock(void)
 	 * console.
 	 */
 	if (!can_use_console()) {
+		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 		console_locked = 0;
 		up_console_sem();
 		return;
@@ -2235,7 +2401,7 @@ void console_unlock(void)
 			len = 0;
 		}
 skip:
-		if (console_seq == log_next_seq)
+		if (did_offload || console_seq == log_next_seq)
 			break;
 
 		msg = log_from_idx(console_idx);
@@ -2267,9 +2433,38 @@ void console_unlock(void)
 		stop_critical_timings();	/* don't trace print latency */
 		call_console_drivers(ext_text, ext_len, text, len);
 		start_critical_timings();
+
+		/*
+		 * Sometimes current task may re-acquire console_sem ahead of
+		 * just woken up printk_kthread, because we let processes to
+		 * compete for console_sem. In this case current task will jump
+		 * to `again' label (if there are any pending messages), print
+		 * one more line, break out of printing loop (we don't reset
+		 * `lines_printed' after wake_up_process() exactly for this
+		 * purpose) and do up_console_sem(); this will be repeated as
+		 * long as current task successfully console_trylock()-s.
+		 *
+		 * Eventually and hopefully, either printk_kthread or some
+		 * other task will acquire console_sem and current process will
+		 * be able to leave console_unlock(). Until this happens we
+		 * cannot be sure that anyone will take over and flush the
+		 * `logbuf' messages. So in the worst case scenario we,
+		 * basically, have old printk()/console_unlock() behaviour:
+		 * a task prints all pending logbuf messages.
+		 *
+		 * If printk_kthread never wakes up (which may indicate that
+		 * the system is unstable or something weird is going on),
+		 * then we keep jumping to `again' label printing one message
+		 * from the logbuf each time. This is a bit ugly, but at least
+		 * we will print out the logbuf. If such condition occurs,
+		 * console_offload_printing() should declare `printk_emergency'
+		 * at some point and we will stop all attempts to offload
+		 * printing.
+		 */
+		did_offload = console_offload_printing();
 		printk_safe_exit_irqrestore(flags);
 
-		if (do_cond_resched)
+		if (!did_offload && do_cond_resched)
 			cond_resched();
 	}
 	console_locked = 0;
@@ -2284,12 +2479,16 @@ void console_unlock(void)
 
 	/*
 	 * Someone could have filled up the buffer again, so re-check if there's
-	 * something to flush. In case we cannot trylock the console_sem again,
-	 * there's a new owner and the console_unlock() from them will do the
-	 * flush, no worries.
+	 * something to flush. Try to lock the console_sem even if we
+	 * `did_offload', because we need to know for sure that some other task
+	 * has acquired the console_sem. In case we cannot trylock the
+	 * console_sem again, there's a new owner and the console_unlock() from
+	 * them will do the flush, no worries.
 	 */
 	raw_spin_lock(&logbuf_lock);
 	retry = console_seq != log_next_seq;
+	if (!retry)
+		clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 	raw_spin_unlock(&logbuf_lock);
 	printk_safe_exit_irqrestore(flags);
 
@@ -2719,8 +2918,11 @@ late_initcall(printk_late_init);
 #if defined CONFIG_PRINTK
 static void wake_up_klogd_work_func(struct irq_work *irq_work)
 {
-	if (test_and_clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending)) {
-		/* If trylock fails, someone else is doing the printing */
+	if (test_bit(PRINTK_PENDING_OUTPUT, &printk_pending)) {
+		/*
+		 * If trylock fails, someone else is doing the printing.
+		 * PRINTK_PENDING_OUTPUT bit is cleared by console_unlock().
+		 */
 		if (console_trylock())
 			console_unlock();
 	}
-- 
2.13.0

[RFC][PATCHv4 3/7] printk: add enforce_emergency parameter

[Sergey Senozhatsky]

This param permits user-space to forcibly on/off printk emergency
mode via /sys/module/printk/parameters/enforce_emergency node.

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 45e585624ced..a1d3a69a023b 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -457,9 +457,15 @@ static DEFINE_PER_CPU(struct task_struct *, printk_kthread);
 static atomic_t printk_emergency __read_mostly;
 /*
  * Disable printk_kthread permanently. Unlike `oops_in_progress'
- * it doesn't go back to 0.
+ * it doesn't go back to 0 (unless set by user-space).
  */
 static bool printk_enforce_emergency __read_mostly;
+
+module_param_named(enforce_emergency, printk_enforce_emergency,
+		    bool, 0644);
+MODULE_PARM_DESC(printk_enforce_emergency,
+		 "don't offload message printing to printk kthread");
+
 /*
  * The number of lines a task can print before offloading printing
  * job to printk_kthread. 0 indicates 'no limit'.
-- 
2.13.0

[RFC][PATCHv4 4/7] printk: enable printk offloading

[Sergey Senozhatsky]

Initialize kernel printing thread and make printk offloading
possible. By default `atomic_print_limit' is set to 0, so no
offloading will take place, unless requested by user.

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a1d3a69a023b..ed0df3d21215 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2942,6 +2942,60 @@ static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
 	.flags = IRQ_WORK_LAZY,
 };
 
+static void printk_kthread_func(unsigned int cpu)
+{
+	while (1) {
+		set_current_state(TASK_INTERRUPTIBLE);
+		if (!test_bit(PRINTK_PENDING_OUTPUT, &printk_pending))
+			schedule();
+
+		__set_current_state(TASK_RUNNING);
+
+		if (kthread_should_stop())
+			break;
+
+		if (kthread_should_park()) {
+			kthread_parkme();
+			/* We might have been woken for stop */
+			continue;
+		}
+
+		console_lock();
+		console_unlock();
+	}
+}
+
+static int printk_kthread_should_run(unsigned int cpu)
+{
+	return test_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
+}
+
+static struct smp_hotplug_thread printk_kthreads = {
+	.store			= &printk_kthread,
+	.thread_should_run	= printk_kthread_should_run,
+	.thread_fn		= printk_kthread_func,
+	.thread_comm		= "printk/%u",
+};
+
+/*
+ * Init printk kthread at late_initcall stage, after core/arch/device/etc.
+ * initialization.
+ */
+static int __init init_printk_kthreads(void)
+{
+	cpumask_copy(&printk_cpumask, cpu_possible_mask);
+
+	if (smpboot_register_percpu_thread_cpumask(&printk_kthreads,
+						   &printk_cpumask)) {
+		printk_enforce_emergency = true;
+		pr_err("printk: failed to create threads\n");
+		return -EINVAL;
+	}
+
+	return 0;
+}
+late_initcall(init_printk_kthreads);
+
 void wake_up_klogd(void)
 {
 	preempt_disable();
-- 
2.13.0

[RFC][PATCHv4 5/7] printk: register PM notifier

[Sergey Senozhatsky]

It's not always possible/safe to wake_up() printk kernel
thread. For example, late suspend/early resume may printk()
while timekeeping is not initialized yet, so calling into the
scheduler may result in recursive warnings.

Another thing to notice is the fact PM at some point
freezes user space and kernel threads: freeze_processes()
and freeze_kernel_threads(), correspondingly. Thus we need
printk() to operate in emergency mode there and attempt to
immediately flush pending kernel message to the console.

This patch registers PM notifier, so PM can switch printk
to emergency mode from PM_FOO_PREPARE notifiers and return
back to printk threaded mode from PM_POST_FOO notifiers.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Suggested-by: Andreas Mohr <andi@lisas.de>
---
 kernel/printk/printk.c | 35 +++++++++++++++++++++++++++++++++++
 1 file changed, 35 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ed0df3d21215..5b2b97ee3440 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -50,6 +50,7 @@
 #include <linux/sched/task_stack.h>
 #include <linux/kthread.h>
 #include <linux/smpboot.h>
+#include <linux/suspend.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -2942,6 +2943,33 @@ static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
 	.flags = IRQ_WORK_LAZY,
 };
 
+static int printk_pm_notify(struct notifier_block *notify_block,
+			    unsigned long mode, void *unused)
+{
+	switch (mode) {
+	case PM_HIBERNATION_PREPARE:
+	case PM_SUSPEND_PREPARE:
+	case PM_RESTORE_PREPARE:
+		printk_emergency_begin();
+		break;
+
+	case PM_POST_SUSPEND:
+	case PM_POST_HIBERNATION:
+	case PM_POST_RESTORE:
+		printk_emergency_end();
+		break;
+
+	default:
+		return NOTIFY_DONE;
+	}
+
+	return NOTIFY_OK;
+}
+
+static struct notifier_block printk_pm_nb = {
+	.notifier_call = printk_pm_notify,
+};
+
 static void printk_kthread_func(unsigned int cpu)
 {
 	while (1) {
@@ -2992,6 +3020,13 @@ static int __init init_printk_kthreads(void)
 		return -EINVAL;
 	}
 
+	if (register_pm_notifier(&printk_pm_nb) != 0) {
+		printk_enforce_emergency = true;
+		smpboot_unregister_percpu_thread(&printk_kthreads);
+		pr_err("printk: unable to register PM notifier\n");
+		return -EINVAL;
+	}
+
 	return 0;
 }
 late_initcall(init_printk_kthreads);
-- 
2.13.0

[RFC][PATCHv4 6/7] printk: register syscore notifier

[Sergey Senozhatsky]

We need to switch to emergency printk mode in kernel_kexec(). One
kernel_kexec() branch calls kernel_restart_prepare(), which updates
`system_state', however, the other one, when user requested to
->preserve_context, does not and we are lacking the information
in printk about kexec being executed. Register a syscore notifier
so printk will be notified by syscore_suspend().

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 5b2b97ee3440..4e5233a265cb 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -51,6 +51,7 @@
 #include <linux/kthread.h>
 #include <linux/smpboot.h>
 #include <linux/suspend.h>
+#include <linux/syscore_ops.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -2970,6 +2971,22 @@ static struct notifier_block printk_pm_nb = {
 	.notifier_call = printk_pm_notify,
 };
 
+static int printk_pm_syscore_suspend(void)
+{
+	printk_emergency_begin();
+	return 0;
+}
+
+static void printk_pm_syscore_resume(void)
+{
+	printk_emergency_end();
+}
+
+static struct syscore_ops printk_pm_syscore_ops = {
+	.suspend = printk_pm_syscore_suspend,
+	.resume = printk_pm_syscore_resume,
+};
+
 static void printk_kthread_func(unsigned int cpu)
 {
 	while (1) {
@@ -3027,6 +3044,7 @@ static int __init init_printk_kthreads(void)
 		return -EINVAL;
 	}
 
+	register_syscore_ops(&printk_pm_syscore_ops);
 	return 0;
 }
 late_initcall(init_printk_kthreads);
-- 
2.13.0

[RFC][PATCHv4 7/7] printk: add printk cpumask sysctl

[Sergey Senozhatsky]

Add `sysctl kernel.printk_cpumask' knob so user can enforce printk
kthread cpumask and control both the number of kthreads we wake up
during printk offloading and the CPUs those wake ups happen.

For example,

    sysctl kernel.printk_cpumask = 0-3

will force printk to offload printing only to CPU0-CPU3.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 include/linux/printk.h |  4 ++++
 kernel/printk/printk.c | 32 ++++++++++++++++++++++++++++++++
 kernel/sysctl.c        |  7 +++++++
 3 files changed, 43 insertions(+)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index e10f27468322..200499b9f23a 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -81,6 +81,7 @@ static inline void console_verbose(void)
 #define DEVKMSG_STR_MAX_SIZE 10
 extern char devkmsg_log_str[];
 struct ctl_table;
+extern unsigned long *printk_cpumask_bits;
 
 struct va_format {
 	const char *fmt;
@@ -196,6 +197,9 @@ devkmsg_sysctl_set_loglvl(struct ctl_table *table, int write, void __user *buf,
 
 extern void wake_up_klogd(void);
 
+extern int proc_printk_cpumask(struct ctl_table *table, int write,
+			  void __user *buffer, size_t *lenp, loff_t *ppos);
+
 char *log_buf_addr_get(void);
 u32 log_buf_len_get(void);
 void log_buf_vmcoreinfo_setup(void);
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 4e5233a265cb..46d82faf8613 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -3049,6 +3049,38 @@ static int __init init_printk_kthreads(void)
 }
 late_initcall(init_printk_kthreads);
 
+#ifdef CONFIG_SYSCTL
+static DEFINE_MUTEX(printk_kthread_proc_mutex);
+unsigned long *printk_cpumask_bits = cpumask_bits(&printk_cpumask);
+
+/*
+ * Update printk kthread cpumask, so user can limit the number of printk
+ * kthreads we wake up during printing offloading.
+ */
+int proc_printk_cpumask(struct ctl_table *table, int write,
+			void __user *buffer, size_t *lenp, loff_t *ppos)
+{
+	int err;
+
+	mutex_lock(&printk_kthread_proc_mutex);
+
+	if (printk_enforce_emergency)
+		goto out;
+
+	err = proc_do_large_bitmap(table, write, buffer, lenp, ppos);
+	if (!err && write) {
+		if (smpboot_update_cpumask_percpu_thread(&printk_kthreads,
+							 &printk_cpumask)) {
+			printk_enforce_emergency = true;
+			pr_err("printk: can't update cpumask\n");
+		}
+	}
+out:
+	mutex_unlock(&printk_kthread_proc_mutex);
+	return err;
+}
+#endif
+
 void wake_up_klogd(void)
 {
 	preempt_disable();
diff --git a/kernel/sysctl.c b/kernel/sysctl.c
index df9f2a367882..d03dc7fa4f7f 100644
--- a/kernel/sysctl.c
+++ b/kernel/sysctl.c
@@ -853,6 +853,13 @@ static struct ctl_table kern_table[] = {
 		.extra1		= &zero,
 		.extra2		= &two,
 	},
+	{
+		.procname	= "printk_cpumask",
+		.data		= &printk_cpumask_bits,
+		.maxlen		= NR_CPUS,
+		.mode		= 0644,
+		.proc_handler	= proc_printk_cpumask,
+	},
 #endif
 	{
 		.procname	= "ngroups_max",
-- 
2.13.0

Re: [RFC][PATCHv4 0/7] printk: introduce printing kernel threads

[Sergey Senozhatsky]

Hello,

On (06/02/17 18:03), Sergey Senozhatsky wrote:
[..]
> 	I've managed to reproduce some of the issues with a single printk
> kthread solution that Jan Kara talked about. Sometimes scheduler decides
> sometimes scheduler decides that printk kthread should run on the same CPU
> as the process that is doing printing, so printk kthread never takes over
> and systems eventually lockups. With SMP threads we can wake up printk
> kthread on a remote CPU (and we know that it will be woken up on a remote
> CPU), so per my tests SMP thread-ed version of printing offloading works
> much better. But more tests are needed.
> 
> 	The patch set is in RFC stage. I think I'll move the whole
> offloading thing under CONFIG_PRINTK_OFFLOAD (e.g.) at some point.
> 
> 	As a side note, seems that with the SMP threaded implementation
> we can do (there are some constraints (!!), of course) some sort of less
> deadlock prone printk. Instead of calling into the scheduler, console_sem,
> console_unlock(), we can wake_up printk_kthread on a foreign CPU. So we will
> not take scheduler locks or console locks from this CPU. (very-very
> schematically):
> 
> int vprintk_emit(....)
> {
> 	logbuf_lock_irqsave(flags);
> 
> 	[..]
> 	printed_len += log_output(facility, level, lflags, dict, dictlen, text, text_len);
> 
> 	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
> 
> 	for_each_cpu_and(cpu, cpu_online_mask, &printk_cpumask) {
> 		if (cpu != smp_processor_id())
> 			wake_up_process(per_cpu(printk_kthread, cpu));
> 	}
> 
> 	logbuf_unlock_irqrestore(flags);
> 	return printed_len;
> }

to be clear, this patch set is a RFC to "just another idea to try out".
it's not meant to be "the final proposal". it has it's pros and cons.


so yet one more alternative solution... here it goes


for offloading don't just wake_up_process(printk_kthread) and hope for
the best, but instead queue IRQ work on foreign CPUs that would try to
bring up the printk_kthread.. CPUs that can process IRQ also can do
rescheduling and probably will have better chances to wake_up printk_kthread
than current printing CPU.



in other words, in console_offload_printing() do something like this
(composed in email client)


	for_each_cpu_and(cpu, cpu_online_mask, &printk_cpumask) {
		set_bit(PRINTK_PENDING_PRINTK_OFFLOAD, &printk_pending);
		irq_work_queue_on(per_cpu_ptr(&wake_up_klogd_work, cpu), cpu);
	}


and in wake_up_klogd_work_func() do

	if (test_and_clear_bit(PRINTK_PENDING_PRINTK_OFFLOAD, &printk_pending))
		wake_up_process(printk_kthread);


and _probably_ we can do two things in wake_up_klogd_work_func() for
PRINTK_PENDING_PRINTK_OFFLOAD. both wake_up() printk_kthread  AND
"if (console_trylock()) console_unlock()". like this:


	if (test_and_clear_bit(PRINTK_PENDING_PRINTK_OFFLOAD, &printk_pending)) {
		wake_up_process(printk_kthread);

		if (console_trylock())
			console_unlock();
	}


the rational is that one of the CPUs has requested offloading and we need to
help that CPU out. that console_unlock() from wake_up_klogd_work_func() will
be under the same `atomic_print_limit' constrains, so it will eventually request
offloading, if there will be too many messages to handle. hopefully not too
late.

we still don't have guarantees that printk_kthread will be scheduled on
a CPU that can run it immediately or anytime in the future, but not too
late. printk_kthread can even be scheduled on the CPU that has requested
offloading in the first place (am I wrong on this assumption?). which means
that printk_kthread may not be able to take over (think of a printk() dump
from IRQ context). that's the reason why I additionally want to
console_trylock() for PRINTK_PENDING_PRINTK_OFFLOAD.


but console_trylock() is not really reliable. not at all. it's a very fast
one shot action that most likely will see console_sem still being locked
but the CPU that has requested offloading. I want something to wait on
console_sem, that's reliably. and we need woken up (running) printk_kthread
for that.


may be... we can set CPU affinity on printk_kthread before we wake it up?
place into rq of the CPU that is processing PRINTK_PENDING_PRINTK_OFFLOAD?

or allow it on any CPU but the currently printing CPU.

or have per-CPU printk kthreads and wake_up processes that are already
bound to specific rq-s. (I know it's ugly, to put it politely. I'm just
trying different solutions/approaches).

	-ss

Re: [RFC][PATCHv4 0/7] printk: introduce printing kernel threads

[Petr Mladek]

On Thu 2017-06-08 17:18:29, Sergey Senozhatsky wrote:
> we still don't have guarantees that printk_kthread will be scheduled on
> a CPU that can run it immediately or anytime in the future, but not too
> late. printk_kthread can even be scheduled on the CPU that has requested
> offloading in the first place (am I wrong on this assumption?). which means
> that printk_kthread may not be able to take over (think of a printk() dump
> from IRQ context). that's the reason why I additionally want to
> console_trylock() for PRINTK_PENDING_PRINTK_OFFLOAD.
> 
> 
> but console_trylock() is not really reliable. not at all. it's a very fast
> one shot action that most likely will see console_sem still being locked
> but the CPU that has requested offloading. I want something to wait on
> console_sem, that's reliably. and we need woken up (running) printk_kthread
> for that.
> 
> 
> may be... we can set CPU affinity on printk_kthread before we wake it up?
> place into rq of the CPU that is processing PRINTK_PENDING_PRINTK_OFFLOAD?
> 
> or allow it on any CPU but the currently printing CPU.
> 
> or have per-CPU printk kthreads and wake_up processes that are already
> bound to specific rq-s. (I know it's ugly, to put it politely. I'm just
> trying different solutions/approaches).

My head is whirling when thinking about all the per-CPU stuff. It is
looking for escape. The way is to keep it as simple as possible.

After all, we should need all this only when there is a flood of
messages. Otherwise, the messages should be handled immediately
within atomic_print_limit.

If there is a flood of messages and we do not sleep inside
console_unlock(), there should always be a new volunteer that
would continue with console flushing.

It the flood stops and the system works, we should have enough
time to recover. If the system stops working during the flood
then I am afraid that even the per-CPU kthreads would not help
much.

Does this makes sense? Or did my head hide some important aspect
again?

Best Regards,
Petr

Re: [RFC][PATCHv4 0/7] printk: introduce printing kernel threads

[Sergey Senozhatsky]

On (06/28/17 15:42), Petr Mladek wrote:
[..]
> My head is whirling when thinking about all the per-CPU stuff. It is
> looking for escape. The way is to keep it as simple as possible.
> 
> After all, we should need all this only when there is a flood of
> messages. Otherwise, the messages should be handled immediately
> within atomic_print_limit.
> 
> If there is a flood of messages and we do not sleep inside
> console_unlock(), there should always be a new volunteer that
> would continue with console flushing.
> 
> It the flood stops and the system works, we should have enough
> time to recover. If the system stops working during the flood
> then I am afraid that even the per-CPU kthreads would not help
> much.
> 
> Does this makes sense? Or did my head hide some important aspect
> again?

yeah, I agree and understand that per-CPU printk kthreads
is a bit... too much.

it was just a quick idea and I just gave it a try. but there
are some potential takeaways from the series (not sure if you
looked at the last patches of the series).

with per-CPU kthreads we easily

1) can be quite flexible
   there can be only certain CPUs that will take over printing duty.
   so if you system has, say, IRQ affinity set up or anything else
   that is critical, you can forbid printk offloading to those CPUs.
   so "important" CPUs will not print out more than atomic_limit chars,
   the rest of the job will be handled by "less important" CPUs.

   * this can be achieved with a single printk kthread.
     but still, that's something I haven't thought about before this
     series.


2) can offload printing to other CPUs from vprintk_emit()
   and avoid any of scheduler->timekeeping->etc. paths. which will
   replace printk_deferred().

   * this can be achieved with a single printk kthread as well.
   ** at the same time this kills the direct print out guarantees.


there was something else. but I forgot what was it...

	-ss

Re: [RFC][PATCHv4 0/7] printk: introduce printing kernel threads

[Petr Mladek]

On Thu 2017-06-29 16:56:30, Sergey Senozhatsky wrote:
> yeah, I agree and understand that per-CPU printk kthreads
> is a bit... too much.
> 
> it was just a quick idea and I just gave it a try. but there
> are some potential takeaways from the series (not sure if you
> looked at the last patches of the series).
> 
> with per-CPU kthreads we easily
> 
> 1) can be quite flexible
>    there can be only certain CPUs that will take over printing duty.
>    so if you system has, say, IRQ affinity set up or anything else
>    that is critical, you can forbid printk offloading to those CPUs.
>    so "important" CPUs will not print out more than atomic_limit chars,
>    the rest of the job will be handled by "less important" CPUs.
> 
>    * this can be achieved with a single printk kthread.
>      but still, that's something I haven't thought about before this
>      series.

Sounds interesting. Well, I would prefer to leave this for
further optimization. It is a completely new area and it might
open another can of worms.

> 2) can offload printing to other CPUs from vprintk_emit()
>    and avoid any of scheduler->timekeeping->etc. paths. which will
>    replace printk_deferred().

I probably miss something. There is still called wake_up_process()
in this patchset and we could not do this in some scheduler and
timekeeping paths. Also we must not take the console_lock() in
these paths because it calls wake_up_process() as well. But
we want to flush few lines when possible.

Best Regards,
Petr

Re: [RFC][PATCHv4 0/7] printk: introduce printing kernel threads

[Sergey Senozhatsky]

On (06/30/17 14:11), Petr Mladek wrote:
> > 2) can offload printing to other CPUs from vprintk_emit()
> >    and avoid any of scheduler->timekeeping->etc. paths. which will
> >    replace printk_deferred().
> 
> I probably miss something. There is still called wake_up_process()
> in this patchset and we could not do this in some scheduler and
> timekeeping paths. Also we must not take the console_lock() in
> these paths because it calls wake_up_process() as well. But
> we want to flush few lines when possible.

yes. but we could call wake_up_process() on !this_cpu.
so we wouldn't take this_cpu ->rq lock and so on.

	CPU1

	vprintk_emit()
		wake_up_process(printk_kthread on CPU2);

	-ss