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

Groups > linux.kernel > #1362024 > unrolled thread

[RFC][PATCH v6 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

  [RFC][PATCH v6 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-03-21 18:30 +0100
    Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-03-22 14:20 +0100
      Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-03-22 15:10 +0100
      Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-03-23 01:40 +0100
        Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-03-23 09:50 +0100
        Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-03-23 11:10 +0100
          Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-03-24 03:30 +0100
    Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-03-22 17:40 +0100
      Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-03-23 02:30 +0100
        Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-03-23 10:30 +0100
          Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async Jan Kara <jack@suse.cz> - 2016-03-23 14:20 +0100
            Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-03-23 15:40 +0100
              Re: [RFC][PATCH v6 1/2] printk: Make printk() completely async Jan Kara <jack@suse.cz> - 2016-03-23 15:50 +0100

#1362024 — [RFC][PATCH v6 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). Another thing to mention,
is that deferred printk() messages may appear before printing kthread
created, so in the very beginning we have to print deferred messages
the old way -- via IRQs.

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              | 209 ++++++++++++++++++++++++++----------
 2 files changed, 161 insertions(+), 58 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 e38579d..99c105d6 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>
@@ -285,6 +286,105 @@ 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 unless someone else
+ * is already printing messages.
+ *
+ * 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 vprintk_emit() */
+static struct task_struct *printk_kthread;
+/* When `true' - printing thread has messages to print */
+static bool need_flush_console;
+
+static int printing_func(void *data)
+{
+	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();
+	}
+
+	return 0;
+}
+
+static int __init init_printk_kthread(void)
+{
+	struct task_struct *thread;
+
+	if (printk_sync)
+		return 0;
+
+	thread = kthread_run(printing_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:
+ */
+#define PRINTK_PENDING_WAKEUP	(1<<0)
+#define PRINTK_PENDING_OUTPUT	(1<<1)
+
+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 trylock fails, someone else is doing the printing */
+		if (console_trylock())
+			console_unlock();
+	}
+
+	if (pending & PRINTK_PENDING_WAKEUP)
+		wake_up_interruptible(&log_wait);
+}
+
+static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
+	.func = wake_up_klogd_work_func,
+	.flags = IRQ_WORK_LAZY,
+};
+
+void wake_up_klogd(void)
+{
+	preempt_disable();
+	if (waitqueue_active(&log_wait)) {
+		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
+		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
+	}
+	preempt_enable();
+}
+
+int printk_deferred(const char *fmt, ...)
+{
+	va_list args;
+	int r;
+
+	va_start(args, fmt);
+	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
+	va_end(args);
+
+	return r;
+}
+
 /* Return log buffer address */
 char *log_buf_addr_get(void)
 {
@@ -1609,6 +1709,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;
@@ -1619,12 +1721,21 @@ asmlinkage int vprintk_emit(int facility, int level,
 	int printed_len = 0;
 	int nmi_message_lost;
 	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;
+	bool sync_print = printk_sync;
+
+	/* disable async printk */
+	if (in_panic)
+		printk_sync = true;
 
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
+		/*
+		 * Deferred sched messages must not be printed
+		 * synchronously regardless the @printk_sync or @in_panic.
+		 */
 		in_sched = true;
+		sync_print = false;
 	}
 
 	boot_delay_msec(level);
@@ -1657,6 +1768,14 @@ asmlinkage int vprintk_emit(int facility, int level,
 	raw_spin_lock(&logbuf_lock);
 	logbuf_cpu = this_cpu;
 
+	/*
+	 * Set printing_func() sleep condition early, under the @logbuf_lock.
+	 * So printing kthread (if RUNNING) will go to console_lock() and spin
+	 * on @logbuf_lock.
+	 */
+	if (!printk_sync)
+		need_flush_console = true;
+
 	if (unlikely(recursion_bug)) {
 		static const char recursion_msg[] =
 			"BUG: recent printk recursion!";
@@ -1762,10 +1881,38 @@ asmlinkage int vprintk_emit(int facility, int level,
 	logbuf_cpu = UINT_MAX;
 	raw_spin_unlock(&logbuf_lock);
 	lockdep_on();
+	/*
+	 * 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 (!sync_print) {
+		if (in_sched) {
+			/*
+			 * @in_sched messages may come too early, when we don't
+			 * yet have @printk_kthread. We can't print deferred
+			 * messages directly, because this may deadlock, route
+			 * them via IRQ context.
+			 */
+			__this_cpu_or(printk_pending,
+					PRINTK_PENDING_OUTPUT);
+			irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
+		} else if (printk_kthread && !in_panic) {
+			/* Offload printing to a schedulable context. */
+			wake_up_process(printk_kthread);
+		} else {
+			sync_print = true;
+		}
+	}
 	local_irq_restore(flags);
 
-	/* If called from the scheduler, we can not call up(). */
-	if (!in_sched) {
+	if (sync_print) {
 		lockdep_off();
 		/*
 		 * Try to acquire and then immediately release the console
@@ -2716,60 +2863,6 @@ 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 trylock fails, someone else is doing the printing */
-		if (console_trylock())
-			console_unlock();
-	}
-
-	if (pending & PRINTK_PENDING_WAKEUP)
-		wake_up_interruptible(&log_wait);
-}
-
-static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
-	.func = wake_up_klogd_work_func,
-	.flags = IRQ_WORK_LAZY,
-};
-
-void wake_up_klogd(void)
-{
-	preempt_disable();
-	if (waitqueue_active(&log_wait)) {
-		this_cpu_or(printk_pending, PRINTK_PENDING_WAKEUP);
-		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
-	}
-	preempt_enable();
-}
-
-int printk_deferred(const char *fmt, ...)
-{
-	va_list args;
-	int r;
-
-	preempt_disable();
-	va_start(args, fmt);
-	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
-	va_end(args);
-
-	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
-	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
-	preempt_enable();
-
-	return r;
-}
-
-/*
  * printk rate limiting, lifted from the networking subsystem.
  *
  * This enforces a rate limit: not more than 10 kernel messages
-- 
2.8.0.rc3.12.g047057b

[toc] | [next] | [standalone]

#1362721

On Tue 2016-03-22 02:25:29, Sergey Senozhatsky wrote:
> From: Jan Kara <jack@suse.cz>
> 
> 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). Another thing to mention,
> is that deferred printk() messages may appear before printing kthread
> created, so in the very beginning we have to print deferred messages
> the old way -- via IRQs.
> 
> 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              | 209 ++++++++++++++++++++++++++----------
>  2 files changed, 161 insertions(+), 58 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index e38579d..99c105d6 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> +/*
> + * Delayed printk version, for scheduler-internal messages:
> + */
> +#define PRINTK_PENDING_WAKEUP	(1<<0)
> +#define PRINTK_PENDING_OUTPUT	(1<<1)
> +
> +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 trylock fails, someone else is doing the printing */
> +		if (console_trylock())
> +			console_unlock();

This is called from IRQ context and thus keeps the original problem
for printk_deferred(). We should try to
wake_up_process(printk_kthread) when allowed.

	if (pending & PRINTK_PENDING_OUTPUT) {
		if (printk_sync || !printk_kthread) {
			/* If trylock fails, someone else is printing. */
			if (console_trylock())
				console_unlock();
		} else {
			wake_up_process(printk_kthread);
		}
	}


> @@ -1609,6 +1709,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;
> @@ -1619,12 +1721,21 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	int printed_len = 0;
>  	int nmi_message_lost;
>  	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;
> +	bool sync_print = printk_sync;

I still think that this local variable adds more mess than good.
Please, rename it to do_printk_sync at least. It will a poor human
to distinguish it from the global one ;-)

