[RFC][PATCH v8 0/2] printk: Make printk() completely async

[RFC][PATCH v8 0/2] printk: Make printk() completely async

[Sergey Senozhatsky]

Hello,

This patch set makes printk() completely asynchronous: new messages
are getting upended to the kernel printk buffer, but instead of 'direct'
printing the actual print job is performed by a dedicated kthread.
This has the advantage that printing always happens from a schedulable
context and thus we don't lockup any particular CPU or even interrupts.

against next-20160324

v8:
-- rename kthread printing function (Petr)
-- clear need_flush_console in console_unlock() under logbuf (Petr)

v7:
-- do not set global printk_sync in panic in vrintk_emit() (Petr)
-- simplify vprintk_emit(). drop some of local variables (Petr)
-- move handling of LOGLEVEL_SCHED messages back to printk_deferred()
   so we wake_up_process()/console_trylock() in vprintk_emit() only
   for !in_sched messages

v6:
-- move wake_up_process out of logbuf lock (Jan, Byungchul)
-- do not disable async printk in recursion handling code.
-- rebase against next-20160321 (w/NMI patches)

v5:
-- make printk.synchronous RO (Petr)
-- make printing_func() correct and do not use wait_queue (Petr)
-- do not panic() when can't allocate printing thread (Petr)
-- do not wake_up_process() only in IRQ, prefer vprintk_emit() (Jan)
-- move wake_up_klogd_work_func() to a separate patch (Petr)
-- move wake_up_process() under logbuf lock so printk recursion logic can
   help us out
-- switch to sync_print mode if printk recursion occured
-- drop "printk: Skip messages on oops" patch

v4:
-- do not directly wake_up() the printing kthread from vprintk_emit(), need
   to go via IRQ->wake_up() to avoid sched deadlocks (Jan)

v3:
-- use a dedicated kthread for printing instead of using wq (Jan, Tetsuo, Tejun)

v2:
- use dedicated printk workqueue with WQ_MEM_RECLAIM bit
- fallback to system-wide workqueue only if allocation of printk_wq has
  failed
- do not use system_wq as a fallback wq. both console_lock() and onsole_unlock()
  can spend a significant amount of time; so we need to use system_long_wq.
- rework sync/!sync detection logic
  a) we can have deferred (in_sched) messages before we allocate printk_wq,
     so the only way to handle those messages is via IRQ context
  b) even in printk.synchronous mode, deferred messages must not be printed
     directly, and should go via IRQ context
  c) even if we allocated printk_wq and have !sync_printk mode, we must route
     deferred messages via IRQ context
