printk() vs tty_io

printk() vs tty_io

[Peter Zijlstra]

Hi tty folks,

I've been poking at reducing the constraints on printk(), like make it
work under rq->lock etc..

Aside from a fwd port of the patch that abuses the console_sem.lock:
https://lkml.org/lkml/2011/6/9/298 and a few other not so very pretty
patches, I ran into the following lockdep splat (using a not so very
pretty lockdep early_printk() patch):

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){-.-...}:

It turns out that writing to a console does wakeups due to tty_io.c.

My question is basically, is there a feasible way around doing these
wakeups from the console::write() path? Everything I thought of was
really quite horrible... and very likely would break stuff since I'm not
that well versed in the whole tty thing.

Re: printk() vs tty_io

[Linus Torvalds]

On Tue, Dec 13, 2011 at 11:33 AM, Peter Zijlstra <peterz@infradead.org> wrote:
>
> I've been poking at reducing the constraints on printk(), like make it
> work under rq->lock etc..

You aren't supposed register a console that wakes things up. But the
only console that honors that afaik is the traditional vt console.
*Maybe* the network console, I didn't check.

I *assume* you only get this lockdep warning if you have a serial console?

                       Linus

Re: printk() vs tty_io

[Ingo Molnar]

* Peter Zijlstra <peterz@infradead.org> wrote:

> Hi tty folks,
> 
> I've been poking at reducing the constraints on printk(), like make it
> work under rq->lock etc..
> 
> Aside from a fwd port of the patch that abuses the 
> console_sem.lock: https://lkml.org/lkml/2011/6/9/298 and a few 
> other not so very pretty patches, I ran into the following 
> lockdep splat (using a not so very pretty lockdep 
> early_printk() patch):

btw., would be nice to also somehow realeasify those debug hacks 
to preserve them for eternity - doing all lockdep output as 
earlyprintk while keeping printks working is a great way to 
debug printk() itself.

Those printk lockups also took a *lot* of time for me to bisect.

Thanks,

	Ingo

Re: printk() vs tty_io

[Peter Zijlstra]

On Tue, 2011-12-13 at 15:52 -0800, Linus Torvalds wrote:
> On Tue, Dec 13, 2011 at 11:33 AM, Peter Zijlstra <peterz@infradead.org> wrote:
> >
> > I've been poking at reducing the constraints on printk(), like make it
> > work under rq->lock etc..
> 
> You aren't supposed register a console that wakes things up. But the
> only console that honors that afaik is the traditional vt console.
> *Maybe* the network console, I didn't check.
> 
> I *assume* you only get this lockdep warning if you have a serial console?

I only ever use serial, I'll try and have a go at reproducing any of
this on a machine that actually has a screen attached.

Anyway, would it make any sense to start enforcing this 'rule'? Can we
reasonably make the serial stuff not wake things? Let alone the
fbdev/ksm consoles that seem popular these days.

Thing is, if everybody and their dog are using ksm, and we cannot make
ksm console wake-free, there's a very limited point to my endeavor to
make printk() work under rq->lock etc..

[PATCH] arch, early_printk: Consolidate early_printk() implementations

[Peter Zijlstra]

Subject: arch, early_printk: Consolidate early_printk() implementations
From: Thomas Gleixner <tglx@linutronix.de>
Date: Sat Jul 23 11:04:08 2011 +0200


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

Index: linux-2.6/arch/arm/kernel/early_printk.c
===================================================================
--- linux-2.6.orig/arch/arm/kernel/early_printk.c
+++ linux-2.6/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;
 }
 
Index: linux-2.6/arch/blackfin/kernel/early_printk.c
===================================================================
--- linux-2.6.orig/arch/blackfin/kernel/early_printk.c
+++ linux-2.6/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
Index: linux-2.6/arch/microblaze/kernel/early_printk.c
===================================================================
--- linux-2.6.orig/arch/microblaze/kernel/early_printk.c
+++ linux-2.6/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;
 }
Index: linux-2.6/arch/mips/kernel/early_printk.c
===================================================================
--- linux-2.6.orig/arch/mips/kernel/early_printk.c
+++ linux-2.6/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);
 }
Index: linux-2.6/arch/powerpc/kernel/udbg.c
===================================================================
--- linux-2.6.orig/arch/powerpc/kernel/udbg.c
+++ linux-2.6/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);
 }
 
