From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932978AbcHWFS2 (ORCPT ); Tue, 23 Aug 2016 01:18:28 -0400 Received: from mail-pf0-f196.google.com ([209.85.192.196]:36178 "EHLO mail-pf0-f196.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932460AbcHWFS0 (ORCPT ); Tue, 23 Aug 2016 01:18:26 -0400 Date: Tue, 23 Aug 2016 14:18:31 +0900 From: Sergey Senozhatsky To: Petr Mladek , Jan Kara , Kay Sievers Cc: Tejun Heo , Calvin Owens , Andrew Morton , linux-kernel@vger.kernel.org, Sergey Senozhatsky , Sergey Senozhatsky Subject: Re: [PATCH][RFC] printk: make pr_cont buffer per-cpu Message-ID: <20160823051831.GA423@swordfish> References: <20160822154030.2715-1-sergey.senozhatsky@gmail.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20160822154030.2715-1-sergey.senozhatsky@gmail.com> User-Agent: Mutt/1.7.0 (2016-08-17) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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(-) 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 @@ -337,10 +337,9 @@ static int console_may_schedule; */ enum log_flags { - LOG_NOCONS = 1, /* already flushed, do not print to console */ - LOG_NEWLINE = 2, /* text ended with a newline */ - LOG_PREFIX = 4, /* text started with a prefix */ - LOG_CONT = 8, /* text is a fragment of a continuation line */ + LOG_NEWLINE = 1, /* text ended with a newline */ + LOG_PREFIX = 2, /* text started with a prefix */ + LOG_CONT = 4, /* text is a fragment of a continuation line */ }; struct printk_log { @@ -1661,108 +1660,62 @@ static inline void printk_delay(void) * though, are printed immediately to the consoles to ensure everything has * reached the console in case of a kernel crash. */ -static struct cont { +struct cont { char buf[LOG_LINE_MAX]; size_t len; /* length == 0 means unused buffer */ - size_t cons; /* bytes written to console */ - struct task_struct *owner; /* task of first print*/ u64 ts_nsec; /* time of first print */ u8 level; /* log level of first message */ u8 facility; /* log facility of first message */ enum log_flags flags; /* prefix, newline flags */ - bool flushed:1; /* buffer sealed and committed */ -} cont; +}; + +static DEFINE_PER_CPU(struct cont, pcpu_cont); +static DEFINE_PER_CPU(bool, cont_printing); -static void cont_flush(enum log_flags flags) +static void cont_flush(struct cont *cont, enum log_flags flags) { - if (cont.flushed) - return; - if (cont.len == 0) + if (cont->len == 0) return; - if (cont.cons) { - /* - * If a fragment of this line was directly flushed to the - * console; wait for the console to pick up the rest of the - * line. LOG_NOCONS suppresses a duplicated output. - */ - log_store(cont.facility, cont.level, flags | LOG_NOCONS, - cont.ts_nsec, NULL, 0, cont.buf, cont.len); - cont.flags = flags; - cont.flushed = true; - } else { - /* - * If no fragment of this line ever reached the console, - * just submit it to the store and free the buffer. - */ - log_store(cont.facility, cont.level, flags, 0, - NULL, 0, cont.buf, cont.len); - cont.len = 0; - } + /* + * If no fragment of this line ever reached the console, + * just submit it to the store and free the buffer. + */ + log_store(cont->facility, cont->level, flags, 0, + NULL, 0, cont->buf, cont->len); + cont->len = 0; } static bool cont_add(int facility, int level, const char *text, size_t len) { - if (cont.len && cont.flushed) - return false; + struct cont *cont = this_cpu_ptr(&pcpu_cont); /* * If ext consoles are present, flush and skip in-kernel * continuation. See nr_ext_console_drivers definition. Also, if * the line gets too long, split it up in separate records. */ - if (nr_ext_console_drivers || cont.len + len > sizeof(cont.buf)) { - cont_flush(LOG_CONT); + if (nr_ext_console_drivers || cont->len + len > sizeof(cont->buf)) { + cont_flush(cont, LOG_CONT); return false; } - if (!cont.len) { - cont.facility = facility; - cont.level = level; - cont.owner = current; - cont.ts_nsec = local_clock(); - cont.flags = 0; - cont.cons = 0; - cont.flushed = false; + if (!cont->len) { + cont->facility = facility; + cont->level = level; + cont->ts_nsec = local_clock(); + cont->flags = 0; } - memcpy(cont.buf + cont.len, text, len); - cont.len += len; + memcpy(cont->buf + cont->len, text, len); + cont->len += len; - if (cont.len > (sizeof(cont.buf) * 80) / 100) - cont_flush(LOG_CONT); + if (cont->len > (sizeof(cont->buf) * 80) / 100) + cont_flush(cont, LOG_CONT); return true; } -static size_t cont_print_text(char *text, size_t size) -{ - size_t textlen = 0; - size_t len; - - if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) { - textlen += print_time(cont.ts_nsec, text); - size -= textlen; - } - - len = cont.len - cont.cons; - if (len > 0) { - if (len+1 > size) - len = size-1; - memcpy(text + textlen, cont.buf + cont.cons, len); - textlen += len; - cont.cons = cont.len; - } - - if (cont.flushed) { - if (cont.flags & LOG_NEWLINE) - text[textlen++] = '\n'; - /* got everything, release buffer */ - cont.len = 0; - } - 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(); + } + } + /* * 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 an earlier newline was missing and it was the same task, * either merge it with the current buffer and flush, or if @@ -1903,11 +1870,11 @@ asmlinkage int vprintk_emit(int facility, int level, * If the preceding printk was from a different task and missed * a newline, flush and append the newline. */ - if (cont.len) { - if (cont.owner == current && !(lflags & LOG_PREFIX)) + if (cont->len) { + if (!(lflags & LOG_PREFIX)) stored = cont_add(facility, level, text, text_len); - cont_flush(LOG_NEWLINE); + cont_flush(cont, LOG_NEWLINE); } if (stored) @@ -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); -} - /** * 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; @@ -2465,8 +2392,7 @@ skip: msg = log_from_idx(console_idx); level = msg->level; - if ((msg->flags & LOG_NOCONS) || - suppress_message_printing(level)) { + if (suppress_message_printing(level)) { /* * Skip record we have buffered and already printed * directly to the console when we received it, and @@ -2474,12 +2400,6 @@ skip: */ console_idx = log_next(console_idx); console_seq++; - /* - * We will get here again when we register a new - * CON_PRINTBUFFER console. Clear the flag so we - * will properly dump everything later. - */ - msg->flags &= ~LOG_NOCONS; console_prev = msg->flags; goto skip; } @@ -2581,6 +2501,18 @@ void console_unblank(void) */ void console_flush_on_panic(void) { + unsigned long flags; + unsigned int cpu; + + /* + * Flush the cont messages; no matter complete + * or incomplete. + */ + local_irq_save(flags); + for_each_online_cpu(cpu) + cont_flush(per_cpu_ptr(&pcpu_cont, cpu), LOG_NEWLINE); + local_irq_restore(flags); + /* * If someone else is holding the console lock, trylock will fail * and may_schedule may be set. Ignore and proceed to unlock so -- 2.9.3