Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1611720 > unrolled thread

[RFC][PATCHv2 0/8] printk: introduce printing kernel thread

Back to article view | Back to linux.kernel

Contents

  [RFC][PATCHv2 0/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:30 +0200
    [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:30 +0200
      Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Petr Mladek <pmladek@suse.com> - 2017-04-04 11:10 +0200
        Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-04 11:40 +0200
      Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Pavel Machek <pavel@ucw.cz> - 2017-04-06 19:20 +0200
        Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 07:20 +0200
          Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Pavel Machek <pavel@ucw.cz> - 2017-04-07 09:30 +0200
            Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 10:20 +0200
              Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread Pavel Machek <pavel@ucw.cz> - 2017-04-07 14:10 +0200
    [RFC][PATCHv2 5/8] sysrq: switch to printk.emergency mode in unsafe places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:30 +0200
      Re: [RFC][PATCHv2 5/8] sysrq: switch to printk.emergency mode in  unsafe places Petr Mladek <pmladek@suse.com> - 2017-03-31 17:40 +0200
        Re: [RFC][PATCHv2 5/8] sysrq: switch to printk.emergency mode in  unsafe places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-01 02:10 +0200
    [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Petr Mladek <pmladek@suse.com> - 2017-03-31 15:20 +0200
        Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Peter Zijlstra <peterz@infradead.org> - 2017-03-31 15:40 +0200
          Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-03 13:30 +0200
            Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu Petr Mladek <pmladek@suse.com> - 2017-04-03 14:50 +0200
    [RFC][PATCHv2 6/8] kexec: switch to printk.emergency mode in unsafe places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [RFC][PATCHv2 6/8] kexec: switch to printk.emergency mode in  unsafe places Petr Mladek <pmladek@suse.com> - 2017-03-31 17:40 +0200
    [RFC][PATCHv2 8/8] printk: enable printk offloading Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-03-31 04:40 +0200
        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-03-31 06:10 +0200
          Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Ye Xiaolong <xiaolong.ye@intel.com> - 2017-03-31 08:50 +0200
            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-31 16:50 +0200
              Re: [printk]  fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage ebiederm@xmission.com (Eric W. Biederman) - 2017-03-31 17:40 +0200
                Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Jan Kara <jack@suse.cz> - 2017-04-03 11:40 +0200
                  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Petr Mladek <pmladek@suse.com> - 2017-04-03 12:10 +0200
                  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-06 19:40 +0200
                    Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 06:50 +0200
                      Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-07 09:20 +0200
                        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 09:50 +0200
                          Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-07 10:20 +0200
                            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-07 14:20 +0200
                              Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-07 14:50 +0200
                                Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Steven Rostedt <rostedt@goodmis.org> - 2017-04-07 16:50 +0200
                                Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-07 17:20 +0200
                                  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Peter Zijlstra <peterz@infradead.org> - 2017-04-07 17:30 +0200
                                    Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-07 17:50 +0200
                                      Re: [printk]  fbc14616f4: BUG:kernel_reboot-without-warning_in_test_stage ebiederm@xmission.com (Eric W. Biederman) - 2017-04-09 20:30 +0200
                                        Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-10 06:50 +0200
                                  Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-09 12:20 +0200
                                    Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-10 07:00 +0200
                                      Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Petr Mladek <pmladek@suse.com> - 2017-04-10 14:00 +0200
                            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Steven Rostedt <rostedt@goodmis.org> - 2017-04-07 16:40 +0200
                              Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Pavel Machek <pavel@ucw.cz> - 2017-04-09 12:00 +0200
                Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-03 13:00 +0200
            Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Ye Xiaolong <xiaolong.ye@intel.com> - 2017-04-05 09:40 +0200
              Re: [printk]  fbc14616f4:  BUG:kernel_reboot-without-warning_in_test_stage Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-05 10:50 +0200
      Re: [RFC][PATCHv2 8/8] printk: enable printk offloading Petr Mladek <pmladek@suse.com> - 2017-04-03 17:50 +0200
        Re: [RFC][PATCHv2 8/8] printk: enable printk offloading Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-04 14:30 +0200
    [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Petr Mladek <pmladek@suse.com> - 2017-03-31 17:10 +0200
      Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Pavel Machek <pavel@ucw.cz> - 2017-04-06 19:30 +0200
        Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Andreas Mohr <andi@lisas.de> - 2017-04-09 13:00 +0200
          Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Petr Mladek <pmladek@suse.com> - 2017-04-10 14:30 +0200
            Re: [RFC][PATCHv2 4/8] pm: switch to printk.emergency mode in unsafe  places Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-04-10 16:40 +0200
    [RFC][PATCHv2 7/8] printk: add printk emergency_mode parameter Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-03-29 11:40 +0200
      Re: [RFC][PATCHv2 7/8] printk: add printk emergency_mode parameter Petr Mladek <pmladek@suse.com> - 2017-04-03 17:30 +0200
        Re: [RFC][PATCHv2 7/8] printk: add printk emergency_mode parameter Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-04-04 10:30 +0200

Page 1 of 3  [1] 2 3  Next page →

#1611720 — [RFC][PATCHv2 0/8] printk: introduce printing kernel thread

Hello

	RFC

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

	The biggest difference compared to v1 is a further expansion of
"switch to old printk() mode", which we now call printk_emergency mode,
annotations (pm, kexec, sysrq).

	We also have a bunch of other ideas to try out/consider (not in
this patch set). E.g. automatic printk_emergency switch on printk_kthread
stalls (when we can't run printk_kthread), moving klogd irq_work out of
per-CPU memory, and so on.

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 (8):
  printk: move printk_pending out of per-cpu
  printk: introduce printing kernel thread
  printk: offload printing from wake_up_klogd_work_func()
  pm: switch to printk.emergency mode in unsafe places
  sysrq: switch to printk.emergency mode in unsafe places
  kexec: switch to printk.emergency mode in unsafe places
  printk: add printk emergency_mode parameter
  printk: enable printk offloading

 drivers/tty/sysrq.c      |   7 ++
 include/linux/console.h  |   3 +
 kernel/kexec_core.c      |   4 ++
 kernel/power/hibernate.c |   8 +++
 kernel/power/suspend.c   |   4 ++
 kernel/printk/printk.c   | 178 +++++++++++++++++++++++++++++++++++++++++------
 6 files changed, 182 insertions(+), 22 deletions(-)

-- 
2.12.2

[toc] | [next] | [standalone]

#1611722 — [RFC][PATCHv2 2/8] printk: introduce printing kernel thread

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. Thus, 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,
and more.

This patch introduces a dedicated printing kernel thread - printk_kthread.
The main purpose of this kthread is to offload printing to a non-atomic
and always scheduleable context, which eliminates 4) and makes 1)-3) less
critical. printk() now just appends log messages to the kernel log buffer
and wake_up()s printk_kthread instead of locking console_sem and calling
into potentially unsafe console_unlock().

This, however, is not always safe on its own. For example, we can't call
into the scheduler from panic(), because this may cause deadlock. That's
why we introduce a concept of printk_emergency() mode, when printk()
switches back to the old behaviour (console_unlock() from vprintk_emit())
in those cases. In general, this switch happens automatically once a EMERG
log level message appears in the log buffer. Another cases when wake_up()
might not work as expected are suspend, hibernate, etc. For those situations
we provide two new functions:
 -- 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.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Signed-off-by: Jan Kara <jack@suse.cz>
---
 include/linux/console.h |   3 ++
 kernel/printk/printk.c  | 107 ++++++++++++++++++++++++++++++++++++++++++++----
 2 files changed, 102 insertions(+), 8 deletions(-)

diff --git a/include/linux/console.h b/include/linux/console.h
index 5949d1855589..f1a86944072e 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 2d07678e9ff9..ab6b3b2a68c6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -48,6 +48,7 @@
 #include <linux/sched/clock.h>
 #include <linux/sched/debug.h>
 #include <linux/sched/task_stack.h>
+#include <linux/kthread.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -402,7 +403,8 @@ DEFINE_RAW_SPINLOCK(logbuf_lock);
 	} while (0)
 
 /*
- * 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
@@ -445,6 +447,42 @@ 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 task_struct *printk_kthread __read_mostly;
+/*
+ * 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_kthread_disabled __read_mostly;
+
+static inline bool printk_kthread_enabled(void)
+{
+	return !printk_kthread_disabled &&
+		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);
+}
+
 /* Return log buffer address */
 char *log_buf_addr_get(void)
 {
@@ -1765,17 +1803,40 @@ 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_kthread_disabled = true;
+
+	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
 	if (!in_sched) {
 		/*
-		 * Try to acquire and then immediately release the console
-		 * semaphore.  The release will print out buffers and wake up
-		 * /dev/kmsg and syslog() users.
+		 * Under heavy printing load/slow serial console/etc
+		 * console_unlock() can stall CPUs, which can result in
+		 * soft/hard-lockups, lost interrupts, RCU stalls, etc.
+		 * Therefore we attempt to print the messages to console
+		 * from a dedicated printk_kthread, which always runs in
+		 * schedulable context.
 		 */
-		if (console_trylock())
-			console_unlock();
+		if (printk_kthread_enabled()) {
+			printk_safe_enter_irqsave(flags);
+			wake_up_process(printk_kthread);
+			printk_safe_exit_irqrestore(flags);
+		} else {
+			/*
+			 * Try to acquire and then immediately release the
+			 * console semaphore. The release will print out
+			 * buffers and wake up /dev/kmsg and syslog() users.
+			 */
+			if (console_trylock())
+				console_unlock();
+		}
 	}
 
 	return printed_len;
@@ -1882,6 +1943,9 @@ 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) {}
+
 #endif /* CONFIG_PRINTK */
 
 #ifdef CONFIG_EARLY_PRINTK
@@ -2164,6 +2228,13 @@ void console_unlock(void)
 	bool do_cond_resched, retry;
 
 	if (console_suspended) {
+		/*
+		 * 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;
 	}
@@ -2182,6 +2253,7 @@ void console_unlock(void)
 	console_may_schedule = 0;
 
 again:
+	clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
 	/*
 	 * We released the console_sem lock, so we need to recheck if
 	 * cpu is online and (if not) is there at least one CON_ANYTIME
@@ -2664,8 +2736,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();
 	}
@@ -2679,6 +2754,22 @@ static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
 	.flags = IRQ_WORK_LAZY,
 };
 
+static int printk_kthread_func(void *data)
+{
+	while (1) {
+		set_current_state(TASK_INTERRUPTIBLE);
+		if (!test_bit(PRINTK_PENDING_OUTPUT, &printk_pending))
+			schedule();
+
+		__set_current_state(TASK_RUNNING);
+
+		console_lock();
+		console_unlock();
+	}
+
+	return 0;
+}
+
 void wake_up_klogd(void)
 {
 	preempt_disable();
-- 
2.12.2

[toc] | [prev] | [next] | [standalone]

#1615809 — Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread

On Wed 2017-03-29 18:25:05, Sergey Senozhatsky wrote:
> This patch introduces a dedicated printing kernel thread - printk_kthread.
> The main purpose of this kthread is to offload printing to a non-atomic
> and always scheduleable context, which eliminates 4) and makes 1)-3) less
> critical. printk() now just appends log messages to the kernel log buffer
> and wake_up()s printk_kthread instead of locking console_sem and calling
> into potentially unsafe console_unlock().
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 2d07678e9ff9..ab6b3b2a68c6 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -445,6 +447,42 @@ 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 task_struct *printk_kthread __read_mostly;
> +/*
> + * 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.
> + */

The comment is not valid once we allow to modify the variable using
the sysfs knob.

> @@ -1765,17 +1803,40 @@ 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_kthread_disabled = true;
> +
> +	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
>  	logbuf_unlock_irqrestore(flags);
>  
>  	/* If called from the scheduler, we can not call up(). */
>  	if (!in_sched) {
>  		/*
> -		 * Try to acquire and then immediately release the console
> -		 * semaphore.  The release will print out buffers and wake up
> -		 * /dev/kmsg and syslog() users.
> +		 * Under heavy printing load/slow serial console/etc
> +		 * console_unlock() can stall CPUs, which can result in
> +		 * soft/hard-lockups, lost interrupts, RCU stalls, etc.
> +		 * Therefore we attempt to print the messages to console
> +		 * from a dedicated printk_kthread, which always runs in
> +		 * schedulable context.
>  		 */
> -		if (console_trylock())
> -			console_unlock();
> +		if (printk_kthread_enabled()) {
> +			printk_safe_enter_irqsave(flags);
> +			wake_up_process(printk_kthread);
> +			printk_safe_exit_irqrestore(flags);

I am really happy that we have the printk_safe stuff available!

> +		} else {
> +			/*
> +			 * Try to acquire and then immediately release the
> +			 * console semaphore. The release will print out
> +			 * buffers and wake up /dev/kmsg and syslog() users.
> +			 */
> +			if (console_trylock())
> +				console_unlock();
> +		}
>  	}
>  
>  	return printed_len;
> @@ -1882,6 +1943,9 @@ 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) {}
> +
>  #endif /* CONFIG_PRINTK */
>  
>  #ifdef CONFIG_EARLY_PRINTK
> @@ -2164,6 +2228,13 @@ void console_unlock(void)
>  	bool do_cond_resched, retry;
>  
>  	if (console_suspended) {
> +		/*
> +		 * 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);

Great catch!

>  		up_console_sem();
>  		return;
>  	}
> @@ -2182,6 +2253,7 @@ void console_unlock(void)
>  	console_may_schedule = 0;
>  
>  again:
> +	clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);

This will not help if new messages appear during
call_console_drivers().

I would move this line after the for(;;) cycle. It will be
cleared when all messages are really handled.

Otherwise, it looks fine to me.

Best Regards,
Petr

[toc] | [prev] | [next] | [standalone]

#1615825 — Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread

On (04/04/17 11:01), Petr Mladek wrote:
[..]
> > +static atomic_t printk_emergency __read_mostly;
> > +/*
> > + * Disable printk_kthread permanently. Unlike `oops_in_progress'
> > + * it doesn't go back to 0.
> > + */
> 
> The comment is not valid once we allow to modify the variable using
> the sysfs knob.

it's updated in that patch (sysfs knob introduction).


[..]
> > @@ -2182,6 +2253,7 @@ void console_unlock(void)
> >  	console_may_schedule = 0;
> >  
> >  again:
> > +	clear_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
> 
> This will not help if new messages appear during
> call_console_drivers().

you are right. wouldn't do much harm (an extra console_unlock() from
printk_kthread in the worst case), but agree.

I added it there because of that "!can_use_console()" branch. not that
I expect printk_kthread being executed on !online CPU, but we might have
no callable consoles.

probably should have that clear_bit() before and after the loop.

	-ss

[toc] | [prev] | [next] | [standalone]

#1618209 — Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread

[Multipart message — attachments visible in raw view] — view raw

Hi!

> 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. Thus, 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,
> and more.

You have made good argumentation for not flushing unlimited ammount of
messages from printk() -- okay. But I don't think this is good idea:

> @@ -1765,17 +1803,40 @@ 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_kthread_disabled = true;
> +
> +	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);