I still hope that we could get rid if it, see below.

> +
> +	/* disable async printk */
> +	if (in_panic)
> +		printk_sync = true;
>  
>  	if (level == LOGLEVEL_SCHED) {
>  		level = LOGLEVEL_DEFAULT;
> +		/*
> +		 * Deferred sched messages must not be printed
> +		 * synchronously regardless the @printk_sync or @in_panic.
> +		 */
>  		in_sched = true;
> +		sync_print = false;
>  	}
>  
>  	boot_delay_msec(level);
> @@ -1657,6 +1768,14 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	raw_spin_lock(&logbuf_lock);
>  	logbuf_cpu = this_cpu;
>  
> +	/*
> +	 * Set printing_func() sleep condition early, under the @logbuf_lock.
> +	 * So printing kthread (if RUNNING) will go to console_lock() and spin
> +	 * on @logbuf_lock.
> +	 */
> +	if (!printk_sync)
> +		need_flush_console = true;

We set this variable for each call and also when printk_kthread is
NULL or when sync_printk is false.

We migth want to clear it also from console_unlock(). I think that
a good place would be in the check:

	raw_spin_lock(&logbuf_lock);
	retry = console_seq != log_next_seq;
	raw_spin_unlock_irqrestore(&logbuf_lock, flags);


