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 [EMAIL PROTECTED]
> ---
> 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 <linux/bootmem.h>
> #include <linux/syscalls.h>
> #include <linux/jiffies.h>
> +#include <linux/workqueue.h>
>
> #include <asm/uaccess.h>
>
> #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<end-start; 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 [EMAIL PROTECTED]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
