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

Groups > linux.kernel > #1370725 > unrolled thread

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

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-04-04 18:10 +0200
    Re: [PATCH v10 1/2] printk: Make printk() completely async Andrew Morton <akpm@linux-foundation.org> - 2016-04-05 01:00 +0200
      Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-04-05 07:20 +0200
        Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-04-05 09:40 +0200
          Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-04-06 02:20 +0200
      Re: [PATCH v10 1/2] printk: Make printk() completely async Jan Kara <jack@suse.cz> - 2016-04-06 11:30 +0200
        Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-04-07 11:50 +0200
          Re: [PATCH v10 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-04-07 13:20 +0200
            Re: [PATCH v10 1/2] printk: Make printk() completely async Jan Kara <jack@suse.cz> - 2016-04-07 15:20 +0200

#1370725 — [PATCH v10 1/2] printk: Make printk() completely async

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              | 87 ++++++++++++++++++++++++++++++++++---
 2 files changed, 90 insertions(+), 7 deletions(-)

diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
index 3d28b50..c23a5bd 100644
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -3122,6 +3122,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..f63dfe4 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 printk_kthread_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;
@@ -1757,12 +1772,29 @@ 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. */
+			printk_kthread_need_flush_console = true;
+			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();
 	}
 
@@ -2722,6 +2754,47 @@ 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 (!printk_kthread_need_flush_console)
+			schedule();
+
+		__set_current_state(TASK_RUNNING);
+		/*
+		 * Avoid an infinite loop when console_unlock() cannot
+		 * access consoles, e.g. because console_suspended is
+		 * true. schedule(), someone else will print the messages
+		 * from resume_console().
+		 */
+		printk_kthread_need_flush_console = false;
+
+		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

[toc] | [next] | [standalone]

#1370944

On Tue,  5 Apr 2016 01:57:27 +0900 Sergey Senozhatsky <sergey.senozhatsky@gmail.com> 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).

The whole idea remains worrisome.  It is definitely making printk()
less reliable in the vast majority of cases: what happens if the
scheduler is busted or random memory has been scribbled on, etc.

All this downside to handle (afaict) one special case.  Surely there is
another way?  For example (but feel free to suggest other approaches!)
can we put some limit on the number of extra characters which the
printing task will print?  Once that limit is hit, new printk callers
will spin until they can get in and do some printing themselves.  Or
something else?

> index 3d28b50..c23a5bd 100644
> --- a/Documentation/kernel-parameters.txt
> +++ b/Documentation/kernel-parameters.txt
> @@ -3122,6 +3122,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.

Well, it's good that we have this.

It would be better if it was runtime-controllable - changing boot
parameters is a bit of a pain.  In fact with this approach, your
zillions-of-scsi-disks scenario becomes less problematic: do the async
offloading during the boot process then switch back to the more
reliable sync printing late in boot.

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

That's rather obvious from the code.  Comments should explain "why",
not "what".

> + */
> +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 printk_kthread_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;
> @@ -1757,12 +1772,29 @@ 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

Nit: this comment down here shouldn't know what the default is.  That
should be documented up at the printk_sync definition site.

> +		 * that kernel doesn't get stalled due to slow serial console.

s/kernel/the kernel/

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

s/kernel/a kernel/


> +		 * called to print everything during panic / oops.

We're missing a description of *why* console_verbose() is handled
specially.

>  		 */
> -		if (console_trylock())
> -			console_unlock();
> +		if (!in_panic && printk_kthread) {

We don't really need local variable in_panic.  I guess it has some
documentary value.

> +			/* Offload printing to a schedulable context. */
> +			printk_kthread_need_flush_console = true;
> +			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();
>  	}
>  
> @@ -2722,6 +2754,47 @@ 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 (!printk_kthread_need_flush_console)
> +			schedule();
> +
> +		__set_current_state(TASK_RUNNING);
> +		/*
> +		 * Avoid an infinite loop when console_unlock() cannot
> +		 * access consoles, e.g. because console_suspended is
> +		 * true. schedule(), someone else will print the messages
> +		 * from resume_console().
> +		 */
> +		printk_kthread_need_flush_console = false;
> +
> +		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");

