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

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

[Sergey Senozhatsky]

Hello,

 RFC

 The patch set is based on slightly updated Jan Kara's patches.

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.

The patch set is against next-20160321

the series in total has 3 patches:
- printk: Make printk() completely async
- printk: Make wake_up_klogd_work_func() async
- printk: make console_unlock() async

per discussion, "printk: make console_unlock() async" will be posted
later on.

v7:
-- 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              | 216 ++++++++++++++++++++++++++----------
 2 files changed, 168 insertions(+), 58 deletions(-)

-- 
2.8.0.rc3.12.g047057b

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

[RFC][PATCH v6 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 99c105d6..70cde26 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -349,9 +349,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_sync && 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 v6 0/2] printk: Make printk() completely async

[Jan Kara]

Hi,

On Tue 22-03-16 02:25:28, Sergey Senozhatsky wrote:
>  The patch set is based on slightly updated Jan Kara's patches.
> 
> 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.
> 
> The patch set is against next-20160321
> 
> the series in total has 3 patches:
> - printk: Make printk() completely async
> - printk: Make wake_up_klogd_work_func() async
> - printk: make console_unlock() async
> 
> per discussion, "printk: make console_unlock() async" will be posted
> later on.

Patches look good to me. I don't think you need to mention the
console_unlock() async patch when it is not part of the series.  BTW, you
seemed to have dropped my patch to skip if there are too many buffered
messages when oops is in progress. Any reason for that?

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

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

[Sergey Senozhatsky]

Hello Jan,

On (03/22/16 07:49), Jan Kara wrote:
> Hi,
> 
> On Tue 22-03-16 02:25:28, Sergey Senozhatsky wrote:
> >  The patch set is based on slightly updated Jan Kara's patches.
> > 
> > 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.
> > 
> > The patch set is against next-20160321
> > 
> > the series in total has 3 patches:
> > - printk: Make printk() completely async
> > - printk: Make wake_up_klogd_work_func() async
> > - printk: make console_unlock() async
> > 
> > per discussion, "printk: make console_unlock() async" will be posted
> > later on.
> 
> Patches look good to me. I don't think you need to mention the
> console_unlock() async patch when it is not part of the series.

thanks.

> BTW, you seemed to have dropped my patch to skip if there are too
> many buffered messages when oops is in progress. Any reason for that?

I did. seems that my box has some problems with emails delivery recently:
http://marc.info/?l=linux-kernel&m=145821214108806

in short,
I'm afraid we can lose valuable data in some cases.
for example

: hardlockup detector with sysctl_hardlockup_all_cpu_backtrace.
:
: static void watchdog_overflow_callback(...)
: {
:         ...
:         if (is_hardlockup()) {
:         ...
:                 if (sysctl_hardlockup_all_cpu_backtrace &&
:                                !test_and_set_bit(0, &hardlockup_allcpu_dumped))
:                         trigger_allbutself_cpu_backtrace();
:
:                 nmi_panic(regs, msg);
:         ...
:         }
:         ...
: }
:
: trigger_allbutself_cpu_backtrace() can be much more than 100 lines.
: trigger_allbutself_cpu_backtrace() may or may not be implemented via
: NMI. for example arch/sparc/kernel/process_64.c

on a large enough system trigger_allbutself_cpu_backtrace() can easily be more
than 100 lines, and trigger_allbutself_cpu_backtrace() may not be able to print
the backtraces to console (for example this hardlockuped CPU owns the console_sem)
before CPU declares oops_in_progress in nmi_panic()->panic().

	-ss

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

[Jan Kara]

On Tue 22-03-16 16:57:38, Sergey Senozhatsky wrote:
> : hardlockup detector with sysctl_hardlockup_all_cpu_backtrace.
> :
> : static void watchdog_overflow_callback(...)
> : {
> :         ...
> :         if (is_hardlockup()) {
> :         ...
> :                 if (sysctl_hardlockup_all_cpu_backtrace &&
> :                                !test_and_set_bit(0, &hardlockup_allcpu_dumped))
> :                         trigger_allbutself_cpu_backtrace();
> :
> :                 nmi_panic(regs, msg);
> :         ...
> :         }
> :         ...
> : }
> :
> : trigger_allbutself_cpu_backtrace() can be much more than 100 lines.
> : trigger_allbutself_cpu_backtrace() may or may not be implemented via
> : NMI. for example arch/sparc/kernel/process_64.c
> 
> on a large enough system trigger_allbutself_cpu_backtrace() can easily be more
> than 100 lines, and trigger_allbutself_cpu_backtrace() may not be able to print
> the backtraces to console (for example this hardlockuped CPU owns the console_sem)
> before CPU declares oops_in_progress in nmi_panic()->panic().

OK, makes sense. We'd probably need more clever logic in detecting when to
skip. Let's drop it for now and revisit it later if it is an issue. Thanks
for explanation.

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

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

[Petr Mladek]

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

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

[Petr Mladek]

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

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

[Petr Mladek]

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

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

[Sergey Senozhatsky]

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

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

[Sergey Senozhatsky]

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

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

[Sergey Senozhatsky]

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

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

