Re: [PATCH] defer printks in irqs

[Peter Zijlstra <a.p.zijlstra@chello.nl>]

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 <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
> 
>