Messages lower then _EMERG may be important, too.. and usually are,
for debugging.

And you keep both code paths, anyway, so they have to work. So you did
not really "fix" issues you are pointing out -- they still remain
there for _EMERG and above.

I agree that printing too much is a problem. Could you just print
"(messages delayed)" in that case, then wake a kernel thread to [rint
the rest?

								Pavel


>  	logbuf_unlock_irqrestore(flags);
>  
>  	/* If called from the scheduler, we can not call up(). */
>  	if (!in_sched) {
>  		/*
> -		 * Try to acquire and then immediately release the console
> -		 * semaphore.  The release will print out buffers and wake up
> -		 * /dev/kmsg and syslog() users.
> +		 * Under heavy printing load/slow serial console/etc
> +		 * console_unlock() can stall CPUs, which can result in
> +		 * soft/hard-lockups, lost interrupts, RCU stalls, etc.
> +		 * Therefore we attempt to print the messages to console
> +		 * from a dedicated printk_kthread, which always runs in
> +		 * schedulable context.
>  		 */
> -		if (console_trylock())
> -			console_unlock();
> +		if (printk_kthread_enabled()) {
> +			printk_safe_enter_irqsave(flags);
> +			wake_up_process(printk_kthread);
> +			printk_safe_exit_irqrestore(flags);
> +		} else {
> +			/*
> +			 * Try to acquire and then immediately release the
> +			 * console semaphore. The release will print out
> +			 * buffers and wake up /dev/kmsg and syslog() users.
> +			 */
> +			if (console_trylock())
> +				console_unlock();
> +		}
>  	}
>


-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [prev] | [next] | [standalone]

#1618481 — Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread

Hello,

On (04/06/17 19:14), Pavel Machek wrote:
[..]
> > @@ -1765,17 +1803,40 @@ 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_kthread_disabled = true;
> > +
> > +	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);
> 
> Messages lower then _EMERG may be important, too.. and usually are,
> for debugging.
> 
> And you keep both code paths, anyway, so they have to work. So you did
> not really "fix" issues you are pointing out -- they still remain
> there for _EMERG and above.

