slow down printk during boot

Optionally add a boot delay after each kernel printk() call, crudely
measured in milliseconds, with a maximum delay of 10 seconds per printk.

Enable CONFIG_BOOT_PRINTK_DELAY=y and then add (e.g.):
"lpj=loops_per_jiffy boot_delay=100"
to the kernel command line.

It has been useful in cases like "during boot, my machine just reboots or the
screen goes black" by slowing down printk, (and adding initcall_debug), we can
usually see the last thing that happened before the lights went out which is
usually a valuable clue.

[akpm@linux-foundation.org: not all architectures implement CONFIG_HZ]
[akpm@linux-foundation.org: fix lots of stuff]
[bunk@stusta.de: kernel/printk.c: make 2 variables static]
[heiko.carstens@de.ibm.com: fix slow down printk on boot compile error]
Signed-off-by: Randy Dunlap <rdunlap@xenotime.net>
Signed-off-by: Dave Jones <davej@redhat.com>
Signed-off-by: Adrian Bunk <bunk@stusta.de>
Signed-off-by: Heiko Carstens <heiko.carstens@de.ibm.com>
Signed-off-by: Andrew Morton <akpm@linux-foundation.org>
Signed-off-by: Linus Torvalds <torvalds@linux-foundation.org>

diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
index 085e4a0..760ed57 100644 (file)
--- a/Documentation/kernel-parameters.txt
+++ b/Documentation/kernel-parameters.txt
@@ -349,6 +349,11 @@ and is between 256 and 4096 characters. It is defined in the file
        blkmtd_bs=
        blkmtd_count=
 
        blkmtd_bs=
        blkmtd_count=
 

+       boot_delay=     Milliseconds to delay each printk during boot.
+                       Values larger than 10 seconds (10000) are changed to
+                       no delay (0).
+                       Format: integer
+

        bttv.card=      [HW,V4L] bttv (bt848 + bt878 based grabber cards)
        bttv.radio=     Most important insmod options are available as
                        kernel args too.
        bttv.card=      [HW,V4L] bttv (bt848 + bt878 based grabber cards)
        bttv.radio=     Most important insmod options are available as
                        kernel args too.

diff --git a/include/linux/jiffies.h b/include/linux/jiffies.h
index e757a74..8b08002 100644 (file)
--- a/include/linux/jiffies.h
+++ b/include/linux/jiffies.h
@@ -148,6 +148,8 @@ static inline u64 get_jiffies_64(void)
  */
 #define MAX_JIFFY_OFFSET ((LONG_MAX >> 1)-1)
 
  */
 #define MAX_JIFFY_OFFSET ((LONG_MAX >> 1)-1)
 

+extern unsigned long preset_lpj;
+

 /*
  * We want to do realistic conversions of time so we need to use the same
  * values the update wall clock code uses as the jiffies size.  This value
 /*
  * We want to do realistic conversions of time so we need to use the same
  * values the update wall clock code uses as the jiffies size.  This value

diff --git a/init/calibrate.c b/init/calibrate.c
index 40ff3b4..2d3d73b 100644 (file)
--- a/init/calibrate.c
+++ b/init/calibrate.c
@@ -10,7 +10,7 @@
 
 #include <asm/timex.h>
 
 
 #include <asm/timex.h>
 

-static unsigned long preset_lpj;
+unsigned long preset_lpj;

 static int __init lpj_setup(char *str)
 {
        preset_lpj = simple_strtoul(str,NULL,0);
 static int __init lpj_setup(char *str)
 {
        preset_lpj = simple_strtoul(str,NULL,0);

diff --git a/kernel/printk.c b/kernel/printk.c
index 8451dfc..b2b5c3a 100644 (file)
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -22,6 +22,8 @@
 #include <linux/tty_driver.h>
 #include <linux/console.h>
 #include <linux/init.h>
 #include <linux/tty_driver.h>
 #include <linux/console.h>
 #include <linux/init.h>

+#include <linux/jiffies.h>
+#include <linux/nmi.h>

 #include <linux/module.h>
 #include <linux/moduleparam.h>
 #include <linux/interrupt.h>                   /* For in_interrupt() */
 #include <linux/module.h>
 #include <linux/moduleparam.h>
 #include <linux/interrupt.h>                   /* For in_interrupt() */


