From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S933741AbcKIPrd (ORCPT ); Wed, 9 Nov 2016 10:47:33 -0500 Received: from mx2.suse.de ([195.135.220.15]:45263 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932531AbcKIPra (ORCPT ); Wed, 9 Nov 2016 10:47:30 -0500 Date: Wed, 9 Nov 2016 16:47:24 +0100 From: Petr Mladek To: Linus Torvalds Cc: Sergey Senozhatsky , Sergey Senozhatsky , Joe Perches , Geert Uytterhoeven , Tetsuo Handa , Linux Kernel Mailing List , Tejun Heo , Calvin Owens , Steven Rostedt , Andrew Morton Subject: Re: linux.git: printk() problem Message-ID: <20161109154724.GB2324@pathway.suse.cz> References: <1477249607.3561.2.camel@perches.com> <20161024140845.GA626@swordfish> <20161025015554.GA495@swordfish> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.5.21 (2010-09-15) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Mon 2016-10-24 19:22:59, Linus Torvalds wrote: > On Mon, Oct 24, 2016 at 7:06 PM, Linus Torvalds > wrote: > > On Mon, Oct 24, 2016 at 6:55 PM, Sergey Senozhatsky > > 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 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 --- 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