we don't drop messages of lower levels. we just print then from a
schedulable context. once the things go off the rails, and EMERG
is a good hint, I think, we stop being optimismitcs and switch to
a "best effort" mode. that is sort of reasonable. if there is a
flood of EMERG messages that are not actually important and,
basically, are result of a coding error, then, I think, the we
must fix that coding error. I mean, there should be some common
sense, and doing
		while (1)
			printk(KERN_EMERG "hello\n");
is probably not.


> I agree that printing too much is a problem. Could you just print
> "(messages delayed)" in that case, then wake a kernel thread to [rint
> the rest?

sorry, but what difference would it make?

it's really unclear at what point we should offload printing if we begin
that "we will offload sometimes". for example, I've seen many spin-lock
lockups where printk was involved.

	CPU0					CPU1		CPU2					CPU3

	spin_lock(&lock)					spin_lock(&lock)			spin_lock(&lock)
	printk("foo") // grabs the console_sem
	printk("bar")				printk("a")
						printk("b")
						printk("c")
						...
						printk("z")
								spin_dump()				spin_dump()
	  call_console_drivers()				 printk()				 printk()
	   serial_driver_write()				 printk()				 printk()
	    spin_lock_irqsave(port->lock)			 ...					 ...
	     uart_console_write(...)				 trigger_all_cpu_backtrace()		 trigger_all_cpu_backtrace()
	      serial_driver_putchar()
	       while (!txrdy(...))
	         cpu_relax()


spin_dump() and trigger_all_cpu_backtrace() result in a bunch of
additional printk()-s so CPU0 has even more job to do in console_unlock(),
while it still holds the contended spin_lock. and so on; there are
many other examples.

so should we declare a "we can spend only 2 seconds in direct printk()
and then must offload printing" rule? I don't think it's much better
than a simpler "we always offload, as long as we think it's safe".

	-ss

[toc] | [prev] | [next] | [standalone]

#1618525 — Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread

[Multipart message — attachments visible in raw view] — view raw

Hi!

> spin_dump() and trigger_all_cpu_backtrace() result in a bunch of
> additional printk()-s so CPU0 has even more job to do in console_unlock(),
> while it still holds the contended spin_lock. and so on; there are
> many other examples.
> 
> so should we declare a "we can spend only 2 seconds in direct printk()
> and then must offload printing" rule? I don't think it's much better
> than a simpler "we always offload, as long as we think it's safe".

I believe we should do the 2 seconds rule. It allows us to print "some
messages delayed" message, so at least whoever is trying to debug the
crash will have the hints that he needs to look at the printk system.

"we always offload, as long as we think it's safe" rule does not
really work, as printk() can not detect if it is safe or not.

									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [prev] | [next] | [standalone]

#1618566 — Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread

Hello,

On (04/07/17 09:21), Pavel Machek wrote:
> > spin_dump() and trigger_all_cpu_backtrace() result in a bunch of
> > additional printk()-s so CPU0 has even more job to do in console_unlock(),
> > while it still holds the contended spin_lock. and so on; there are
> > many other examples.
> > 
> > so should we declare a "we can spend only 2 seconds in direct printk()
> > and then must offload printing" rule? I don't think it's much better
> > than a simpler "we always offload, as long as we think it's safe".
> 
> I believe we should do the 2 seconds rule. It allows us to print "some
> messages delayed" message, so at least whoever is trying to debug the
> crash will have the hints that he needs to look at the printk system.

do you mean panic()? in panic() we call console_flush_on_panic(),
which immediately outputs all pending logbuf messages. printk()
offloading does not happen there.


> "we always offload, as long as we think it's safe" rule does not
> really work, as printk() can not detect if it is safe or not.

but "2 seconds" rule has that "as long as we think it's safe" string
attached as well. just because we do offloading. which is sometimes
un-safe. so regardless the timeout value (0 seconds or 2 seconds) we
still need some sort of a hint from the path that issues printk()
because that path (panic, kexec, sysrq, etc.) knows for sure when
things are abnormal. printk() is pretty clueless in this regard.
/* well, I still think that EMERG loglevel thing is not completely
 broken. */

	-ss

[toc] | [prev] | [next] | [standalone]

#1618714 — Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread

[Multipart message — attachments visible in raw view] — view raw

Hi!

> On (04/07/17 09:21), Pavel Machek wrote:
> > > spin_dump() and trigger_all_cpu_backtrace() result in a bunch of
> > > additional printk()-s so CPU0 has even more job to do in console_unlock(),
> > > while it still holds the contended spin_lock. and so on; there are
> > > many other examples.
> > > 
> > > so should we declare a "we can spend only 2 seconds in direct printk()
> > > and then must offload printing" rule? I don't think it's much better
> > > than a simpler "we always offload, as long as we think it's safe".
> > 
> > I believe we should do the 2 seconds rule. It allows us to print "some
> > messages delayed" message, so at least whoever is trying to debug the
> > crash will have the hints that he needs to look at the printk system.
> 
> do you mean panic()? in panic() we call console_flush_on_panic(),
> which immediately outputs all pending logbuf messages. printk()
> offloading does not happen there.

Not panic(). I have seen many crashes where we had printk(KERN_ERR)
and then hard hang. And the printk() was really important for debugging.

> > "we always offload, as long as we think it's safe" rule does not
> > really work, as printk() can not detect if it is safe or not.
> 
> but "2 seconds" rule has that "as long as we think it's safe" string
> attached as well. just because we do offloading. which is sometimes
> un-safe. so regardless the timeout value (0 seconds or 2 seconds) we
> still need some sort of a hint from the path that issues printk()
> because that path (panic, kexec, sysrq, etc.) knows for sure when
> things are abnormal. printk() is pretty clueless in this regard.
> /* well, I still think that EMERG loglevel thing is not completely
>  broken. */

Well, at least with my solution you know there are messages that were
not printed.

Yes, you'd still want to switch printk_now() for stuff like
panic(). But if you get it wrong (and you will), at least you will see
the "something is missing here" message in the log. 

								Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [prev] | [next] | [standalone]

#1611728 — [RFC][PATCHv2 5/8] sysrq: switch to printk.emergency mode in unsafe places

It's not always possible/safe to wake_up() printk kernel
thread from sysrq (theoretically). Thus we better switch
printk() to emergency mode in some of the sysrq handlers,
which allows us to immediately flush pending kernel message
to the console.

This patch adds printk_emergency_begin/on sections.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Suggested-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
---
 drivers/tty/sysrq.c | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/drivers/tty/sysrq.c b/drivers/tty/sysrq.c
index c6fc7141d7b2..817dfb69914d 100644
--- a/drivers/tty/sysrq.c
+++ b/drivers/tty/sysrq.c
@@ -49,6 +49,7 @@
 #include <linux/syscalls.h>
 #include <linux/of.h>
 #include <linux/rcupdate.h>
+#include <linux/console.h>
 
 #include <asm/ptrace.h>
 #include <asm/irq_regs.h>
@@ -239,6 +240,7 @@ static DECLARE_WORK(sysrq_showallcpus, sysrq_showregs_othercpus);
 
 static void sysrq_handle_showallcpus(int key)
 {
+	printk_emergency_begin();
 	/*
 	 * Fall back to the workqueue based printing if the
 	 * backtrace printing did not succeed or the
@@ -253,6 +255,7 @@ static void sysrq_handle_showallcpus(int key)
 		}
 		schedule_work(&sysrq_showallcpus);
 	}
+	printk_emergency_end();
 }
 
 static struct sysrq_key_op sysrq_showallcpus_op = {
@@ -279,8 +282,10 @@ static struct sysrq_key_op sysrq_showregs_op = {
 
 static void sysrq_handle_showstate(int key)
 {
+	printk_emergency_begin();
 	show_state();
 	show_workqueue_state();
+	printk_emergency_end();
 }
 static struct sysrq_key_op sysrq_showstate_op = {
 	.handler	= sysrq_handle_showstate,
@@ -291,7 +296,9 @@ static struct sysrq_key_op sysrq_showstate_op = {
 
 static void sysrq_handle_showstate_blocked(int key)
 {
+	printk_emergency_begin();
 	show_state_filter(TASK_UNINTERRUPTIBLE);
+	printk_emergency_end();
 }
 static struct sysrq_key_op sysrq_showstate_blocked_op = {
 	.handler	= sysrq_handle_showstate_blocked,
-- 
2.12.2

[toc] | [prev] | [next] | [standalone]

#1614115 — Re: [RFC][PATCHv2 5/8] sysrq: switch to printk.emergency mode in unsafe places

On Wed 2017-03-29 18:25:08, Sergey Senozhatsky wrote:
> It's not always possible/safe to wake_up() printk kernel
> thread from sysrq (theoretically). Thus we better switch
> printk() to emergency mode in some of the sysrq handlers,
> which allows us to immediately flush pending kernel message
> to the console.
>
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Suggested-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>

It looks like a decent selection. It is pity that some of
them might produce rather long output and theoretically
cause a softlookup. But I do not know about a better solution
at the moment. In each case, it will not be worse than before
this patchset.

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

[toc] | [prev] | [next] | [standalone]

#1614342 — Re: [RFC][PATCHv2 5/8] sysrq: switch to printk.emergency mode in unsafe places

Hello,

On (03/31/17 17:37), Petr Mladek wrote:
> On Wed 2017-03-29 18:25:08, Sergey Senozhatsky wrote:
> > It's not always possible/safe to wake_up() printk kernel
> > thread from sysrq (theoretically). Thus we better switch
> > printk() to emergency mode in some of the sysrq handlers,
> > which allows us to immediately flush pending kernel message
> > to the console.
> >
> > Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> > Suggested-by: Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>
> 
> It looks like a decent selection. It is pity that some of
> them might produce rather long output and theoretically
> cause a softlookup. But I do not know about a better solution
> at the moment. In each case, it will not be worse than before
> this patchset.

thanks.

this patch will be replaced with a more 'generic' one, which
I posted in reply yo Ye Xiaolong's report.

	-ss

[toc] | [prev] | [next] | [standalone]

#1611730 — [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu

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 2984fb0f0257..2d07678e9ff9 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -401,6 +401,14 @@ DEFINE_RAW_SPINLOCK(logbuf_lock);
 		printk_safe_exit_irqrestore(flags);	\
 	} while (0)
 
+/*
+ * Delayed printk version, for scheduler-internal messages:
+ */
+#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 */
@@ -2654,25 +2662,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);
 }
 
