* [PATCH] init: Scream bloody murder if interrupts are enabled too early
@ 2013-03-07 22:19 Steven Rostedt
2013-03-08 9:03 ` Ard van Breemen
2013-03-08 19:49 ` Paul E. McKenney
0 siblings, 2 replies; 4+ messages in thread
From: Steven Rostedt @ 2013-03-07 22:19 UTC (permalink / raw)
To: LKML; +Cc: Andrew Morton, Ard van Breemen
[ Andrew, can you pull this patch into -mm? ]
As I was testing a lot of my code recently, and having several
"successes", I accidentally noticed in the dmesg this little line:
[ 0.000000] start_kernel(): bug: interrupts were enabled *very* early, fixing it
Sure enough, one of my patches two commits ago enabled interrupts early.
The sad part here is that I never noticed it, and I ran several tests
with ktest too, and ktest did not notice this line.
What ktest looks for (and so does many other automated testing scripts)
is a back trace produced by a WARN_ON() or BUG(). As a back trace was
never produced, my buggy patch could have slipped into linux-next, or
even worse, mainline.
Adding a WARN_ON() makes this bug a little more obvious:
[ 0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[ 0.000000] __ex_table already sorted, skipping sort
[ 0.000000] Checking aperture...
[ 0.000000] No AGP bridge found
[ 0.000000] Calgary: detecting Calgary via BIOS EBDA area
[ 0.000000] Calgary: Unable to locate Rio Grande table in EBDA - bailing!
[ 0.000000] Memory: 2003192k/2054848k available (4792k kernel code, 460k absent, 51196k reserved, 6277k data, 1152k init)
[ 0.000000] ------------[ cut here ]------------
[ 0.000000] WARNING: at /home/rostedt/work/git/linux-trace.git/init/main.c:543 start_kernel+0x215/0x40e()
[ 0.000000] Hardware name: To Be Filled By O.E.M.
[ 0.000000] Modules linked in:
[ 0.000000] Pid: 0, comm: swapper/0 Not tainted 3.8.0-test+ #275
[ 0.000000] Call Trace:
[ 0.000000] [<ffffffff8103781d>] warn_slowpath_common+0x83/0x9b
[ 0.000000] [<ffffffff8103784f>] warn_slowpath_null+0x1a/0x1c
[ 0.000000] [<ffffffff81ae5a30>] start_kernel+0x215/0x40e
[ 0.000000] [<ffffffff81ae5623>] ? repair_env_string+0x56/0x56
[ 0.000000] [<ffffffff81ae5312>] x86_64_start_reservations+0x10e/0x112
[ 0.000000] [<ffffffff81ae5120>] ? early_idt_handlers+0x120/0x120
[ 0.000000] [<ffffffff81ae5418>] x86_64_start_kernel+0x102/0x111
[ 0.000000] ---[ end trace 1ca9c978643fe899 ]---
[ 0.000000] start_kernel(): bug: interrupts were enabled *very* early, fixing it
[ 0.000000] Preemptible hierarchical RCU implementation.
[ 0.000000] RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=4.
[ 0.000000] NR_IRQS:4352 nr_irqs:712 16
[ 0.000000] Console: colour VGA+ 80x25
[ 0.000000] console [ttyS0] enabled, bootconsole disabled
[ 0.000000] console [ttyS0] enabled, bootconsole disabled
Do you see it?
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
diff --git a/init/main.c b/init/main.c
index 63534a1..f0fe0a5 100644
--- a/init/main.c
+++ b/init/main.c
@@ -539,7 +539,7 @@ asmlinkage void __init start_kernel(void)
* fragile until we cpu_idle() for the first time.
*/
preempt_disable();
- if (!irqs_disabled()) {
+ if (WARN_ON(!irqs_disabled())) {
printk(KERN_WARNING "start_kernel(): bug: interrupts were "
"enabled *very* early, fixing it\n");
local_irq_disable();
^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: [PATCH] init: Scream bloody murder if interrupts are enabled too early
2013-03-07 22:19 [PATCH] init: Scream bloody murder if interrupts are enabled too early Steven Rostedt
@ 2013-03-08 9:03 ` Ard van Breemen
2013-03-08 11:38 ` Steven Rostedt
2013-03-08 19:49 ` Paul E. McKenney
1 sibling, 1 reply; 4+ messages in thread
From: Ard van Breemen @ 2013-03-08 9:03 UTC (permalink / raw)
To: Steven Rostedt; +Cc: LKML, Andrew Morton
Hi,
On Thu, Mar 07, 2013 at 05:19:03PM -0500, Steven Rostedt wrote:
> diff --git a/init/main.c b/init/main.c
> index 63534a1..f0fe0a5 100644
> --- a/init/main.c
> +++ b/init/main.c
> @@ -539,7 +539,7 @@ asmlinkage void __init start_kernel(void)
> * fragile until we cpu_idle() for the first time.
> */
> preempt_disable();
> - if (!irqs_disabled()) {
> + if (WARN_ON(!irqs_disabled())) {
> printk(KERN_WARNING "start_kernel(): bug: interrupts were "
> "enabled *very* early, fixing it\n");
> local_irq_disable();
>
The original code was a few versions before the WARN macros.
I think it's better to just change the printk to something like:
WARN(1,"interrupts were enabled *very* early, fixing it\n")
This will print the cause of the warning and then dump stack,
instead of having an unrelated message under the stackdump.
But: IANAM(acro)E(xpert), the real incantation might be
different.
But you are absolutely right that we should scream and shout.
This time in a way that's more in line with the others.
Regards,
Ard van Breemen.
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [PATCH] init: Scream bloody murder if interrupts are enabled too early
2013-03-08 9:03 ` Ard van Breemen
@ 2013-03-08 11:38 ` Steven Rostedt
0 siblings, 0 replies; 4+ messages in thread
From: Steven Rostedt @ 2013-03-08 11:38 UTC (permalink / raw)
To: Ard van Breemen; +Cc: LKML, Andrew Morton
On Fri, 2013-03-08 at 10:03 +0100, Ard van Breemen wrote:
> The original code was a few versions before the WARN macros.
> I think it's better to just change the printk to something like:
> WARN(1,"interrupts were enabled *very* early, fixing it\n")
>
Yeah, I thought about updating to that, but I was lazy. I was hoping
nobody would notice. ;-)
OK, I'll send out -v2 as soon as I finish testing it.
Thanks,
-- Steve
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [PATCH] init: Scream bloody murder if interrupts are enabled too early
2013-03-07 22:19 [PATCH] init: Scream bloody murder if interrupts are enabled too early Steven Rostedt
2013-03-08 9:03 ` Ard van Breemen
@ 2013-03-08 19:49 ` Paul E. McKenney
1 sibling, 0 replies; 4+ messages in thread
From: Paul E. McKenney @ 2013-03-08 19:49 UTC (permalink / raw)
To: Steven Rostedt; +Cc: LKML, Andrew Morton, Ard van Breemen
On Thu, Mar 07, 2013 at 05:19:03PM -0500, Steven Rostedt wrote:
> [ Andrew, can you pull this patch into -mm? ]
>
> As I was testing a lot of my code recently, and having several
> "successes", I accidentally noticed in the dmesg this little line:
>
> [ 0.000000] start_kernel(): bug: interrupts were enabled *very* early, fixing it
>
>
> Sure enough, one of my patches two commits ago enabled interrupts early.
> The sad part here is that I never noticed it, and I ran several tests
> with ktest too, and ktest did not notice this line.
>
> What ktest looks for (and so does many other automated testing scripts)
> is a back trace produced by a WARN_ON() or BUG(). As a back trace was
> never produced, my buggy patch could have slipped into linux-next, or
> even worse, mainline.
>
> Adding a WARN_ON() makes this bug a little more obvious:
>
> [ 0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
> [ 0.000000] __ex_table already sorted, skipping sort
> [ 0.000000] Checking aperture...
> [ 0.000000] No AGP bridge found
> [ 0.000000] Calgary: detecting Calgary via BIOS EBDA area
> [ 0.000000] Calgary: Unable to locate Rio Grande table in EBDA - bailing!
> [ 0.000000] Memory: 2003192k/2054848k available (4792k kernel code, 460k absent, 51196k reserved, 6277k data, 1152k init)
> [ 0.000000] ------------[ cut here ]------------
> [ 0.000000] WARNING: at /home/rostedt/work/git/linux-trace.git/init/main.c:543 start_kernel+0x215/0x40e()
> [ 0.000000] Hardware name: To Be Filled By O.E.M.
> [ 0.000000] Modules linked in:
> [ 0.000000] Pid: 0, comm: swapper/0 Not tainted 3.8.0-test+ #275
> [ 0.000000] Call Trace:
> [ 0.000000] [<ffffffff8103781d>] warn_slowpath_common+0x83/0x9b
> [ 0.000000] [<ffffffff8103784f>] warn_slowpath_null+0x1a/0x1c
> [ 0.000000] [<ffffffff81ae5a30>] start_kernel+0x215/0x40e
> [ 0.000000] [<ffffffff81ae5623>] ? repair_env_string+0x56/0x56
> [ 0.000000] [<ffffffff81ae5312>] x86_64_start_reservations+0x10e/0x112
> [ 0.000000] [<ffffffff81ae5120>] ? early_idt_handlers+0x120/0x120
> [ 0.000000] [<ffffffff81ae5418>] x86_64_start_kernel+0x102/0x111
> [ 0.000000] ---[ end trace 1ca9c978643fe899 ]---
> [ 0.000000] start_kernel(): bug: interrupts were enabled *very* early, fixing it
> [ 0.000000] Preemptible hierarchical RCU implementation.
> [ 0.000000] RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=4.
> [ 0.000000] NR_IRQS:4352 nr_irqs:712 16
> [ 0.000000] Console: colour VGA+ 80x25
> [ 0.000000] console [ttyS0] enabled, bootconsole disabled
> [ 0.000000] console [ttyS0] enabled, bootconsole disabled
>
> Do you see it?
Yes, but only after looking through it three times.
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
Reviewed-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> diff --git a/init/main.c b/init/main.c
> index 63534a1..f0fe0a5 100644
> --- a/init/main.c
> +++ b/init/main.c
> @@ -539,7 +539,7 @@ asmlinkage void __init start_kernel(void)
> * fragile until we cpu_idle() for the first time.
> */
> preempt_disable();
> - if (!irqs_disabled()) {
> + if (WARN_ON(!irqs_disabled())) {
> printk(KERN_WARNING "start_kernel(): bug: interrupts were "
> "enabled *very* early, fixing it\n");
> local_irq_disable();
>
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
>
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2013-03-08 19:49 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2013-03-07 22:19 [PATCH] init: Scream bloody murder if interrupts are enabled too early Steven Rostedt
2013-03-08 9:03 ` Ard van Breemen
2013-03-08 11:38 ` Steven Rostedt
2013-03-08 19:49 ` Paul E. McKenney
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).