>  	if (unlikely(recursion_bug)) {
>  		static const char recursion_msg[] =
>  			"BUG: recent printk recursion!";
> @@ -1762,10 +1881,38 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	logbuf_cpu = UINT_MAX;
>  	raw_spin_unlock(&logbuf_lock);
>  	lockdep_on();
> +	/*
> +	 * 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 (!sync_print) {
> +		if (in_sched) {
> +			/*
> +			 * @in_sched messages may come too early, when we don't
> +			 * yet have @printk_kthread. We can't print deferred
> +			 * messages directly, because this may deadlock, route
> +			 * them via IRQ context.
> +			 */
> +			__this_cpu_or(printk_pending,
> +					PRINTK_PENDING_OUTPUT);
> +			irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> +		} else if (printk_kthread && !in_panic) {
> +			/* Offload printing to a schedulable context. */
> +			wake_up_process(printk_kthread);
> +		} else {
> +			sync_print = true;
> +		}
> +	}
>  	local_irq_restore(flags);

Please, what is the exact reason to call the above stuff before
we release IRQs here? I guess that it is related to the discussions
about possible lock debugging, infinite loops, ...

I wonder how the disabled IRQs help here. It is very likely that I
miss something.

In each case, irq_work_queue() is lock-less and was used with IRQs
enabled before.

So, it might be related to wake_up_process(). It takes a lock but
using

       raw_spin_lock_irqsave(&p->pi_lock, flags);

, so it disables IRQs in the critical section. Do we need to guard
it in between?

I think that you actually wanted to disable lockdep or any other lock
debugging, instead.

I wonder if the following code would do the job and is better readable
to others.

	/*
	 * 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 (in_sched) {
		/*
		 * @in_sched messages may come too early, when we don't
		 * yet have @printk_kthread. We can't print deferred
		 * messages directly, because this may deadlock, route
		 * them via IRQ context.
		 */
		__this_cpu_or(printk_pending,
			      PRINTK_PENDING_OUTPUT);
		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
		goto out;
	}

	/* Avoid printk recursion */
	lockdep_off();

	if  (printk_kthread && !in_panic) {
		/* Offload printing to a schedulable context. */
		wake_up_process(printk_kthread);
		goto out_lockdep;
	} 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();


I do not say that it is a "dream-of-like" code. One important thing for
me is that it does not use "sync_printk" variable.

You original code modified "sync_printk" according to "in_sched" and
"in_panic" variables earlier in vprintk_emit. Then it again checked
all three variables here which produced strange twists in my head ;-)


Best regards,
Petr

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

#1362757

On Tue 2016-03-22 14:11:06, Petr Mladek wrote:
> On Tue 2016-03-22 02:25:29, Sergey Senozhatsky wrote:
> > +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();
> 
> This is called from IRQ context and thus keeps the original problem
> for printk_deferred(). We should try to
> wake_up_process(printk_kthread) when allowed.
> 
> 	if (pending & PRINTK_PENDING_OUTPUT) {
> 		if (printk_sync || !printk_kthread) {
> 			/* If trylock fails, someone else is printing. */
> 			if (console_trylock())
> 				console_unlock();
> 		} else {
> 			wake_up_process(printk_kthread);
> 		}
> 	}