@@ -2685,7 +2683,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();
@@ -2701,7 +2699,7 @@ int printk_deferred(const char *fmt, ...)
 	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
 	va_end(args);
 
-	__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.12.2

[toc] | [prev] | [next] | [standalone]

#1614018 — Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu

On Wed 2017-03-29 18:25:04, Sergey Senozhatsky wrote:
> 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 2984fb0f0257..2d07678e9ff9 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -401,6 +401,14 @@ DEFINE_RAW_SPINLOCK(logbuf_lock);
>  		printk_safe_exit_irqrestore(flags);	\
>  	} while (0)
>  
> +/*
> + * Delayed printk version, for scheduler-internal messages:
> + */
> +#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 */
> @@ -2654,25 +2662,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);
>  }
>  
> @@ -2685,7 +2683,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);

We should add here a write barrier:

	/*
	 * irq_work_queue() uses cmpxchg() and implies the memory
	 * barrier only when the work is queued. An explicit barrier
	 * is needed here to make sure that wake_up_klogd_work_func()
	 * sees printk_pending set even when the work was already queued
	 * because of an other pending event.
	 */
	 smp_wmb();

>  		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
>  	}
>  	preempt_enable();
> @@ -2701,7 +2699,7 @@ int printk_deferred(const char *fmt, ...)
>  	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
>  	va_end(args);
>  
> -	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
> +	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);