Index: linux-2.6/arch/sh/kernel/sh_bios.c
===================================================================
--- linux-2.6.orig/arch/sh/kernel/sh_bios.c
+++ linux-2.6/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;
Index: linux-2.6/arch/sparc/kernel/setup_32.c
===================================================================
--- linux-2.6.orig/arch/sparc/kernel/setup_32.c
+++ linux-2.6/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 */
Index: linux-2.6/arch/sparc/kernel/setup_64.c
===================================================================
--- linux-2.6.orig/arch/sparc/kernel/setup_64.c
+++ linux-2.6/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");
Index: linux-2.6/arch/tile/kernel/early_printk.c
===================================================================
--- linux-2.6.orig/arch/tile/kernel/early_printk.c
+++ linux-2.6/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\
Index: linux-2.6/arch/um/kernel/early_printk.c
===================================================================
--- linux-2.6.orig/arch/um/kernel/early_printk.c
+++ linux-2.6/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;
 }
 
Index: linux-2.6/arch/unicore32/kernel/early_printk.c
===================================================================
--- linux-2.6.orig/arch/unicore32/kernel/early_printk.c
+++ linux-2.6/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;
Index: linux-2.6/arch/x86/kernel/early_printk.c
===================================================================
--- linux-2.6.orig/arch/x86/kernel/early_printk.c
+++ linux-2.6/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);
 
Index: linux-2.6/include/linux/console.h
===================================================================
--- linux-2.6.orig/include/linux/console.h
+++ linux-2.6/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);
Index: linux-2.6/include/linux/printk.h
===================================================================
--- linux-2.6.orig/include/linux/printk.h
+++ linux-2.6/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);
Index: linux-2.6/kernel/printk.c
===================================================================
--- linux-2.6.orig/kernel/printk.c
+++ linux-2.6/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)

[PATCH] lockdep: Enable earlyprintk output

[Peter Zijlstra]

Subject: lockdep: Enable earlyprintk output
From: Peter Zijlstra <a.p.zijlstra@chello.nl>
Date: Mon Dec 12 19:04:44 CET 2011


Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 kernel/lockdep.c |  492 ++++++++++++++++++++++++++++---------------------------
 1 file changed, 257 insertions(+), 235 deletions(-)
Index: linux-2.6/kernel/lockdep.c
===================================================================
--- linux-2.6.orig/kernel/lockdep.c
+++ linux-2.6/kernel/lockdep.c
@@ -67,6 +67,28 @@ module_param(lock_stat, int, 0644);
 #define lock_stat 0
 #endif
 
+#ifdef CONFIG_EARLY_PRINTK
+int use_early_printk = 0;
+module_param(use_early_printk, int, 0644);
+#endif
+
+static int lprintk(const char *fmt, ...)
+{
+	va_list args;
+	int r;
+
+	va_start(args, fmt);
+#ifdef CONFIG_EARLY_PRINTK
+	if (use_early_printk && (r = early_vprintk(fmt, args)))
+		;
+	else
+#endif
+	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 +431,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 +448,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 +530,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 +546,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 +560,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 +575,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 +683,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 +751,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 +785,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 +813,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 +856,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 +1096,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 +1127,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 +1168,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 +1219,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 +1384,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 +1419,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 +1462,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 +1506,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 +1520,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 +1716,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 +1736,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 +1911,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 +2041,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 +2049,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 +2070,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 +2223,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 +2243,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 +2260,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 +2308,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 +2345,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 +2406,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 +2956,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 +3001,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 +3066,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 +3173,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 +3194,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 +3509,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 +3639,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 +3971,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 +3993,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 +4015,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 +4073,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 +4099,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 +4113,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 +4142,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 +4157,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 +4171,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,16 +4191,16 @@ 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);
 	lockdep_print_held_locks(curr);
-	printk("\nstack backtrace:\n");
+	lprintk("\nstack backtrace:\n");
 	dump_stack();
 }
 EXPORT_SYMBOL_GPL(lockdep_rcu_suspicious);

Re: printk() vs tty_io

[Peter Zijlstra]

On Wed, 2011-12-14 at 07:59 +0100, Ingo Molnar wrote:

> btw., would be nice to also somehow realeasify those debug hacks 
> to preserve them for eternity - doing all lockdep output as 
> earlyprintk while keeping printks working is a great way to 
> debug printk() itself.
> 
> Those printk lockups also took a *lot* of time for me to bisect.

