(adding Kay Sievers who wrote most of this)
On Tue, 2016-08-23 at 00:40 +0900, Sergey Senozhatsky wrote: > Hello, > > RFC and POC > > Petr, I took a very quick look at your series [1]. I think it > won't work on some of the setups I'm toying with, where multiple CPUs > can do a simultaneous pr_cont() output. What do you about the following > approach? > > (it's not really tested, I just finished writing the code. Will test it > more tomorrow. But I kinda like that at this point it removes almost > twice the code it adds, which is probably because I missed some cases). > > ===8<==== > > This patch changes pr_cont buffer to be a per-cpu variable, so > CPUs don't compete anymore for a single cont buffer. Thus we minimize > the possibility of preliminary/forced flushes of incomplete pr_cont > buffers. > The basic idea is that the first time CPU issues a pr_cont or > !LOG_NEWLINE output it starts a non-preemptible region which ends when > CPUs writes a NEW_LINE symbol. > Schematically: > > pr_cont() /* preempt_disable() */ > << write to this_cpu_ptr cont buffer > pr_cont() > << write to this_cpu_ptr cont buffer > ... > pr_cont("\n") /* log_store(). preempt_enable() */ > > The only possible case (unless I'm missing something) for a > race is when IRQ is issuing a pr_cont() output, interrupting the CPU > which is already in the middle of pr_cont() printing. > > > [1]: http://marc.info/?l=linux-kernel&m=146860197621876 > > Signed-off-by: Sergey Senozhatsky <sergey.senozhat...@gmail.com> > --- > kernel/printk/printk.c | 193 > ++++++++++++++++--------------------------------- > 1 file changed, 64 insertions(+), 129 deletions(-) > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 0d3e026..2bf8b85 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,22 @@ asmlinkage int vprintk_emit(int facility, int level, > lflags |= LOG_PREFIX|LOG_NEWLINE; > > if (!(lflags & LOG_NEWLINE)) { > + if (!this_cpu_read(cont_printing)) { > + bool unsafe_pr_cont = preemptible() && > + !rcu_preempt_depth(); > + > + if (unsafe_pr_cont) { > + 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 +1860,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 +1873,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 +2021,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 +2313,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 +2366,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 +2395,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 +2403,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 +2504,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