Ah, this is in the 2nd patch. I am sorry for the noise.

Best Regards,
Petr

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

#1363142

Hello Petr,

On (03/22/16 14:11), Petr Mladek wrote:
[..]
> > -	/* cpu currently holding logbuf_lock in this function */
> > -	static unsigned int logbuf_cpu = UINT_MAX;
> > +	bool in_panic = console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH;
> > +	bool sync_print = printk_sync;
> 
> I still think that this local variable adds more mess than good.
> Please, rename it to do_printk_sync at least. It will a poor human
> to distinguish it from the global one ;-)

ok, I'll take a look :)

> > +	 * Set printing_func() sleep condition early, under the @logbuf_lock.
> > +	 * So printing kthread (if RUNNING) will go to console_lock() and spin
> > +	 * on @logbuf_lock.
> > +	 */
> > +	if (!printk_sync)
> > +		need_flush_console = true;
> 
> We set this variable for each call and also when printk_kthread is
> NULL or when sync_printk is false.

hm, yes. (printk_kthread && !need_flush_console) makes more sense.
so we it doesn't get re-dirty if already set.

> We migth want to clear it also from console_unlock(). I think that
> a good place would be in the check:
> 
> 	raw_spin_lock(&logbuf_lock);
> 	retry = console_seq != log_next_seq;
> 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);

hm, what's wrong with clearing it in printk_kthread  printing function?

> > +	if (!sync_print) {
> > +		if (in_sched) {
> > +			/*
> > +			 * @in_sched messages may come too early, when we don't
> > +			 * yet have @printk_kthread. We can't print deferred
> > +			 * messages directly, because this may deadlock, route
> > +			 * them via IRQ context.
> > +			 */
> > +			__this_cpu_or(printk_pending,
> > +					PRINTK_PENDING_OUTPUT);
> > +			irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> > +		} else if (printk_kthread && !in_panic) {
> > +			/* Offload printing to a schedulable context. */
> > +			wake_up_process(printk_kthread);
> > +		} else {
> > +			sync_print = true;
> > +		}
> > +	}
> >  	local_irq_restore(flags);
> 
> Please, what is the exact reason to call the above stuff before
> we release IRQs here? I guess that it is related to the discussions
> about possible lock debugging, infinite loops, ...
> 
> I wonder how the disabled IRQs help here. It is very likely that I
> miss something.

with IRQs enabled we have preemption enabled, so this thing

        __this_cpu_or(printk_pending,
                        PRINTK_PENDING_OUTPUT);
        irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));

can set pending and queue irq_work on different CPUs.

using "this_cpu = smp_processor_id()" which is taken right after
local_irq_save(flags) at the beginning of vprintk_emit() is not an
option - once we enable preemption CPUs are free to go offline. so
this thing wants to be under preemption disable(), and local_irq_save()
gives us it.

well, I can do

        + preempt_disable()
        + local_irq_restore()

        if (!sync_print) {
        ...
                __this_cpu_or()
                irq_work_queue()
        ...
        }
        - local_irq_restore()
        + preempt_enable()

but

> In each case, irq_work_queue() is lock-less and was used with IRQs
> enabled before.
> 
> So, it might be related to wake_up_process(). It takes a lock but
> using
> 
>        raw_spin_lock_irqsave(&p->pi_lock, flags);

wake_up_process disables IRQs in the beginning anyway.
so we have

        local_irq_restore()
        local_irq_save()

which is sort of nasty. disabling IRQs can be a bit expensive, not
that printk is that hot path, but I wanted to avoid additional latencies
that can happen due to IRQ enable-disable ping-pong.

> , so it disables IRQs in the critical section. Do we need to guard
> it in between?
> 
> I think that you actually wanted to disable lockdep or any other lock
> debugging, instead.

preemption.