This gets normal scheduling policy, so a spinning userspace SCHED_FIFO
task will block printk for ever.  This seems bad.

> +	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);

Could do with a comment explaining why late_initcall was chosen.

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

#1371214

Hello Andrew,

On (04/04/16 15:51), Andrew Morton wrote:
[..]
> The whole idea remains worrisome.  It is definitely making printk()
> less reliable in the vast majority of cases: what happens if the
> scheduler is busted or random memory has been scribbled on, etc.

yes.

well, printk, in some sense, already depend on the scheduler: console
semaphore on its own; cond_resched() from console_unlock() with console_sem
being locked, etc. neither memory corruption is something that printk() can
always handle nicely. I saw logbuf_lock corruption and recursive spin_dump
from vprintk_emit(), was quite dramatic.


> All this downside to handle (afaict) one special case.

well, it's not just to make zillions-of-scsi-disks happy. I'm facing
different scenarios, more general ones, a 'moderate printk abuse'
(combined with slow serial console). printk is not always friendly
and shiny, it has some secrets and it can bite easily (lockups, stalls,
starvations, sched throttling, et cetera), and this is not something
that every developer know.

> Surely there is another way?  For example (but feel free to suggest other
> approaches!) can we put some limit on the number of extra characters which
> the printing task will print?  Once that limit is hit, new printk callers
> will spin until they can get in and do some printing themselves.  Or
> something else?

hm... there are not so many options, I think. this busy wait, depending on
the number of CPUs (and some other factors), can provoke mass softlockups
on other CPUs and a number of bad things. printk() and its deferred version
can be called from any context, so in some cases spinning in printk is as
good as doing console_unlock()->call_concosle_drivers() loop (iow, not really
good). things are not so bad (well, Tetsuo has some issues here though) if
printk() is called from non-atomic context, since now we have cond_resched()
in console_unlock() for console_lock()/console_trylock() callers; but printk()
from atomic context is still a problem -- we need to offload the actual
printing, unless we can guarantee that every atomic printk will be followed
by non-atomic printk (which will do the printing).

> > +	printk.synchronous=
..
> Well, it's good that we have this.
> 
> It would be better if it was runtime-controllable - changing boot
> parameters is a bit of a pain.  In fact with this approach, your
> zillions-of-scsi-disks scenario becomes less problematic: do the async
> offloading during the boot process then switch back to the more
> reliable sync printing late in boot.

well, I can add it if you insist.
my personal opinion is to keep it RO; RO->RW transition is easier than
RW->RO. giving the control over printk behaviour to user space can
potentially be even worse than drop_caches. besides I couldn't clearly
understand based on what observations user space may decide to switch
printk back to sync mode? and what may cause user space to switch printk
back from sync to async... lockups in dmesg output? any hint?

..
> > + * When true, printing to console will happen synchronously.
> > + * The default value on UP systems is 'true'.
> 
> That's rather obvious from the code.  Comments should explain "why",
> not "what".

fair enough.

> > +		 * By default we print message to console asynchronously so
> 
> Nit: this comment down here shouldn't know what the default is.  That
> should be documented up at the printk_sync definition site.

ok.

> > +		 * that kernel doesn't get stalled due to slow serial console.
> 
> s/kernel/the kernel/

ok.

> > +		 * requested by kernel parameter, or when console_verbose() was
> 
> s/kernel/a kernel/

ok.

> 
> > +		 * called to print everything during panic / oops.
> 
> We're missing a description of *why* console_verbose() is handled
> specially.

ok.