Same here.

We are going to use printk_pending even more in the other patches.
I still have to check the final state. It might be useful
to define a helper if the barrier is needed on more locations.

Otherwise the change looks fine to me. It should reduce redundant
wakeups.

Best Regards,
Petr

[toc] | [prev] | [next] | [standalone]

#1614031 — Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu

On Fri, Mar 31, 2017 at 03:09:50PM +0200, Petr Mladek wrote:
> On Wed 2017-03-29 18:25:04, Sergey Senozhatsky wrote:

> >  	if (waitqueue_active(&log_wait)) {
> > -		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
> > +		set_bit(PRINTK_PENDING_WAKEUP, &printk_pending);
> 
> We should add here a write barrier:
> 
> 	/*
> 	 * irq_work_queue() uses cmpxchg() and implies the memory
> 	 * barrier only when the work is queued. An explicit barrier
> 	 * is needed here to make sure that wake_up_klogd_work_func()
> 	 * sees printk_pending set even when the work was already queued
> 	 * because of an other pending event.
> 	 */
> 	 smp_wmb();
> 
> >  		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> >  	}
> >  	preempt_enable();

smp_mb__after_atomic() is probably better, because if you're not
ordering with the cmpxchg, you're ordering against a load done by
cmpxchg to see it doesn't need to do anything.