well, disabling lockdep is may be a good thing to do as well...

> 	if (in_sched) {
> 		/*
> 		 * @in_sched messages may come too early, when we don't
> 		 * yet have @printk_kthread. We can't print deferred
> 		 * messages directly, because this may deadlock, route
> 		 * them via IRQ context.
> 		 */
> 		__this_cpu_or(printk_pending,
> 			      PRINTK_PENDING_OUTPUT);
> 		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> 		goto out;
> 	}
> 
> 	/* Avoid printk recursion */
> 	lockdep_off();
> 
> 	if  (printk_kthread && !in_panic) {
> 		/* Offload printing to a schedulable context. */
> 		wake_up_process(printk_kthread);
> 		goto out_lockdep;
> 	} 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();
> 

ok, I'll take a look.

eventually (after 0003) vprintk_emit() is

	if (in_sched) {
		__this_cpu_or(printk_pending,
				PRINTK_PENDING_OUTPUT);
		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
	}
	local_irq_restore(flags);
	if (!in_sched) {
		lockdep_off();
		if (console_trylock())
			console_unlock();
		lockdep_on();
	}

> I do not say that it is a "dream-of-like" code. One important thing for
> me is that it does not use "sync_printk" variable.
> 
> You original code modified "sync_printk" according to "in_sched" and
> "in_panic" variables earlier in vprintk_emit. Then it again checked
> all three variables here which produced strange twists in my head ;-)

yeah, I can see your point. a bunch of goto-s can probably help here.

	-ss

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

#1363251

On (03/23/16 09:37), Sergey Senozhatsky wrote:
[..]
> ok, I'll take a look.
> 
> eventually (after 0003) vprintk_emit() is
> 
> 	if (in_sched) {
> 		__this_cpu_or(printk_pending,
> 				PRINTK_PENDING_OUTPUT);
> 		irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
> 	}
> 	local_irq_restore(flags);
> 	if (!in_sched) {
> 		lockdep_off();
> 		if (console_trylock())
> 			console_unlock();
> 		lockdep_on();
> 	}
> 
> > I do not say that it is a "dream-of-like" code. One important thing for
> > me is that it does not use "sync_printk" variable.
> >
> > You original code modified "sync_printk" according to "in_sched" and
> > "in_panic" variables earlier in vprintk_emit. Then it again checked
> > all three variables here which produced strange twists in my head ;-)
> 

hm... may be we can do even better.
move printk_pending and irq_work_queue() back to printk_deferred() and
do the preemption magic there. so vprintk_emit() can be lighter. will
take a look later today.

	-ss

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

#1363281

On Wed 2016-03-23 09:37:25, Sergey Senozhatsky wrote:
> Hello Petr,
> 
> On (03/22/16 14:11), Petr Mladek wrote:
> > > +	 * Set printing_func() sleep condition early, under the @logbuf_lock.
> > > +	 * So printing kthread (if RUNNING) will go to console_lock() and spin
> > > +	 * on @logbuf_lock.
> > > +	 */
> > > +	if (!printk_sync)
> > > +		need_flush_console = true;
> > 
> > We set this variable for each call and also when printk_kthread is
> > NULL or when sync_printk is false.
> 
> hm, yes. (printk_kthread && !need_flush_console) makes more sense.
> so we it doesn't get re-dirty if already set.

This does not solve the problem mentioned below. There still might be
extra cycle if the kthread is inside console_unclock().

> > We migth want to clear it also from console_unlock(). I think that
> > a good place would be in the check:
> > 
> > 	raw_spin_lock(&logbuf_lock);
> > 	retry = console_seq != log_next_seq;
> > 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
> 
> hm, what's wrong with clearing it in printk_kthread  printing function?

I though about the following scenario:

CPU0					CPU1

vprintk_emit()
  need_flush_console = true;

  wake_up_process(printk_thread)

					printing_func()

					  need_flush_console = false;

					  console_lock()
					  console_unlock()