> > -		if (console_trylock())
> > -			console_unlock();
> > +		if (!in_panic && printk_kthread) {
> 
> We don't really need local variable in_panic.  I guess it has some
> documentary value.

just a shorter version of "console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH".

> > +
> > +	thread = kthread_run(printk_kthread_func, NULL, "printk");
> 
> This gets normal scheduling policy, so a spinning userspace SCHED_FIFO
> task will block printk for ever.  This seems bad.

yes, using SCHED_RR/FIFO policy here makes sense.

> > +late_initcall(init_printk_kthread);
> 
> Could do with a comment explaining why late_initcall was chosen.

late_initcall was chosen because of workqueue early_initcall, and
I just decided not to change it when I switched from wq to a
dedicated printk kthread. late_initcall seemed to be OK. can do
init_printk_kthread() somewhere in init/main start_kernel().

	-ss

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

#1371284

On (04/05/16 14:17), Sergey Senozhatsky wrote:
[..]
> > Could do with a comment explaining why late_initcall was chosen.
> 
> late_initcall was chosen because of workqueue early_initcall, and
> I just decided not to change it when I switched from wq to a
> dedicated printk kthread. late_initcall seemed to be OK. can do
> init_printk_kthread() somewhere in init/main start_kernel().

or rather move it a bit earlier. core_init sounds appropriate;
or postcore. don't want to export yet another printk symbol.

	-ss

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

#1372089

Hello,

so I currently have something like this.
untouched things:
  - module param is RO; offload printing to kthread

(I'll wait for opinions/replies).

=======

From 1e7de1f9a590d8f23609f943362768e4c14580cc Mon Sep 17 00:00:00 2001
From: Jan Kara <jack@suse.cz>
Date: Tue, 5 Apr 2016 01:57:27 +0900
Subject: [PATCH] printk: Make printk() completely async

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              | 94 ++++++++++++++++++++++++++++++++++---
 2 files changed, 97 insertions(+), 7 deletions(-)

diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
index 46c0b19..733a13d 100644
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -3117,6 +3117,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..217f27a 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,16 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
 static char *log_buf = __log_buf;
 static u32 log_buf_len = __LOG_BUF_LEN;
 
+/* Control whether printing to console must be synchronous. */
+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 printk_kthread_need_flush_console;
+
 /* Return log buffer address */
 char *log_buf_addr_get(void)
 {
@@ -1608,6 +1619,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 +1630,6 @@ 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;
 
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
@@ -1757,12 +1768,35 @@ 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.
+		 * Attempt to print the messages to console asynchronously so
+		 * that the 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 a kernel parameter, or when console_verbose()
+		 * was called to print everything during panic / oops.
+		 * Unlike bust_spinlocks() and oops_in_progress,
+		 * console_verbose() sets console_loglevel to MOTORMOUTH and
+		 * never clears it, while oops_in_progress can go back to 0,
+		 * switching printk back to async mode; we want printk to
+		 * operate in sync mode once panic() occurred.
 		 */
-		if (console_trylock())
-			console_unlock();
+		if (console_loglevel != CONSOLE_LOGLEVEL_MOTORMOUTH &&
+				printk_kthread) {
+			/* Offload printing to a schedulable context. */
+			printk_kthread_need_flush_console = true;
+			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();
 	}
 
@@ -2722,6 +2756,52 @@ 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 (!printk_kthread_need_flush_console)
+			schedule();
+
+		__set_current_state(TASK_RUNNING);
+		/*
+		 * Avoid an infinite loop when console_unlock() cannot
+		 * access consoles, e.g. because console_suspended is
+		 * true. schedule(), someone else will print the messages
+		 * from resume_console().
+		 */
+		printk_kthread_need_flush_console = false;
+
+		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 {
+		struct sched_param param = {
+			.sched_priority = MAX_RT_PRIO - 1,
+		};
+
+		sched_setscheduler(thread, SCHED_FIFO, &param);
+		printk_kthread = thread;
+	}
+	return 0;
+}
+core_initcall(init_printk_kthread);
+
 /*
  * Delayed printk version, for scheduler-internal messages:
  */
-- 
2.8.0.rc0.1.gd285ab0

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

#1372328

On Mon 04-04-16 15:51:49, Andrew Morton wrote:
> On Tue,  5 Apr 2016 01:57:27 +0900 Sergey Senozhatsky <sergey.senozhatsky@gmail.com> 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).
> 
> The whole idea remains worrisome.  It is definitely making printk()
> less reliable in the vast majority of cases: what happens if the
> scheduler is busted or random memory has been scribbled on, etc.

So the scheduler dependency was always there due to handling of
console_sem and some console drivers possibly scheduling out while holding
console_sem. Recently the dependency has increased by adding cond_resched()
into console_unlock() loop in 8d91f8b15361 (printk: do cond_resched()
between lines while outputting to consoles). Also the changelog of that
commit explains another case besides 'tons of SCSI devices' which leads to
printk lockups. I have also seen a case where printing of 'martian packets'
killed the machine because it was too intensive (but it has been an older
kernel and I think networking people have added some ratelimiting for those
messages so it shouldn't happen anymore).

Now this commit makes the dependency on the scheduler even harder - unless
we know something is wrong (in_panic set) we rely on scheduler to schedule
the printing kthread. So I agree there is some risk in this patch.

> All this downside to handle (afaict) one special case.  Surely there is
> another way?  For example (but feel free to suggest other approaches!)
> can we put some limit on the number of extra characters which the
> printing task will print?  Once that limit is hit, new printk callers
> will spin until they can get in and do some printing themselves.  Or
> something else?

We have been through this a few times without much success. Last revision
of my patches did what you suggest but although the idea sounds simple, the
implementation turned out to be relatively complex and even you didn't
quite like it [1]. Moreover when I raised this issue at Kernel Summit 2015,
Hannes Reinecke mentioned that even these patches are not enough to make
his huge machine boot with serial console because printing still delays
device probing too much and systemd times out during boot. Then Linus said
that he'd want to keep things simple and just make printk asynchronous and
switch to synchronous in case problems are detected - which is what I and
Sergey have implemented in this patch.

So currently I'm of the opinion that we should merge this patch and see how
well it works in reality. I've tested it and it works for me and Sergey.
Maybe I can try breaking it some more by crashing the in various ways
kernel if it makes you calmer. In case we see problems in some setups,
there's always the kernel option to return to the original behavior and we
can work from there improving what we have...

[1] Message-Id: <20150918151411.a3fa65c3e4f33f9f2ddf1fd8@linux-foundation.org>

> > index 3d28b50..c23a5bd 100644
> > --- a/Documentation/kernel-parameters.txt
> > +++ b/Documentation/kernel-parameters.txt
> > @@ -3122,6 +3122,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.
> 
> Well, it's good that we have this.
> 
> It would be better if it was runtime-controllable - changing boot
> parameters is a bit of a pain.  In fact with this approach, your
> zillions-of-scsi-disks scenario becomes less problematic: do the async
> offloading during the boot process then switch back to the more
> reliable sync printing late in boot.

Doing this should be relatively easy. It would be userspace's decision
whether they want more reliable or faster printk. Sounds fine with me.

> > +static int __init init_printk_kthread(void)
> > +{
> > +	struct task_struct *thread;
> > +
> > +	if (printk_sync)
> > +		return 0;
> > +
> > +	thread = kthread_run(printk_kthread_func, NULL, "printk");
> 
> This gets normal scheduling policy, so a spinning userspace SCHED_FIFO
> task will block printk for ever.  This seems bad.

I have to research this a bit but won't the SCHED_FIFO task that has
potentially unbounded amount of work lockup the CPU even though it does
occasional cond_resched()?

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

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

#1373212

Hello,

On (04/06/16 10:27), Jan Kara wrote:
[..]
> > Well, it's good that we have this.
> > 
> > It would be better if it was runtime-controllable - changing boot
> > parameters is a bit of a pain.  In fact with this approach, your
> > zillions-of-scsi-disks scenario becomes less problematic: do the async
> > offloading during the boot process then switch back to the more
> > reliable sync printing late in boot.
> 
> Doing this should be relatively easy. It would be userspace's decision
> whether they want more reliable or faster printk. Sounds fine with me.

I can add it as a separate patch to the series. should be quite trivial.

I have [minor] concerns, though. I can see how, for example, user space
can decide what logging level it wants '1 4 4 7' or anything else, but
how can user space decide what printk implementation it wants to use?

I'm more or less positive not to back-port that `synchronous RW' patch
to the kernels that I use; just because I don't want to give this freedom
to people, sync printk is something I'm trying to run away from.


> > This gets normal scheduling policy, so a spinning userspace SCHED_FIFO
> > task will block printk for ever.  This seems bad.
> 
> I have to research this a bit but won't the SCHED_FIFO task that has
> potentially unbounded amount of work lockup the CPU even though it does
> occasional cond_resched()?

depending on `watchdog_thresh' value, it can take something like 20+
seconds before watchdog will notice softlockup.
so I'm setting printk kthread prio to `MAX_RT_PRIO - 1' as of now,
just in case.

I think I'll leave printk kthread init as a late_initcall. probably
would prefer core/arch/device init calls to happen in sync printk mode.

	-ss

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

#1373282

Hello,

On (04/07/16 18:48), Sergey Senozhatsky wrote:
> On (04/06/16 10:27), Jan Kara wrote:
> [..]
> > > Well, it's good that we have this.
> > > 
> > > It would be better if it was runtime-controllable - changing boot
> > > parameters is a bit of a pain.  In fact with this approach, your
> > > zillions-of-scsi-disks scenario becomes less problematic: do the async
> > > offloading during the boot process then switch back to the more
> > > reliable sync printing late in boot.
> > 
> > Doing this should be relatively easy. It would be userspace's decision
> > whether they want more reliable or faster printk. Sounds fine with me.

ok, after some thinking -- it makes a lot of sense to have it. good old
sync printk is potentially more reliable after all. I think I also now
want to meke the 'default' for printk_sync being 'true'. so we won't
spoil printk on the systems that never had any problems with it. at
least for one release cycle, may be. thus, people would need to request
async printk via boot param and switch back to sync printk once the booting
process is done [or keep async printk].

how does that sound?

	-ss

> > > This gets normal scheduling policy, so a spinning userspace SCHED_FIFO
> > > task will block printk for ever.  This seems bad.
> > 
> > I have to research this a bit but won't the SCHED_FIFO task that has
> > potentially unbounded amount of work lockup the CPU even though it does
> > occasional cond_resched()?
> 
> depending on `watchdog_thresh' value, it can take something like 20+
> seconds before watchdog will notice softlockup.
> so I'm setting printk kthread prio to `MAX_RT_PRIO - 1' as of now,
> just in case.
> 
> I think I'll leave printk kthread init as a late_initcall. probably
> would prefer core/arch/device init calls to happen in sync printk mode.

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

#1373390

On Thu 07-04-16 21:08:26, Sergey Senozhatsky wrote:
> Hello,
> 
> On (04/07/16 18:48), Sergey Senozhatsky wrote:
> > On (04/06/16 10:27), Jan Kara wrote:
> > [..]
> > > > Well, it's good that we have this.
> > > > 
> > > > It would be better if it was runtime-controllable - changing boot
> > > > parameters is a bit of a pain.  In fact with this approach, your
> > > > zillions-of-scsi-disks scenario becomes less problematic: do the async
> > > > offloading during the boot process then switch back to the more
> > > > reliable sync printing late in boot.
> > > 
> > > Doing this should be relatively easy. It would be userspace's decision
> > > whether they want more reliable or faster printk. Sounds fine with me.
> 
> ok, after some thinking -- it makes a lot of sense to have it. good old
> sync printk is potentially more reliable after all. I think I also now
> want to meke the 'default' for printk_sync being 'true'. so we won't
> spoil printk on the systems that never had any problems with it. at
> least for one release cycle, may be. thus, people would need to request
> async printk via boot param and switch back to sync printk once the booting
> process is done [or keep async printk].
> 
> how does that sound?

That is fine with me. We can always enable this by default in our distro so
that it gets more exposure and big machines are able to boot...

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

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web