[toc] | [prev] | [next] | [standalone]

#1615119 — Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu

On (03/31/17 15:33), Peter Zijlstra wrote:
> On Fri, Mar 31, 2017 at 03:09:50PM +0200, Petr Mladek wrote:
> > On Wed 2017-03-29 18:25:04, Sergey Senozhatsky wrote:
> 
> > >  	if (waitqueue_active(&log_wait)) {
> > > -		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
> > > +		set_bit(PRINTK_PENDING_WAKEUP, &printk_pending);
> > 
> > We should add here a write barrier:
> > 
> > 	/*
> > 	 * irq_work_queue() uses cmpxchg() and implies the memory
> > 	 * barrier only when the work is queued. An explicit barrier
> > 	 * is needed here to make sure that wake_up_klogd_work_func()
> > 	 * sees printk_pending set even when the work was already queued
> > 	 * because of an other pending event.
> > 	 */
> > 	 smp_wmb();
> > 
> > >  		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> > >  	}
> > >  	preempt_enable();
> 
> smp_mb__after_atomic() is probably better, because if you're not
> ordering with the cmpxchg, you're ordering against a load done by
> cmpxchg to see it doesn't need to do anything.

Petr and Peter, thanks for the review.

can you educate me, what exactly is broken there?

when called from console_unlock(), we have something as follows

	console_unlock()
	{
		for (;;) {
			spin_lock_irqsave();
			...
			spin_unlock_irqrestore();
			...
		}

		spin_unlock_irqrestore();

<<IRQs enabled>>

		if (wake_klogd)
			wake_up_klogd()
			{
				set_bit(PRINTK_PENDING_WAKEUP, &printk_pending);
				irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
			}
	}


