From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753427Ab2GEHDP (ORCPT ); Thu, 5 Jul 2012 03:03:15 -0400 Received: from ozlabs.org ([203.10.76.45]:59754 "EHLO ozlabs.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751110Ab2GEHDK (ORCPT ); Thu, 5 Jul 2012 03:03:10 -0400 From: Michael Neuling To: Kay Sievers cc: linuxppc-dev@ozlabs.org, Linus Torvalds , Greg Kroah-Hartman , Andrew Morton , Steven Rostedt , LKML , Ingo Molnar , Wu Fengguang , Joe Perches , "Paul E. McKenney" Subject: Re: [PATCH v3] printk: Have printk() never buffer its data In-reply-to: <1340726856.977.6.camel@mop> References: <1340651142.7037.2.camel@gandalf.stny.rr.com> <20120625150722.8cd4f45d.akpm@linux-foundation.org> <20120625235531.GB3652@kroah.com> <20120626002307.GA4389@kroah.com> <1340726856.977.6.camel@mop> Comments: In-reply-to Kay Sievers message dated "Tue, 26 Jun 2012 18:07:36 +0200." X-Mailer: MH-E 8.2; nmh 1.3; GNU Emacs 23.3.1 Date: Thu, 05 Jul 2012 17:03:07 +1000 Message-ID: <22482.1341471787@neuling.org> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org > On Mon, 2012-06-25 at 18:40 -0700, Linus Torvalds wrote: > > On Mon, Jun 25, 2012 at 5:56 PM, Kay Sievers wrote: > > > > > > Buffering has nice effects though: > > > It makes continuation lines appear as one record in the buffer, not as > > > n individual prints with n headers. > > > > As I already mentioned, buffering for *logging* is different from > > buffering for *printing*. > > > > I think it might be a great idea to buffer for logging in order to > > generate one individual buffer record there. > > > > But it needs to be printed as it is generated. > > That's a good idea. > > Something like this could work - only minimally tested at this moment. This breaks some powerpc configs and is in Linus' tree now as 084681d14e. When we have printks without a newline (like show_regs()), it sometimes: 1) drops the console output for that line (dmesg is fine). Patch to fix this below. 2) adds a newline unnecessary to both console and dmesg. I have no fix for this currently. Reverting this patch fixes both problems. Post rc4 is way to late to be adding largely untested features like this. I suggest we revert this until the next merge window. Mikey diff --git a/kernel/printk.c b/kernel/printk.c index dba1821..91659da 100644 --- a/kernel/printk.c +++ b/kernel/printk.c @@ -1335,7 +1335,7 @@ static void cont_flush(void) if (cont.len == 0) return; - log_store(cont.facility, cont.level, LOG_NOCONS, cont.ts_nsec, + log_store(cont.facility, cont.level, LOG_DEFAULT, cont.ts_nsec, NULL, 0, cont.buf, cont.len); cont.flushed = true; > > > From: Kay Sievers > Subject: printk: flush continuation lines immediately to console > > Continuation lines are buffered internally to merge the chunked > printk()s into a single record, and to isolate potentially racy > continuation users from usual terminated line users. > > This though, has the effect that partial lines are not printed to > the console in the moment they are emitted. In case the kernel > crashes in the meantime, the potentially interesting printed > information will never reach the consoles. > > Here we share the continuation buffer with the console copy logic, > and partial lines are immediately flushed to the consoles, but still > buffered internally to improve the integrity of the messages. > --- > > kernel/printk.c | 129 +++++++++++++++++++++++++++++++++++++++++++------------ > 1 file changed, 101 insertions(+), 28 deletions(-) > > diff --git a/kernel/printk.c b/kernel/printk.c > index a2276b9..92c34bd1 100644 > --- a/kernel/printk.c > +++ b/kernel/printk.c > @@ -193,12 +193,19 @@ static int console_may_schedule; > * separated by ',', and find the message after the ';' character. > */ > > +enum log_flags { > + LOG_DEFAULT = 0, > + LOG_NOCONS = 1, /* already flushed, do not print to console */ > +}; > + > struct log { > u64 ts_nsec; /* timestamp in nanoseconds */ > u16 len; /* length of entire record */ > u16 text_len; /* length of text buffer */ > u16 dict_len; /* length of dictionary buffer */ > - u16 level; /* syslog level + facility */ > + u8 facility; /* syslog facility */ > + u8 flags:5; /* internal record flags */ > + u8 level:3; /* syslog level */ > }; > > /* > @@ -286,6 +293,7 @@ static u32 log_next(u32 idx) > > /* insert record into the buffer, discard old ones, update heads */ > static void log_store(int facility, int level, > + enum log_flags flags, u64 ts_nsec, > const char *dict, u16 dict_len, > const char *text, u16 text_len) > { > @@ -329,8 +337,13 @@ static void log_store(int facility, int level, > msg->text_len = text_len; > memcpy(log_dict(msg), dict, dict_len); > msg->dict_len = dict_len; > - msg->level = (facility << 3) | (level & 7); > - msg->ts_nsec = local_clock(); > + msg->facility = facility; > + msg->level = level & 7; > + msg->flags = flags & 0x1f; > + if (ts_nsec > 0) > + msg->ts_nsec = ts_nsec; > + else > + msg->ts_nsec = local_clock(); > memset(log_dict(msg) + dict_len, 0, pad_len); > msg->len = sizeof(struct log) + text_len + dict_len + pad_len; > > @@ -446,7 +459,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf, > ts_usec = msg->ts_nsec; > do_div(ts_usec, 1000); > len = sprintf(user->buf, "%u,%llu,%llu;", > - msg->level, user->seq, ts_usec); > + (msg->facility << 3) | msg->level, user->seq, ts_usec); > > /* escape non-printable characters */ > for (i = 0; i < msg->text_len; i++) { > @@ -787,6 +800,21 @@ static bool printk_time; > #endif > module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR); > > +static size_t print_time(u64 ts, char *buf) > +{ > + unsigned long rem_nsec; > + > + if (!printk_time) > + return 0; > + > + if (!buf) > + return 15; > + > + rem_nsec = do_div(ts, 1000000000); > + return sprintf(buf, "[%5lu.%06lu] ", > + (unsigned long)ts, rem_nsec / 1000); > +} > + > static size_t print_prefix(const struct log *msg, bool syslog, char *buf) > { > size_t len = 0; > @@ -803,18 +831,7 @@ static size_t print_prefix(const struct log *msg, bool syslog, char *buf) > } > } > > - if (printk_time) { > - if (buf) { > - unsigned long long ts = msg->ts_nsec; > - unsigned long rem_nsec = do_div(ts, 1000000000); > - > - len += sprintf(buf + len, "[%5lu.%06lu] ", > - (unsigned long) ts, rem_nsec / 1000); > - } else { > - len += 15; > - } > - } > - > + len += print_time(msg->ts_nsec, buf ? buf + len : NULL); > return len; > } > > @@ -1272,15 +1289,25 @@ static inline void printk_delay(void) > } > } > > +/* > + * Continuation lines are buffered, and not committed to the record buffer > + * until the line is complete, or a race forces a flush. The line fragments > + * though, are printed immediately to the consoles to ensure everything has > + * reached the console in case of a kernel crash. > + */ > +static char cont_buf[LOG_LINE_MAX]; > +static size_t cont_len; > +static size_t cont_cons; > +static size_t cont_cons_len; > +static int cont_level; > +static u64 cont_ts_nsec; > +static struct task_struct *cont_task; > + > asmlinkage int vprintk_emit(int facility, int level, > const char *dict, size_t dictlen, > const char *fmt, va_list args) > { > static int recursion_bug; > - static char cont_buf[LOG_LINE_MAX]; > - static size_t cont_len; > - static int cont_level; > - static struct task_struct *cont_task; > static char textbuf[LOG_LINE_MAX]; > char *text = textbuf; > size_t text_len; > @@ -1326,7 +1353,8 @@ asmlinkage int vprintk_emit(int facility, int level, > recursion_bug = 0; > printed_len += strlen(recursion_msg); > /* emit KERN_CRIT message */ > - log_store(0, 2, NULL, 0, recursion_msg, printed_len); > + log_store(0, 2, LOG_DEFAULT, 0, > + NULL, 0, recursion_msg, printed_len); > } > > /* > @@ -1369,13 +1397,17 @@ asmlinkage int vprintk_emit(int facility, int level, > * Flush earlier buffer, which is either from a > * different thread, or when we got a new prefix. > */ > - log_store(facility, cont_level, NULL, 0, cont_buf, cont_len); > + log_store(facility, cont_level, > + LOG_NOCONS, cont_ts_nsec, > + NULL, 0, cont_buf, cont_len); > cont_len = 0; > } > > if (!cont_len) { > + cont_cons = 0; > cont_level = level; > cont_task = current; > + cont_ts_nsec = local_clock(); > } > > /* buffer or append to earlier buffer from the same thread */ > @@ -1383,6 +1415,8 @@ asmlinkage int vprintk_emit(int facility, int level, > text_len = sizeof(cont_buf) - cont_len; > memcpy(cont_buf + cont_len, text, text_len); > cont_len += text_len; > + cont_cons_len = cont_len; > + printed_len = text_len; > } else { > if (cont_len && cont_task == current) { > if (prefix) { > @@ -1392,6 +1426,7 @@ asmlinkage int vprintk_emit(int facility, int level, > * with an interrupt. > */ > log_store(facility, cont_level, > + LOG_NOCONS, cont_ts_nsec, > NULL, 0, cont_buf, cont_len); > cont_len = 0; > } > @@ -1401,14 +1436,15 @@ asmlinkage int vprintk_emit(int facility, int level, > text_len = sizeof(cont_buf) - cont_len; > memcpy(cont_buf + cont_len, text, text_len); > cont_len += text_len; > + cont_cons_len = cont_len; > log_store(facility, cont_level, > + LOG_NOCONS, cont_ts_nsec, > NULL, 0, cont_buf, cont_len); > cont_len = 0; > - cont_task = NULL; > - printed_len = cont_len; > + printed_len = text_len; > } else { > /* ordinary single and terminated line */ > - log_store(facility, level, > + log_store(facility, level, LOG_DEFAULT, 0, > dict, dictlen, text, text_len); > printed_len = text_len; > } > @@ -1795,6 +1831,7 @@ static u32 console_idx; > */ > void console_unlock(void) > { > + static char text[LOG_LINE_MAX]; > static u64 seen_seq; > unsigned long flags; > bool wake_klogd = false; > @@ -1807,10 +1844,37 @@ void console_unlock(void) > > console_may_schedule = 0; > > + /* flush buffered message fragment immediately to console */ > + raw_spin_lock_irqsave(&logbuf_lock, flags); > + if (cont_cons_len && (cont_cons < cont_cons_len || !cont_len)) { > + size_t textlen = 0; > + size_t len; > + > + len = cont_cons_len - cont_cons; > + if (!cont_cons) > + textlen = print_time(cont_ts_nsec, text); > + memcpy(text + textlen, cont_buf + cont_cons, len); > + textlen += len; > + cont_cons = cont_cons_len; > + > + if (!cont_len) { > + /* last chunk of line; terminate */ > + text[textlen++] = '\n'; > + cont_cons_len = 0; > + } > + raw_spin_unlock(&logbuf_lock); > + > + stop_critical_timings(); > + call_console_drivers(cont_level, text, textlen); > + start_critical_timings(); > + > + local_irq_restore(flags); > + } else > + raw_spin_unlock_irqrestore(&logbuf_lock, flags); > + > again: > for (;;) { > struct log *msg; > - static char text[LOG_LINE_MAX]; > size_t len; > int level; > > @@ -1825,13 +1889,22 @@ again: > console_seq = log_first_seq; > console_idx = log_first_idx; > } > - > +skip: > if (console_seq == log_next_seq) > break; > > msg = log_from_idx(console_idx); > - level = msg->level & 7; > + if (msg->flags & LOG_NOCONS) { > + /* > + * Skip record we have buffered and already printed > + * directly to the console when we received it. > + */ > + console_idx = log_next(console_idx); > + console_seq++; > + goto skip; > + } > > + level = msg->level; > len = msg_print_text(msg, false, text, sizeof(text)); > > console_idx = log_next(console_idx); > > > -- > To unsubscribe from this list: send the line "unsubscribe linux-kernel" in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html > Please read the FAQ at http://www.tux.org/lkml/ >