Yeah, they're horrible.. took me long enough to reproduce, and even now
I know how its not easy.

Anyway, I just posted the two patches that make lockdep do
early_printk(), they're not too horrid. I still need to look at making
dump_stack() play nice as well, but so far I've managed to grok bits
from the held lock output only.

Re: printk() vs tty_io

[Ingo Molnar]

* Peter Zijlstra <peterz@infradead.org> wrote:

> On Wed, 2011-12-14 at 07:59 +0100, Ingo Molnar wrote:
> 
> > btw., would be nice to also somehow realeasify those debug 
> > hacks to preserve them for eternity - doing all lockdep 
> > output as earlyprintk while keeping printks working is a 
> > great way to debug printk() itself.
> > 
> > Those printk lockups also took a *lot* of time for me to 
> > bisect.
> 
> Yeah, they're horrible.. took me long enough to reproduce, and 
> even now I know how its not easy.
> 
> Anyway, I just posted the two patches that make lockdep do 
> early_printk(), they're not too horrid. [...]

Given how crutial lockdep is to analyzing lockups, i think this 
decoupling from printk() innards is a good idea in general.

[ It also rhymes well with the general principles of lockdep, to 
  create all of its infrastructure from scratch, to be able to 
  use it everywhere. ]

The small lprintk() ugliness we can live with i think.

Thanks,

	Ingo

Re: printk() vs tty_io

[Alan Cox]

On Tue, 13 Dec 2011 15:52:35 -0800
Linus Torvalds <torvalds@linux-foundation.org> wrote:

> On Tue, Dec 13, 2011 at 11:33 AM, Peter Zijlstra <peterz@infradead.org> wrote:
> >
> > I've been poking at reducing the constraints on printk(), like make it
> > work under rq->lock etc..
> 
> You aren't supposed register a console that wakes things up. But the
> only console that honors that afaik is the traditional vt console.
> *Maybe* the network console, I didn't check.

Serial console tries to be good as does netconsole. Serial USB console
can't so just does its best.

Not sure about some of the DRM framebuffer ones either.

Re: printk() vs tty_io

[Peter Zijlstra]

On Wed, 2011-12-14 at 10:43 +0000, Alan Cox wrote:
> On Tue, 13 Dec 2011 15:52:35 -0800
> Linus Torvalds <torvalds@linux-foundation.org> wrote:
> 
> > On Tue, Dec 13, 2011 at 11:33 AM, Peter Zijlstra <peterz@infradead.org> wrote:
> > >
> > > I've been poking at reducing the constraints on printk(), like make it
> > > work under rq->lock etc..
> > 
> > You aren't supposed register a console that wakes things up. But the
> > only console that honors that afaik is the traditional vt console.
> > *Maybe* the network console, I didn't check.
> 
> Serial console tries to be good as does netconsole. 

Well, this was the 8250 serial port driver doing wakeups. Its a simple
on-board serial port,

[   29.797007]        [<ffffffff8108a650>] __wake_up_common+0x4e/0x84
[   29.797007]        [<ffffffff8108d6ea>] __wake_up+0x39/0x4d
[   29.797007]        [<ffffffff8135d0db>] tty_wakeup+0x5b/0x60
[   29.797007]        [<ffffffff81373fb9>] uart_write_wakeup+0x21/0x23
[   29.797007]        [<ffffffff81376899>] transmit_chars+0xd8/0x12f
[   29.797007]        [<ffffffff81377f3a>] serial8250_handle_port+0x2d9/0x2fd
[   29.797007]        [<ffffffff81377fcb>] serial8250_handle_irq+0x16/0x1d
[   29.797007]        [<ffffffff81377ff5>] serial8250_default_handle_irq+0x23/0x27
[   29.797007]        [<ffffffff81377ade>] serial8250_interrupt+0x4d/0xc6
[   29.797007]        [<ffffffff810c9ae8>] handle_irq_event_percpu+0xab/0x1fc
[   29.797007]        [<ffffffff810c9c7a>] handle_irq_event+0x41/0x61
[   29.797007]        [<ffffffff810cc4cd>] handle_edge_irq+0xd1/0xf6
[   29.797007]        [<ffffffff8103ab85>] handle_irq+0x24/0x2f
[   29.797007]        [<ffffffff8150acdd>] do_IRQ+0x4d/0xb3