we queue a per-CPU irq_work. given that by the time we execute wake_up_klogd()
we have local IRQs enabled on that CPU. is it possible that we will have that
CPU's irq_work still being queued?


when called from printk_deferred().

I'm still trying to understand what scenario can cause the problem. so
basically on that CPU we have a call into the scheduler/timer which ends
up in printk_deferred()... and then we have console_unlock()->wake_up_klogd()
//* local IRQs enabled but the irq_work is still queued *// and atop of it
we have IRQ that executes that CPU's run_list and fails to see updated
PRINTK_PENDING_WAKEUP bit, because wake_up_klogd() was called on already
queued wake_up_klogd_work. is this the case? if so, can this race happen on
the CPU?

I don't object the barrier, I'm just trying to have a better understanding
what's broken. sorry if I'm missing something very obvious.

	-ss

[toc] | [prev] | [next] | [standalone]

#1615173 — Re: [RFC][PATCHv2 1/8] printk: move printk_pending out of per-cpu

On Mon 2017-04-03 20:23:01, Sergey Senozhatsky wrote:
> On (03/31/17 15:33), Peter Zijlstra wrote:
> > On Fri, Mar 31, 2017 at 03:09:50PM +0200, Petr Mladek wrote:
> > > On Wed 2017-03-29 18:25:04, Sergey Senozhatsky wrote:
> > 
> > > >  	if (waitqueue_active(&log_wait)) {
> > > > -		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
> > > > +		set_bit(PRINTK_PENDING_WAKEUP, &printk_pending);
> > > 
> > > We should add here a write barrier:
> > > 
> > > 	/*
> > > 	 * irq_work_queue() uses cmpxchg() and implies the memory
> > > 	 * barrier only when the work is queued. An explicit barrier
> > > 	 * is needed here to make sure that wake_up_klogd_work_func()
> > > 	 * sees printk_pending set even when the work was already queued
> > > 	 * because of an other pending event.
> > > 	 */
> > > 	 smp_wmb();
> > > 
> > > >  		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> > > >  	}
> > > >  	preempt_enable();
> > 
> > smp_mb__after_atomic() is probably better, because if you're not
> > ordering with the cmpxchg, you're ordering against a load done by
> > cmpxchg to see it doesn't need to do anything.
> 
> Petr and Peter, thanks for the review.
> 
> can you educate me, what exactly is broken there?

