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>

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>
Randy Dunlap · Linus Torvalds
1 parent 1bcf548293
Showing 5 changed files with 85 additions and 1 deletions Side-by-side Diff
Documentation/kernel-parameters.txt
include/linux/jiffies.h
init/calibrate.c
kernel/printk.c
lib/Kconfig.debug
@@ -349,6 +349,11 @@
 	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.
@@ -148,6 +148,8 @@
  */
 #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
@@ -10,7 +10,7 @@
  
 #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);
@@ -22,6 +22,8 @@
 #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() */
@@ -162,6 +164,61 @@
  
 __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:
  *
@@ -526,6 +583,8 @@
 	char *p;
 	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())
@@ -413,6 +413,24 @@
 	  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
...	...	@@ -349,6 +349,11 @@
349	349	blkmtd_bs=
350	350	blkmtd_count=
351	351
	352	+ boot_delay= Milliseconds to delay each printk during boot.
	353	+ Values larger than 10 seconds (10000) are changed to
	354	+ no delay (0).
	355	+ Format: integer
	356	+
352	357	bttv.card= [HW,V4L] bttv (bt848 + bt878 based grabber cards)
353	358	bttv.radio= Most important insmod options are available as
354	359	kernel args too.
...	...	@@ -148,6 +148,8 @@
148	148	*/
149	149	#define MAX_JIFFY_OFFSET ((LONG_MAX >> 1)-1)
150	150
	151	+extern unsigned long preset_lpj;
	152	+
151	153	/*
152	154	* We want to do realistic conversions of time so we need to use the same
153	155	* values the update wall clock code uses as the jiffies size. This value
...	...	@@ -10,7 +10,7 @@
10	10
11	11	#include <asm/timex.h>
12	12
13		-static unsigned long preset_lpj;
	13	+unsigned long preset_lpj;
14	14	static int __init lpj_setup(char *str)
15	15	{
16	16	preset_lpj = simple_strtoul(str,NULL,0);
...	...	@@ -22,6 +22,8 @@
22	22	#include <linux/tty_driver.h>
23	23	#include <linux/console.h>
24	24	#include <linux/init.h>
	25	+#include <linux/jiffies.h>
	26	+#include <linux/nmi.h>
25	27	#include <linux/module.h>
26	28	#include <linux/moduleparam.h>
27	29	#include <linux/interrupt.h> /* For in_interrupt() */
...	...	@@ -162,6 +164,61 @@
162	164
163	165	__setup("log_buf_len=", log_buf_len_setup);
164	166
	167	+#ifdef CONFIG_BOOT_PRINTK_DELAY
	168	+
	169	+static unsigned int boot_delay; /* msecs delay after each printk during bootup */
	170	+static unsigned long long printk_delay_msec; /* per msec, based on boot_delay */
	171	+
	172	+static int __init boot_delay_setup(char *str)
	173	+{
	174	+ unsigned long lpj;
	175	+ unsigned long long loops_per_msec;
	176	+
	177	+ lpj = preset_lpj ? preset_lpj : 1000000; /* some guess */
	178	+ loops_per_msec = (unsigned long long)lpj / 1000 * HZ;
	179	+
	180	+ get_option(&str, &boot_delay);
	181	+ if (boot_delay > 10 * 1000)
	182	+ boot_delay = 0;
	183	+
	184	+ printk_delay_msec = loops_per_msec;
	185	+ printk(KERN_DEBUG "boot_delay: %u, preset_lpj: %ld, lpj: %lu, "
	186	+ "HZ: %d, printk_delay_msec: %llu\n",
	187	+ boot_delay, preset_lpj, lpj, HZ, printk_delay_msec);
	188	+ return 1;
	189	+}
	190	+__setup("boot_delay=", boot_delay_setup);
	191	+
	192	+static void boot_delay_msec(void)
	193	+{
	194	+ unsigned long long k;
	195	+ unsigned long timeout;
	196	+
	197	+ if (boot_delay == 0 \|\| system_state != SYSTEM_BOOTING)
	198	+ return;
	199	+
	200	+ k = (unsigned long long)printk_delay_msec * boot_delay;
	201	+
	202	+ timeout = jiffies + msecs_to_jiffies(boot_delay);
	203	+ while (k) {
	204	+ k--;
	205	+ cpu_relax();
	206	+ /*
	207	+ * use (volatile) jiffies to prevent
	208	+ * compiler reduction; loop termination via jiffies
	209	+ * is secondary and may or may not happen.
	210	+ */
	211	+ if (time_after(jiffies, timeout))
	212	+ break;
	213	+ touch_nmi_watchdog();
	214	+ }
	215	+}
	216	+#else
	217	+static inline void boot_delay_msec(void)
	218	+{
	219	+}
	220	+#endif
	221	+
165	222	/*
166	223	* Commands to do_syslog:
167	224	*
...	...	@@ -526,6 +583,8 @@
526	583	char *p;
527	584	static char printk_buf[1024];
528	585	static int log_level_unknown = 1;
	586	+
	587	+ boot_delay_msec();
529	588
530	589	preempt_disable();
531	590	if (unlikely(oops_in_progress) && printk_cpu == smp_processor_id())
...	...	@@ -413,6 +413,24 @@
413	413	become the default in the future, until then this option is there to
414	414	test gcc for this.
415	415
	416	+config BOOT_PRINTK_DELAY
	417	+ bool "Delay each boot printk message by N milliseconds"
	418	+ depends on DEBUG_KERNEL && PRINTK && GENERIC_CALIBRATE_DELAY
	419	+ help
	420	+ This build option allows you to read kernel boot messages
	421	+ by inserting a short delay after each one. The delay is
	422	+ specified in milliseconds on the kernel command line,
	423	+ using "boot_delay=N".
	424	+
	425	+ It is likely that you would also need to use "lpj=M" to preset
	426	+ the "loops per jiffie" value.
	427	+ See a previous boot log for the "lpj" value to use for your
	428	+ system, and then set "lpj=M" before setting "boot_delay=N".
	429	+ NOTE: Using this option may adversely affect SMP systems.
	430	+ I.e., processors other than the first one may not boot up.
	431	+ BOOT_PRINTK_DELAY also may cause DETECT_SOFTLOCKUP to detect
	432	+ what it believes to be lockup conditions.
	433	+
416	434	config RCU_TORTURE_TEST
417	435	tristate "torture tests for RCU"
418	436	depends on DEBUG_KERNEL