@@ -162,6 +164,61 @@ out:
 
 __setup("log_buf_len=", log_buf_len_setup);
 
 
 __setup("log_buf_len=", log_buf_len_setup);
 

+#ifdef CONFIG_BOOT_PRINTK_DELAY
+
+static unsigned int boot_delay; /* msecs delay after each printk during bootup */
+static unsigned long long printk_delay_msec; /* per msec, based on boot_delay */
+
+static int __init boot_delay_setup(char *str)
+{
+       unsigned long lpj;
+       unsigned long long loops_per_msec;
+
+       lpj = preset_lpj ? preset_lpj : 1000000;        /* some guess */
+       loops_per_msec = (unsigned long long)lpj / 1000 * HZ;
+
+       get_option(&str, &boot_delay);
+       if (boot_delay > 10 * 1000)
+               boot_delay = 0;
+
+       printk_delay_msec = loops_per_msec;
+       printk(KERN_DEBUG "boot_delay: %u, preset_lpj: %ld, lpj: %lu, "
+               "HZ: %d, printk_delay_msec: %llu\n",
+               boot_delay, preset_lpj, lpj, HZ, printk_delay_msec);
+       return 1;
+}
+__setup("boot_delay=", boot_delay_setup);
+
+static void boot_delay_msec(void)
+{
+       unsigned long long k;
+       unsigned long timeout;
+
+       if (boot_delay == 0 || system_state != SYSTEM_BOOTING)
+               return;
+
+       k = (unsigned long long)printk_delay_msec * boot_delay;
+
+       timeout = jiffies + msecs_to_jiffies(boot_delay);
+       while (k) {
+               k--;
+               cpu_relax();
+               /*
+                * use (volatile) jiffies to prevent
+                * compiler reduction; loop termination via jiffies
+                * is secondary and may or may not happen.
+                */
+               if (time_after(jiffies, timeout))
+                       break;
+               touch_nmi_watchdog();
+       }
+}
+#else
+static inline void boot_delay_msec(void)
+{
+}
+#endif
+

 /*
  * Commands to do_syslog:
  *
 /*
  * Commands to do_syslog:
  *


@@ -527,6 +584,8 @@ asmlinkage int vprintk(const char *fmt, va_list args)
        static char printk_buf[1024];
        static int log_level_unknown = 1;
 
        static char printk_buf[1024];
        static int log_level_unknown = 1;
 

+       boot_delay_msec();
+

        preempt_disable();
        if (unlikely(oops_in_progress) && printk_cpu == smp_processor_id())
                /* If a crash is occurring during printk() on this CPU,
        preempt_disable();
        if (unlikely(oops_in_progress) && printk_cpu == smp_processor_id())
                /* If a crash is occurring during printk() on this CPU,

diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index 396c38b..7d16e64 100644 (file)
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -413,6 +413,24 @@ config FORCED_INLINING
          become the default in the future, until then this option is there to
          test gcc for this.
 
          become the default in the future, until then this option is there to
          test gcc for this.
 

+config BOOT_PRINTK_DELAY
+       bool "Delay each boot printk message by N milliseconds"
+       depends on DEBUG_KERNEL && PRINTK && GENERIC_CALIBRATE_DELAY
+       help
+         This build option allows you to read kernel boot messages
+         by inserting a short delay after each one.  The delay is
+         specified in milliseconds on the kernel command line,
+         using "boot_delay=N".
+
+         It is likely that you would also need to use "lpj=M" to preset
+         the "loops per jiffie" value.
+         See a previous boot log for the "lpj" value to use for your
+         system, and then set "lpj=M" before setting "boot_delay=N".
+         NOTE:  Using this option may adversely affect SMP systems.
+         I.e., processors other than the first one may not boot up.
+         BOOT_PRINTK_DELAY also may cause DETECT_SOFTLOCKUP to detect
+         what it believes to be lockup conditions.
+

 config RCU_TORTURE_TEST
        tristate "torture tests for RCU"
        depends on DEBUG_KERNEL
 config RCU_TORTURE_TEST
        tristate "torture tests for RCU"
        depends on DEBUG_KERNEL