- so this adds additional bool flags to vprint_emit() and introduces a new
  pending bit to `printk_pending'
- fix build on !PRINTK configs

Jan Kara (2):
  printk: Make printk() completely async
  printk: Make wake_up_klogd_work_func() async

 Documentation/kernel-parameters.txt |  10 ++++
 kernel/printk/printk.c              | 104 ++++++++++++++++++++++++++++++++----
 2 files changed, 104 insertions(+), 10 deletions(-)

-- 
2.8.0.rc3.12.g047057b

[RFC][PATCH v8 1/2] printk: Make printk() completely async

[Sergey Senozhatsky]

From: Jan Kara <jack@suse.cz>

Currently, printk() sometimes waits for message to be printed to console
and sometimes it does not (when console_sem is held by some other
process). In case printk() grabs console_sem and starts printing to
console, it prints messages from kernel printk buffer until the buffer
is empty. When serial console is attached, printing is slow and thus
other CPUs in the system have plenty of time to append new messages to
the buffer while one CPU is printing. Thus the CPU can spend unbounded
amount of time doing printing in console_unlock().  This is especially
serious problem if the printk() calling console_unlock() was called with
interrupts disabled.

In practice users have observed a CPU can spend tens of seconds printing
in console_unlock() (usually during boot when hundreds of SCSI devices
are discovered) resulting in RCU stalls (CPU doing printing doesn't
reach quiescent state for a long time), softlockup reports (IPIs for the
printing CPU don't get served and thus other CPUs are spinning waiting
for the printing CPU to process IPIs), and eventually a machine death
(as messages from stalls and lockups append to printk buffer faster than
we are able to print). So these machines are unable to boot with serial
console attached. Another observed issue is that due to slow printk,
hardware discovery is slow and udev times out before kernel manages to
discover all the attached HW. Also during artificial stress testing SATA
disk disappears from the system because its interrupts aren't served for
too long.

This patch makes printk() completely asynchronous (similar to what
printk_deferred() did until now). It appends message to the kernel
printk buffer and wake_up()s a special dedicated kthread to do the
printing to console. This has the advantage that printing always happens
from a schedulable contex and thus we don't lockup any particular CPU or
even interrupts. Also it has the advantage that printk() is fast and
thus kernel booting is not slowed down by slow serial console.
Disadvantage of this method is that in case of crash there is higher
chance that important messages won't appear in console output (we may
need working scheduling to print message to console). We somewhat
mitigate this risk by switching printk to the original method of
immediate printing to console if oops is in progress.  Also for
debugging purposes we provide printk.synchronous kernel parameter which
resorts to the original printk behavior.

printk() is expected to work under different conditions and in different
scenarios, including corner cases of OOM when all of the workers are busy
(e.g. allocating memory), thus printk() uses its own dedicated printing
kthread, rather than relying on workqueue (even with WQ_MEM_RECLAIM bit
set we potentially can receive delays in printing until workqueue
declares a ->mayday, as noted by Tetsuo Handa).

Signed-off-by: Jan Kara <jack@suse.cz>
Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 Documentation/kernel-parameters.txt | 10 ++++
 kernel/printk/printk.c              | 91 ++++++++++++++++++++++++++++++++++---
 2 files changed, 94 insertions(+), 7 deletions(-)

diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
index ecc74fa..4745e94 100644
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -3114,6 +3114,16 @@ bytes respectively. Such letter suffixes can also be entirely omitted.
 	printk.time=	Show timing data prefixed to each printk message line
 			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
 
+	printk.synchronous=
+			By default kernel messages are printed to console
+			asynchronously (except during early boot or when oops
+			is happening). That avoids kernel stalling behind slow
+			serial console and thus avoids softlockups, interrupt
+			timeouts, or userspace timing out during heavy printing.
+			However for debugging problems, printing messages to
+			console immediately may be desirable. This option
+			enables such behavior.
+
 	processor.max_cstate=	[HW,ACPI]
 			Limit processor to maximum C-state
 			max_cstate=9 overrides any DMI blacklist limit.
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index bfbf284..a984c5a 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -46,6 +46,7 @@
 #include <linux/utsname.h>
 #include <linux/ctype.h>
 #include <linux/uio.h>
+#include <linux/kthread.h>
 
 #include <asm/uaccess.h>
 #include <asm-generic/sections.h>
@@ -284,6 +285,19 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
 static char *log_buf = __log_buf;
 static u32 log_buf_len = __LOG_BUF_LEN;
 
+/*
+ * When true, printing to console will happen synchronously.
+ * The default value on UP systems is 'true'.
+ */
+static bool __read_mostly printk_sync = !IS_ENABLED(CONFIG_SMP);
+module_param_named(synchronous, printk_sync, bool, S_IRUGO);
+MODULE_PARM_DESC(synchronous, "make printing to console synchronous");
+
+/* Printing kthread for async printk */
+static struct task_struct *printk_kthread;
+/* When `true' - printing thread has messages to print */
+static bool need_flush_console;
+
 /* Return log buffer address */
 char *log_buf_addr_get(void)
 {
@@ -1608,6 +1622,8 @@ asmlinkage int vprintk_emit(int facility, int level,
 			    const char *dict, size_t dictlen,
 			    const char *fmt, va_list args)
 {
+	/* cpu currently holding logbuf_lock in this function */
+	static unsigned int logbuf_cpu = UINT_MAX;
 	static bool recursion_bug;
 	static char textbuf[LOG_LINE_MAX];
 	char *text = textbuf;
@@ -1617,8 +1633,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 	int this_cpu;
 	int printed_len = 0;
 	bool in_sched = false;
-	/* cpu currently holding logbuf_lock in this function */
-	static unsigned int logbuf_cpu = UINT_MAX;
+	bool in_panic = console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH;
 
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
@@ -1655,6 +1670,14 @@ asmlinkage int vprintk_emit(int facility, int level,
 	raw_spin_lock(&logbuf_lock);
 	logbuf_cpu = this_cpu;
 
+	/*
+	 * Set printing kthread sleep condition early, under the
+	 * logbuf_lock, so it (if RUNNING) will go to console_lock()
+	 * and spin on logbuf_lock.
+	 */
+	if (!in_panic && printk_kthread && !need_flush_console)
+		need_flush_console = true;
+
 	if (unlikely(recursion_bug)) {
 		static const char recursion_msg[] =
 			"BUG: recent printk recursion!";
@@ -1757,12 +1780,28 @@ asmlinkage int vprintk_emit(int facility, int level,
 	if (!in_sched) {
 		lockdep_off();
 		/*
-		 * Try to acquire and then immediately release the console
-		 * semaphore.  The release will print out buffers and wake up
-		 * /dev/kmsg and syslog() users.
+		 * By default we print message to console asynchronously so
+		 * that kernel doesn't get stalled due to slow serial console.
+		 * That can lead to softlockups, lost interrupts, or userspace
+		 * timing out under heavy printing load.
+		 *
+		 * However we resort to synchronous printing of messages during
+		 * early boot, when synchronous printing was explicitly
+		 * requested by kernel parameter, or when console_verbose() was
+		 * called to print everything during panic / oops.
 		 */
-		if (console_trylock())
-			console_unlock();
+		if (!in_panic && printk_kthread) {
+			/* Offload printing to a schedulable context. */
+			wake_up_process(printk_kthread);
+		} 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();
+		}
 		lockdep_on();
 	}
 
@@ -1899,6 +1938,8 @@ static size_t cont_print_text(char *text, size_t size) { return 0; }
 /* Still needs to be defined for users */
 DEFINE_PER_CPU(printk_func_t, printk_func);
 
+static struct task_struct *printk_kthread;
+static bool need_flush_console;
 #endif /* CONFIG_PRINTK */
 
 #ifdef CONFIG_EARLY_PRINTK
@@ -2337,6 +2378,8 @@ skip:
 	 */
 	raw_spin_lock(&logbuf_lock);
 	retry = console_seq != log_next_seq;
+	if (!retry && printk_kthread)
+		need_flush_console = false;
 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
 
 	if (retry && console_trylock())
@@ -2722,6 +2765,40 @@ static int __init printk_late_init(void)
 late_initcall(printk_late_init);
 
 #if defined CONFIG_PRINTK
+static int printk_kthread_func(void *data)
+{
+	while (1) {
+		set_current_state(TASK_INTERRUPTIBLE);
+		if (!need_flush_console)
+			schedule();
+
+		__set_current_state(TASK_RUNNING);
+
+		console_lock();
+		console_unlock();
+	}
+
+	return 0;
+}
+
+static int __init init_printk_kthread(void)
+{
+	struct task_struct *thread;
+
+	if (printk_sync)
+		return 0;
+
+	thread = kthread_run(printk_kthread_func, NULL, "printk");
+	if (IS_ERR(thread)) {
+		pr_err("printk: unable to create printing thread\n");
+		printk_sync = true;
+	} else {
+		printk_kthread = thread;
+	}
+	return 0;
+}
+late_initcall(init_printk_kthread);
+
 /*
  * Delayed printk version, for scheduler-internal messages:
  */
-- 
2.8.0.rc3.12.g047057b

[RFC][PATCH v8 2/2] printk: Make wake_up_klogd_work_func() async

[Sergey Senozhatsky]

From: Jan Kara <jack@suse.cz>

Offload printing of scheduler deferred messages from IRQ context
to a schedulable printing kthread, when possible (the same way we
do it in vprintk_emit()). Otherwise, the CPU can spend unbounded
amount of time doing printing in console_unlock() from IRQ.

Signed-off-by: Jan Kara <jack@suse.cz>
Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 13 ++++++++++---
 1 file changed, 10 insertions(+), 3 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a984c5a..475bfd0 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2812,9 +2812,16 @@ 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 trylock fails, someone else is doing the printing */
-		if (console_trylock())
-			console_unlock();
+		if (printk_kthread) {
+			wake_up_process(printk_kthread);
+		} else {
+			/*
+			 * If trylock fails, someone else is doing
+			 * the printing
+			 */
+			if (console_trylock())
+				console_unlock();
+		}
 	}
 
 	if (pending & PRINTK_PENDING_WAKEUP)
-- 
2.8.0.rc3.12.g047057b

Re: [RFC][PATCH v8 1/2] printk: Make printk() completely async

[Jan Kara]

On Fri 25-03-16 00:43:22, Sergey Senozhatsky wrote:
> @@ -1655,6 +1670,14 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	raw_spin_lock(&logbuf_lock);
>  	logbuf_cpu = this_cpu;
>  
> +	/*
> +	 * Set printing kthread sleep condition early, under the
> +	 * logbuf_lock, so it (if RUNNING) will go to console_lock()
> +	 * and spin on logbuf_lock.
> +	 */
> +	if (!in_panic && printk_kthread && !need_flush_console)
> +		need_flush_console = true;
> +
>  	if (unlikely(recursion_bug)) {
>  		static const char recursion_msg[] =
>  			"BUG: recent printk recursion!";

I like the cleaned up need_flush_console handling! Just a suggestion: It
may be more logical to handle need_flush_console setting under logbuf_lock
but after we actually store the message in the buffer, not before. Doesn't
matter for correctness now but may be more future-proof.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: [RFC][PATCH v8 1/2] printk: Make printk() completely async

[Petr Mladek]

On Fri 2016-03-25 00:43:22, Sergey Senozhatsky wrote:
> From: Jan Kara <jack@suse.cz>
> 
> Currently, printk() sometimes waits for message to be printed to console
> and sometimes it does not (when console_sem is held by some other
> process). In case printk() grabs console_sem and starts printing to
> console, it prints messages from kernel printk buffer until the buffer
> is empty. When serial console is attached, printing is slow and thus
> other CPUs in the system have plenty of time to append new messages to
> the buffer while one CPU is printing. Thus the CPU can spend unbounded
> amount of time doing printing in console_unlock().  This is especially
> serious problem if the printk() calling console_unlock() was called with
> interrupts disabled.
> 
> In practice users have observed a CPU can spend tens of seconds printing
> in console_unlock() (usually during boot when hundreds of SCSI devices
> are discovered) resulting in RCU stalls (CPU doing printing doesn't
> reach quiescent state for a long time), softlockup reports (IPIs for the
> printing CPU don't get served and thus other CPUs are spinning waiting
> for the printing CPU to process IPIs), and eventually a machine death
> (as messages from stalls and lockups append to printk buffer faster than
> we are able to print). So these machines are unable to boot with serial
> console attached. Another observed issue is that due to slow printk,
> hardware discovery is slow and udev times out before kernel manages to
> discover all the attached HW. Also during artificial stress testing SATA
> disk disappears from the system because its interrupts aren't served for
> too long.
> 
> This patch makes printk() completely asynchronous (similar to what
> printk_deferred() did until now). It appends message to the kernel
> printk buffer and wake_up()s a special dedicated kthread to do the
> printing to console. This has the advantage that printing always happens
> from a schedulable contex and thus we don't lockup any particular CPU or
> even interrupts. Also it has the advantage that printk() is fast and
> thus kernel booting is not slowed down by slow serial console.
> Disadvantage of this method is that in case of crash there is higher
> chance that important messages won't appear in console output (we may
> need working scheduling to print message to console). We somewhat
> mitigate this risk by switching printk to the original method of
> immediate printing to console if oops is in progress.  Also for
> debugging purposes we provide printk.synchronous kernel parameter which
> resorts to the original printk behavior.
> 
> printk() is expected to work under different conditions and in different
> scenarios, including corner cases of OOM when all of the workers are busy
> (e.g. allocating memory), thus printk() uses its own dedicated printing
> kthread, rather than relying on workqueue (even with WQ_MEM_RECLAIM bit
> set we potentially can receive delays in printing until workqueue
> declares a ->mayday, as noted by Tetsuo Handa).
> 
> Signed-off-by: Jan Kara <jack@suse.cz>
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  Documentation/kernel-parameters.txt | 10 ++++
>  kernel/printk/printk.c              | 91 ++++++++++++++++++++++++++++++++++---
>  2 files changed, 94 insertions(+), 7 deletions(-)
> 
> diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
> index ecc74fa..4745e94 100644
> --- a/Documentation/kernel-parameters.txt
> +++ b/Documentation/kernel-parameters.txt
> @@ -3114,6 +3114,16 @@ bytes respectively. Such letter suffixes can also be entirely omitted.
>  	printk.time=	Show timing data prefixed to each printk message line
>  			Format: <bool>  (1/Y/y=enable, 0/N/n=disable)
>  
> +	printk.synchronous=
> +			By default kernel messages are printed to console
> +			asynchronously (except during early boot or when oops
> +			is happening). That avoids kernel stalling behind slow
> +			serial console and thus avoids softlockups, interrupt
> +			timeouts, or userspace timing out during heavy printing.
> +			However for debugging problems, printing messages to
> +			console immediately may be desirable. This option
> +			enables such behavior.
> +
>  	processor.max_cstate=	[HW,ACPI]
>  			Limit processor to maximum C-state
>  			max_cstate=9 overrides any DMI blacklist limit.
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index bfbf284..a984c5a 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -46,6 +46,7 @@
>  #include <linux/utsname.h>
>  #include <linux/ctype.h>
>  #include <linux/uio.h>
> +#include <linux/kthread.h>
>  
>  #include <asm/uaccess.h>
>  #include <asm-generic/sections.h>
> @@ -284,6 +285,19 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
>  static char *log_buf = __log_buf;
>  static u32 log_buf_len = __LOG_BUF_LEN;
>  
> +/*
> + * When true, printing to console will happen synchronously.
> + * The default value on UP systems is 'true'.
> + */
> +static bool __read_mostly printk_sync = !IS_ENABLED(CONFIG_SMP);
> +module_param_named(synchronous, printk_sync, bool, S_IRUGO);
> +MODULE_PARM_DESC(synchronous, "make printing to console synchronous");
> +
> +/* Printing kthread for async printk */
> +static struct task_struct *printk_kthread;
> +/* When `true' - printing thread has messages to print */
> +static bool need_flush_console;
> +
>  /* Return log buffer address */
>  char *log_buf_addr_get(void)
>  {
> @@ -1608,6 +1622,8 @@ asmlinkage int vprintk_emit(int facility, int level,
>  			    const char *dict, size_t dictlen,
>  			    const char *fmt, va_list args)
>  {
> +	/* cpu currently holding logbuf_lock in this function */
> +	static unsigned int logbuf_cpu = UINT_MAX;
>  	static bool recursion_bug;
>  	static char textbuf[LOG_LINE_MAX];
>  	char *text = textbuf;
> @@ -1617,8 +1633,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	int this_cpu;
>  	int printed_len = 0;
>  	bool in_sched = false;
> -	/* cpu currently holding logbuf_lock in this function */
> -	static unsigned int logbuf_cpu = UINT_MAX;
> +	bool in_panic = console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH;
>  
>  	if (level == LOGLEVEL_SCHED) {
>  		level = LOGLEVEL_DEFAULT;
> @@ -1655,6 +1670,14 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	raw_spin_lock(&logbuf_lock);
>  	logbuf_cpu = this_cpu;
>  
> +	/*
> +	 * Set printing kthread sleep condition early, under the
> +	 * logbuf_lock, so it (if RUNNING) will go to console_lock()
> +	 * and spin on logbuf_lock.
> +	 */
> +	if (!in_panic && printk_kthread && !need_flush_console)
> +		need_flush_console = true;

I would remove the if-statement and always set it:

  + It does not matter if we set it in panic. It will not affect
    anything.

  + The check for printk_kthread is racy. It might be false here
    and it might be true later when check whether to wakeup
    the kthread or try to get console directly.

  + We might set it true even when it was true before.

I think that this was an attempt to avoid a spurious wake up.
But we solve it better way now.


>  	if (unlikely(recursion_bug)) {
>  		static const char recursion_msg[] =
>  			"BUG: recent printk recursion!";
> @@ -1757,12 +1780,28 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	if (!in_sched) {
>  		lockdep_off();
>  		/*
> -		 * Try to acquire and then immediately release the console
> -		 * semaphore.  The release will print out buffers and wake up
> -		 * /dev/kmsg and syslog() users.
> +		 * By default we print message to console asynchronously so
> +		 * that kernel doesn't get stalled due to slow serial console.
> +		 * That can lead to softlockups, lost interrupts, or userspace
> +		 * timing out under heavy printing load.
> +		 *
> +		 * However we resort to synchronous printing of messages during
> +		 * early boot, when synchronous printing was explicitly
> +		 * requested by kernel parameter, or when console_verbose() was
> +		 * called to print everything during panic / oops.
>  		 */
> -		if (console_trylock())
> -			console_unlock();
> +		if (!in_panic && printk_kthread) {
> +			/* Offload printing to a schedulable context. */
> +			wake_up_process(printk_kthread);
> +		} 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();
> +		}
>  		lockdep_on();
>  	}
>  
> @@ -1899,6 +1938,8 @@ static size_t cont_print_text(char *text, size_t size) { return 0; }
>  /* Still needs to be defined for users */
>  DEFINE_PER_CPU(printk_func_t, printk_func);
>  
> +static struct task_struct *printk_kthread;
> +static bool need_flush_console;
>  #endif /* CONFIG_PRINTK */
>  
>  #ifdef CONFIG_EARLY_PRINTK
> @@ -2337,6 +2378,8 @@ skip:
>  	 */
>  	raw_spin_lock(&logbuf_lock);
>  	retry = console_seq != log_next_seq;
> +	if (!retry && printk_kthread)
> +		need_flush_console = false;

Similar here. I remove the if-statement and always set it. We will
either retry or it should be false anyway.

>  	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
>  
>  	if (retry && console_trylock())
> @@ -2722,6 +2765,40 @@ static int __init printk_late_init(void)
>  late_initcall(printk_late_init);
>  
>  #if defined CONFIG_PRINTK
> +static int printk_kthread_func(void *data)
> +{
> +	while (1) {
> +		set_current_state(TASK_INTERRUPTIBLE);
> +		if (!need_flush_console)
> +			schedule();
> +
> +		__set_current_state(TASK_RUNNING);


We still must do here:

		need_flush_console = false;

Othrerwise, we might start "busy" cycling. cosole_unlock()
sometimes returns earlly, e.g. when console_suspended is set
or !can_use_console() returns true.

Sigh, the handling of "need_flush_console" is a bit strange.
Part of the logic depends on logbuf_lock and the other part
must be lockless.

I think that this lockless assigment deserve a comment, e.g.

		/*
		 * Avoid an infinite loop when console_unlock() cannot
		 * access consoles, e.g. because of a suspend. We
		 * could get asleep here. Someone else will call
		 * consoles if conditions change.
		 */

Also another name might help. If we set it false here, the value
does describe a global state. The variable describes if this
kthread needs to flush the console. So, more precise name would be

	printk_kthread_need_flush_console


I think that we are close. I really like the current state of
the patch and how minimalistic it is.


Best Regards,
Petr

Re: [RFC][PATCH v8 2/2] printk: Make wake_up_klogd_work_func() async

[Petr Mladek]

On Fri 2016-03-25 00:43:23, Sergey Senozhatsky wrote:
> From: Jan Kara <jack@suse.cz>
> 
> Offload printing of scheduler deferred messages from IRQ context
> to a schedulable printing kthread, when possible (the same way we
> do it in vprintk_emit()). Otherwise, the CPU can spend unbounded
> amount of time doing printing in console_unlock() from IRQ.
> 
> Signed-off-by: Jan Kara <jack@suse.cz>
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>

Nice change. Makes perfect sense.

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

Best Regards,
Petr

Re: [RFC][PATCH v8 1/2] printk: Make printk() completely async

[Jan Kara]

On Thu 31-03-16 13:12:29, Petr Mladek wrote:
> >  #if defined CONFIG_PRINTK
> > +static int printk_kthread_func(void *data)
> > +{
> > +	while (1) {
> > +		set_current_state(TASK_INTERRUPTIBLE);
> > +		if (!need_flush_console)
> > +			schedule();
> > +
> > +		__set_current_state(TASK_RUNNING);
> 
> 
> We still must do here:
> 
> 		need_flush_console = false;
> 
> Othrerwise, we might start "busy" cycling. cosole_unlock()
> sometimes returns earlly, e.g. when console_suspended is set
> or !can_use_console() returns true.
> 
> Sigh, the handling of "need_flush_console" is a bit strange.
> Part of the logic depends on logbuf_lock and the other part
> must be lockless.

Frankly, I think we are overcomplicating this. What we really need to detect
in printk_kthread_func() is whether someone appended something to the console
since we woken up. Sure, console_unlock() may have already printed that
and we would unnecessarily make one more loop over console_lock() and
console_unlock() but who cares...

So what about having printk_kthread_func() like:

	while (1) {
		set_current_state(TASK_INTERRUPTIBLE);
		if (!need_flush_console)
			schedule();
		__set_current_state(TASK_RUNNING);
		need_flush_console = false;
		console_lock();
		console_unlock();
	}

In vprintk_emit() we do:

	if (!in_panic && printk_kthread) {
		/* Offload printing to a schedulable context. */
		need_flush_console = true;
		wake_up_process(printk_kthread);
	} else {
		...

This guarantees that after message was appended to the buffer in
vprintk_emit(), the message got either printed by console_unlock() or
printk_kthread is in TASK_RUNNING state and will call console_unlock() once
scheduled. It also guarantees that printk_kthread_func() won't loop forever
when there's nothing to print. And that is all we need...

I think the simplicity of this is worth the possible extra loops in
printk_kthread_func().

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: [RFC][PATCH v8 1/2] printk: Make printk() completely async

[Sergey Senozhatsky]

Hello Petr,

On (03/31/16 13:12), Petr Mladek wrote:
> > +	 * Set printing kthread sleep condition early, under the
> > +	 * logbuf_lock, so it (if RUNNING) will go to console_lock()
> > +	 * and spin on logbuf_lock.
> > +	 */
> > +	if (!in_panic && printk_kthread && !need_flush_console)
> > +		need_flush_console = true;
> 
> I would remove the if-statement and always set it:
> 
>   + It does not matter if we set it in panic. It will not affect
>     anything.

hm... yes, you're right.

>   + The check for printk_kthread is racy. It might be false here
>     and it might be true later when check whether to wakeup
>     the kthread or try to get console directly.

which is fine, isn't it? we will wakeup the printing kthread, it will
console_lock()/console_unlock() (regardless the state of need_flush_console).
printing thread checks need_flush_console only when it decides whether
it shall schedule.

>   + We might set it true even when it was true before.
> 
> I think that this was an attempt to avoid a spurious wake up.
> But we solve it better way now.

we also may have 'printk.synchronous = 1', which will purposelessly
dirty need_flush_console from various CPUs from every printk /* and
upon every return from console_unlock() */; that's why I added both
printk_kthread and !need_flush_console (re-dirty already dirtied)
checks.

> >  	raw_spin_lock(&logbuf_lock);
> >  	retry = console_seq != log_next_seq;
> > +	if (!retry && printk_kthread)
> > +		need_flush_console = false;
> 
> Similar here. I remove the if-statement and always set it. We will
> either retry or it should be false anyway.

well, 'printk.synchronous = 1'. seems that `!retry' check can be
dropped, I agree.

a side nano-note,
apart from 'printk.synchronous = 1', we also can have !printk_kthread
because kthread_run(printk_kthread_func) failed. it's quite unlikely,
but still.

[..]
> > +	while (1) {
> > +		set_current_state(TASK_INTERRUPTIBLE);
> > +		if (!need_flush_console)
> > +			schedule();
> > +
> > +		__set_current_state(TASK_RUNNING);
> 
> 
> We still must do here:
> 
> 		need_flush_console = false;

oh, wow! that's a major mistake. thanks a lot for catching this!
shame on me.

> 		/*
> 		 * Avoid an infinite loop when console_unlock() cannot
> 		 * access consoles, e.g. because of a suspend. We
> 		 * could get asleep here. Someone else will call
> 		 * consoles if conditions change.
> 		 */

looks ok.

> Also another name might help. If we set it false here, the value
> does describe a global state. The variable describes if this
> kthread needs to flush the console. So, more precise name would be
> 
> 	printk_kthread_need_flush_console

yes, makes sense.

> I think that we are close. I really like the current state of
> the patch and how minimalistic it is.


thanks for your review.

I'll re-spin.

	-ss

Re: [RFC][PATCH v8 1/2] printk: Make printk() completely async

[Sergey Senozhatsky]

Hello Jan,

On (03/29/16 11:14), Jan Kara wrote:
> On Fri 25-03-16 00:43:22, Sergey Senozhatsky wrote:
> > @@ -1655,6 +1670,14 @@ asmlinkage int vprintk_emit(int facility, int level,
> >  	raw_spin_lock(&logbuf_lock);
> >  	logbuf_cpu = this_cpu;
> >  
> > +	/*
> > +	 * Set printing kthread sleep condition early, under the
> > +	 * logbuf_lock, so it (if RUNNING) will go to console_lock()
> > +	 * and spin on logbuf_lock.
> > +	 */
> > +	if (!in_panic && printk_kthread && !need_flush_console)
> > +		need_flush_console = true;
> > +
> >  	if (unlikely(recursion_bug)) {
> >  		static const char recursion_msg[] =
> >  			"BUG: recent printk recursion!";
> 
> I like the cleaned up need_flush_console handling! Just a suggestion: It
> may be more logical to handle need_flush_console setting under logbuf_lock
> but after we actually store the message in the buffer, not before. Doesn't
> matter for correctness now but may be more future-proof.

I wanted to set it asap (when we know for sure that we will log_store()),
to have a bit more chances to avoid schedule() in printing thread. well,
that's just several log_store()-s, not a big deal, so I guess I can move
it to:

+	if (...)
+		need_flush_console = true;
	logbuf_cpu = UINT_MAX;
	raw_spin_unlock(&logbuf_lock);
	lockdep_on();
	local_irq_restore(flags);

	-ss

Re: [RFC][PATCH v8 1/2] printk: Make printk() completely async

[Petr Mladek]

On Fri 2016-04-01 10:08:03, Sergey Senozhatsky wrote:
> Hello Petr,
> 
> On (03/31/16 13:12), Petr Mladek wrote:
> > > +	 * Set printing kthread sleep condition early, under the
> > > +	 * logbuf_lock, so it (if RUNNING) will go to console_lock()
> > > +	 * and spin on logbuf_lock.
> > > +	 */
> > > +	if (!in_panic && printk_kthread && !need_flush_console)
> > > +		need_flush_console = true;
> > 
> > I would remove the if-statement and always set it:
> > 
> >   + It does not matter if we set it in panic. It will not affect
> >     anything.
> 
> hm... yes, you're right.
> 
> >   + The check for printk_kthread is racy. It might be false here
> >     and it might be true later when check whether to wakeup
> >     the kthread or try to get console directly.
> 
> which is fine, isn't it? we will wakeup the printing kthread, it will
> console_lock()/console_unlock() (regardless the state of need_flush_console).
> printing thread checks need_flush_console only when it decides whether
> it shall schedule.

You almost persuaded me :-) But what about this?

CPU0					CPU1

printk()

  if (printk_kthread)
  # fails and need_flush_console
  # stays false

					init_printk_kthread()
					  # put printk_thread into
					  # run queue
					  printk_kthread = ...;

  if (!in_panic && printk_kthread)
    wake_up_process(printk_kthread);


					# printk kthread finally gets
					# scheduled
					printk_kthread_func()

					set_current_state(TASK_INTERRUPTIBLE);
					if (!need_flush_console)
					  schedule();

=> printk_kthread is happily sleeping without calling console.

We would rearrange printk_kthread_func() to call console
first before going to sleep. But I feel that it still might be
racy some other way because the operations are not synchronized.
For example, printk_kthread_func() might get scheduled on yet
another CPU and might go call consoles before printk_kthread
gets assigned but it might get rescheduled before it goes
into a sleep on preemptive kernel.

I think that it does not matter how need_flush_console if
the kthread is not running. The only drawback is that it will
most likely call consoles once without any real work but
it is only once on start up and we might need it anyway to
handle the above race.

> >   + We might set it true even when it was true before.
> > 
> > I think that this was an attempt to avoid a spurious wake up.
> > But we solve it better way now.
> 
> we also may have 'printk.synchronous = 1', which will purposelessly
> dirty need_flush_console from various CPUs from every printk /* and
> upon every return from console_unlock() */; that's why I added both
> printk_kthread and !need_flush_console (re-dirty already dirtied)
> checks.

I do not see any code that will modify need_flush_console when
printk.synchronous is modified at runtime. If it is set during boot
the kthread will never run and it does not matter how
need_console_flush is set.

I know that all this is rather theoretical. My main point is to remove
unnecessary checks that make the code harder to read and does not bring
any big advantage.


> > >  	raw_spin_lock(&logbuf_lock);
> > >  	retry = console_seq != log_next_seq;
> > > +	if (!retry && printk_kthread)
> > > +		need_flush_console = false;
> > 
> > Similar here. I remove the if-statement and always set it. We will
> > either retry or it should be false anyway.
> 
> well, 'printk.synchronous = 1'. seems that `!retry' check can be
> dropped, I agree.
> 
> a side nano-note,
> apart from 'printk.synchronous = 1', we also can have !printk_kthread
> because kthread_run(printk_kthread_func) failed. it's quite unlikely,
> but still.

If the kthread does not run, it does not matter how need_flush_console
is set. It is similar to the above check. It adds extra logic to the
code that does not bring any big win.

Sigh, I never know when it is the right time to stop wrangling about
details. Well, the easier code helps me to see real problems.

Best Regards,
Petr

Re: [RFC][PATCH v8 1/2] printk: Make printk() completely async

[Sergey Senozhatsky]

Hello Petr,

On (04/01/16 10:59), Petr Mladek wrote:
[..]
> CPU0					CPU1
> 
> printk()
> 
>   if (printk_kthread)
>   # fails and need_flush_console
>   # stays false
> 
> 					init_printk_kthread()
> 					  # put printk_thread into
> 					  # run queue
> 					  printk_kthread = ...;
> 
>   if (!in_panic && printk_kthread)
>     wake_up_process(printk_kthread);
> 
> 
> 					# printk kthread finally gets
> 					# scheduled
> 					printk_kthread_func()
> 
> 					set_current_state(TASK_INTERRUPTIBLE);
> 					if (!need_flush_console)
> 					  schedule();
> 
> => printk_kthread is happily sleeping without calling console.

oohh, that tiny race. well, looks quite harmless, it's unlikely that
we had printk()-s up until late_initcall(init_printk_kthread) and not
a single one ever after. but good find!

so the check
	if (printk_kthread)
		need_flush_console = 1

can be replaced with
	if (!printk_sync)
		need_flush_console = 1

or... may be dropped.

> I do not see any code that will modify need_flush_console when
> printk.synchronous is modified at runtime.

printk.synchronous is RO; no runtime modification.

> I know that all this is rather theoretical. My main point is to remove
> unnecessary checks that make the code harder to read and does not bring
> any big advantage.

my point is that those checks are just .loads, which help to avoid
spurious .stores from various CPUs.

CPU1		CPU2		CPU3		...	CPU1024

lock logbuf
need_flush=1
unlock logbuf
		lock logbuf
		need_flush=1
		unlock logbuf
				lock logbuf
				need_flush=1
				unlock logbuf
wakeup kthread					
						...
							lock logbuf
							need_flush=1
							unlock logbuf

isn't it a bit useless need_flush=1 traffic?

	-ss

Re: [RFC][PATCH v8 1/2] printk: Make printk() completely async

[Petr Mladek]

On Fri 2016-04-01 18:36:02, Sergey Senozhatsky wrote:
> Hello Petr,
> 
> On (04/01/16 10:59), Petr Mladek wrote:
> [..]
> > CPU0					CPU1
> > 
> > printk()
> > 
> >   if (printk_kthread)
> >   # fails and need_flush_console
> >   # stays false
> > 
> > 					init_printk_kthread()
> > 					  # put printk_thread into
> > 					  # run queue
> > 					  printk_kthread = ...;
> > 
> >   if (!in_panic && printk_kthread)
> >     wake_up_process(printk_kthread);
> > 
> > 
> > 					# printk kthread finally gets
> > 					# scheduled
> > 					printk_kthread_func()
> > 
> > 					set_current_state(TASK_INTERRUPTIBLE);
> > 					if (!need_flush_console)
> > 					  schedule();
> > 
> > => printk_kthread is happily sleeping without calling console.
> 
> oohh, that tiny race. well, looks quite harmless, it's unlikely that
> we had printk()-s up until late_initcall(init_printk_kthread) and not
> a single one ever after. but good find!
> 
> so the check
> 	if (printk_kthread)
> 		need_flush_console = 1
> 
> can be replaced with
> 	if (!printk_sync)
> 		need_flush_console = 1
> 
> or... may be dropped.

Yup or yup, see below.

> > I do not see any code that will modify need_flush_console when
> > printk.synchronous is modified at runtime.
> 
> printk.synchronous is RO; no runtime modification.
> 
> > I know that all this is rather theoretical. My main point is to remove
> > unnecessary checks that make the code harder to read and does not bring
> > any big advantage.
> 
> my point is that those checks are just .loads, which help to avoid
> spurious .stores from various CPUs.
> 
> CPU1		CPU2		CPU3		...	CPU1024
> 
> lock logbuf
> need_flush=1
> unlock logbuf
> 		lock logbuf
> 		need_flush=1
> 		unlock logbuf
> 				lock logbuf
> 				need_flush=1
> 				unlock logbuf
> wakeup kthread					
> 						...
> 							lock logbuf
> 							need_flush=1
> 							unlock logbuf
> 
> isn't it a bit useless need_flush=1 traffic?

So, it is a small trade off between code readability and data writes
in a slow path. I do not have strong opinion about it. Feel free to
use what you like, just please use the same approach in both
vprintk_emit() and console_unlock().

Best Regards,
Petr

Re: [RFC][PATCH v8 1/2] printk: Make printk() completely async

[Petr Mladek]

On Thu 2016-03-31 13:52:50, Jan Kara wrote:
> On Thu 31-03-16 13:12:29, Petr Mladek wrote:
> > >  #if defined CONFIG_PRINTK
> > > +static int printk_kthread_func(void *data)
> > > +{
> > > +	while (1) {
> > > +		set_current_state(TASK_INTERRUPTIBLE);
> > > +		if (!need_flush_console)
> > > +			schedule();
> > > +
> > > +		__set_current_state(TASK_RUNNING);
> > 
> > 
> > We still must do here:
> > 
> > 		need_flush_console = false;
> > 
> > Othrerwise, we might start "busy" cycling. cosole_unlock()
> > sometimes returns earlly, e.g. when console_suspended is set
> > or !can_use_console() returns true.
> > 
> > Sigh, the handling of "need_flush_console" is a bit strange.
> > Part of the logic depends on logbuf_lock and the other part
> > must be lockless.
> 
> Frankly, I think we are overcomplicating this. What we really need to detect
> in printk_kthread_func() is whether someone appended something to the console
> since we woken up. Sure, console_unlock() may have already printed that
> and we would unnecessarily make one more loop over console_lock() and
> console_unlock() but who cares...
> 
> So what about having printk_kthread_func() like:
> 
> 	while (1) {
> 		set_current_state(TASK_INTERRUPTIBLE);
> 		if (!need_flush_console)
> 			schedule();
> 		__set_current_state(TASK_RUNNING);
> 		need_flush_console = false;
> 		console_lock();
> 		console_unlock();
> 	}
> 
> In vprintk_emit() we do:
> 
> 	if (!in_panic && printk_kthread) {
> 		/* Offload printing to a schedulable context. */
> 		need_flush_console = true;
> 		wake_up_process(printk_kthread);
> 	} else {
> 		...
> 
> This guarantees that after message was appended to the buffer in
> vprintk_emit(), the message got either printed by console_unlock() or
> printk_kthread is in TASK_RUNNING state and will call console_unlock() once
> scheduled. It also guarantees that printk_kthread_func() won't loop forever
> when there's nothing to print. And that is all we need...
> 
> I think the simplicity of this is worth the possible extra loops in
> printk_kthread_func().

I do not have strong opinion about this. I agree that the simplicity
of your proposal is nice. You are much more experienced kernel
developer. If you say that the potential extra loop is fine, I am
fine with it as well :-)

Best Regards,
Petr

Re: [RFC][PATCH v8 1/2] printk: Make printk() completely async

[Sergey Senozhatsky]

Hello,

On (04/04/16 11:41), Petr Mladek wrote:
[..]
> > So what about having printk_kthread_func() like:
> > 
> > 	while (1) {
> > 		set_current_state(TASK_INTERRUPTIBLE);
> > 		if (!need_flush_console)
> > 			schedule();
> > 		__set_current_state(TASK_RUNNING);
> > 		need_flush_console = false;
> > 		console_lock();
> > 		console_unlock();
> > 	}
> > 
> > In vprintk_emit() we do:
> > 
> > 	if (!in_panic && printk_kthread) {
> > 		/* Offload printing to a schedulable context. */
> > 		need_flush_console = true;
> > 		wake_up_process(printk_kthread);
> > 	} else {
> > 		...
> > 
> > This guarantees that after message was appended to the buffer in
> > vprintk_emit(), the message got either printed by console_unlock() or
> > printk_kthread is in TASK_RUNNING state and will call console_unlock() once
> > scheduled. It also guarantees that printk_kthread_func() won't loop forever
> > when there's nothing to print. And that is all we need...
> > 
> > I think the simplicity of this is worth the possible extra loops in
> > printk_kthread_func().
> 
> I do not have strong opinion about this. I agree that the simplicity
> of your proposal is nice. You are much more experienced kernel
> developer. If you say that the potential extra loop is fine, I am
> fine with it as well :-)
> 

works for me, re-sent.
the patch is even smaller now, and we almost have nothing else to
cut off from it :)

	-ss