Date:   Wed, 9 Nov 2016 16:47:24 +0100
From:   Petr Mladek <pmladek@...e.com>
To:     Linus Torvalds <torvalds@...ux-foundation.org>
Cc:     Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        Joe Perches <joe@...ches.com>,
        Geert Uytterhoeven <geert@...ux-m68k.org>,
        Tetsuo Handa <penguin-kernel@...ove.sakura.ne.jp>,
        Linux Kernel Mailing List <linux-kernel@...r.kernel.org>,
        Tejun Heo <tj@...nel.org>, Calvin Owens <calvinowens@...com>,
        Steven Rostedt <rostedt@...dmis.org>,
        Andrew Morton <akpm@...ux-foundation.org>
Subject: Re: linux.git: printk() problem

On Mon 2016-10-24 19:22:59, Linus Torvalds wrote:
> On Mon, Oct 24, 2016 at 7:06 PM, Linus Torvalds
> <torvalds@...ux-foundation.org> wrote:
> > On Mon, Oct 24, 2016 at 6:55 PM, Sergey Senozhatsky
> > <sergey.senozhatsky.work@...il.com> wrote:
> >>
> >> I think cont_flush() should grab the logbuf_lock lock, because
> >> it does log_store() and touches the cont.len. so something like
> >> this perhaps
> >
> > Absolutely. Good catch.
> 
> Actually, you can't do it the way you did (inside cont_flush), because
> "cont_flush()" is already called with logbuf_lock held in most cases
> (see "cont_add()").
> 
> So it's really just the timer function that needs to take the
> logbuf_lock before it calls cont_flush().
> 
> So here's a new version. How does this look to you?
> 
> Again, this still tests "cont.len" outside the lock (not just in
> console_unlock(), but also in deferred_cont_flush()). And it's fine:
> even if it sees the "wrong" value due to some race, it does so either
> because cont.len was just set to non-zero (and whoever set it will
> force the re-check anyway), or it got cleared just as it was tested
> (and at worst you end up with an extra timer invocation).

This patch really seems to reduce the number of too-early flushed
continuous lines. It reduces the scattered output. But I am not sure
if we want to add a timer code into the printk calls at this stage
(for 4.9-rc5).

Well, the patch looks fine, except that we call cont_flush() without
poking console. It is not a regression because only newlines triggered
console in the past and they still do but...

I would suggest to revert the commit bfd8d3f23b51018388be
("printk: make reading the kernel log flush pending lines") for
4.9. Then we could  test/fix it properly for 4.10. Me and Sergey would
happily help with it.

Just in case, you still want to commit this patch. I would suggest
to apply the one below on top.


>From 7a0ad7ce2347346fc81872fe42a95ad5dfba4098 Mon Sep 17 00:00:00 2001
From: Petr Mladek <pmladek@...e.com>
Date: Tue, 25 Oct 2016 15:23:13 +0200
Subject: [PATCH] printk: Poke console and other loggers when cont buffer is
 flushed

The commit bfd8d3f23b51018388be041 ("printk: make reading the kernel
log flush pending lines") allows to add new message into the log
buffer without flushing it to the console and waking other loggers.

This patch adds wake_up_console() and calls it when the cont
buffer is flushed. The function name will make more sense once
we switch to the async printk.

Note that it is enough to poke console. The other loggers
are waken from console_unlock() when there is a new message.

The patch also renames PRINTK_PENDING flags and wake_up_klogd_work*
stuff to reduce confusion. First, there are more possible log
daemons, e.g. klogd, syslogd. Second, the word "console" is more
descriptive than "output".

This patch is based on top of the fix proposed at
https://lkml.kernel.org/r/CA+55aFwKYnrMJr_vSE+GfDGszeUGyd=CPUD15-zZ8yWQW61GBA@mail.gmail.com

Signed-off-by: Petr Mladek <pmladek@...e.com>
---
 kernel/printk/printk.c | 60 ++++++++++++++++++++++++++++++++++----------------
 1 file changed, 41 insertions(+), 19 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e63aa679614e..f0e72de6ddbc 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -780,6 +780,7 @@ static ssize_t devkmsg_write(struct kiocb *iocb, struct iov_iter *from)
 }
 
 static void deferred_cont_flush(void);
+static void __wake_up_console(void);
 
 static ssize_t devkmsg_read(struct file *file, char __user *buf,
 			    size_t count, loff_t *ppos)
@@ -1620,13 +1621,11 @@ static bool cont_flush(void)
 static void flush_timer(unsigned long data)
 {
 	unsigned long flags;
-	bool did_flush;
 
 	raw_spin_lock_irqsave(&logbuf_lock, flags);
-	did_flush = cont_flush();
+	if (cont_flush())
+		__wake_up_console();
 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
-	if (did_flush)
-		wake_up_klogd();
 }
 
 static void deferred_cont_flush(void)