vprintk_emit()

  need_flush_console = true;

					    # flush 1st message
					    # flush 2nd message

					    if (!need_flush_console)
					      # fails and continues

					    console_lock()
					    console_unlock()

					    # nope because 2nd
					    # message already flushed

					  if (!need_flush_console)
					     schedule()

					     # did one unnecessary
					     # cycle to get asleep


Best Regards,
Petr

PS: If you touch the code, please rename printing_func() to
printk_kthread_func() to make it more clear what it does.
I am sorry for nitpicking.

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

#1363871

On (03/23/16 11:04), Petr Mladek wrote:
[..]
> 					  if (!need_flush_console)
> 					     schedule()
> 
> 					     # did one unnecessary
> 					     # cycle to get asleep

OK. well, didn't consider it to be a problem, but I'll make it
symmetric:
	we set need_flush_console under logbuf lock,
	we clear it under logbuf lock.

should be simpler.

> PS: If you touch the code, please rename printing_func() to
> printk_kthread_func() to make it more clear what it does.

oh, yes, was going to do it but somehow forgot.

	-ss

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

#1362842

On Tue 2016-03-22 02:25:29, Sergey Senozhatsky wrote:
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index e38579d..99c105d6 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1619,12 +1721,21 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	int printed_len = 0;
>  	int nmi_message_lost;
>  	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;

I am just looking at the printk in NMI patchset and I will need to
deal with the panic state as well. I am not sure if this detection
is secure.

This console level is set also by kdb_show_stack()
and kdb_dumpregs(). I am not sure how this kdb stuff works
and if it affects normal kernel but...

Anyway, it seems that many locations detects the panic situation
via the variable oops_in_progress. It has another advantage
that it can be easily checked and we would not need any extra
variable here.


> +	bool sync_print = printk_sync;
> +
> +	/* disable async printk */
> +	if (in_panic)
> +		printk_sync = true;

In each case, we should not switch the global state if we
only print debug traces.

Best Regards,
Petr

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

#1363149

On (03/22/16 17:36), Petr Mladek wrote:
> > -	/* cpu currently holding logbuf_lock in this function */
> > -	static unsigned int logbuf_cpu = UINT_MAX;
> > +	bool in_panic = console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH;
> 
> I am just looking at the printk in NMI patchset and I will need to
> deal with the panic state as well. I am not sure if this detection
> is secure.
> 
> This console level is set also by kdb_show_stack()
> and kdb_dumpregs(). I am not sure how this kdb stuff works
> and if it affects normal kernel but...
> 
> Anyway, it seems that many locations detects the panic situation
> via the variable oops_in_progress. It has another advantage
> that it can be easily checked and we would not need any extra
> variable here.

oops_in_progress is not my favorite global. and we can't rely on it
in async printk.

in panic() we have

 console_verbose();
 bust_spinlocks(1); 		<< sets to one

	pr_emerg("Kernel panic - not syncing: %s\n", buf);
	smp_send_stop();

 bust_spinlocks(0);		<< sets it back to zero

	console_flush_on_panic();

there are several issues here.
- first, panic_cpu does not see oops_in_progress right after bust_spinlocks(0).
thus all printk issued from panic_cpu can go via async printk.

- second, smp_send_stop() does not guarantee that all of the CPUs received
STOP IPI by the time it returns. on some platforms (ARM, for instance)
smp_send_stop()

:        if (!cpumask_empty(&mask))
:                smp_cross_call(&mask, IPI_CPU_STOP);
:
:        /* Wait up to one second for other CPUs to stop */
:        timeout = USEC_PER_SEC;
:        while (num_online_cpus() > 1 && timeout--)
:                 udelay(1);
:
:        if (num_online_cpus() > 1)
:               pr_warn("SMP: failed to stop secondary CPUs\n");
:
:        return;

 waits for one second and returns back to panic_cpu, and panic_cpu sets
oops_in_progress back to zero. simulataneously SOPT_IPIs can start arriving
to remaining CPUs. on some platforms (ARM, for instance) STOP_IPI is

