Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1757520AbYAXWuh (ORCPT ); Thu, 24 Jan 2008 17:50:37 -0500 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1754023AbYAXWua (ORCPT ); Thu, 24 Jan 2008 17:50:30 -0500 Received: from pentafluge.infradead.org ([213.146.154.40]:46489 "EHLO pentafluge.infradead.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752353AbYAXWu2 (ORCPT ); Thu, 24 Jan 2008 17:50:28 -0500 Subject: Re: [PATCH] defer printks in irqs From: Peter Zijlstra To: Tim Bird Cc: Steven Rostedt , Daniel Walker , LKML , Ingo Molnar , Linus Torvalds , Andrew Morton , Christoph Hellwig , Mathieu Desnoyers , Gregory Haskins , Arnaldo Carvalho de Melo , Thomas Gleixner , Sam Ravnborg , "Frank Ch. Eigler" , Jan Kiszka , John Stultz , Arjan van de Ven , Steven Rostedt In-Reply-To: <47991454.50603@am.sony.com> References: <20080123160236.969334052@goodmis.org> <20080123160441.236562634@goodmis.org> <1201107978.13596.16.camel@imap.mvista.com> <1201110185.13596.22.camel@imap.mvista.com> <47991454.50603@am.sony.com> Content-Type: text/plain Date: Thu, 24 Jan 2008 23:48:55 +0100 Message-Id: <1201214935.6341.105.camel@lappy> Mime-Version: 1.0 X-Mailer: Evolution 2.21.5 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 10202 Lines: 302 On Thu, 2008-01-24 at 14:42 -0800, Tim Bird wrote: > Steven Rostedt wrote: > > Tim, could you send me your "postponed print" patches. That sounds like > > something the -rt patch could use. > > Sure. See below. > > This patch changes the way the printk code processes output to the > console buffer. On some platforms, especially those with a serial > console, the way printk output the messages to console caused significant > interrupt-off periods. This code introduces two config options to > improve that handling. > > Without this change, test code run on a 178 MHZ ARM platform > showed an interrupt off period for a particularly long printk message > of 24 milliseconds. With this patch applied, and the options set > to 'Y', the same message only had an interrupt-off period of > 482 microseconds. > > Portions of this (some parts that reorder locking and irq management > primitives) were taken from the RT-preempt patch. > > The patch does several things: > > 1. It moves the location of the irqrestore operations in the > printk code, so that the console writing can occur with interrupts enabled > > 2. It changes the code so that characters are written to the console > one-at-a-time. The serial console code holds interrupts disabled for the > duration of its output to the serial port. To decrease the interrupt-off > time, only a small amount of data is written at a time. (This could be tuned > by writing chunks larger than 1 character at a time, but the current solution > was easiest, and gives the lowest interrupt-off times.) > > 3. The printk code was changed so that if it is entered with interrupts > disabled, it does not output to console immediately. Rather, a workqueue > routine is scheduled to process the console output later (when interrupts > are enabled). > > 4. An init-time routine was created, to prevent trying to schedule the > workqueue routine too early in the system boot sequence. > > Here's the patch: I suspect these features reduce the change a crash messages makes it out onto the console, but fail to spot any of the copious text mention this critical issue. > Signed-off-by: Tim Bird tim.bird@am.sony.com > --- > kernel/printk.c | 92 85 + 7 - 0 ! > lib/Kconfig.debug | 42 42 + 0 - 0 ! > 2 files changed, 127 insertions(+), 7 deletions(-) > > Index: linux-2.6.24-rc8/kernel/printk.c > =================================================================== > --- linux-2.6.24-rc8.orig/kernel/printk.c > +++ linux-2.6.24-rc8/kernel/printk.c > @@ -33,11 +33,14 @@ > #include > #include > #include > +#include > > #include > > #define __LOG_BUF_LEN (1 << CONFIG_LOG_BUF_SHIFT) > > +#define PRINTK_BUF_SIZE 1024 > + > /* printk's without a loglevel use this.. */ > #define DEFAULT_MESSAGE_LOGLEVEL 4 /* KERN_WARNING */ > > @@ -47,6 +50,10 @@ > > DECLARE_WAIT_QUEUE_HEAD(log_wait); > > +static void printk_console_flush(struct work_struct *ignored); > +static int have_callable_console(void); > +static DECLARE_WORK(printk_console_work, printk_console_flush); > + > int console_printk[4] = { > DEFAULT_CONSOLE_LOGLEVEL, /* console_loglevel */ > DEFAULT_MESSAGE_LOGLEVEL, /* default_message_loglevel */ > @@ -220,6 +227,43 @@ static inline void boot_delay_msec(void) > #endif > > /* > + * We can't schedule printk console flushing during early boot. > + * This flag holds it off until after we've initialized some > + * important stuff. > + */ > +static int pcf_ok = 0; > + > +static int __init init_printk_console_flush(void) > +{ > + pcf_ok = 1; > + return 0; > +} > +__initcall(init_printk_console_flush); > + > +void printk_console_flush(struct work_struct *ignored) > +{ > + unsigned long flags; > + int chars_to_flush; > + > + spin_lock_irqsave(&logbuf_lock, flags); > + chars_to_flush = log_end - con_start; > + spin_unlock_irqrestore(&logbuf_lock, flags); > + > + if (chars_to_flush) { > + acquire_console_sem(); > + > + if ((cpu_online(smp_processor_id()) || > + have_callable_console())) { > + console_may_schedule = 0; > + release_console_sem(); > + } else { > + console_locked = 0; > + up(&console_sem); > + } > + } > +} > + > +/* > * Return the number of unread characters in the log buffer. > */ > int log_buf_get_len(void) > @@ -436,8 +480,16 @@ static void __call_console_drivers(unsig > for (con = console_drivers; con; con = con->next) { > if ((con->flags & CON_ENABLED) && con->write && > (cpu_online(smp_processor_id()) || > - (con->flags & CON_ANYTIME))) > + (con->flags & CON_ANYTIME))) { > +#ifdef CONFIG_PRINTK_SHORT_IRQ_DISABLE > + int i; > + for(i=0; i + con->write(con, &LOG_BUF(start+i), 1); > + } > +#else > con->write(con, &LOG_BUF(start), end - start); > +#endif > + } > } > } > > @@ -633,8 +685,9 @@ asmlinkage int vprintk(const char *fmt, > unsigned long flags; > int printed_len; > char *p; > - static char printk_buf[1024]; > + static char printk_buf[PRINTK_BUF_SIZE]; > static int log_level_unknown = 1; > + int defer; > > boot_delay_msec(); > > @@ -649,6 +702,7 @@ asmlinkage int vprintk(const char *fmt, > lockdep_off(); > spin_lock(&logbuf_lock); > printk_cpu = smp_processor_id(); > + preempt_enable(); > > /* Emit the output into the temporary buffer */ > printed_len = vscnprintf(printk_buf, sizeof(printk_buf), fmt, args); > @@ -718,6 +772,19 @@ asmlinkage int vprintk(const char *fmt, > console_locked = 1; > printk_cpu = UINT_MAX; > spin_unlock(&logbuf_lock); > + lockdep_on(); > + local_irq_restore(flags); > + > + defer = 0; > +#ifdef CONFIG_PRINTK_DEFER_IN_IRQ > + /* > + * If we're in an interrupt and it's not an emergency, > + * don't emit to console just yet. > + */ > + if ((irqs_disabled() || in_interrupt()) && !oops_in_progress) { > + defer = 1; > + } > +#endif > > /* > * Console drivers may assume that per-cpu resources have > @@ -725,7 +792,8 @@ asmlinkage int vprintk(const char *fmt, > * being able to cope (CON_ANYTIME) don't call them until > * this CPU is officially up. > */ > - if (cpu_online(smp_processor_id()) || have_callable_console()) { > + if (!defer && (cpu_online(smp_processor_id()) || > + have_callable_console())) { > console_may_schedule = 0; > release_console_sem(); > } else { > @@ -733,8 +801,6 @@ asmlinkage int vprintk(const char *fmt, > console_locked = 0; > up(&console_sem); > } > - lockdep_on(); > - raw_local_irq_restore(flags); > } else { > /* > * Someone else owns the drivers. We drop the spinlock, which > @@ -747,7 +813,11 @@ asmlinkage int vprintk(const char *fmt, > raw_local_irq_restore(flags); > } > > - preempt_enable(); > + /* didn't flush console all the way yet? - schedule for later */ > + if ((log_end - con_start) && pcf_ok) { > + schedule_work(&printk_console_work); > + } > + > return printed_len; > } > EXPORT_SYMBOL(printk); > @@ -971,13 +1041,21 @@ void release_console_sem(void) > _con_start = con_start; > _log_end = log_end; > con_start = log_end; /* Flush */ > + > +#ifdef CONFIG_PRINTK_SHORT_IRQ_DISABLE > + /* allow irqs during console out */ > + spin_unlock_irqrestore(&logbuf_lock, flags); > + call_console_drivers(_con_start, _log_end); > +#else > spin_unlock(&logbuf_lock); > call_console_drivers(_con_start, _log_end); > local_irq_restore(flags); > +#endif > } > console_locked = 0; > - up(&console_sem); > spin_unlock_irqrestore(&logbuf_lock, flags); > + up(&console_sem); > + > if (wake_klogd) > wake_up_klogd(); > } > Index: linux-2.6.24-rc8/lib/Kconfig.debug > =================================================================== > --- linux-2.6.24-rc8.orig/lib/Kconfig.debug > +++ linux-2.6.24-rc8/lib/Kconfig.debug > @@ -17,6 +17,48 @@ config ENABLE_WARN_DEPRECATED > Disable this to suppress the "warning: 'foo' is deprecated > (declared at kernel/power/somefile.c:1234)" messages. > > +config PRINTK_SHORT_IRQ_DISABLE > + bool "Enable interrupts for shorter times during printk output" > + default n > + depends on PRINTK > + help > + Selecting this option will cause the kernel to write the > + contents of the printk buffer to the console with interrupts > + enabled, and in small increments. > + > + With the default setting of 'n', the kernel attempts to > + send printk messages to the console with interrupts disabled, > + and it sends the entire contents of the printk buffer in one go. > + > + For some consoles (notably the serial console, which is commonly > + used in embedded products), this results in long interrupt-off > + periods. > + > + Users interested in good real-time scheduling should set this > + to 'y'. > + > +config PRINTK_DEFER_IN_IRQ > + bool "Defer writing printk output to console during interrupts" > + default n > + depends on PRINTK && PRINTK_SHORT_IRQ_DISABLE > + help > + Selecting this option will cause the kernel to hold off writing > + printk messages to the console until interrupts are enabled. > + On some systems, printk buffer and console handling can take > + a long time. If done with interrupts off for the entire duration > + of the operation, this results in long interrupt-off periods. > + > + With the default setting of 'n', the kernel attempts to > + send printk messages to the console whether it is in interrupt > + context or not. > + > + With a setting of 'y', when printk is called with interrupts > + disabled, the messages are buffered in the kernel's > + log buffer until later. If you are debugging the kernel > + with printks in interrupt routines, you should set this > + to 'n'. Users interested in good real-time scheduling > + should set this to 'y'. > + > config ENABLE_MUST_CHECK > bool "Enable __must_check logic" > default y > > -- 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/