which places the wakeup under uport->lock, serial8250_console_write()
takes uport->lock, under console_sem, connecting the locks.

Re: printk() vs tty_io

[Ted Ts'o]

On Wed, Dec 14, 2011 at 11:56:46AM +0100, Peter Zijlstra wrote:
> 
> Well, this was the 8250 serial port driver doing wakeups. Its a simple
> on-board serial port,
> 
> [   29.797007]        [<ffffffff8108a650>] __wake_up_common+0x4e/0x84
> [   29.797007]        [<ffffffff8108d6ea>] __wake_up+0x39/0x4d
> [   29.797007]        [<ffffffff8135d0db>] tty_wakeup+0x5b/0x60
> [   29.797007]        [<ffffffff81373fb9>] uart_write_wakeup+0x21/0x23
> [   29.797007]        [<ffffffff81376899>] transmit_chars+0xd8/0x12f
> [   29.797007]        [<ffffffff81377f3a>] serial8250_handle_port+0x2d9/0x2fd
> [   29.797007]        [<ffffffff81377fcb>] serial8250_handle_irq+0x16/0x1d
> [   29.797007]        [<ffffffff81377ff5>] serial8250_default_handle_irq+0x23/0x27
> [   29.797007]        [<ffffffff81377ade>] serial8250_interrupt+0x4d/0xc6
> [   29.797007]        [<ffffffff810c9ae8>] handle_irq_event_percpu+0xab/0x1fc
> [   29.797007]        [<ffffffff810c9c7a>] handle_irq_event+0x41/0x61
> [   29.797007]        [<ffffffff810cc4cd>] handle_edge_irq+0xd1/0xf6
> [   29.797007]        [<ffffffff8103ab85>] handle_irq+0x24/0x2f
> [   29.797007]        [<ffffffff8150acdd>] do_IRQ+0x4d/0xb3
> 
> which places the wakeup under uport->lock, serial8250_console_write()
> takes uport->lock, under console_sem, connecting the locks.

printk() goes through serial8250_console_write() which writes to the
UART device using a busy loop, with local IRQ's disabled.  So it's not
serial8250_console_write() which is waking things up; this is coming
form interrupt handler running on some different CPU.

Am I missing something?

						- Ted

Re: printk() vs tty_io

[Peter Zijlstra]

On Wed, 2011-12-14 at 09:05 -0500, Ted Ts'o wrote:
> On Wed, Dec 14, 2011 at 11:56:46AM +0100, Peter Zijlstra wrote:
> > 
> > Well, this was the 8250 serial port driver doing wakeups. Its a simple
> > on-board serial port,
> > 
> > [   29.797007]        [<ffffffff8108a650>] __wake_up_common+0x4e/0x84
> > [   29.797007]        [<ffffffff8108d6ea>] __wake_up+0x39/0x4d
> > [   29.797007]        [<ffffffff8135d0db>] tty_wakeup+0x5b/0x60
> > [   29.797007]        [<ffffffff81373fb9>] uart_write_wakeup+0x21/0x23
> > [   29.797007]        [<ffffffff81376899>] transmit_chars+0xd8/0x12f
> > [   29.797007]        [<ffffffff81377f3a>] serial8250_handle_port+0x2d9/0x2fd
> > [   29.797007]        [<ffffffff81377fcb>] serial8250_handle_irq+0x16/0x1d
> > [   29.797007]        [<ffffffff81377ff5>] serial8250_default_handle_irq+0x23/0x27
> > [   29.797007]        [<ffffffff81377ade>] serial8250_interrupt+0x4d/0xc6
> > [   29.797007]        [<ffffffff810c9ae8>] handle_irq_event_percpu+0xab/0x1fc
> > [   29.797007]        [<ffffffff810c9c7a>] handle_irq_event+0x41/0x61
> > [   29.797007]        [<ffffffff810cc4cd>] handle_edge_irq+0xd1/0xf6
> > [   29.797007]        [<ffffffff8103ab85>] handle_irq+0x24/0x2f
> > [   29.797007]        [<ffffffff8150acdd>] do_IRQ+0x4d/0xb3
> > 
> > which places the wakeup under uport->lock, serial8250_console_write()
> > takes uport->lock, under console_sem, connecting the locks.
> 
> printk() goes through serial8250_console_write() which writes to the
> UART device using a busy loop, with local IRQ's disabled.  So it's not
> serial8250_console_write() which is waking things up; this is coming
> form interrupt handler running on some different CPU.

Which can still deadlock you just fine..

Re: printk() vs tty_io

[Linus Torvalds]

On Wed, Dec 14, 2011 at 6:23 AM, Peter Zijlstra <peterz@infradead.org> wrote:
>>
>> printk() goes through serial8250_console_write() which writes to the
>> UART device using a busy loop, with local IRQ's disabled.  So it's not
>> serial8250_console_write() which is waking things up; this is coming
>> form interrupt handler running on some different CPU.
>
> Which can still deadlock you just fine..

Ugh. There is a *ton* of stuff inside that serial port lock,
including, yes, the uart_write_wakeup().

And it does look like it's protecting port->tty or something, so I
don't see that we can just move the wakeup to outside the lock, which
was my first reaction.

Ugh.

                  Linus

Re: printk() vs tty_io

[Peter Zijlstra]

On Wed, 2011-12-14 at 07:54 -0800, Linus Torvalds wrote:

> Ugh. There is a *ton* of stuff inside that serial port lock,
> including, yes, the uart_write_wakeup().
> 
> And it does look like it's protecting port->tty or something, so I
> don't see that we can just move the wakeup to outside the lock, which
> was my first reaction.

We probably could, I can have a closer look, but the main question is,
are we going to commit to no wakeups from console implementations? That
would mean removing the USB serial console support and other such stuff.

[ Personally I think USB serial console is insane, if you really need
something like that use the ehci-dbgp thing, that at least has a chance
of working. ]

If we're not going to commit to that (which would be valid choice given
where we are), my printk efforts are pointless and I'll reconsider.