:                 raw_spin_lock(&stop_lock);
:                 pr_crit("CPU%u: stopping\n", cpu);
:                 dump_stack();
:                 raw_spin_unlock(&stop_lock);
:         }
:
:         set_cpu_online(cpu, false);
:
:         local_fiq_disable();
:         local_irq_disable();
:
:         while (1)
:                 cpu_relax();


so CPUs dump_stack()s can in theory happen when oops_in_progress is zero
and, thus, printk will try to print it by printk_kthread, which is not
something we really want to do in panic().

so I wanted to have in printk some panic indication that once set never
gets cleared. my proposal was

void console_panic(void)
{
	printk_sync = false;
}

or similar.

	-ss

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

#1363272

On Wed 2016-03-23 10:24:43, Sergey Senozhatsky wrote:
> On (03/22/16 17:36), Petr Mladek wrote:
> > > -	/* cpu currently holding logbuf_lock in this function */
> > > -	static unsigned int logbuf_cpu = UINT_MAX;
> > > +	bool in_panic = console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH;
> > 
> > I am just looking at the printk in NMI patchset and I will need to
> > deal with the panic state as well. I am not sure if this detection
> > is secure.
> > 
> > This console level is set also by kdb_show_stack()
> > and kdb_dumpregs(). I am not sure how this kdb stuff works
> > and if it affects normal kernel but...
> > 
> > Anyway, it seems that many locations detects the panic situation
> > via the variable oops_in_progress. It has another advantage
> > that it can be easily checked and we would not need any extra
> > variable here.
> 
> oops_in_progress is not my favorite global. and we can't rely on it
> in async printk.
> 
> in panic() we have
> 
>  console_verbose();
>  bust_spinlocks(1); 		<< sets to one
> 
> 	pr_emerg("Kernel panic - not syncing: %s\n", buf);
> 	smp_send_stop();
> 
>  bust_spinlocks(0);		<< sets it back to zero
> 
> 	console_flush_on_panic();
> 
> there are several issues here.
> - first, panic_cpu does not see oops_in_progress right after bust_spinlocks(0).
> thus all printk issued from panic_cpu can go via async printk.

I though that it actually could be an advantage. console_verbore() is
called also by oops_begin() and it does not need to be fatal. But you
are right that it does not need to be the righ approach.


> - second, smp_send_stop() does not guarantee that all of the CPUs received
> STOP IPI by the time it returns. on some platforms (ARM, for instance)
> smp_send_stop()

Good to know.

> so I wanted to have in printk some panic indication that once set never
> gets cleared. my proposal was
> 
> void console_panic(void)
> {
> 	printk_sync = false;
> }

Great idea. I think that we want to call this in panic() instead of
in vprintk_emit(). I mean that we should change the global flag only
when we are really going down.

Best Regards,
Petr

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

#1363420

On Wed 23-03-16 10:25:41, Petr Mladek wrote:
> On Wed 2016-03-23 10:24:43, Sergey Senozhatsky wrote:
> > On (03/22/16 17:36), Petr Mladek wrote:
> > > > -	/* cpu currently holding logbuf_lock in this function */
> > > > -	static unsigned int logbuf_cpu = UINT_MAX;
> > > > +	bool in_panic = console_loglevel == CONSOLE_LOGLEVEL_MOTORMOUTH;
> > > 
> > > I am just looking at the printk in NMI patchset and I will need to
> > > deal with the panic state as well. I am not sure if this detection
> > > is secure.
> > > 
> > > This console level is set also by kdb_show_stack()
> > > and kdb_dumpregs(). I am not sure how this kdb stuff works
> > > and if it affects normal kernel but...
> > > 
> > > Anyway, it seems that many locations detects the panic situation
> > > via the variable oops_in_progress. It has another advantage
> > > that it can be easily checked and we would not need any extra
> > > variable here.
> > 
> > oops_in_progress is not my favorite global. and we can't rely on it
> > in async printk.
> > 
> > in panic() we have
> > 
> >  console_verbose();
> >  bust_spinlocks(1); 		<< sets to one
> > 
> > 	pr_emerg("Kernel panic - not syncing: %s\n", buf);
> > 	smp_send_stop();
> > 
> >  bust_spinlocks(0);		<< sets it back to zero
> > 
> > 	console_flush_on_panic();
> > 
> > there are several issues here.
> > - first, panic_cpu does not see oops_in_progress right after bust_spinlocks(0).
> > thus all printk issued from panic_cpu can go via async printk.
> 
> I though that it actually could be an advantage. console_verbore() is
> called also by oops_begin() and it does not need to be fatal. But you
> are right that it does not need to be the righ approach.