@@ -2730,40 +2729,57 @@ static int __init printk_late_init(void)
 
 #if defined CONFIG_PRINTK
 /*
- * Delayed printk version, for scheduler-internal messages:
+ * Handle console and wakeup loggers via IRQ work so that it can be done
+ * from any context.
  */
-#define PRINTK_PENDING_WAKEUP	0x01
-#define PRINTK_PENDING_OUTPUT	0x02
+#define PRINTK_PENDING_LOGGERS	0x01
+#define PRINTK_PENDING_CONSOLE	0x02
 
 static DEFINE_PER_CPU(int, printk_pending);
 
-static void wake_up_klogd_work_func(struct irq_work *irq_work)
+static void printk_pending_func(struct irq_work *irq_work)
 {
 	int pending = __this_cpu_xchg(printk_pending, 0);
 
-	if (pending & PRINTK_PENDING_OUTPUT) {
+	if (pending & PRINTK_PENDING_CONSOLE) {
 		/* If trylock fails, someone else is doing the printing */
 		if (console_trylock())
 			console_unlock();
 	}
 
-	if (pending & PRINTK_PENDING_WAKEUP)
+	if (pending & PRINTK_PENDING_LOGGERS)
 		wake_up_interruptible(&log_wait);
+
 	deferred_cont_flush();
 }
 
-static DEFINE_PER_CPU(struct irq_work, wake_up_klogd_work) = {
-	.func = wake_up_klogd_work_func,
+static DEFINE_PER_CPU(struct irq_work, printk_pending_work) = {
+	.func = printk_pending_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));
+		this_cpu_or(printk_pending, PRINTK_PENDING_LOGGERS);
+		irq_work_queue(this_cpu_ptr(&printk_pending_work));
 	}
+
+	preempt_enable();
+}
+
+static void __wake_up_console(void)
+{
+	this_cpu_or(printk_pending, PRINTK_PENDING_CONSOLE);
+	irq_work_queue(this_cpu_ptr(&printk_pending_work));
+}
+
+static void wake_up_console(void)
+{
+	preempt_disable();
+	__wake_up_console();
 	preempt_enable();
 }
 
@@ -2777,8 +2793,7 @@ int printk_deferred(const char *fmt, ...)
 	r = vprintk_emit(0, LOGLEVEL_SCHED, NULL, 0, fmt, args);
 	va_end(args);
 
-	__this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
-	irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
+	__wake_up_console();
 	preempt_enable();
 
 	return r;
@@ -2893,6 +2908,7 @@ void kmsg_dump(enum kmsg_dump_reason reason)
 {
 	struct kmsg_dumper *dumper;
 	unsigned long flags;
+	int did_flush = 0;
 
 	if ((reason > KMSG_DUMP_OOPS) && !always_kmsg_dump)
 		return;
@@ -2906,7 +2922,7 @@ void kmsg_dump(enum kmsg_dump_reason reason)
 		dumper->active = true;
 
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
-		cont_flush();
+		did_flush |= cont_flush();
 		dumper->cur_seq = clear_seq;
 		dumper->cur_idx = clear_idx;
 		dumper->next_seq = log_next_seq;
@@ -2920,6 +2936,9 @@ void kmsg_dump(enum kmsg_dump_reason reason)
 		dumper->active = false;
 	}
 	rcu_read_unlock();
+
+	if (did_flush)
+		wake_up_console();
 }
 
 /**
@@ -2997,7 +3016,8 @@ bool kmsg_dump_get_line(struct kmsg_dumper *dumper, bool syslog,
 	bool ret;
 
 	raw_spin_lock_irqsave(&logbuf_lock, flags);
-	cont_flush();
+	if (cont_flush())
+		__wake_up_console();
 	ret = kmsg_dump_get_line_nolock(dumper, syslog, line, size, len);
 	raw_spin_unlock_irqrestore(&logbuf_lock, flags);
 
@@ -3039,7 +3059,9 @@ bool kmsg_dump_get_buffer(struct kmsg_dumper *dumper, bool syslog,
 		goto out;
 
 	raw_spin_lock_irqsave(&logbuf_lock, flags);
-	cont_flush();
+	if (cont_flush())
+		__wake_up_console();
+
 	if (dumper->cur_seq < log_first_seq) {
 		/* messages are gone, move to first available one */
 		dumper->cur_seq = log_first_seq;
-- 
1.8.5.6

Powered by blists - more mailing lists