[Petr Mladek]

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

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

[Petr Mladek]

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.

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

[Jan Kara]

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

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

[Sergey Senozhatsky]

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

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

[Jan Kara]

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

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

[Sergey Senozhatsky]

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

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

[Pavel Machek]

On Tue 2016-03-22 07:49:48, Jan Kara wrote:
> Hi,
> 
> On Tue 22-03-16 02:25:28, Sergey Senozhatsky wrote:
> >  The patch set is based on slightly updated Jan Kara's patches.
> > 
> > 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.
> > 
> > The patch set is against next-20160321
> > 
> > the series in total has 3 patches:
> > - printk: Make printk() completely async
> > - printk: Make wake_up_klogd_work_func() async
> > - printk: make console_unlock() async
> > 
> > per discussion, "printk: make console_unlock() async" will be posted
> > later on.
> 
> Patches look good to me. I don't think you need to mention the
> console_unlock() async patch when it is not part of the series.  BTW, you
> seemed to have dropped my patch to skip if there are too many buffered
> messages when oops is in progress. Any reason for that?

So... from basically linux 0.0, cli() printk("") could be used for
debugging. ... and that's now gone. Right?

Can you explain why that is good idea?
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

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

[Sergey Senozhatsky]

On (04/23/16 21:40), Pavel Machek wrote:
[..]
> > > The patch set is against next-20160321
> > > 
> > > the series in total has 3 patches:
> > > - printk: Make printk() completely async
> > > - printk: Make wake_up_klogd_work_func() async
> > > - printk: make console_unlock() async
> > > 
> > > per discussion, "printk: make console_unlock() async" will be posted
> > > later on.
> > 
> > Patches look good to me. I don't think you need to mention the
> > console_unlock() async patch when it is not part of the series.  BTW, you
> > seemed to have dropped my patch to skip if there are too many buffered
> > messages when oops is in progress. Any reason for that?
> 
> So... from basically linux 0.0, cli() printk("") could be used for
> debugging. ... and that's now gone. Right?
> 
> Can you explain why that is good idea?

it's not gone. you need to explicitly enable async printk mode. the case
you mentioned -- cli() printk("")->console_unlock() -- apart from being
useful in some scenarios, can cause problems in others, simply because
under some circumstances it can run forever, as long as there are printk()
calls coming from other CPUs (which can happen during, f.e., debugging).
did you mean UP systems? well, async printk is sort of useless on UP systems
anyway.

	-ss

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

[Pavel Machek]

On Sun 2016-04-24 14:14:49, Sergey Senozhatsky wrote:
> On (04/23/16 21:40), Pavel Machek wrote:
> [..]
> > > > The patch set is against next-20160321
> > > > 
> > > > the series in total has 3 patches:
> > > > - printk: Make printk() completely async
> > > > - printk: Make wake_up_klogd_work_func() async
> > > > - printk: make console_unlock() async
> > > > 
> > > > per discussion, "printk: make console_unlock() async" will be posted
> > > > later on.
> > > 
> > > Patches look good to me. I don't think you need to mention the
> > > console_unlock() async patch when it is not part of the series.  BTW, you
> > > seemed to have dropped my patch to skip if there are too many buffered
> > > messages when oops is in progress. Any reason for that?
> > 
> > So... from basically linux 0.0, cli() printk("") could be used for
> > debugging. ... and that's now gone. Right?
> > 
> > Can you explain why that is good idea?
> 
> it's not gone. you need to explicitly enable async printk mode. the case
> you mentioned -- cli() printk("")->console_unlock() -- apart from being
> useful in some scenarios, can cause problems in others, simply because
> under some circumstances it can run forever, as long as there are printk()
> calls coming from other CPUs (which can happen during, f.e., debugging).
> did you mean UP systems? well, async printk is sort of useless on UP systems
> anyway.

Well, yes, it has been long known that printk() can take long
time.. Still that's not a problem for smaller system.

Now, patch set above says "Make printk() completely async" -- so I
assumed that it does...

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

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

[Sergey Senozhatsky]

On (04/24/16 15:35), Pavel Machek wrote:
[..]
> > > So... from basically linux 0.0, cli() printk("") could be used for
> > > debugging. ... and that's now gone. Right?
> > > 
> > > Can you explain why that is good idea?
> > 
> > it's not gone. you need to explicitly enable async printk mode. the case
> > you mentioned -- cli() printk("")->console_unlock() -- apart from being
> > useful in some scenarios, can cause problems in others, simply because
> > under some circumstances it can run forever, as long as there are printk()
> > calls coming from other CPUs (which can happen during, f.e., debugging).
> > did you mean UP systems? well, async printk is sort of useless on UP systems
> > anyway.
> 
> Well, yes, it has been long known that printk() can take long
> time.. Still that's not a problem for smaller system.

well, embedded systems can have slow serial consoles (so
console_unlock()->call_consoles_drivers() endup in uart/etc
device driver). and small systems are the systems where I
see problems with printk.

> Now, patch set above says "Make printk() completely async" -- so I
> assumed that it does...

that's my bad, sorry. I didn't keep an eye on the cover letter
(except for the changelog).

	-ss