printk() vs tty_io
Subsystems (10)
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.
Quoted 3 lines · Peter Zijlstra
I've been poking at reducing the constraints on
printk(), like make it work underrq->locketc..
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
Quoted 10 lines · Linus Torvalds
Quoted 3 lines · Peter Zijlstra
I've been poking at reducing the constraints on
printk(), like make it work underrq->locketc..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..
Quoted 8 lines · On Tue, 13 Dec 2011 15:52:35 -0800 Linus Torvalds…
Quoted 3 lines · Peter Zijlstra
I've been poking at reducing the constraints on
printk(), like make it work underrq->locketc..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.
Quoted 5 lines · Alan Cox
Quoted 2 lines · On Tue, 13 Dec 2011 15:52:35 -0800 Linus Torvalds…
Quoted 1 line · Peter Zijlstra
Quoted 8 lines
Quoted 6 lines
Quoted 2 lines
I've been poking at reducing the constraints on
printk(), like make it work underrq->locketc..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.
Quoted 19 lines · Peter Zijlstra
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
Quoted 2 lines
which places the wakeup under
uport->lock,serial8250_console_write()takesuport->lock, underconsole_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
Quoted 20 lines · Ted Ts'o
Quoted 19 lines · Peter Zijlstra
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
Quoted 7 lines
Quoted 2 lines
which places the wakeup under
uport->lock,serial8250_console_write()takesuport->lock, underconsole_sem, connecting the locks.
printk()goes throughserial8250_console_write()which writes to the UART device using a busy loop, with local IRQ's disabled. So it's notserial8250_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..
Quoted 7 lines · Peter Zijlstra
Quoted 5 lines
printk()goes throughserial8250_console_write()which writes to the UART device using a busy loop, with local IRQ's disabled. So it's notserial8250_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
Quoted 6 lines · Linus Torvalds
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->ttyor 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.
Quoted 3 lines
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.
Quoted 3 lines
[ 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.
Quoted 2 lines
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
Quoted 2 lines · Alan Cox
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.
Quoted 4 lines · Peter Zijlstra
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
Quoted 8 lines · Linus Torvalds
Quoted 4 lines · Peter Zijlstra
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.
Quoted 8 lines
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.
Quoted 5 lines
- 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.
Quoted 2 lines
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
Quoted 5 lines
- 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
Quoted 1 line · Linus Torvalds
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.
Quoted 3 lines · Peter Zijlstra
[ 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
Quoted 10 lines · Peter Zijlstra
Hi tty folks,
I've been poking at reducing the constraints on
printk(), like make it work underrq->locketc..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
PATCH 1/1 arch, early_printk: Consolidate early_printk() implementations
Subject: arch, early_printk: Consolidate early_printk() implementations
From: Thomas Gleixner <[email protected]>
Date: Sat Jul 23 11:04:08 2011 +0200
--- 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(-)
arch/arm/kernel/early_printk.c +3 -14
@@ -29,28 +29,17 @@ static void early_console_write(struct cearly_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 ; }
arch/blackfin/kernel/early_printk.c +0 -2
@@ -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
arch/microblaze/kernel/early_printk.c +3 -21
@@ -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 ; }
arch/mips/kernel/early_printk.c +4 -6
@@ -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); }
arch/powerpc/kernel/udbg.c +2 -4
@@ -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); }
arch/sh/kernel/sh_bios.c +0 -2
@@ -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 ;
arch/sparc/kernel/setup_32.c +1 -0
@@ -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 */
arch/sparc/kernel/setup_64.c +7 -1
@@ -487,6 +487,12 @@ static void __init init_sparc64_elf_hwcapopc_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" );
arch/tile/kernel/early_printk.c +4 -22
@@ -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(chavoid __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\
arch/um/kernel/early_printk.c +5 -3
@@ -16,7 +16,7 @@ static void early_console_write(struct cum_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 ; }
arch/unicore32/kernel/early_printk.c +4 -8
@@ -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 ;
arch/x86/kernel/early_printk.c +2 -19
@@ -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(chaif (!buf)return 0 ; -if (early_console_initialized) +if (early_console)return 0 ; - early_console_initialized =1 ; keep = (strstr (buf,"keep" ) !=NULL );
include/linux/console.h +1 -0
@@ -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);
include/linux/printk.h +12 -1
@@ -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 );
kernel/printk.c +28 -7
@@ -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 1/1 lockdep: Enable earlyprintk output
In reply to Ingo MolnarSubject: lockdep: Enable earlyprintk output
From: Peter Zijlstra <[email protected]>
Date: Mon Dec 12 19:04:44 CET 2011
--- kernel/lockdep.c | 492 ++++++++++++++++++++++++++++--------------------------- 1 file changed, 257 insertions(+), 235 deletions(-)
kernel/lockdep.c +257 -235
@@ -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_traceif (!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 lif (!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(strint 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 *lif (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_entrif (!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_liif (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_strif (!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_lockstruct 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 *cif (!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(strif (!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 *currif (!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_struif (!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_strulockdep_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_structvoid 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_sif (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 flif (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_stif (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_structif (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(structif (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);
Quoted 6 lines · Ingo Molnar
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.
Quoted 7 lines · Peter Zijlstra
Quoted 5 lines · Ingo Molnar
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.
Quoted 8 lines
Quoted 2 lines
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
Quoted 25 lines · Peter Zijlstra
Hi tty folks,
I've been poking at reducing the constraints on
printk(), like make it work underrq->locketc..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 lockdepearly_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){-.-...}:
Quoted 7 lines
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