[RFC][PATCH 0/7] improve printk reliability

[RFC][PATCH 0/7] improve printk reliability

[Peter Zijlstra]

Hi,

So these are my current efforts to make my own console output more
reliable. I've hit every deadlock described in this series and a few
more.

With these patches applied I can printk() and WARN() from inside 
scheduler context and not have my machine deadlock, even without the 
aid of early_printk().

While I'll go an remove the sole printk() I found in the scheduler
so that we don't have to rely on the console doing this, it is good
to have a reliable console that can do this.

As it stands some of the patches, the semaphore one in particular,
are really too ugly to live so I won't push those but wanted to share
anyway.

Debugging this was 'fun', and I really hope to not have to do it
again :-)

[RFC][PATCH 1/7] arch, early_printk: Consolidate early_printk() implementations

[Peter Zijlstra]

[-- Attachment #1: tglx-early-printk-consolidate.patch --]
[-- Type: text/plain, Size: 12111 bytes --]

Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
[ expose early_vprintk(), change return values ]
Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 arch/arm/kernel/early_printk.c        |   17 ++--------------
 arch/blackfin/kernel/early_printk.c   |    2 -
 arch/microblaze/kernel/early_printk.c |   24 ++---------------------
 arch/mips/kernel/early_printk.c       |   10 +++------
 arch/powerpc/kernel/udbg.c            |    6 +----
 arch/sh/kernel/sh_bios.c              |    2 -
 arch/sparc/kernel/setup_32.c          |    1 
 arch/sparc/kernel/setup_64.c          |    8 ++++++-
 arch/tile/kernel/early_printk.c       |   26 +++----------------------
 arch/um/kernel/early_printk.c         |    8 ++++---
 arch/unicore32/kernel/early_printk.c  |   12 +++--------
 arch/x86/kernel/early_printk.c        |   21 +-------------------
 include/linux/console.h               |    1 
 include/linux/printk.h                |   13 +++++++++++-
 kernel/printk.c                       |   35 +++++++++++++++++++++++++++-------
 15 files changed, 76 insertions(+), 110 deletions(-)
--- a/arch/arm/kernel/early_printk.c
+++ b/arch/arm/kernel/early_printk.c
@@ -29,28 +29,17 @@ static void early_console_write(struct c
 	early_write(s, n);
 }
 
-static struct console early_console = {
+static struct console early_console_dev = {
 	.name =		"earlycon",
 	.write =	early_console_write,
 	.flags =	CON_PRINTBUFFER | CON_BOOT,
 	.index =	-1,
 };
 
-asmlinkage void early_printk(const char *fmt, ...)
-{
-	char buf[512];
-	int n;
-	va_list ap;
-
-	va_start(ap, fmt);
-	n = vscnprintf(buf, sizeof(buf), fmt, ap);
-	early_write(buf, n);
-	va_end(ap);
-}
-
 static int __init setup_early_printk(char *buf)
 {
-	register_console(&early_console);
+	early_console = &early_console_dev;
+	register_console(&early_console_dev);
 	return 0;
 }
 
--- a/arch/blackfin/kernel/early_printk.c
+++ b/arch/blackfin/kernel/early_printk.c
@@ -25,8 +25,6 @@ extern struct console *bfin_earlyserial_
 extern struct console *bfin_jc_early_init(void);
 #endif
 
-static struct console *early_console;
-
 /* Default console */
 #define DEFAULT_PORT 0
 #define DEFAULT_CFLAG CS8|B57600
--- a/arch/microblaze/kernel/early_printk.c
+++ b/arch/microblaze/kernel/early_printk.c
@@ -21,7 +21,6 @@
 #include <asm/setup.h>
 #include <asm/prom.h>
 
-static u32 early_console_initialized;
 static u32 base_addr;
 
 #ifdef CONFIG_SERIAL_UARTLITE_CONSOLE
@@ -109,27 +108,11 @@ static struct console early_serial_uart1
 };
 #endif /* CONFIG_SERIAL_8250_CONSOLE */
 
-static struct console *early_console;
-
-void early_printk(const char *fmt, ...)
-{
-	char buf[512];
-	int n;
-	va_list ap;
-
-	if (early_console_initialized) {
-		va_start(ap, fmt);
-		n = vscnprintf(buf, 512, fmt, ap);
-		early_console->write(early_console, buf, n);
-		va_end(ap);
-	}
-}
-
 int __init setup_early_printk(char *opt)
 {
 	int version = 0;
 
-	if (early_console_initialized)
+	if (early_console)
 		return 1;
 
 	base_addr = of_early_console(&version);
@@ -159,7 +142,6 @@ int __init setup_early_printk(char *opt)
 		}
 
 		register_console(early_console);
-		early_console_initialized = 1;
 		return 0;
 	}
 	return 1;
@@ -179,9 +161,9 @@ void __init remap_early_printk(void)
 
 void __init disable_early_printk(void)
 {
-	if (!early_console_initialized || !early_console)
+	if (!early_console)
 		return;
 	printk(KERN_WARNING "disabling early console\n");
 	unregister_console(early_console);
-	early_console_initialized = 0;
+	early_console = NULL;
 }
--- a/arch/mips/kernel/early_printk.c
+++ b/arch/mips/kernel/early_printk.c
@@ -25,20 +25,18 @@ early_console_write(struct console *con,
 	}
 }
 