If we oops, I want printk to be sync regardless whether the machine is able
to live afterwards or not. You never know in advance... That's why I've
chosen the console_verbose() trigger and I still think it is better than
oops_in_progress or special console_panic() trigger.

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

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

#1363462

Hello,

On (03/23/16 14:20), Jan Kara wrote:
[..]
> > I though that it actually could be an advantage. console_verbore() is
> > called also by oops_begin() and it does not need to be fatal. But you
> > are right that it does not need to be the righ approach.
> 
> If we oops, I want printk to be sync regardless whether the machine is able
> to live afterwards or not. You never know in advance... That's why I've
> chosen the console_verbose() trigger and I still think it is better than
> oops_in_progress or special console_panic() trigger.

console_verbose() is good enough. well, with special console_panic() trigger
we can have better control and distinguish between "print a lot" and "things
are bad for sure, print in sync mode". there are 2 archs that call console_verbose()
in setup_arch():

- arch/microblaze/kernel/setup.c

: void __init setup_arch(char **cmdline_p)
: {
:         *cmdline_p = boot_command_line;
: 
:         console_verbose();			<<<<
: 
:         unflatten_device_tree();
: 
:         setup_cpuinfo();
: 
:         microblaze_cache_init();
: 
:         setup_memory();

- arch/nios2/kernel/setup.c

: void __init setup_arch(char **cmdline_p)
: {
:         int bootmap_size;
: 
:         console_verbose();			<<<<
: 
: #ifdef CONFIG_EARLY_PRINTK
:         setup_early_printk();
: #endif


so printk will never work in async mode there. hm... should we care?

	-ss

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

#1363465

On Wed 23-03-16 23:30:20, Sergey Senozhatsky wrote:
> Hello,
> 
> On (03/23/16 14:20), Jan Kara wrote:
> [..]
> > > I though that it actually could be an advantage. console_verbore() is
> > > called also by oops_begin() and it does not need to be fatal. But you
> > > are right that it does not need to be the righ approach.
> > 
> > If we oops, I want printk to be sync regardless whether the machine is able
> > to live afterwards or not. You never know in advance... That's why I've
> > chosen the console_verbose() trigger and I still think it is better than
> > oops_in_progress or special console_panic() trigger.
> 
> console_verbose() is good enough. well, with special console_panic() trigger
> we can have better control and distinguish between "print a lot" and "things
> are bad for sure, print in sync mode". there are 2 archs that call console_verbose()
> in setup_arch():
> 
> - arch/microblaze/kernel/setup.c
> 
> : void __init setup_arch(char **cmdline_p)
> : {
> :         *cmdline_p = boot_command_line;
> : 
> :         console_verbose();			<<<<
> : 
> :         unflatten_device_tree();
> : 
> :         setup_cpuinfo();
> : 
> :         microblaze_cache_init();
> : 
> :         setup_memory();
> 
> - arch/nios2/kernel/setup.c
> 
> : void __init setup_arch(char **cmdline_p)
> : {
> :         int bootmap_size;
> : 
> :         console_verbose();			<<<<
> : 
> : #ifdef CONFIG_EARLY_PRINTK
> :         setup_early_printk();
> : #endif
> 
> 
> so printk will never work in async mode there. hm... should we care?

I don't think we do. After all I believe they do console_verbose() to make
debugging boot issues easier and printk_sync helps that as well. If they
care about printk being async, they could always reset printk_sync to false
after boot is done...
								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web