Re: printk() vs tty_io

[Alan Cox]

> We probably could, I can have a closer look, but the main question is,
> are we going to commit to no wakeups from console implementations? That
> would mean removing the USB serial console support and other such stuff.

That's a non starter.

> [ Personally I think USB serial console is insane, if you really need
> something like that use the ehci-dbgp thing, that at least has a chance
> of working. ]

Sometimes USB serial console is the best you've got.

> If we're not going to commit to that (which would be valid choice given
> where we are), my printk efforts are pointless and I'll reconsider.

For lockdep spews do they need to be spewed synchronously - clearly it's
good if they can be but its possible that they could be buffered ?

Alan

Re: printk() vs tty_io

[Peter Zijlstra]

On Thu, 2011-12-15 at 10:32 +0000, Alan Cox wrote:

> For lockdep spews do they need to be spewed synchronously - clearly it's
> good if they can be but its possible that they could be buffered ?

This wasn't about lockdep per-se, it all started with me trying to
cleanup printk()'s abuse of lockdep_off()/lockdep_on. Which then grew
into something a little bigger.

I'm fine with dropping the larger goal of making printk() work in all
but NMI context and focus on the initial cleanup.

Re: printk() vs tty_io

[Linus Torvalds]

On Thu, Dec 15, 2011 at 1:56 AM, Peter Zijlstra <peterz@infradead.org> wrote:
>
> We probably could, I can have a closer look, but the main question is,
> are we going to commit to no wakeups from console implementations? That
> would mean removing the USB serial console support and other such stuff.

I guess we can't.

So new approach:

 - screw it. the rq lock is just too central, you cannot call printk
from under it. And if you have an oops under it, you're screwed.

   Peter, why do you want to try to work from under the rq lock?

 - Make a special "debug printk" that is not synchronous. Just make it
buffer things, and have it actually print out from a worker thread or
whatever. This one *only* takes the lock for that buffer itself, and
works everywhere. We could probably even do tricks to make it
NMI-safe.

   Make code that isn't an oops or other very synchronous "have to
print out *now*" aim to use this "softer" printk.

Hmm?

                   Linus

Re: printk() vs tty_io

[Ingo Molnar]

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

> On Thu, Dec 15, 2011 at 1:56 AM, Peter Zijlstra <peterz@infradead.org> wrote:
> >
> > We probably could, I can have a closer look, but the main question is,
> > are we going to commit to no wakeups from console implementations? That
> > would mean removing the USB serial console support and other such stuff.
> 
> I guess we can't.
> 
> So new approach:
> 
>  - screw it. the rq lock is just too central, you cannot call 
> printk from under it. And if you have an oops under it, you're 
> screwed.
> 
>    Peter, why do you want to try to work from under the rq 
>    lock?