-static struct console early_console __initdata = {
+static struct console early_console_prom = {
 	.name	= "early",
 	.write	= early_console_write,
 	.flags	= CON_PRINTBUFFER | CON_BOOT,
 	.index	= -1
 };
 
-static int early_console_initialized __initdata;
-
 void __init setup_early_printk(void)
 {
-	if (early_console_initialized)
+	if (early_console)
 		return;
-	early_console_initialized = 1;
+	early_console = &early_console_prom;
 
-	register_console(&early_console);
+	register_console(&early_console_prom);
 }
--- a/arch/powerpc/kernel/udbg.c
+++ b/arch/powerpc/kernel/udbg.c
@@ -182,15 +182,13 @@ static struct console udbg_console = {
 	.index	= 0,
 };
 
-static int early_console_initialized;
-
 /*
  * Called by setup_system after ppc_md->probe and ppc_md->early_init.
  * Call it again after setting udbg_putc in ppc_md->setup_arch.
  */
 void __init register_early_udbg_console(void)
 {
-	if (early_console_initialized)
+	if (early_console)
 		return;
 
 	if (!udbg_putc)
@@ -200,7 +198,7 @@ void __init register_early_udbg_console(
 		printk(KERN_INFO "early console immortal !\n");
 		udbg_console.flags &= ~CON_BOOT;
 	}
-	early_console_initialized = 1;
+	early_console = &udbg_console;
 	register_console(&udbg_console);
 }
 
--- a/arch/sh/kernel/sh_bios.c
+++ b/arch/sh/kernel/sh_bios.c
@@ -144,8 +144,6 @@ static struct console bios_console = {
 	.index		= -1,
 };
 
-static struct console *early_console;
-
 static int __init setup_early_printk(char *buf)
 {
 	int keep_early = 0;
--- a/arch/sparc/kernel/setup_32.c
+++ b/arch/sparc/kernel/setup_32.c
@@ -221,6 +221,7 @@ void __init setup_arch(char **cmdline_p)
 
 	boot_flags_init(*cmdline_p);
 
+	early_console = &prom_early_console;
 	register_console(&prom_early_console);
 
 	/* Set sparc_cpu_model */
--- a/arch/sparc/kernel/setup_64.c
+++ b/arch/sparc/kernel/setup_64.c
@@ -487,6 +487,12 @@ static void __init init_sparc64_elf_hwca
 		popc_patch();
 }
 
+static inline void register_prom_console(void)
+{
+	early_console = &prom_early_console;
+	register_console(&prom_early_console);
+}
+
 void __init setup_arch(char **cmdline_p)
 {
 	/* Initialize PROM console and command line. */
@@ -498,7 +504,7 @@ void __init setup_arch(char **cmdline_p)
 #ifdef CONFIG_EARLYFB
 	if (btext_find_display())
 #endif
-		register_console(&prom_early_console);
+		register_prom_console();
 
 	if (tlb_type == hypervisor)
 		printk("ARCH: SUN4V\n");
--- a/arch/tile/kernel/early_printk.c
+++ b/arch/tile/kernel/early_printk.c
@@ -32,25 +32,8 @@ static struct console early_hv_console =
 };
 
 /* Direct interface for emergencies */
-static struct console *early_console = &early_hv_console;
-static int early_console_initialized;
 static int early_console_complete;
 
-static void early_vprintk(const char *fmt, va_list ap)
-{
-	char buf[512];
-	int n = vscnprintf(buf, sizeof(buf), fmt, ap);
-	early_console->write(early_console, buf, n);
-}
-
-void early_printk(const char *fmt, ...)
-{
-	va_list ap;
-	va_start(ap, fmt);
-	early_vprintk(fmt, ap);
-	va_end(ap);
-}
-
 void early_panic(const char *fmt, ...)
 {
 	va_list ap;
@@ -68,14 +51,13 @@ static int __initdata keep_early;
 
 static int __init setup_early_printk(char *str)
 {
-	if (early_console_initialized)
+	if (early_console)
 		return 1;
 
 	if (str != NULL && strncmp(str, "keep", 4) == 0)
 		keep_early = 1;
 
 	early_console = &early_hv_console;
-	early_console_initialized = 1;
 	register_console(early_console);
 
 	return 0;
@@ -84,12 +66,12 @@ static int __init setup_early_printk(cha
 void __init disable_early_printk(void)
 {
 	early_console_complete = 1;
-	if (!early_console_initialized || !early_console)
+	if (!early_console)
 		return;
 	if (!keep_early) {
 		early_printk("disabling early console\n");
 		unregister_console(early_console);
-		early_console_initialized = 0;
+		early_console = NULL;
 	} else {
 		early_printk("keeping early console\n");
 	}
@@ -97,7 +79,7 @@ void __init disable_early_printk(void)
 
 void warn_early_printk(void)
 {
-	if (early_console_complete || early_console_initialized)
+	if (early_console_complete || early_console)
 		return;
 	early_printk("\
 Machine shutting down before console output is fully initialized.\n\
--- a/arch/um/kernel/early_printk.c
+++ b/arch/um/kernel/early_printk.c
@@ -16,7 +16,7 @@ static void early_console_write(struct c
 	um_early_printk(s, n);
 }
 
-static struct console early_console = {
+static struct console early_console_dev = {
 	.name = "earlycon",
 	.write = early_console_write,
 	.flags = CON_BOOT,
@@ -25,8 +25,10 @@ static struct console early_console = {
 
 static int __init setup_early_printk(char *buf)
 {
-	register_console(&early_console);
-
+	if (!early_console) {
+		early_console = &early_console_dev;
+		register_console(&early_console_dev);
+	}
 	return 0;
 }
 
--- a/arch/unicore32/kernel/early_printk.c
+++ b/arch/unicore32/kernel/early_printk.c
@@ -33,21 +33,17 @@ static struct console early_ocd_console 
 	.index =	-1,
 };
 
-/* Direct interface for emergencies */
-static struct console *early_console = &early_ocd_console;
-
-static int __initdata keep_early;
-
 static int __init setup_early_printk(char *buf)
 {
-	if (!buf)
+	int keep_early;
+
+	if (!buf || early_console)
 		return 0;
 
 	if (strstr(buf, "keep"))
 		keep_early = 1;
 
-	if (!strncmp(buf, "ocd", 3))
-		early_console = &early_ocd_console;
+	early_console = &early_ocd_console;
 
 	if (keep_early)
 		early_console->flags &= ~CON_BOOT;
--- a/arch/x86/kernel/early_printk.c
+++ b/arch/x86/kernel/early_printk.c
@@ -169,25 +169,9 @@ static struct console early_serial_conso
 	.index =	-1,
 };
 
-/* Direct interface for emergencies */
-static struct console *early_console = &early_vga_console;
-static int __initdata early_console_initialized;
-
-asmlinkage void early_printk(const char *fmt, ...)
-{
-	char buf[512];
-	int n;
-	va_list ap;
-
-	va_start(ap, fmt);
-	n = vscnprintf(buf, sizeof(buf), fmt, ap);
-	early_console->write(early_console, buf, n);
-	va_end(ap);
-}
-
 static inline void early_console_register(struct console *con, int keep_early)
 {
-	if (early_console->index != -1) {
+	if (con->index != -1) {
 		printk(KERN_CRIT "ERROR: earlyprintk= %s already used\n",
 		       con->name);
 		return;
@@ -207,9 +191,8 @@ static int __init setup_early_printk(cha
 	if (!buf)
 		return 0;
 
-	if (early_console_initialized)
+	if (early_console)
 		return 0;
-	early_console_initialized = 1;
 
 	keep = (strstr(buf, "keep") != NULL);
 
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -133,6 +133,7 @@ struct console {
 	for (con = console_drivers; con != NULL; con = con->next)
 
 extern int console_set_on_cmdline;
+extern struct console *early_console;
 
 extern int add_preferred_console(char *name, int idx, char *options);
 extern int update_console_cmdline(char *name, int idx, char *name_new, int idx_new, char *options);
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -88,8 +88,19 @@ int no_printk(const char *fmt, ...)
 	return 0;
 }
 
+#ifdef CONFIG_EARLY_PRINTK
 extern asmlinkage __printf(1, 2)
-void early_printk(const char *fmt, ...);
+int early_printk(const char *fmt, ...);
+
+extern asmlinkage __printf(1, 0)
+int early_vprintk(const char *fmt, va_list args);
+#else
+static inline __printf(1, 2) __cold
+int early_printk(const char *s, ...) { return 0; }
+
+static inline __printf(1, 0) __cold
+int early_vprintk(const char *fmt, va_list args) { return 0; }
+#endif
 
 extern int printk_needs_cpu(int cpu);
 extern void printk_tick(void);
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -44,13 +44,6 @@
 
 #include <asm/uaccess.h>
 
-/*
- * Architectures can override it:
- */
-void asmlinkage __attribute__((weak)) early_printk(const char *fmt, ...)
-{
-}
-
 #define __LOG_BUF_LEN	(1 << CONFIG_LOG_BUF_SHIFT)
 
 /* printk's without a loglevel use this.. */
@@ -521,6 +514,34 @@ static void __call_console_drivers(unsig
 	}
 }
 
+#ifdef CONFIG_EARLY_PRINTK
+struct console *early_console;
+
+asmlinkage int early_vprintk(const char *fmt, va_list ap)
+{
+	char buf[512];
+	int n = vscnprintf(buf, sizeof(buf), fmt, ap);
+	if (early_console)
+		early_console->write(early_console, buf, n);
+	else
+		n = 0;
+
+	return n;
+}
+
+asmlinkage int early_printk(const char *fmt, ...)
+{
+	va_list ap;
+	int r;
+
+	va_start(ap, fmt);
+	r = early_vprintk(fmt, ap);
+	va_end(ap);
+
+	return r;
+}
+#endif
+
 static int __read_mostly ignore_loglevel;
 
 static int __init ignore_loglevel_setup(char *str)

Re: [RFC][PATCH 1/7] arch, early_printk: Consolidate early_printk() implementations

[Mike Frysinger]

>  arch/blackfin/kernel/early_printk.c   |    2 -

Acked-by: Mike Frysinger <vapier@gentoo.org>
-mike

Re: [RFC][PATCH 1/7] arch, early_printk: Consolidate early_printk() implementations

[Peter Zijlstra]

On Wed, 2011-12-21 at 11:57 +0100, Peter Zijlstra wrote:

For correctness sake, quilt ate:

From: Thomas Gleixner <tglx@linutronix.de>

> Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> [ expose early_vprintk(), change return values ]
> Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
> --- 

Re: [RFC][PATCH 1/7] arch, early_printk: Consolidate early_printk() implementations

[David Miller]

From: Peter Zijlstra <a.p.zijlstra@chello.nl>
Date: Wed, 21 Dec 2011 11:57:40 +0100

>  arch/sparc/kernel/setup_32.c          |    1 
>  arch/sparc/kernel/setup_64.c          |    8 ++++++-

Acked-by: David S. Miller <davem@davemloft.net>

[RFC][PATCH 2/7] lockdep: Provide early_printk() support

[Peter Zijlstra]

[-- Attachment #1: lockdep-early-printk.patch --]
[-- Type: text/plain, Size: 35416 bytes --]


Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/lockdep.c |  488 ++++++++++++++++++++++++++++---------------------------
 1 file changed, 252 insertions(+), 236 deletions(-)
--- a/kernel/lockdep.c
+++ b/kernel/lockdep.c
@@ -67,6 +67,22 @@ module_param(lock_stat, int, 0644);
 #define lock_stat 0
 #endif
 
+int use_early_printk = 0;
+module_param(use_early_printk, int, 0644);
+
+static int lprintk(const char *fmt, ...)
+{
+	va_list args;
+	int r;
+
+	va_start(args, fmt);
+	if (!use_early_printk || !(r = early_vprintk(fmt, args)))
+		r = vprintk(fmt, args);
+	va_end(args);
+
+	return r;
+}
+
 /*
  * lockdep_lock: protects the lockdep graph, the hashes and the
  *               class/list/hash allocators.
@@ -409,8 +425,8 @@ static int save_trace(struct stack_trace
 		if (!debug_locks_off_graph_unlock())
 			return 0;
 
-		printk("BUG: MAX_STACK_TRACE_ENTRIES too low!\n");
-		printk("turning off the locking correctness validator.\n");
+		lprintk("BUG: MAX_STACK_TRACE_ENTRIES too low!\n");
+		lprintk("turning off the locking correctness validator.\n");
 		dump_stack();
 
 		return 0;
@@ -426,7 +442,7 @@ unsigned int max_lockdep_depth;
 
 #ifdef CONFIG_DEBUG_LOCKDEP
 /*
- * We cannot printk in early bootup code. Not even early_printk()
+ * We cannot printk in early bootup code. Not even early_lprintk()
  * might work. So we mark any initialization errors and printk
  * about it later on, in lockdep_info().
  */
@@ -508,13 +524,13 @@ static void __print_lock_name(struct loc
 	name = class->name;
 	if (!name) {
 		name = __get_key_name(class->key, str);
-		printk("%s", name);
+		lprintk("%s", name);
 	} else {
-		printk("%s", name);
+		lprintk("%s", name);
 		if (class->name_version > 1)
-			printk("#%d", class->name_version);
+			lprintk("#%d", class->name_version);
 		if (class->subclass)
-			printk("/%d", class->subclass);
+			lprintk("/%d", class->subclass);
 	}
 }
 
@@ -524,9 +540,9 @@ static void print_lock_name(struct lock_
 
 	get_usage_chars(class, usage);
 
-	printk(" (");
+	lprintk(" (");
 	__print_lock_name(class);
-	printk("){%s}", usage);
+	lprintk("){%s}", usage);
 }
 
 static void print_lockdep_cache(struct lockdep_map *lock)
@@ -538,13 +554,13 @@ static void print_lockdep_cache(struct l
 	if (!name)
 		name = __get_key_name(lock->key->subkeys, str);
 
-	printk("%s", name);
+	lprintk("%s", name);
 }
 
 static void print_lock(struct held_lock *hlock)
 {
 	print_lock_name(hlock_class(hlock));
-	printk(", at: ");
+	lprintk(", at: ");
 	print_ip_sym(hlock->acquire_ip);
 }
 
@@ -553,21 +569,21 @@ static void lockdep_print_held_locks(str
 	int i, depth = curr->lockdep_depth;
 
 	if (!depth) {
-		printk("no locks held by %s/%d.\n", curr->comm, task_pid_nr(curr));
+		lprintk("no locks held by %s/%d.\n", curr->comm, task_pid_nr(curr));
 		return;
 	}
-	printk("%d lock%s held by %s/%d:\n",
+	lprintk("%d lock%s held by %s/%d:\n",
 		depth, depth > 1 ? "s" : "", curr->comm, task_pid_nr(curr));
 
 	for (i = 0; i < depth; i++) {
-		printk(" #%d: ", i);
+		lprintk(" #%d: ", i);
 		print_lock(curr->held_locks + i);
 	}
 }
 
 static void print_kernel_ident(void)
 {
-	printk("%s %.*s %s\n", init_utsname()->release,
+	lprintk("%s %.*s %s\n", init_utsname()->release,
 		(int)strcspn(init_utsname()->version, " "),
 		init_utsname()->version,
 		print_tainted());
@@ -661,9 +677,9 @@ look_up_lock_class(struct lockdep_map *l
 
 	if (unlikely(subclass >= MAX_LOCKDEP_SUBCLASSES)) {
 		debug_locks_off();
-		printk(KERN_ERR
+		lprintk(KERN_ERR
 			"BUG: looking up invalid subclass: %u\n", subclass);
-		printk(KERN_ERR
+		lprintk(KERN_ERR
 			"turning off the locking correctness validator.\n");
 		dump_stack();
 		return NULL;
@@ -729,9 +745,9 @@ register_lock_class(struct lockdep_map *
  	 */
 	if (!static_obj(lock->key)) {
 		debug_locks_off();
-		printk("INFO: trying to register non-static key.\n");
-		printk("the code is fine but needs lockdep annotation.\n");
-		printk("turning off the locking correctness validator.\n");
+		lprintk("INFO: trying to register non-static key.\n");
+		lprintk("the code is fine but needs lockdep annotation.\n");
+		lprintk("turning off the locking correctness validator.\n");
 		dump_stack();
 
 		return NULL;
@@ -763,8 +779,8 @@ register_lock_class(struct lockdep_map *
 		}
 		raw_local_irq_restore(flags);
 
-		printk("BUG: MAX_LOCKDEP_KEYS too low!\n");
-		printk("turning off the locking correctness validator.\n");
+		lprintk("BUG: MAX_LOCKDEP_KEYS too low!\n");
+		lprintk("turning off the locking correctness validator.\n");
 		dump_stack();
 		return NULL;
 	}
@@ -791,10 +807,10 @@ register_lock_class(struct lockdep_map *
 		graph_unlock();
 		raw_local_irq_restore(flags);
 
-		printk("\nnew class %p: %s", class->key, class->name);
+		lprintk("\nnew class %p: %s", class->key, class->name);
 		if (class->name_version > 1)
-			printk("#%d", class->name_version);
-		printk("\n");
+			lprintk("#%d", class->name_version);
+		lprintk("\n");
 		dump_stack();
 
 		raw_local_irq_save(flags);
@@ -834,8 +850,8 @@ static struct lock_list *alloc_list_entr
 		if (!debug_locks_off_graph_unlock())
 			return NULL;
 
-		printk("BUG: MAX_LOCKDEP_ENTRIES too low!\n");
-		printk("turning off the locking correctness validator.\n");
+		lprintk("BUG: MAX_LOCKDEP_ENTRIES too low!\n");
+		lprintk("turning off the locking correctness validator.\n");
 		dump_stack();
 		return NULL;
 	}
@@ -1074,9 +1090,9 @@ print_circular_bug_entry(struct lock_lis
 {
 	if (debug_locks_silent)
 		return 0;
-	printk("\n-> #%u", depth);
+	lprintk("\n-> #%u", depth);
 	print_lock_name(target->class);
-	printk(":\n");
+	lprintk(":\n");
 	print_stack_trace(&target->trace, 6);
 
 	return 0;
@@ -1105,31 +1121,31 @@ print_circular_lock_scenario(struct held
 	 * from the safe_class lock to the unsafe_class lock.
 	 */
 	if (parent != source) {
-		printk("Chain exists of:\n  ");
+		lprintk("Chain exists of:\n  ");
 		__print_lock_name(source);
-		printk(" --> ");
+		lprintk(" --> ");
 		__print_lock_name(parent);
-		printk(" --> ");
+		lprintk(" --> ");
 		__print_lock_name(target);
-		printk("\n\n");
+		lprintk("\n\n");
 	}
 
-	printk(" Possible unsafe locking scenario:\n\n");
-	printk("       CPU0                    CPU1\n");
-	printk("       ----                    ----\n");
-	printk("  lock(");
+	lprintk(" Possible unsafe locking scenario:\n\n");
+	lprintk("       CPU0                    CPU1\n");
+	lprintk("       ----                    ----\n");
+	lprintk("  lock(");
 	__print_lock_name(target);
-	printk(");\n");
-	printk("                               lock(");
+	lprintk(");\n");
+	lprintk("                               lock(");
 	__print_lock_name(parent);
-	printk(");\n");
-	printk("                               lock(");
+	lprintk(");\n");
+	lprintk("                               lock(");
 	__print_lock_name(target);
-	printk(");\n");
-	printk("  lock(");
+	lprintk(");\n");
+	lprintk("  lock(");
 	__print_lock_name(source);
-	printk(");\n");
-	printk("\n *** DEADLOCK ***\n\n");
+	lprintk(");\n");
+	lprintk("\n *** DEADLOCK ***\n\n");
 }
 
 /*
@@ -1146,18 +1162,18 @@ print_circular_bug_header(struct lock_li
 	if (debug_locks_silent)
 		return 0;
 
-	printk("\n");
-	printk("======================================================\n");
-	printk("[ INFO: possible circular locking dependency detected ]\n");
+	lprintk("\n");
+	lprintk("======================================================\n");
+	lprintk("[ INFO: possible circular locking dependency detected ]\n");
 	print_kernel_ident();
-	printk("-------------------------------------------------------\n");
-	printk("%s/%d is trying to acquire lock:\n",
+	lprintk("-------------------------------------------------------\n");
+	lprintk("%s/%d is trying to acquire lock:\n",
 		curr->comm, task_pid_nr(curr));
 	print_lock(check_src);
-	printk("\nbut task is already holding lock:\n");
+	lprintk("\nbut task is already holding lock:\n");
 	print_lock(check_tgt);
-	printk("\nwhich lock already depends on the new lock.\n\n");
-	printk("\nthe existing dependency chain (in reverse order) is:\n");
+	lprintk("\nwhich lock already depends on the new lock.\n\n");
+	lprintk("\nthe existing dependency chain (in reverse order) is:\n");
 
 	print_circular_bug_entry(entry, depth);
 
@@ -1197,13 +1213,13 @@ static noinline int print_circular_bug(s
 		parent = get_lock_parent(parent);
 	}
 
-	printk("\nother info that might help us debug this:\n\n");
+	lprintk("\nother info that might help us debug this:\n\n");
 	print_circular_lock_scenario(check_src, check_tgt,
 				     first_parent);
 
 	lockdep_print_held_locks(curr);
 
-	printk("\nstack backtrace:\n");
+	lprintk("\nstack backtrace:\n");
 	dump_stack();
 
 	return 0;
@@ -1362,23 +1378,23 @@ static void print_lock_class_header(stru
 {
 	int bit;
 
-	printk("%*s->", depth, "");
+	lprintk("%*s->", depth, "");
 	print_lock_name(class);
-	printk(" ops: %lu", class->ops);
-	printk(" {\n");
+	lprintk(" ops: %lu", class->ops);
+	lprintk(" {\n");
 
 	for (bit = 0; bit < LOCK_USAGE_STATES; bit++) {
 		if (class->usage_mask & (1 << bit)) {
 			int len = depth;
 
-			len += printk("%*s   %s", depth, "", usage_str[bit]);
-			len += printk(" at:\n");
+			len += lprintk("%*s   %s", depth, "", usage_str[bit]);
+			len += lprintk(" at:\n");
 			print_stack_trace(class->usage_traces + bit, len);
 		}
 	}
-	printk("%*s }\n", depth, "");
+	lprintk("%*s }\n", depth, "");
 
-	printk("%*s ... key      at: ",depth,"");
+	lprintk("%*s ... key      at: ",depth,"");
 	print_ip_sym((unsigned long)class->key);
 }
 
@@ -1397,12 +1413,12 @@ print_shortest_lock_dependencies(struct 
 
 	do {
 		print_lock_class_header(entry->class, depth);
-		printk("%*s ... acquired at:\n", depth, "");
+		lprintk("%*s ... acquired at:\n", depth, "");
 		print_stack_trace(&entry->trace, 2);
-		printk("\n");
+		lprintk("\n");
 
 		if (depth == 0 && (entry != root)) {
-			printk("lockdep:%s bad path found in chain graph\n", __func__);
+			lprintk("lockdep:%s bad path found in chain graph\n", __func__);
 			break;
 		}
 
@@ -1440,33 +1456,33 @@ print_irq_lock_scenario(struct lock_list
 	 * from the safe_class lock to the unsafe_class lock.
 	 */
 	if (middle_class != unsafe_class) {
-		printk("Chain exists of:\n  ");
+		lprintk("Chain exists of:\n  ");
 		__print_lock_name(safe_class);
-		printk(" --> ");
+		lprintk(" --> ");
 		__print_lock_name(middle_class);
-		printk(" --> ");
+		lprintk(" --> ");
 		__print_lock_name(unsafe_class);
-		printk("\n\n");
+		lprintk("\n\n");
 	}
 
-	printk(" Possible interrupt unsafe locking scenario:\n\n");
-	printk("       CPU0                    CPU1\n");
-	printk("       ----                    ----\n");
-	printk("  lock(");
+	lprintk(" Possible interrupt unsafe locking scenario:\n\n");
+	lprintk("       CPU0                    CPU1\n");
+	lprintk("       ----                    ----\n");
+	lprintk("  lock(");
 	__print_lock_name(unsafe_class);
-	printk(");\n");
-	printk("                               local_irq_disable();\n");
-	printk("                               lock(");
+	lprintk(");\n");
+	lprintk("                               local_irq_disable();\n");
+	lprintk("                               lock(");
 	__print_lock_name(safe_class);
-	printk(");\n");
-	printk("                               lock(");
+	lprintk(");\n");
+	lprintk("                               lock(");
 	__print_lock_name(middle_class);
-	printk(");\n");
-	printk("  <Interrupt>\n");
-	printk("    lock(");
+	lprintk(");\n");
+	lprintk("  <Interrupt>\n");
+	lprintk("    lock(");
 	__print_lock_name(safe_class);
-	printk(");\n");
-	printk("\n *** DEADLOCK ***\n\n");
+	lprintk(");\n");
+	lprintk("\n *** DEADLOCK ***\n\n");
 }
 
 static int
@@ -1484,13 +1500,13 @@ print_bad_irq_dependency(struct task_str
 	if (!debug_locks_off_graph_unlock() || debug_locks_silent)
 		return 0;
 
-	printk("\n");
-	printk("======================================================\n");
-	printk("[ INFO: %s-safe -> %s-unsafe lock order detected ]\n",
+	lprintk("\n");
+	lprintk("======================================================\n");
+	lprintk("[ INFO: %s-safe -> %s-unsafe lock order detected ]\n",
 		irqclass, irqclass);
 	print_kernel_ident();
-	printk("------------------------------------------------------\n");
-	printk("%s/%d [HC%u[%lu]:SC%u[%lu]:HE%u:SE%u] is trying to acquire:\n",
+	lprintk("------------------------------------------------------\n");
+	lprintk("%s/%d [HC%u[%lu]:SC%u[%lu]:HE%u:SE%u] is trying to acquire:\n",
 		curr->comm, task_pid_nr(curr),
 		curr->hardirq_context, hardirq_count() >> HARDIRQ_SHIFT,
 		curr->softirq_context, softirq_count() >> SOFTIRQ_SHIFT,
@@ -1498,47 +1514,47 @@ print_bad_irq_dependency(struct task_str
 		curr->softirqs_enabled);
 	print_lock(next);
 
-	printk("\nand this task is already holding:\n");
+	lprintk("\nand this task is already holding:\n");
 	print_lock(prev);
-	printk("which would create a new lock dependency:\n");
+	lprintk("which would create a new lock dependency:\n");
 	print_lock_name(hlock_class(prev));
-	printk(" ->");
+	lprintk(" ->");
 	print_lock_name(hlock_class(next));
-	printk("\n");
+	lprintk("\n");
 
-	printk("\nbut this new dependency connects a %s-irq-safe lock:\n",
+	lprintk("\nbut this new dependency connects a %s-irq-safe lock:\n",
 		irqclass);
 	print_lock_name(backwards_entry->class);
-	printk("\n... which became %s-irq-safe at:\n", irqclass);
+	lprintk("\n... which became %s-irq-safe at:\n", irqclass);
 
 	print_stack_trace(backwards_entry->class->usage_traces + bit1, 1);
 
-	printk("\nto a %s-irq-unsafe lock:\n", irqclass);
+	lprintk("\nto a %s-irq-unsafe lock:\n", irqclass);
 	print_lock_name(forwards_entry->class);
-	printk("\n... which became %s-irq-unsafe at:\n", irqclass);
-	printk("...");
+	lprintk("\n... which became %s-irq-unsafe at:\n", irqclass);
+	lprintk("...");
 
 	print_stack_trace(forwards_entry->class->usage_traces + bit2, 1);
 
-	printk("\nother info that might help us debug this:\n\n");
+	lprintk("\nother info that might help us debug this:\n\n");
 	print_irq_lock_scenario(backwards_entry, forwards_entry,
 				hlock_class(prev), hlock_class(next));
 
 	lockdep_print_held_locks(curr);
 
-	printk("\nthe dependencies between %s-irq-safe lock", irqclass);
-	printk(" and the holding lock:\n");
+	lprintk("\nthe dependencies between %s-irq-safe lock", irqclass);
+	lprintk(" and the holding lock:\n");
 	if (!save_trace(&prev_root->trace))
 		return 0;
 	print_shortest_lock_dependencies(backwards_entry, prev_root);
 
-	printk("\nthe dependencies between the lock to be acquired");
-	printk(" and %s-irq-unsafe lock:\n", irqclass);
+	lprintk("\nthe dependencies between the lock to be acquired");
+	lprintk(" and %s-irq-unsafe lock:\n", irqclass);
 	if (!save_trace(&next_root->trace))
 		return 0;
 	print_shortest_lock_dependencies(forwards_entry, next_root);
 
-	printk("\nstack backtrace:\n");
+	lprintk("\nstack backtrace:\n");
 	dump_stack();
 
 	return 0;
@@ -1694,17 +1710,17 @@ print_deadlock_scenario(struct held_lock
 	struct lock_class *next = hlock_class(nxt);
 	struct lock_class *prev = hlock_class(prv);
 
-	printk(" Possible unsafe locking scenario:\n\n");
-	printk("       CPU0\n");
-	printk("       ----\n");
-	printk("  lock(");
+	lprintk(" Possible unsafe locking scenario:\n\n");
+	lprintk("       CPU0\n");
+	lprintk("       ----\n");
+	lprintk("  lock(");
 	__print_lock_name(prev);
-	printk(");\n");
-	printk("  lock(");
+	lprintk(");\n");
+	lprintk("  lock(");
 	__print_lock_name(next);
-	printk(");\n");
-	printk("\n *** DEADLOCK ***\n\n");
-	printk(" May be due to missing lock nesting notation\n\n");
+	lprintk(");\n");
+	lprintk("\n *** DEADLOCK ***\n\n");
+	lprintk(" May be due to missing lock nesting notation\n\n");
 }
 
 static int
@@ -1714,22 +1730,22 @@ print_deadlock_bug(struct task_struct *c
 	if (!debug_locks_off_graph_unlock() || debug_locks_silent)
 		return 0;
 
-	printk("\n");
-	printk("=============================================\n");
-	printk("[ INFO: possible recursive locking detected ]\n");
+	lprintk("\n");
+	lprintk("=============================================\n");
+	lprintk("[ INFO: possible recursive locking detected ]\n");
 	print_kernel_ident();
-	printk("---------------------------------------------\n");
-	printk("%s/%d is trying to acquire lock:\n",
+	lprintk("---------------------------------------------\n");
+	lprintk("%s/%d is trying to acquire lock:\n",
 		curr->comm, task_pid_nr(curr));
 	print_lock(next);
-	printk("\nbut task is already holding lock:\n");
+	lprintk("\nbut task is already holding lock:\n");
 	print_lock(prev);
 
-	printk("\nother info that might help us debug this:\n");
+	lprintk("\nother info that might help us debug this:\n");
 	print_deadlock_scenario(next, prev);
 	lockdep_print_held_locks(curr);
 
-	printk("\nstack backtrace:\n");
+	lprintk("\nstack backtrace:\n");
 	dump_stack();
 
 	return 0;
@@ -1889,11 +1905,11 @@ check_prev_add(struct task_struct *curr,
 	 */
 	if (verbose(hlock_class(prev)) || verbose(hlock_class(next))) {
 		graph_unlock();
-		printk("\n new dependency: ");
+		lprintk("\n new dependency: ");
 		print_lock_name(hlock_class(prev));
-		printk(" => ");
+		lprintk(" => ");
 		print_lock_name(hlock_class(next));
-		printk("\n");
+		lprintk("\n");
 		dump_stack();
 		return graph_lock();
 	}
@@ -2019,7 +2035,7 @@ static inline int lookup_chain_cache(str
 cache_hit:
 			debug_atomic_inc(chain_lookup_hits);
 			if (very_verbose(class))
-				printk("\nhash chain already cached, key: "
+				lprintk("\nhash chain already cached, key: "
 					"%016Lx tail class: [%p] %s\n",
 					(unsigned long long)chain_key,
 					class->key, class->name);
@@ -2027,7 +2043,7 @@ static inline int lookup_chain_cache(str
 		}
 	}
 	if (very_verbose(class))
-		printk("\nnew hash chain, key: %016Lx tail class: [%p] %s\n",
+		lprintk("\nnew hash chain, key: %016Lx tail class: [%p] %s\n",
 			(unsigned long long)chain_key, class->key, class->name);
 	/*
 	 * Allocate a new chain entry from the static array, and add
@@ -2048,8 +2064,8 @@ static inline int lookup_chain_cache(str
 		if (!debug_locks_off_graph_unlock())
 			return 0;
 
-		printk("BUG: MAX_LOCKDEP_CHAINS too low!\n");
-		printk("turning off the locking correctness validator.\n");
+		lprintk("BUG: MAX_LOCKDEP_CHAINS too low!\n");
+		lprintk("turning off the locking correctness validator.\n");
 		dump_stack();
 		return 0;
 	}
@@ -2201,17 +2217,17 @@ print_usage_bug_scenario(struct held_loc
 {
 	struct lock_class *class = hlock_class(lock);
 
-	printk(" Possible unsafe locking scenario:\n\n");
-	printk("       CPU0\n");
-	printk("       ----\n");
-	printk("  lock(");
+	lprintk(" Possible unsafe locking scenario:\n\n");
+	lprintk("       CPU0\n");
+	lprintk("       ----\n");
+	lprintk("  lock(");
 	__print_lock_name(class);
-	printk(");\n");
-	printk("  <Interrupt>\n");
-	printk("    lock(");
+	lprintk(");\n");
+	lprintk("  <Interrupt>\n");
+	lprintk("    lock(");
 	__print_lock_name(class);
-	printk(");\n");
-	printk("\n *** DEADLOCK ***\n\n");
+	lprintk(");\n");
+	lprintk("\n *** DEADLOCK ***\n\n");
 }
 
 static int
@@ -2221,16 +2237,16 @@ print_usage_bug(struct task_struct *curr
 	if (!debug_locks_off_graph_unlock() || debug_locks_silent)
 		return 0;
 
-	printk("\n");
-	printk("=================================\n");
-	printk("[ INFO: inconsistent lock state ]\n");
+	lprintk("\n");
+	lprintk("=================================\n");
+	lprintk("[ INFO: inconsistent lock state ]\n");
 	print_kernel_ident();
-	printk("---------------------------------\n");
+	lprintk("---------------------------------\n");
 
-	printk("inconsistent {%s} -> {%s} usage.\n",
+	lprintk("inconsistent {%s} -> {%s} usage.\n",
 		usage_str[prev_bit], usage_str[new_bit]);
 
-	printk("%s/%d [HC%u[%lu]:SC%u[%lu]:HE%u:SE%u] takes:\n",
+	lprintk("%s/%d [HC%u[%lu]:SC%u[%lu]:HE%u:SE%u] takes:\n",
 		curr->comm, task_pid_nr(curr),
 		trace_hardirq_context(curr), hardirq_count() >> HARDIRQ_SHIFT,
 		trace_softirq_context(curr), softirq_count() >> SOFTIRQ_SHIFT,
@@ -2238,16 +2254,16 @@ print_usage_bug(struct task_struct *curr
 		trace_softirqs_enabled(curr));
 	print_lock(this);
 
-	printk("{%s} state was registered at:\n", usage_str[prev_bit]);
+	lprintk("{%s} state was registered at:\n", usage_str[prev_bit]);
 	print_stack_trace(hlock_class(this)->usage_traces + prev_bit, 1);
 
 	print_irqtrace_events(curr);
-	printk("\nother info that might help us debug this:\n");
+	lprintk("\nother info that might help us debug this:\n");
 	print_usage_bug_scenario(this);
 
 	lockdep_print_held_locks(curr);
 
-	printk("\nstack backtrace:\n");
+	lprintk("\nstack backtrace:\n");
 	dump_stack();
 
 	return 0;
@@ -2286,28 +2302,28 @@ print_irq_inversion_bug(struct task_stru
 	if (!debug_locks_off_graph_unlock() || debug_locks_silent)
 		return 0;
 
-	printk("\n");
-	printk("=========================================================\n");
-	printk("[ INFO: possible irq lock inversion dependency detected ]\n");
+	lprintk("\n");
+	lprintk("=========================================================\n");
+	lprintk("[ INFO: possible irq lock inversion dependency detected ]\n");
 	print_kernel_ident();
-	printk("---------------------------------------------------------\n");
-	printk("%s/%d just changed the state of lock:\n",
+	lprintk("---------------------------------------------------------\n");
+	lprintk("%s/%d just changed the state of lock:\n",
 		curr->comm, task_pid_nr(curr));
 	print_lock(this);
 	if (forwards)
-		printk("but this lock took another, %s-unsafe lock in the past:\n", irqclass);
+		lprintk("but this lock took another, %s-unsafe lock in the past:\n", irqclass);
 	else
-		printk("but this lock was taken by another, %s-safe lock in the past:\n", irqclass);
+		lprintk("but this lock was taken by another, %s-safe lock in the past:\n", irqclass);
 	print_lock_name(other->class);
-	printk("\n\nand interrupts could create inverse lock ordering between them.\n\n");
+	lprintk("\n\nand interrupts could create inverse lock ordering between them.\n\n");
 
-	printk("\nother info that might help us debug this:\n");
+	lprintk("\nother info that might help us debug this:\n");
 
 	/* Find a middle lock (if one exists) */
 	depth = get_lock_depth(other);
 	do {
 		if (depth == 0 && (entry != root)) {
-			printk("lockdep:%s bad path found in chain graph\n", __func__);
+			lprintk("lockdep:%s bad path found in chain graph\n", __func__);
 			break;
 		}
 		middle = entry;
@@ -2323,12 +2339,12 @@ print_irq_inversion_bug(struct task_stru
 
 	lockdep_print_held_locks(curr);
 
-	printk("\nthe shortest dependencies between 2nd lock and 1st lock:\n");
+	lprintk("\nthe shortest dependencies between 2nd lock and 1st lock:\n");
 	if (!save_trace(&root->trace))
 		return 0;
 	print_shortest_lock_dependencies(other, root);
 
-	printk("\nstack backtrace:\n");
+	lprintk("\nstack backtrace:\n");
 	dump_stack();
 
 	return 0;
@@ -2384,14 +2400,14 @@ check_usage_backwards(struct task_struct
 
 void print_irqtrace_events(struct task_struct *curr)
 {
-	printk("irq event stamp: %u\n", curr->irq_events);
-	printk("hardirqs last  enabled at (%u): ", curr->hardirq_enable_event);
+	lprintk("irq event stamp: %u\n", curr->irq_events);
+	lprintk("hardirqs last  enabled at (%u): ", curr->hardirq_enable_event);
 	print_ip_sym(curr->hardirq_enable_ip);
-	printk("hardirqs last disabled at (%u): ", curr->hardirq_disable_event);
+	lprintk("hardirqs last disabled at (%u): ", curr->hardirq_disable_event);
 	print_ip_sym(curr->hardirq_disable_ip);
-	printk("softirqs last  enabled at (%u): ", curr->softirq_enable_event);
+	lprintk("softirqs last  enabled at (%u): ", curr->softirq_enable_event);
 	print_ip_sym(curr->softirq_enable_ip);
-	printk("softirqs last disabled at (%u): ", curr->softirq_disable_event);
+	lprintk("softirqs last disabled at (%u): ", curr->softirq_disable_event);
 	print_ip_sym(curr->softirq_disable_ip);
 }
 
@@ -2934,7 +2950,7 @@ static int mark_lock(struct task_struct 
 	 * We must printk outside of the graph_lock:
 	 */
 	if (ret == 2) {
-		printk("\nmarked lock as {%s}:\n", usage_str[new_bit]);
+		lprintk("\nmarked lock as {%s}:\n", usage_str[new_bit]);
 		print_lock(this);
 		print_irqtrace_events(curr);
 		dump_stack();
@@ -2979,7 +2995,7 @@ void lockdep_init_map(struct lockdep_map
 	 * Sanity check, the lock-class key must be persistent:
 	 */
 	if (!static_obj(key)) {
-		printk("BUG: key %p not in .data!\n", key);
+		lprintk("BUG: key %p not in .data!\n", key);
 		/*
 		 * What it says above ^^^^^, I suggest you read it.
 		 */
@@ -3044,10 +3060,10 @@ static int __lock_acquire(struct lockdep
 	}
 	atomic_inc((atomic_t *)&class->ops);
 	if (very_verbose(class)) {
-		printk("\nacquire class [%p] %s", class->key, class->name);
+		lprintk("\nacquire class [%p] %s", class->key, class->name);
 		if (class->name_version > 1)
-			printk("#%d", class->name_version);
-		printk("\n");
+			lprintk("#%d", class->name_version);
+		lprintk("\n");
 		dump_stack();
 	}
 
@@ -3151,8 +3167,8 @@ static int __lock_acquire(struct lockdep
 #endif
 	if (unlikely(curr->lockdep_depth >= MAX_LOCK_DEPTH)) {
 		debug_locks_off();
-		printk("BUG: MAX_LOCK_DEPTH too low!\n");
-		printk("turning off the locking correctness validator.\n");
+		lprintk("BUG: MAX_LOCK_DEPTH too low!\n");
+		lprintk("turning off the locking correctness validator.\n");
 		dump_stack();
 		return 0;
 	}
@@ -3172,21 +3188,21 @@ print_unlock_inbalance_bug(struct task_s
 	if (debug_locks_silent)
 		return 0;
 
-	printk("\n");
-	printk("=====================================\n");
-	printk("[ BUG: bad unlock balance detected! ]\n");
+	lprintk("\n");
+	lprintk("=====================================\n");
+	lprintk("[ BUG: bad unlock balance detected! ]\n");
 	print_kernel_ident();
-	printk("-------------------------------------\n");
-	printk("%s/%d is trying to release lock (",
+	lprintk("-------------------------------------\n");
+	lprintk("%s/%d is trying to release lock (",
 		curr->comm, task_pid_nr(curr));
 	print_lockdep_cache(lock);
-	printk(") at:\n");
+	lprintk(") at:\n");
 	print_ip_sym(ip);
-	printk("but there are no more locks to release!\n");
-	printk("\nother info that might help us debug this:\n");
+	lprintk("but there are no more locks to release!\n");
+	lprintk("\nother info that might help us debug this:\n");
 	lockdep_print_held_locks(curr);
 
-	printk("\nstack backtrace:\n");
+	lprintk("\nstack backtrace:\n");
 	dump_stack();
 
 	return 0;
@@ -3487,11 +3503,11 @@ static void check_flags(unsigned long fl
 
 	if (irqs_disabled_flags(flags)) {
 		if (DEBUG_LOCKS_WARN_ON(current->hardirqs_enabled)) {
-			printk("possible reason: unannotated irqs-off.\n");
+			lprintk("possible reason: unannotated irqs-off.\n");
 		}
 	} else {
 		if (DEBUG_LOCKS_WARN_ON(!current->hardirqs_enabled)) {
-			printk("possible reason: unannotated irqs-on.\n");
+			lprintk("possible reason: unannotated irqs-on.\n");
 		}
 	}
 
@@ -3617,21 +3633,21 @@ print_lock_contention_bug(struct task_st
 	if (debug_locks_silent)
 		return 0;
 
-	printk("\n");
-	printk("=================================\n");
-	printk("[ BUG: bad contention detected! ]\n");
+	lprintk("\n");
+	lprintk("=================================\n");
+	lprintk("[ BUG: bad contention detected! ]\n");
 	print_kernel_ident();
-	printk("---------------------------------\n");
-	printk("%s/%d is trying to contend lock (",
+	lprintk("---------------------------------\n");
+	lprintk("%s/%d is trying to contend lock (",
 		curr->comm, task_pid_nr(curr));
 	print_lockdep_cache(lock);
-	printk(") at:\n");
+	lprintk(") at:\n");
 	print_ip_sym(ip);
-	printk("but there are no locks held!\n");
-	printk("\nother info that might help us debug this:\n");
+	lprintk("but there are no locks held!\n");
+	lprintk("\nother info that might help us debug this:\n");
 	lockdep_print_held_locks(curr);
 
-	printk("\nstack backtrace:\n");
+	lprintk("\nstack backtrace:\n");
 	dump_stack();
 
 	return 0;
@@ -3949,17 +3965,17 @@ void lockdep_init(void)
 
 void __init lockdep_info(void)
 {
-	printk("Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar\n");
+	lprintk("Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar\n");
 
-	printk("... MAX_LOCKDEP_SUBCLASSES:  %lu\n", MAX_LOCKDEP_SUBCLASSES);
-	printk("... MAX_LOCK_DEPTH:          %lu\n", MAX_LOCK_DEPTH);
-	printk("... MAX_LOCKDEP_KEYS:        %lu\n", MAX_LOCKDEP_KEYS);
-	printk("... CLASSHASH_SIZE:          %lu\n", CLASSHASH_SIZE);
-	printk("... MAX_LOCKDEP_ENTRIES:     %lu\n", MAX_LOCKDEP_ENTRIES);
-	printk("... MAX_LOCKDEP_CHAINS:      %lu\n", MAX_LOCKDEP_CHAINS);
-	printk("... CHAINHASH_SIZE:          %lu\n", CHAINHASH_SIZE);
+	lprintk("... MAX_LOCKDEP_SUBCLASSES:  %lu\n", MAX_LOCKDEP_SUBCLASSES);
+	lprintk("... MAX_LOCK_DEPTH:          %lu\n", MAX_LOCK_DEPTH);
+	lprintk("... MAX_LOCKDEP_KEYS:        %lu\n", MAX_LOCKDEP_KEYS);
+	lprintk("... CLASSHASH_SIZE:          %lu\n", CLASSHASH_SIZE);
+	lprintk("... MAX_LOCKDEP_ENTRIES:     %lu\n", MAX_LOCKDEP_ENTRIES);
+	lprintk("... MAX_LOCKDEP_CHAINS:      %lu\n", MAX_LOCKDEP_CHAINS);
+	lprintk("... CHAINHASH_SIZE:          %lu\n", CHAINHASH_SIZE);
 
-	printk(" memory used by lock dependency info: %lu kB\n",
+	lprintk(" memory used by lock dependency info: %lu kB\n",
 		(sizeof(struct lock_class) * MAX_LOCKDEP_KEYS +
 		sizeof(struct list_head) * CLASSHASH_SIZE +
 		sizeof(struct lock_list) * MAX_LOCKDEP_ENTRIES +
@@ -3971,14 +3987,14 @@ void __init lockdep_info(void)
 		) / 1024
 		);
 
-	printk(" per task-struct memory footprint: %lu bytes\n",
+	lprintk(" per task-struct memory footprint: %lu bytes\n",
 		sizeof(struct held_lock) * MAX_LOCK_DEPTH);
 
 #ifdef CONFIG_DEBUG_LOCKDEP
 	if (lockdep_init_error) {
-		printk("WARNING: lockdep init error! lock-%s was acquired"
+		lprintk("WARNING: lockdep init error! lock-%s was acquired"
 			"before lockdep_init\n", lock_init_error);
-		printk("Call stack leading to lockdep invocation was:\n");
+		lprintk("Call stack leading to lockdep invocation was:\n");
 		print_stack_trace(&lockdep_init_trace, 0);
 	}
 #endif
@@ -3993,17 +4009,17 @@ print_freed_lock_bug(struct task_struct 
 	if (debug_locks_silent)
 		return;
 
-	printk("\n");
-	printk("=========================\n");
-	printk("[ BUG: held lock freed! ]\n");
+	lprintk("\n");
+	lprintk("=========================\n");
+	lprintk("[ BUG: held lock freed! ]\n");
 	print_kernel_ident();
-	printk("-------------------------\n");
-	printk("%s/%d is freeing memory %p-%p, with a lock still held there!\n",
+	lprintk("-------------------------\n");
+	lprintk("%s/%d is freeing memory %p-%p, with a lock still held there!\n",
 		curr->comm, task_pid_nr(curr), mem_from, mem_to-1);
 	print_lock(hlock);
 	lockdep_print_held_locks(curr);
 
-	printk("\nstack backtrace:\n");
+	lprintk("\nstack backtrace:\n");
 	dump_stack();
 }
 
@@ -4051,16 +4067,16 @@ static void print_held_locks_bug(struct 
 	if (debug_locks_silent)
 		return;
 
-	printk("\n");
-	printk("=====================================\n");
-	printk("[ BUG: lock held at task exit time! ]\n");
+	lprintk("\n");
+	lprintk("=====================================\n");
+	lprintk("[ BUG: lock held at task exit time! ]\n");
 	print_kernel_ident();
-	printk("-------------------------------------\n");
-	printk("%s/%d is exiting with locks still held!\n",
+	lprintk("-------------------------------------\n");
+	lprintk("%s/%d is exiting with locks still held!\n",
 		curr->comm, task_pid_nr(curr));
 	lockdep_print_held_locks(curr);
 
-	printk("\nstack backtrace:\n");
+	lprintk("\nstack backtrace:\n");
 	dump_stack();
 }
 
@@ -4077,10 +4093,10 @@ void debug_show_all_locks(void)
 	int unlock = 1;
 
 	if (unlikely(!debug_locks)) {
-		printk("INFO: lockdep is turned off.\n");
+		lprintk("INFO: lockdep is turned off.\n");
 		return;
 	}
-	printk("\nShowing all locks held in the system:\n");
+	lprintk("\nShowing all locks held in the system:\n");
 
 	/*
 	 * Here we try to get the tasklist_lock as hard as possible,
@@ -4091,18 +4107,18 @@ void debug_show_all_locks(void)
 retry:
 	if (!read_trylock(&tasklist_lock)) {
 		if (count == 10)
-			printk("hm, tasklist_lock locked, retrying... ");
+			lprintk("hm, tasklist_lock locked, retrying... ");
 		if (count) {
 			count--;
-			printk(" #%d", 10-count);
+			lprintk(" #%d", 10-count);
 			mdelay(200);
 			goto retry;
 		}
-		printk(" ignoring it.\n");
+		lprintk(" ignoring it.\n");
 		unlock = 0;
 	} else {
 		if (count != 10)
-			printk(KERN_CONT " locked it.\n");
+			lprintk(KERN_CONT " locked it.\n");
 	}
 
 	do_each_thread(g, p) {
@@ -4120,8 +4136,8 @@ void debug_show_all_locks(void)
 				unlock = 1;
 	} while_each_thread(g, p);
 
-	printk("\n");
-	printk("=============================================\n\n");
+	lprintk("\n");
+	lprintk("=============================================\n\n");
 
 	if (unlock)
 		read_unlock(&tasklist_lock);
@@ -4135,7 +4151,7 @@ EXPORT_SYMBOL_GPL(debug_show_all_locks);
 void debug_show_held_locks(struct task_struct *task)
 {
 	if (unlikely(!debug_locks)) {
-		printk("INFO: lockdep is turned off.\n");
+		lprintk("INFO: lockdep is turned off.\n");
 		return;
 	}
 	lockdep_print_held_locks(task);
@@ -4149,12 +4165,12 @@ void lockdep_sys_exit(void)
 	if (unlikely(curr->lockdep_depth)) {
 		if (!debug_locks_off())
 			return;
-		printk("\n");
-		printk("================================================\n");
-		printk("[ BUG: lock held when returning to user space! ]\n");
+		lprintk("\n");
+		lprintk("================================================\n");
+		lprintk("[ BUG: lock held when returning to user space! ]\n");
 		print_kernel_ident();
-		printk("------------------------------------------------\n");
-		printk("%s/%d is leaving the kernel with locks still held!\n",
+		lprintk("------------------------------------------------\n");
+		lprintk("%s/%d is leaving the kernel with locks still held!\n",
 				curr->comm, curr->pid);
 		lockdep_print_held_locks(curr);
 	}
@@ -4169,14 +4185,14 @@ void lockdep_rcu_suspicious(const char *
 		return;
 #endif /* #ifdef CONFIG_PROVE_RCU_REPEATEDLY */
 	/* Note: the following can be executed concurrently, so be careful. */
-	printk("\n");
-	printk("===============================\n");
-	printk("[ INFO: suspicious RCU usage. ]\n");
+	lprintk("\n");
+	lprintk("===============================\n");
+	lprintk("[ INFO: suspicious RCU usage. ]\n");
 	print_kernel_ident();
-	printk("-------------------------------\n");
-	printk("%s:%d %s!\n", file, line, s);
-	printk("\nother info that might help us debug this:\n\n");
-	printk("\nrcu_scheduler_active = %d, debug_locks = %d\n", rcu_scheduler_active, debug_locks);
+	lprintk("-------------------------------\n");
+	lprintk("%s:%d %s!\n", file, line, s);
+	lprintk("\nother info that might help us debug this:\n\n");
+	lprintk("\nrcu_scheduler_active = %d, debug_locks = %d\n", rcu_scheduler_active, debug_locks);
 
 	/*
 	 * If a CPU is in the RCU-free window in idle (ie: in the section
@@ -4197,10 +4213,10 @@ void lockdep_rcu_suspicious(const char *
 	 * rcu_read_lock_bh() and so on from extended quiescent states.
 	 */
 	if (rcu_is_cpu_idle())
-		printk("RCU used illegally from extended quiescent state!\n");
+		lprintk("RCU used illegally from extended quiescent state!\n");
 
 	lockdep_print_held_locks(curr);
-	printk("\nstack backtrace:\n");
+	lprintk("\nstack backtrace:\n");
 	dump_stack();
 }
 EXPORT_SYMBOL_GPL(lockdep_rcu_suspicious);

[RFC][PATCH 3/7] printk, lockdep: Remove lockdep_off() usage

[Peter Zijlstra]

[-- Attachment #1: printk-remove-lockdep_off-4.patch --]
[-- Type: text/plain, Size: 608 bytes --]

Now that we've removed all reasons for disabling lockdep in the printk
code, stop doing so.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/printk.c |    2 --
 1 file changed, 2 deletions(-)
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -884,7 +884,6 @@ asmlinkage int vprintk(const char *fmt, 
 		zap_locks();
 	}
 
-	lockdep_off();
 	raw_spin_lock(&logbuf_lock);
 	printk_cpu = this_cpu;
 
@@ -981,7 +980,6 @@ asmlinkage int vprintk(const char *fmt, 
 	if (console_trylock_for_printk(this_cpu))
 		console_unlock();
 
-	lockdep_on();
 out_restore_irqs:
 	local_irq_restore(flags);
 

[RFC][PATCH 4/7] printk: Rework printk recursion

[Peter Zijlstra]

[-- Attachment #1: printk-frobbery.patch --]
[-- Type: text/plain, Size: 6189 bytes --]

The current printk recursion detection mechanism has a couple of
problems:
 - it relies on being serialized on logbuf_lock
 - zap_locks() totally wrecks any and all output except maybe
   the recusion, but not even that in some cases.

The first problem is easy to understand and easy to fix, when the lock
operation recurses the recursion state is not detected and we deadlock
due to nested locking. Simply replace the printk_cpu thing with a
per-cpu recursion counter.

The second problem is slightly more difficult. The problem with
zap_locks() is that they re-init the locks possibly concurrently with
a user. The idea is that the current thread gets a 'fresh' unlocked
lock so that it can print its msgs, however if the concurrent printk()
cpu does raw_spin_unlock() it corrupts the spinlock state such that
nobody can print (tail is ahead of the head, *FAIL*).

Cure this by avoiding the logbuf_lock and console_sem alltogether for
recursive printk()s by using a separate per-cpu buffer to store the
msg in before dumping it out to the console.

As an extra reliability feature it prefers to use the early_console
when its available to avoid console->console nesting and resulting
deadlocks.

As a side effect of all this, recursive printk()s will not appear in
the logbuf and will thus be invisible for kmsg_dump(). The advantage
is a much more robust error path for normal consoles.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/printk.c |   79 +++++++++++++++++++++++++++++---------------------------
 1 file changed, 41 insertions(+), 38 deletions(-)
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -497,10 +497,7 @@ void kdb_syslog_data(char *syslog_data[4
 }
 #endif	/* CONFIG_KGDB_KDB */
 
-/*
- * Call the console drivers on a range of log_buf
- */
-static void __call_console_drivers(unsigned start, unsigned end)
+static void con_write(const char *buf, unsigned len)
 {
 	struct console *con;
 
@@ -510,22 +507,25 @@ static void __call_console_drivers(unsig
 		if ((con->flags & CON_ENABLED) && con->write &&
 				(cpu_online(smp_processor_id()) ||
 				(con->flags & CON_ANYTIME)))
-			con->write(con, &LOG_BUF(start), end - start);
+			con->write(con, buf, len);
 	}
 }
 
+#define PRINTK_BUF_SIZE 512
+static DEFINE_PER_CPU(char [PRINTK_BUF_SIZE], printk_cpu_buf);
+
 #ifdef CONFIG_EARLY_PRINTK
 struct console *early_console;
 
 asmlinkage int early_vprintk(const char *fmt, va_list ap)
 {
-	char buf[512];
-	int n = vscnprintf(buf, sizeof(buf), fmt, ap);
+	char *buf = get_cpu_var(printk_cpu_buf);
+	int n = vscnprintf(buf, PRINTK_BUF_SIZE, fmt, ap);
 	if (early_console)
 		early_console->write(early_console, buf, n);
 	else
 		n = 0;
-
+	put_cpu_var(printk_cpu_buf);
 	return n;
 }
 
@@ -542,6 +542,20 @@ asmlinkage int early_printk(const char *
 }
 #endif
 
+static int recursive_vprintk(const char *fmt, va_list ap)
+{
+	char *buf = get_cpu_var(printk_cpu_buf);
+	int n = vscnprintf(buf, PRINTK_BUF_SIZE, fmt, ap);
+#ifdef CONFIG_EARLY_PRINTK
+	if (early_console)
+		early_console->write(early_console, buf, n);
+	else
+#endif
+		con_write(buf, n);
+	put_cpu_var(printk_cpu_buf);
+	return n;
+}
+
 static int __read_mostly ignore_loglevel;
 
 static int __init ignore_loglevel_setup(char *str)
@@ -558,6 +572,14 @@ MODULE_PARM_DESC(ignore_loglevel, "ignor
 	"print all kernel messages to the console.");
 
 /*
+ * Call the console drivers on a range of log_buf
+ */
+static void __call_console_drivers(unsigned start, unsigned end)
+{
+	con_write(&LOG_BUF(start), end - start);
+}
+
+/*
  * Write out chars from start to end - 1 inclusive
  */
 static void _call_console_drivers(unsigned start,
@@ -694,28 +716,6 @@ static void emit_log_char(char c)
 		logged_chars++;
 }
 
-/*
- * Zap console related locks when oopsing. Only zap at most once
- * every 10 seconds, to leave time for slow consoles to print a
- * full oops.
- */
-static void zap_locks(void)
-{
-	static unsigned long oops_timestamp;
-
-	if (time_after_eq(jiffies, oops_timestamp) &&
-			!time_after(jiffies, oops_timestamp + 30 * HZ))
-		return;
-
-	oops_timestamp = jiffies;
-
-	debug_locks_off();
-	/* If a crash is occurring, make sure we can't deadlock */
-	raw_spin_lock_init(&logbuf_lock);
-	/* And make sure that we print immediately */
-	sema_init(&console_sem, 1);
-}
-
 #if defined(CONFIG_PRINTK_TIME)
 static int printk_time = 1;
 #else
@@ -777,9 +777,6 @@ asmlinkage int printk(const char *fmt, .
 	return r;
 }
 
-/* cpu currently holding logbuf_lock */
-static volatile unsigned int printk_cpu = UINT_MAX;
-
 /*
  * Can we actually use the console at this time on this cpu?
  *
@@ -823,7 +820,6 @@ static int console_trylock_for_printk(un
 			retval = 0;
 		}
 	}
-	printk_cpu = UINT_MAX;
 	if (wake)
 		up(&console_sem);
 	raw_spin_unlock(&logbuf_lock);
@@ -849,6 +845,9 @@ static inline void printk_delay(void)
 	}
 }
 
+static DEFINE_PER_CPU(int, printk_recursion);
+
+
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
 	int printed_len = 0;
@@ -869,7 +868,7 @@ asmlinkage int vprintk(const char *fmt, 
 	/*
 	 * Ouch, printk recursed into itself!
 	 */
-	if (unlikely(printk_cpu == this_cpu)) {
+	if (unlikely(__this_cpu_read(printk_recursion))) {
 		/*
 		 * If a crash is occurring during printk() on this CPU,
 		 * then try to get the crash message out but make sure
@@ -881,11 +880,14 @@ asmlinkage int vprintk(const char *fmt, 
 			recursion_bug = 1;
 			goto out_restore_irqs;
 		}
-		zap_locks();
+
+		debug_locks_off();
+		recursive_vprintk(fmt, args);
+		goto out_restore_irqs;
 	}
+	__this_cpu_inc(printk_recursion);
 
 	raw_spin_lock(&logbuf_lock);
-	printk_cpu = this_cpu;
 
 	if (recursion_bug) {
 		recursion_bug = 0;
@@ -947,7 +949,7 @@ asmlinkage int vprintk(const char *fmt, 
 				unsigned long long t;
 				unsigned long nanosec_rem;
 
-				t = cpu_clock(printk_cpu);
+				t = sched_clock_cpu(this_cpu);
 				nanosec_rem = do_div(t, 1000000000);
 				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
 						(unsigned long) t,
@@ -980,6 +982,7 @@ asmlinkage int vprintk(const char *fmt, 
 	if (console_trylock_for_printk(this_cpu))
 		console_unlock();
 
+	__this_cpu_dec(printk_recursion);
 out_restore_irqs:
 	local_irq_restore(flags);
 

[RFC][PATCH 5/7] semaphore: Pull wakeup out from under sem->lock

[Peter Zijlstra]

[-- Attachment #1: sem-vs-printk.patch --]
[-- Type: text/plain, Size: 2677 bytes --]

Rather horrid patch this, surely there's a better way..

rcuc/1/13 is trying to acquire lock:
 ((console_sem).lock){-.-...}, at:
but task is already holding lock:
 (&rt_rq->rt_runtime_lock){-.....}, at:
which lock already depends on the new lock.

the existing dependency chain (in reverse order) is:

 -> #3 (&rt_rq->rt_runtime_lock){-.....}:
 -> #2 (&rq->lock){-.-.-.}:
 -> #1 (&p->pi_lock){-.-.-.}:
 -> #0 ((console_sem).lock){-.-...}:

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/semaphore.c |   46 +++++++++++++++++++++++++---------------------
 1 file changed, 25 insertions(+), 21 deletions(-)
--- a/kernel/semaphore.c
+++ b/kernel/semaphore.c
@@ -168,6 +168,14 @@ int down_timeout(struct semaphore *sem, 
 }
 EXPORT_SYMBOL(down_timeout);
 
+/* Functions for the contended case */
+
+struct semaphore_waiter {
+	struct list_head list;
+	struct task_struct *task;
+	int up;
+};
+
 /**
  * up - release the semaphore
  * @sem: the semaphore to release
@@ -177,32 +185,36 @@ EXPORT_SYMBOL(down_timeout);
  */
 void up(struct semaphore *sem)
 {
+	struct semaphore_waiter *waiter;
+	struct task_struct *task;
 	unsigned long flags;
 
 	raw_spin_lock_irqsave(&sem->lock, flags);
-	if (likely(list_empty(&sem->wait_list)))
+	if (likely(list_empty(&sem->wait_list))) {
 		sem->count++;
-	else
-		__up(sem);
+		raw_spin_unlock_irqrestore(&sem->lock, flags);
+		return;
+	}
+
+	waiter = list_first_entry(&sem->wait_list, struct semaphore_waiter, list);
+	task = waiter->task;
+	list_del(&waiter->list);
+	waiter->up = 1;
+	get_task_struct(task);
 	raw_spin_unlock_irqrestore(&sem->lock, flags);
+
+	wake_up_process(task);
+	put_task_struct(task);
 }
 EXPORT_SYMBOL(up);
 
-/* Functions for the contended case */
-
-struct semaphore_waiter {
-	struct list_head list;
-	struct task_struct *task;
-	int up;
-};
-
 /*
  * Because this function is inlined, the 'state' parameter will be
  * constant, and thus optimised away by the compiler.  Likewise the
  * 'timeout' parameter for the cases without timeouts.
  */
-static inline int __sched __down_common(struct semaphore *sem, long state,
-								long timeout)
+static inline
+int __sched __down_common(struct semaphore *sem, long state, long timeout)
 {
 	struct task_struct *task = current;
 	struct semaphore_waiter waiter;
@@ -253,11 +265,3 @@ static noinline int __sched __down_timeo
 	return __down_common(sem, TASK_UNINTERRUPTIBLE, jiffies);
 }
 
-static noinline void __sched __up(struct semaphore *sem)
-{
-	struct semaphore_waiter *waiter = list_first_entry(&sem->wait_list,
-						struct semaphore_waiter, list);
-	list_del(&waiter->list);
-	waiter->up = 1;
-	wake_up_process(waiter->task);
-}

[RFC][PATCH 6/7] printk: Poke printk extra hard

[Peter Zijlstra]

[-- Attachment #1: printk-debug.patch --]
[-- Type: text/plain, Size: 1902 bytes --]


Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 include/linux/sched.h |    2 ++
 init/main.c           |    1 +
 kernel/sched/core.c   |   18 ++++++++++++++++++
 lib/Kconfig.debug     |   12 ++++++++++++
 4 files changed, 33 insertions(+)
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -2742,6 +2742,8 @@ static inline unsigned long rlimit_max(u
 	return task_rlimit_max(current, limit);
 }
 
+extern void printk_init(void);
+
 #endif /* __KERNEL__ */
 
 #endif
--- a/init/main.c
+++ b/init/main.c
@@ -591,6 +591,7 @@ asmlinkage void __init start_kernel(void
 		initrd_start = 0;
 	}
 #endif
+	printk_init();
 	page_cgroup_init();
 	debug_objects_mem_init();
 	kmemleak_init();
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -6953,6 +6953,24 @@ void __init sched_init(void)
 	scheduler_running = 1;
 }
 
+#ifdef CONFIG_PRINTK_DEBUG
+void printk_init(void)
+{
+	struct rq *rq;
+	unsigned long flags;
+
+	local_irq_save(flags);
+	rq = this_rq();
+	raw_spin_lock(&rq->lock);
+	printk(KERN_DEBUG "printk: echo echo echo..\n");
+	raw_spin_unlock(&rq->lock);
+	local_irq_restore(flags);
+
+}
+#else
+void printk_init(void) { };
+#endif
+
 #ifdef CONFIG_DEBUG_ATOMIC_SLEEP
 static inline int preempt_count_equals(int preempt_offset)
 {
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -644,6 +644,18 @@ config DEBUG_LOCKDEP
 	  additional runtime checks to debug itself, at the price
 	  of more runtime overhead.
 
+config PRINTK_DEBUG
+	bool "Printk() wakeup debugging"
+	depends on PROVE_LOCKING
+	default n
+	help
+	 This feature registers a boot time dependency between rq->lock and
+	 printk(), this is useful to determine if your particular console
+	 setup issues wakeups while writing to the console. This is interesting
+	 to know since those that do are less reliable for debugging purposes.
+
+	 Say N if you are unsure.
+
 config TRACE_IRQFLAGS
 	bool
 	help

Re: [RFC][PATCH 6/7] printk: Poke printk extra hard

[Linus Torvalds]

On Wed, Dec 21, 2011 at 2:57 AM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
>
>
> +#ifdef CONFIG_PRINTK_DEBUG
> +void printk_init(void)
> +{
> +       struct rq *rq;
> +       unsigned long flags;
> +
> +       local_irq_save(flags);
> +       rq = this_rq();
> +       raw_spin_lock(&rq->lock);
> +       printk(KERN_DEBUG "printk: echo echo echo..\n");
> +       raw_spin_unlock(&rq->lock);
> +       local_irq_restore(flags);

Ok, I can't really say that I think this is worth a config option like this.

Maybe an example module or something?

And I don't know *why*, but my immediate reaction to the message was
that it either should be serious and say what it tested ("printk()
works under rq lock"), or it should say "Bork bork bork". "echo echo
echo" sounds just stupid.

                 Linus

Re: [RFC][PATCH 6/7] printk: Poke printk extra hard

[Ingo Molnar]

* Linus Torvalds <torvalds@linux-foundation.org> wrote:

> On Wed, Dec 21, 2011 at 2:57 AM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> >
> >
> > +#ifdef CONFIG_PRINTK_DEBUG
> > +void printk_init(void)
> > +{
> > +       struct rq *rq;
> > +       unsigned long flags;
> > +
> > +       local_irq_save(flags);
> > +       rq = this_rq();
> > +       raw_spin_lock(&rq->lock);
> > +       printk(KERN_DEBUG "printk: echo echo echo..\n");
> > +       raw_spin_unlock(&rq->lock);
> > +       local_irq_restore(flags);
> 
> Ok, I can't really say that I think this is worth a config option like this.
> 
> Maybe an example module or something?
> 
> And I don't know *why*, but my immediate reaction to the 
> message was that it either should be serious and say what it 
> tested ("printk() works under rq lock"), or it should say 
> "Bork bork bork". "echo echo echo" sounds just stupid.

We could perhaps use the standard mike test message:

  printk: Tap, tap, is this thing on?

Thanks,

	Ingo

Re: [RFC][PATCH 6/7] printk: Poke printk extra hard

[Peter Zijlstra]

On Thu, 2011-12-22 at 08:02 +0100, Ingo Molnar wrote:
> * Linus Torvalds <torvalds@linux-foundation.org> wrote:
> 
> > On Wed, Dec 21, 2011 at 2:57 AM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> > >
> > >
> > > +#ifdef CONFIG_PRINTK_DEBUG
> > > +void printk_init(void)
> > > +{
> > > +       struct rq *rq;
> > > +       unsigned long flags;
> > > +
> > > +       local_irq_save(flags);
> > > +       rq = this_rq();
> > > +       raw_spin_lock(&rq->lock);
> > > +       printk(KERN_DEBUG "printk: echo echo echo..\n");
> > > +       raw_spin_unlock(&rq->lock);
> > > +       local_irq_restore(flags);
> > 
> > Ok, I can't really say that I think this is worth a config option like this.
> > 
> > Maybe an example module or something?

I really really really don't want to expose struct rq to modules, that's
just asking for trouble. But yeah, I know what you mean with not being
worth the config option, but then, I thought I might as well post it, it
can't be more horrible than the sem patch, can it ;-)

> > And I don't know *why*, but my immediate reaction to the 
> > message was that it either should be serious and say what it 
> > tested ("printk() works under rq lock"), or it should say 
> > "Bork bork bork". "echo echo echo" sounds just stupid.
> 
> We could perhaps use the standard mike test message:
> 
>   printk: Tap, tap, is this thing on?

Yeah, I clearly wasn't creative enough, I'm tempted to go with Linus'
suggestion though.

Re: [RFC][PATCH 6/7] printk: Poke printk extra hard

[Ingo Molnar]

* Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:

> On Thu, 2011-12-22 at 08:02 +0100, Ingo Molnar wrote:
> > * Linus Torvalds <torvalds@linux-foundation.org> wrote:
> > 
> > > On Wed, Dec 21, 2011 at 2:57 AM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> > > >
> > > >
> > > > +#ifdef CONFIG_PRINTK_DEBUG
> > > > +void printk_init(void)
> > > > +{
> > > > +       struct rq *rq;
> > > > +       unsigned long flags;
> > > > +
> > > > +       local_irq_save(flags);
> > > > +       rq = this_rq();
> > > > +       raw_spin_lock(&rq->lock);
> > > > +       printk(KERN_DEBUG "printk: echo echo echo..\n");
> > > > +       raw_spin_unlock(&rq->lock);
> > > > +       local_irq_restore(flags);
> > > 
> > > Ok, I can't really say that I think this is worth a config option like this.
> > > 
> > > Maybe an example module or something?
> 
> I really really really don't want to expose struct rq to 
> modules, that's just asking for trouble. But yeah, I know what 
> you mean with not being worth the config option, but then, I 
> thought I might as well post it, it can't be more horrible 
> than the sem patch, can it ;-)

Could be made part of the locking self-tests - that way it does 
not add an extra config option! ;-)

Thanks,

	Ingo

Re: [RFC][PATCH 6/7] printk: Poke printk extra hard

[Peter Zijlstra]

On Thu, 2011-12-22 at 10:03 +0100, Ingo Molnar wrote:

> Could be made part of the locking self-tests - that way it does 
> not add an extra config option! ;-)

Fair chance it will blow up and disable lockdep for pretty much every
console implementation out there, except 8250serial when used in
conjunction with all patches in this thread.

Maybe not the normal vga console, but I haven't tried on a machine that
has a monitor attached yet (they're usually not on remote power switches
and I'm too lazy to reach over and press reset).

Re: [RFC][PATCH 6/7] printk: Poke printk extra hard

[Ingo Molnar]

* Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:

> On Thu, 2011-12-22 at 10:03 +0100, Ingo Molnar wrote:
> 
> > Could be made part of the locking self-tests - that way it 
> > does not add an extra config option! ;-)
> 
> Fair chance it will blow up and disable lockdep for pretty 
> much every console implementation out there, except 8250serial 
> when used in conjunction with all patches in this thread.

If it blows up without being fixed then it's not a good idea.

> Maybe not the normal vga console, but I haven't tried on a 
> machine that has a monitor attached yet (they're usually not 
> on remote power switches and I'm too lazy to reach over and 
> press reset).

The VGA console does not require a monitor attached.

Thanks,

	Ingo

Re: [RFC][PATCH 6/7] printk: Poke printk extra hard

[Peter Zijlstra]

On Thu, 2011-12-22 at 11:15 +0100, Ingo Molnar wrote:
> * Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> 
> > On Thu, 2011-12-22 at 10:03 +0100, Ingo Molnar wrote:
> > 
> > > Could be made part of the locking self-tests - that way it 
> > > does not add an extra config option! ;-)
> > 
> > Fair chance it will blow up and disable lockdep for pretty 
> > much every console implementation out there, except 8250serial 
> > when used in conjunction with all patches in this thread.
> 
> If it blows up without being fixed then it's not a good idea.

Right, and we can't fix them, its 'allowed'. I just wanted to make sure
I had the debug option so that I can debug my own serial consoles to
make sure they do behave nicely.

> > Maybe not the normal vga console, but I haven't tried on a 
> > machine that has a monitor attached yet (they're usually not 
> > on remote power switches and I'm too lazy to reach over and 
> > press reset).
> 
> The VGA console does not require a monitor attached.

Ah, right, I could just add it to the console list together with the
serial thing.

[RFC][PATCH 7/7] serial, 8250: Mostly avoid wakeups from under port->lock

[Peter Zijlstra]

[-- Attachment #1: 8250.patch --]
[-- Type: text/plain, Size: 4882 bytes --]

While not a strict requirement (anymore), it is nice not to issue
wakeups (or have them connected by locks) from console output.

This patch avoids doing most wakeups from under port->lock, which is
connected to 8250console_write(). Only seriously challenged UARTs will
still do the wakeup, but since I don't actually have such a creature,
I'm less inclined to fix it up.

  [ INFO: possible circular locking dependency detected ]
  3.2.0-rc5-tip+ #185 Tainted: G        W
  -------------------------------------------------------
  watchdog/0/10 is trying to acquire lock:
   ((console_sem).lock){-.-...}, at:
  but task is already holding lock:
   (&rt_rq->rt_runtime_lock){-.-...}, at:
  which lock already depends on the new lock.

  the existing dependency chain (in reverse order) is:

   -> #5 (&rt_rq->rt_runtime_lock){-.-...}:
   -> #4 (&rq->lock){-.-.-.}:
   -> #3 (&p->pi_lock){-.-.-.}:
   -> #2 (&tty->write_wait){-.-...}:
   -> #1 (&port_lock_key){-.-...}:
   -> #0 ((console_sem).lock){-.-...}:

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 drivers/tty/serial/8250.c |   62 +++++++++++++++++++++++++++++++++++++---------
 1 file changed, 50 insertions(+), 12 deletions(-)
--- a/drivers/tty/serial/8250.c
+++ b/drivers/tty/serial/8250.c
@@ -1326,7 +1326,7 @@ static void serial8250_stop_tx(struct ua
 	}
 }
 
-static void transmit_chars(struct uart_8250_port *up);
+static int transmit_chars(struct uart_8250_port *up);
 
 static void serial8250_start_tx(struct uart_port *port)
 {
@@ -1343,8 +1343,15 @@ static void serial8250_start_tx(struct u
 			up->lsr_saved_flags |= lsr & LSR_SAVE_FLAGS;
 			if ((up->port.type == PORT_RM9000) ?
 				(lsr & UART_LSR_THRE) :
-				(lsr & UART_LSR_TEMT))
-				transmit_chars(up);
+				(lsr & UART_LSR_TEMT)) {
+				/*
+				 * This will nest a wakeup inside port->lock
+				 * and is thus less reliable than a well
+				 * functioning uart.
+				 */
+				if (transmit_chars(up))
+					uart_write_wakeup(&up->port);
+			}
 		}
 	}
 
@@ -1484,24 +1491,25 @@ receive_chars(struct uart_8250_port *up,
 	*status = lsr;
 }
 
-static void transmit_chars(struct uart_8250_port *up)
+static int transmit_chars(struct uart_8250_port *up)
 {
 	struct circ_buf *xmit = &up->port.state->xmit;
 	int count;
+	int ret = 0;
 
 	if (up->port.x_char) {
 		serial_outp(up, UART_TX, up->port.x_char);
 		up->port.icount.tx++;
 		up->port.x_char = 0;
-		return;
+		goto out;
 	}
 	if (uart_tx_stopped(&up->port)) {
 		serial8250_stop_tx(&up->port);
-		return;
+		goto out;
 	}
 	if (uart_circ_empty(xmit)) {
 		__stop_tx(up);
-		return;
+		goto out;
 	}
 
 	count = up->tx_loadsz;
@@ -1514,12 +1522,15 @@ static void transmit_chars(struct uart_8
 	} while (--count > 0);
 
 	if (uart_circ_chars_pending(xmit) < WAKEUP_CHARS)
-		uart_write_wakeup(&up->port);
+		ret = 1;
 
 	DEBUG_INTR("THRE...");
 
 	if (uart_circ_empty(xmit))
 		__stop_tx(up);
+
+out:
+	return ret;
 }
 
 static unsigned int check_modem_status(struct uart_8250_port *up)
@@ -1546,12 +1557,38 @@ static unsigned int check_modem_status(s
 }
 
 /*
+ * Unlocks port->lock and issues a uart_write_wakeup() outside of the lock.
+ *
+ * Duplicates parts of uart_write_wakeup().
+ */
+static void
+port_unlock_and_wake(struct uart_8250_port *up, unsigned long flags, int wake)
+{
+	struct uart_state *state;
+	struct tty_struct *tty;
+
+	if (!wake) {
+		spin_unlock_irqrestore(&up->port.lock, flags);
+		return;
+	}
+
+	state = up->port.state;
+	BUG_ON(!state);
+	tty = state->port.tty;
+	tty_kref_get(tty);
+	spin_unlock_irqrestore(&up->port.lock, flags);
+	tty_wakeup(tty);
+	tty_kref_put(tty);
+}
+
+/*
  * This handles the interrupt from one port.
  */
 static void serial8250_handle_port(struct uart_8250_port *up)
 {
 	unsigned int status;
 	unsigned long flags;
+	int wakeup = 0;
 
 	spin_lock_irqsave(&up->port.lock, flags);
 
@@ -1563,9 +1600,9 @@ static void serial8250_handle_port(struc
 		receive_chars(up, &status);
 	check_modem_status(up);
 	if (status & UART_LSR_THRE)
-		transmit_chars(up);
+		wakeup = transmit_chars(up);
 
-	spin_unlock_irqrestore(&up->port.lock, flags);
+	port_unlock_and_wake(up, flags, wakeup);
 }
 
 int serial8250_handle_irq(struct uart_port *port, unsigned int iir)
@@ -1771,6 +1808,7 @@ static void serial8250_backup_timeout(un
 	struct uart_8250_port *up = (struct uart_8250_port *)data;
 	unsigned int iir, ier = 0, lsr;
 	unsigned long flags;
+	int wakeup = 0;
 
 	spin_lock_irqsave(&up->port.lock, flags);
 
@@ -1801,12 +1839,12 @@ static void serial8250_backup_timeout(un
 	}
 
 	if (!(iir & UART_IIR_NO_INT))
-		transmit_chars(up);
+		wakeup = transmit_chars(up);
 
 	if (is_real_interrupt(up->port.irq))
 		serial_out(up, UART_IER, ier);
 
-	spin_unlock_irqrestore(&up->port.lock, flags);
+	port_unlock_and_wake(up, flags, wakeup);
 
 	/* Standard timer interval plus 0.2s to keep the port running */
 	mod_timer(&up->timer,

Re: [RFC][PATCH 7/7] serial, 8250: Mostly avoid wakeups from under port->lock

[Alan Cox]

On Wed, 21 Dec 2011 11:57:46 +0100
Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:

> While not a strict requirement (anymore), it is nice not to issue
> wakeups (or have them connected by locks) from console output.
> 
> This patch avoids doing most wakeups from under port->lock, which is
> connected to 8250console_write(). Only seriously challenged UARTs will
> still do the wakeup, but since I don't actually have such a creature,
> I'm less inclined to fix it up.

Gak..

> +	BUG_ON(!state);
> +	tty = state->port.tty;
> +	tty_kref_get(tty);
> +	spin_unlock_irqrestore(&up->port.lock, flags);
> +	tty_wakeup(tty);
> +	tty_kref_put(tty);

driver innards shouldn't know this stuff and this makes it worse rather
than cleaning it up

The basic idea looks fine but I really don't want magic lock hackery in
the 8250 driver. We need a way of generalising this so the code is
cleaner and the locking internal knowledge stays out of the driver itself.

Also I think it's probably buggy - sending the x_char is forward progress
so probably needs to cause a wakeup.

So for the moment NAK, but worthy of figuring out how to do it right

Re: [RFC][PATCH 7/7] serial, 8250: Mostly avoid wakeups from under port->lock

[Peter Zijlstra]

On Wed, 2011-12-21 at 16:03 +0000, Alan Cox wrote:

> > +	BUG_ON(!state);
> > +	tty = state->port.tty;
> > +	tty_kref_get(tty);
> > +	spin_unlock_irqrestore(&up->port.lock, flags);
> > +	tty_wakeup(tty);
> > +	tty_kref_put(tty);
> 
> driver innards shouldn't know this stuff and this makes it worse rather
> than cleaning it up

Fair enough, if I can push it into serial_core.c I can probably fix that
one weird case as well, I couldn't inside the 8250 driver because the
port lock was taken by the serial core code.

> The basic idea looks fine but I really don't want magic lock hackery in
> the 8250 driver. We need a way of generalising this so the code is
> cleaner and the locking internal knowledge stays out of the driver itself.
> 
> Also I think it's probably buggy - sending the x_char is forward progress
> so probably needs to cause a wakeup.

Could you explain that more, its not actually connecting with any
neurons..

> So for the moment NAK, but worthy of figuring out how to do it right

OK, will try and see if I can poke at it a level upwards.. 

Re: [RFC][PATCH 7/7] serial, 8250: Mostly avoid wakeups from under port->lock

[Peter Zijlstra]

On Wed, 2011-12-21 at 17:22 +0100, Peter Zijlstra wrote:

> Could you explain that more, its not actually connecting with any
> neurons..

Note that I don't actually know how uarts work. So telling me to go read
that fine^Weffin' manual/wikipedia page is a good option.

I found me this page:

 http://www.lammertbies.nl/comm/info/serial-uart.html

and I guess I'll read it and pay extra attention to the flow control
part, since I found in serial_core.h that x_char is xon/xoff related.

Re: [RFC][PATCH 7/7] serial, 8250: Mostly avoid wakeups from under port->lock

[Alan Cox]

> > Also I think it's probably buggy - sending the x_char is forward progress
> > so probably needs to cause a wakeup.
> 
> Could you explain that more, its not actually connecting with any
> neurons..

The tty output queue is the ring buffer + one byte (x_char). It's
effectively two priority queues one of which is 1 byte long and high
priority, the other of which is low priority.

> > So for the moment NAK, but worthy of figuring out how to do it right
> 
> OK, will try and see if I can poke at it a level upwards.. 

I think that is the right magic - and also means all the embedded
consoles might be poked the right way.

Re: [RFC][PATCH 0/7] improve printk reliability

[Peter Zijlstra]

On Wed, 2011-12-21 at 11:57 +0100, Peter Zijlstra wrote:
> Hi,
> 
> So these are my current efforts to make my own console output more
> reliable. I've hit every deadlock described in this series and a few
> more.
> 
> With these patches applied I can printk() and WARN() from inside 
> scheduler context and not have my machine deadlock, even without the 
> aid of early_printk().
> 
> While I'll go an remove the sole printk() I found in the scheduler
> so that we don't have to rely on the console doing this, it is good
> to have a reliable console that can do this.
> 
> As it stands some of the patches, the semaphore one in particular,
> are really too ugly to live so I won't push those but wanted to share
> anyway.
> 
> Debugging this was 'fun', and I really hope to not have to do it
> again :-)

Also, these patches enable lockdep over printk(), allowing lockdep to
detect previously undetected deadlocks with console implementations,
irrespective of rq->lock.