From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1757654AbcHWLrO (ORCPT ); Tue, 23 Aug 2016 07:47:14 -0400 Received: from mx2.suse.de ([195.135.220.15]:44115 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1757213AbcHWLrF (ORCPT ); Tue, 23 Aug 2016 07:47:05 -0400 Date: Tue, 23 Aug 2016 13:47:02 +0200 From: Petr Mladek To: Sergey Senozhatsky Cc: Jan Kara , Kay Sievers , Tejun Heo , Calvin Owens , Andrew Morton , linux-kernel@vger.kernel.org, Sergey Senozhatsky Subject: Re: [PATCH][RFC] printk: make pr_cont buffer per-cpu Message-ID: <20160823114702.GC4866@pathway.suse.cz> References: <20160822154030.2715-1-sergey.senozhatsky@gmail.com> <20160823051831.GA423@swordfish> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20160823051831.GA423@swordfish> 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 Tue 2016-08-23 14:18:31, Sergey Senozhatsky wrote: > On (08/23/16 00:40), Sergey Senozhatsky wrote: > > RFC and POC > [..] > > if (!(lflags & LOG_NEWLINE)) { > > + if (!this_cpu_read(cont_printing)) { > > + bool unsafe_pr_cont = preemptible() && > > + !rcu_preempt_depth(); > > d'oh, how did it get there... this simply disables per-cpu pr_cont(). sorry. > what I wanted to do there is to add a dependency on system_state: > > if (!this_cpu_read(cont_printing) && (system_state == SYSTEM_RUNNING)) { > .... > } > > one of the problems is x86 cpu_up, which does pr_cont()-s in announce_cpu() > and then explicitly calls shedule() in do_boot_cpu(). so we have a > > pr_cont(); > shedule(); > pr_cont(); > shedule(); > ... > pr_cont("\n"); > > pattern. which is probably OK, given that we are in a non-smp mode yet. thus > I'm enabling per-cpu pr_cont buffers only when the system is SYSTEM_RUNNING. > > ===8<==== > > Signed-off-by: Sergey Senozhatsky > --- > kernel/printk/printk.c | 190 ++++++++++++++++--------------------------------- > 1 file changed, 61 insertions(+), 129 deletions(-) The simplification is nice but... > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 0d3e026..7f48cbf 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > - return textlen; > -} > - > asmlinkage int vprintk_emit(int facility, int level, > const char *dict, size_t dictlen, > const char *fmt, va_list args) > @@ -1779,6 +1732,7 @@ asmlinkage int vprintk_emit(int facility, int level, > int printed_len = 0; > int nmi_message_lost; > bool in_sched = false; > + struct cont *cont; > > if (level == LOGLEVEL_SCHED) { > level = LOGLEVEL_DEFAULT; > @@ -1789,6 +1743,7 @@ asmlinkage int vprintk_emit(int facility, int level, > printk_delay(); > > local_irq_save(flags); > + cont = this_cpu_ptr(&pcpu_cont); > this_cpu = smp_processor_id(); > > /* > @@ -1878,12 +1833,19 @@ asmlinkage int vprintk_emit(int facility, int level, > lflags |= LOG_PREFIX|LOG_NEWLINE; > > if (!(lflags & LOG_NEWLINE)) { > + if (!this_cpu_read(cont_printing)) { > + if (system_state == SYSTEM_RUNNING) { > + this_cpu_write(cont_printing, true); > + preempt_disable(); > + } > + } I am afraid that this is not acceptable. It means that printk() will have an unexpected side effect. The missing "\n" at the end of a printed string would disable preemption. See below for more. > + > /* > * Flush the conflicting buffer. An earlier newline was missing, > * or another task also prints continuation lines. > */ > - if (cont.len && (lflags & LOG_PREFIX || cont.owner != current)) > - cont_flush(LOG_NEWLINE); > + if (cont->len && (lflags & LOG_PREFIX)) > + cont_flush(cont, LOG_NEWLINE); > > /* buffer line if possible, otherwise store it right away */ > if (cont_add(facility, level, text, text_len)) > @@ -1895,6 +1857,11 @@ asmlinkage int vprintk_emit(int facility, int level, > } else { > bool stored = false; > > + if (this_cpu_read(cont_printing)) { > + this_cpu_write(cont_printing, false); > + preempt_enable(); > + } If "\n" is missing by mistake. The preemption will not get enabled and the task would stall. Note that printk() is heavily used when debugging kernel. People would hate us if every n-th build is unusable because of forgotten '\n'. > /* > * If an earlier newline was missing and it was the same task, > * either merge it with the current buffer and flush, or if > @@ -2051,7 +2018,6 @@ static struct cont { > size_t len; > size_t cons; > u8 level; > - bool flushed:1; > } cont; > static char *log_text(const struct printk_log *msg) { return NULL; } > static char *log_dict(const struct printk_log *msg) { return NULL; } > @@ -2344,42 +2310,6 @@ static inline int can_use_console(void) > return cpu_online(raw_smp_processor_id()) || have_callable_console(); > } > > -static void console_cont_flush(char *text, size_t size) > -{ > - unsigned long flags; > - size_t len; > - > - raw_spin_lock_irqsave(&logbuf_lock, flags); > - > - if (!cont.len) > - goto out; > - > - if (suppress_message_printing(cont.level)) { > - cont.cons = cont.len; > - if (cont.flushed) > - cont.len = 0; > - goto out; > - } > - > - /* > - * We still queue earlier records, likely because the console was > - * busy. The earlier ones need to be printed before this one, we > - * did not flush any fragment so far, so just let it queue up. > - */ > - if (console_seq < log_next_seq && !cont.cons) > - goto out; > - > - len = cont_print_text(text, size); > - raw_spin_unlock(&logbuf_lock); > - stop_critical_timings(); > - call_console_drivers(cont.level, NULL, 0, text, len); > - start_critical_timings(); > - local_irq_restore(flags); > - return; > -out: > - raw_spin_unlock_irqrestore(&logbuf_lock, flags); > -} This is a trade off between a "perfect" output and an early output. I do not feel like deciding about it. In each case, a buggy line (without \n") would stay "hidden" in the per-CPU buffer until another line with "\n" is printed on the given CPU. > /** > * console_unlock - unlock the console system > * > @@ -2433,9 +2363,6 @@ again: > return; > } > > - /* flush buffered message fragment immediately to console */ > - console_cont_flush(text, sizeof(text)); > - > for (;;) { > struct printk_log *msg; > size_t ext_len = 0; I think that cont lines should be a corner case. There should be only a limited use of them. We should not make too complicated things to support them. Also printk() must not get harder to use because of them. I still see a messed output rather as a cosmetic problem in compare with possible possible deadlocks or hung tasks. Best Regards, Petr