Good point!

> when called from console_unlock(), we have something as follows
> 
> 	console_unlock()
> 	{
> 		for (;;) {
> 			spin_lock_irqsave();
> 			...
> 			spin_unlock_irqrestore();
> 			...
> 		}
> 
> 		spin_unlock_irqrestore();
> 
> <<IRQs enabled>>
> 
> 		if (wake_klogd)
> 			wake_up_klogd()
> 			{
> 				set_bit(PRINTK_PENDING_WAKEUP, &printk_pending);
> 				irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> 			}
> 	}
> 
> 
> we queue a per-CPU irq_work.

Ah, I forgot that irq_work is still per-CPU. In this case, everything
seems to be safe even without the barrier. The important thing is that
there always will be queued an irq_work that will see and handle the
bit. I believe that the barrier would be needed if the irq_work was
global.

I am sorry for the noise.

Best Regards,
Petr

[toc] | [prev] | [next] | [standalone]

#1611731 — [RFC][PATCHv2 6/8] kexec: switch to printk.emergency mode in unsafe places

Switch to printk emergency mode in kernel_kexec(), this
lets us to immediately flush pending kernel message to
the console and to avoid potentially unsafe calls into
the scheduler.

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

diff --git a/kernel/kexec_core.c b/kernel/kexec_core.c
index bfe62d5b3872..5684ba36ec15 100644
--- a/kernel/kexec_core.c
+++ b/kernel/kexec_core.c
@@ -1496,6 +1496,8 @@ int kernel_kexec(void)
 		goto Unlock;
 	}
 
+	printk_emergency_begin();
+
 #ifdef CONFIG_KEXEC_JUMP
 	if (kexec_image->preserve_context) {
 		lock_system_sleep();
@@ -1565,6 +1567,8 @@ int kernel_kexec(void)
 	}
 #endif
 
+	printk_emergency_end();
+
  Unlock:
 	mutex_unlock(&kexec_mutex);
 	return error;
-- 
2.12.2

[toc] | [prev] | [next] | [standalone]

#1614122 — Re: [RFC][PATCHv2 6/8] kexec: switch to printk.emergency mode in unsafe places

On Wed 2017-03-29 18:25:09, Sergey Senozhatsky wrote:
> Switch to printk emergency mode in kernel_kexec(), this
> lets us to immediately flush pending kernel message to
> the console and to avoid potentially unsafe calls into
> the scheduler.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

Looks fine and works as expected.

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

[toc] | [prev] | [next] | [standalone]

#1611739 — [RFC][PATCHv2 8/8] printk: enable printk offloading

Initialize the kernel printing thread and enable printk()
offloading.

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0d96839bb450..acfdc50580db 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2796,6 +2796,25 @@ static int printk_kthread_func(void *data)
 	return 0;
 }
 
+/*
+ * Init printk kthread at late_initcall stage, after core/arch/device/etc.
+ * initialization.
+ */
+static int __init init_printk_kthread(void)
+{
+	struct task_struct *thread;
+
+	thread = kthread_run(printk_kthread_func, NULL, "printk");
+	if (IS_ERR(thread)) {
+		pr_err("printk: unable to create printing thread\n");
+		return PTR_ERR(thread);
+	}
+
+	printk_kthread = thread;
+	return 0;
+}
+late_initcall(init_printk_kthread);
+
 void wake_up_klogd(void)
 {
 	preempt_disable();
-- 
2.12.2

[toc] | [prev] | [next] | [standalone]

Page 1 of 3  [1] 2 3  Next page →

Back to top | Article view | linux.kernel

csiph-web