Well, no real strong reason: we had that nasty xtime_lock 
related lockup in printk() (which was arguably much worse than 
the rq lock dependency - and it got fixed), and everyone assumed 
that somehow we could just remove the rq lock dependency from 
printk() as well.

It appears we can't - and that's OK.

Was an intellectual excercise which didnt work out.

>  - Make a special "debug printk" that is not synchronous. Just 
> make it buffer things, and have it actually print out from a 
> worker thread or whatever. This one *only* takes the lock for 
> that buffer itself, and works everywhere. We could probably 
> even do tricks to make it NMI-safe.

We kind of already have such a thing: trace_printk() - which 
works from the weirdest of atomic contexts as well.

IIRC Peter uses trace_printk() to develop the scheduler all the 
time.

What we could perhaps do is a sort of 'shut up regular printk 
and feed all printks into the trace buffers' kind of debug 
switch.

>    Make code that isn't an oops or other very synchronous 
> "have to print out *now*" aim to use this "softer" printk.

For early and nast oopses we have a very primitive printk: 
earlyprintk=keep which can just act as a full printk 
replacement. I use earlyprintk=keep while regular printk is 
disabled (there's no console).

[ earlyprintk can be used to debug everything except printk() 
  lockups, obviously. ]

Thanks,

	Ingo

Re: printk() vs tty_io

[Greg KH]

On Thu, Dec 15, 2011 at 10:56:45AM +0100, Peter Zijlstra wrote:
> [ Personally I think USB serial console is insane, if you really need
> something like that use the ehci-dbgp thing, that at least has a chance
> of working. ]

USB serial console was written on a drunken bet and the fact that it
even works at all constantly amazes me.  I know people use it as that's
all they have access to, but for "real" debugging, you are right, you
need the ehci-debug device to ensure that you really get the oops
messages the system sends out.

thanks,

greg k-h

Re: printk() vs tty_io

[Alan Cox]

>  - Make a special "debug printk" that is not synchronous. Just make it
> buffer things, and have it actually print out from a worker thread or
> whatever. This one *only* takes the lock for that buffer itself, and
> works everywhere. We could probably even do tricks to make it
> NMI-safe.

No buffer lock needed within limits - our kfifo implementation doesn't
need them on sensible hardware.

Alan

Re: printk() vs tty_io

[Peter Zijlstra]

On Thu, 2011-12-15 at 09:08 -0800, Linus Torvalds wrote:
>    Peter, why do you want to try to work from under the rq lock?

As Ingo already mentioned, there was no strong reason. The rationale was
reducing surprise lockups like that xtime_lock thing. Also, there are
various WARNs in the scheduler code that could possibly trigger and
cause a deadlock.

Then again, they're not supposed to trigger and mostly if they do we
don't get an insta deadlock (at least not on the consoles I've used),
but there is the possibility of course.

I'm not sure the WARNs are enough reason to invent a new async printk
facility, but if you feel strongly about that I can look into doing it.

Re: printk() vs tty_io

[Stijn Devriendt]

On Tue, Dec 13, 2011 at 8:33 PM, Peter Zijlstra <peterz@infradead.org> wrote:
> Hi tty folks,
>
> I've been poking at reducing the constraints on printk(), like make it
> work under rq->lock etc..
>
> Aside from a fwd port of the patch that abuses the console_sem.lock:
> https://lkml.org/lkml/2011/6/9/298 and a few other not so very pretty
> patches, I ran into the following lockdep splat (using a not so very
> pretty lockdep early_printk() patch):
>
> 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){-.-...}:
>
> It turns out that writing to a console does wakeups due to tty_io.c.
>
> My question is basically, is there a feasible way around doing these
> wakeups from the console::write() path? Everything I thought of was
> really quite horrible... and very likely would break stuff since I'm not
> that well versed in the whole tty thing.
>

Would it be possible to solve the problem by allowing wake-ups from
inside the rq->lock? After all your hard work moving most of the wakeup
work out of the ttwu() code and the ttwu-queuing for cross-cpu wakeups
I believe that allowing wakeups from inside the rq->lock could be doable.

Regards,
Stijn