plateform is 
-> cat /proc/cpuinfo 
processor	: 0
vendor_id	: GenuineIntel
cpu family	: 6
model		: 8
model name	: Pentium III (Coppermine)
stepping	: 3
cpu MHz		: 664.519
cache size	: 256 KB
fdiv_bug	: no
hlt_bug		: no
f00f_bug	: no
coma_bug	: no
fpu		: yes
fpu_exception	: yes
cpuid level	: 2
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 sep mtrr pge mca cmov pat pse36 mmx fxsr sse up
bogomips	: 1334.17
clflush size	: 32

http://bugzilla.kernel.org/show_bug.cgi?id=10489

Please reply via email (more information from the submitter is in the 
Bugzilla entry).


ReportedBy: jeanmarc.lacroix@free.Fr

Earliest failing kernel version: 2.6.25
Distribution: DEbian Etch
Hardware Environment: PIII
Software Environment: 
Problem Description: Warning at boot after running all 
embedded test

Steps to reproduce: boot !!!


   2.701005] Registering sys device '<NULL>'
[    2.702320] Registering sys device '<NULL>'
[    2.703711] Registering sys device '<NULL>'
[    2.704536] Initializing RT-Tester: OK
[    2.704824] device: 'snapshot': device_add
[    2.705140] PM: Adding info for No Bus:snapshot
[    2.706804] audit: initializing netlink socket (disabled)
[    2.707199] type=2000 audit(1208713807.707:1): initialized
[    2.707509] Kprobe smoke test started
[    2.709300] ------------[ cut here ]------------
[    2.709420] WARNING: at kernel/lockdep.c:2658 check_flags+0x4d/0x12c()
[    2.709541] Modules linked in:
[    2.709588] Pid: 1, comm: swapper Not tainted 2.6.25.jml.057 #1
[    2.709588]  [<c0126acc>] warn_on_slowpath+0x41/0x51
[    2.709588]  [<c010bafc>] ? save_stack_trace+0x1d/0x3b
[    2.709588]  [<c0140a83>] ? save_trace+0x37/0x89
[    2.709588]  [<c011987d>] ? kernel_map_pages+0x103/0x11c
[    2.709588]  [<c0109803>] ? native_sched_clock+0xca/0xea
[    2.709588]  [<c0142958>] ? mark_held_locks+0x41/0x5c
[    2.709588]  [<c0382580>] ? kprobe_exceptions_notify+0x322/0x3af
[    2.709588]  [<c0142aff>] ? trace_hardirqs_on+0xf1/0x119
[    2.709588]  [<c03825b3>] ? kprobe_exceptions_notify+0x355/0x3af
[    2.709588]  [<c0140823>] check_flags+0x4d/0x12c
[    2.709588]  [<c0143c9d>] lock_release+0x58/0x195
[    2.709588]  [<c038347c>] ? __atomic_notifier_call_chain+0x0/0x80
[    2.709588]  [<c03834d6>] __atomic_notifier_call_chain+0x5a/0x80
[    2.709588]  [<c0383508>] atomic_notifier_call_chain+0xc/0xe
[    2.709588]  [<c013b6d4>] notify_die+0x2d/0x2f
[    2.709588]  [<c038168a>] do_debug+0x67/0xfe
[    2.709588]  [<c0381287>] debug_stack_correct+0x27/0x30
[    2.709588]  [<c01564c0>] ? kprobe_target+0x1/0x34
[    2.709588]  [<c0156572>] ? init_test_probes+0x50/0x186
[    2.709588]  [<c04fae48>] init_kprobes+0x85/0x8c
[    2.709588]  [<c04e947b>] kernel_init+0x13d/0x298
[    2.709588]  [<c04e933e>] ? kernel_init+0x0/0x298
[    2.709588]  [<c04e933e>] ? kernel_init+0x0/0x298
[    2.709588]  [<c0105ef7>] kernel_thread_helper+0x7/0x10
[    2.709588]  =======================
[    2.709588] ---[ end trace 778e504de7e3b1e3 ]---
[    2.709588] possible reason: unannotated irqs-off.
[    2.709588] irq event stamp: 370065
[    2.709588] hardirqs last  enabled at (370065): [<c0382580>]
kprobe_exceptions_notify+0x322/0x3af
[    2.709588] hardirqs last disabled at (370064): [<c0381bb7>]
do_int3+0x1d/0x7d
[    2.709588] softirqs last  enabled at (370050): [<c012b464>]
__do_softirq+0xfa/0x100
[    2.709588] softirqs last disabled at (370045): [<c0107438>]
do_softirq+0x74/0xd9
[    2.714751] Kprobe smoke test passed successfully
[    2.716150] Total HugeTLB memory allocated, 0
[    2.717288] VFS: Disk quotas dquot_6.5.1
[    2.717689] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    2.719630] device class 'bsg': registering
[    2.720568] Block layer SCSI generic (bsg) driver version 0.4 loaded (major
253)
[    2.720619] io scheduler noop registered
[    2.720732] io scheduler anticipatory registered
[    2.720848] io scheduler deadline registered
[    2.721089] io scheduler cfq registered (default)
[    2.721354] pci 0000:00:01.0: Boot video device




cu
Adrian

On Mon, Apr 21, 2008 at 5:06 PM, Adrian Bunk <bunk@kernel.org> wrote:
> http://bugzilla.kernel.org/show_bug.cgi?id=10489
>
>  Please reply via email (more information from the submitter is in the
>  Bugzilla entry).
>
>
>  ReportedBy: jeanmarc.lacroix@free.Fr
>
>  Earliest failing kernel version: 2.6.25
>  Distribution: DEbian Etch
>  Hardware Environment: PIII
>  Software Environment:
>  Problem Description: Warning at boot after running all
>  embedded test
>
>  Steps to reproduce: boot !!!
>
>
>    2.701005] Registering sys device '<NULL>'
>  [    2.702320] Registering sys device '<NULL>'
>  [    2.703711] Registering sys device '<NULL>'
>  [    2.704536] Initializing RT-Tester: OK
>  [    2.704824] device: 'snapshot': device_add
>  [    2.705140] PM: Adding info for No Bus:snapshot
>  [    2.706804] audit: initializing netlink socket (disabled)
>  [    2.707199] type=2000 audit(1208713807.707:1): initialized
>  [    2.707509] Kprobe smoke test started
>  [    2.709300] ------------[ cut here ]------------
>  [    2.709420] WARNING: at kernel/lockdep.c:2658 check_flags+0x4d/0x12c()
>  [    2.709541] Modules linked in:
>  [    2.709588] Pid: 1, comm: swapper Not tainted 2.6.25.jml.057 #1
>  [    2.709588]  [<c0126acc>] warn_on_slowpath+0x41/0x51
>  [    2.709588]  [<c010bafc>] ? save_stack_trace+0x1d/0x3b
>  [    2.709588]  [<c0140a83>] ? save_trace+0x37/0x89
>  [    2.709588]  [<c011987d>] ? kernel_map_pages+0x103/0x11c
>  [    2.709588]  [<c0109803>] ? native_sched_clock+0xca/0xea
>  [    2.709588]  [<c0142958>] ? mark_held_locks+0x41/0x5c
>  [    2.709588]  [<c0382580>] ? kprobe_exceptions_notify+0x322/0x3af
>  [    2.709588]  [<c0142aff>] ? trace_hardirqs_on+0xf1/0x119
>  [    2.709588]  [<c03825b3>] ? kprobe_exceptions_notify+0x355/0x3af
>  [    2.709588]  [<c0140823>] check_flags+0x4d/0x12c
>  [    2.709588]  [<c0143c9d>] lock_release+0x58/0x195
>  [    2.709588]  [<c038347c>] ? __atomic_notifier_call_chain+0x0/0x80
>  [    2.709588]  [<c03834d6>] __atomic_notifier_call_chain+0x5a/0x80
>  [    2.709588]  [<c0383508>] atomic_notifier_call_chain+0xc/0xe
>  [    2.709588]  [<c013b6d4>] notify_die+0x2d/0x2f
>  [    2.709588]  [<c038168a>] do_debug+0x67/0xfe
>  [    2.709588]  [<c0381287>] debug_stack_correct+0x27/0x30
>  [    2.709588]  [<c01564c0>] ? kprobe_target+0x1/0x34
>  [    2.709588]  [<c0156572>] ? init_test_probes+0x50/0x186
>  [    2.709588]  [<c04fae48>] init_kprobes+0x85/0x8c
>  [    2.709588]  [<c04e947b>] kernel_init+0x13d/0x298
>  [    2.709588]  [<c04e933e>] ? kernel_init+0x0/0x298
>  [    2.709588]  [<c04e933e>] ? kernel_init+0x0/0x298
>  [    2.709588]  [<c0105ef7>] kernel_thread_helper+0x7/0x10
>  [    2.709588]  =======================
>  [    2.709588] ---[ end trace 778e504de7e3b1e3 ]---
>  [    2.709588] possible reason: unannotated irqs-off.
>  [    2.709588] irq event stamp: 370065
>  [    2.709588] hardirqs last  enabled at (370065): [<c0382580>]
>  kprobe_exceptions_notify+0x322/0x3af
>  [    2.709588] hardirqs last disabled at (370064): [<c0381bb7>]
>  do_int3+0x1d/0x7d
>  [    2.709588] softirqs last  enabled at (370050): [<c012b464>]
>  __do_softirq+0xfa/0x100
>  [    2.709588] softirqs last disabled at (370045): [<c0107438>]
>  do_softirq+0x74/0xd9
>  [    2.714751] Kprobe smoke test passed successfully
>  [    2.716150] Total HugeTLB memory allocated, 0
>  [    2.717288] VFS: Disk quotas dquot_6.5.1
>  [    2.717689] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
>  [    2.719630] device class 'bsg': registering
>  [    2.720568] Block layer SCSI generic (bsg) driver version 0.4 loaded
>  (major
>  253)
>  [    2.720619] io scheduler noop registered
>  [    2.720732] io scheduler anticipatory registered
>  [    2.720848] io scheduler deadline registered
>  [    2.721089] io scheduler cfq registered (default)
>  [    2.721354] pci 0000:00:01.0: Boot video device
>

This is because kprobes (just like kmemcheck and mmiotrace) needs to
disable interrupts while it single-steps the instruction. This is not
dangerous, and should be fixed by doing as the warning suggests, by
annotating the irqs-off. I don't remember the name of the function(s),
it is probably somewhere in lockdep.h.

Vegard

Hi,

I cannot reproduce it here, but this seems to be a likely fix.

Vegard


diff --git a/arch/x86/kernel/kprobes.c b/arch/x86/kernel/kprobes.c
index 34a5912..6d58f6e 100644
--- a/arch/x86/kernel/kprobes.c
+++ b/arch/x86/kernel/kprobes.c
@@ -424,6 +424,7 @@ static void __kprobes prepare_singlestep(struct kprobe *p, struct pt_regs *regs)
 	clear_btf();
 	regs->flags |= X86_EFLAGS_TF;
 	regs->flags &= ~X86_EFLAGS_IF;
+	trace_hardirqs_off();
 	/* single step inline if the instruction is an int3 */
 	if (p->opcode == BREAKPOINT_INSTRUCTION)
 		regs->ip = (unsigned long)p->addr;

Reply-To: mhiramat@redhat.com

Thank you for reporting.

Actually, kprobes tries to fixup thread's flags in post_kprobe_handler
(which is called from kprobe_exceptions_notify) by
trace_hardirqs_fixup_flags(pt_regs->flags). However, even the irq flag
is set in pt_regs->flags, true hardirq is still off until returning
from do_debug. Thus, lockdep assumes that hardirq is off without annotation.

IMHO, one possible solution is that fixing hardirq flags right after
notify_die in do_debug instead of in post_kprobe_handler.

Thanks,

Reply-To: peterz@infradead.org

On Mon, 2008-04-21 at 18:54 -0400, Masami Hiramatsu wrote:
> Thank you for reporting.
> 
> Actually, kprobes tries to fixup thread's flags in post_kprobe_handler
> (which is called from kprobe_exceptions_notify) by
> trace_hardirqs_fixup_flags(pt_regs->flags). However, even the irq flag
> is set in pt_regs->flags, true hardirq is still off until returning
> from do_debug. Thus, lockdep assumes that hardirq is off without annotation.
> 
> IMHO, one possible solution is that fixing hardirq flags right after
> notify_die in do_debug instead of in post_kprobe_handler.

My reply to BZ 10489:


> [    2.707509] Kprobe smoke test started
> [    2.709300] ------------[ cut here ]------------
> [    2.709420] WARNING: at kernel/lockdep.c:2658 check_flags+0x4d/0x12c()
> [    2.709541] Modules linked in:
> [    2.709588] Pid: 1, comm: swapper Not tainted 2.6.25.jml.057 #1
> [    2.709588]  [<c0126acc>] warn_on_slowpath+0x41/0x51
> [    2.709588]  [<c010bafc>] ? save_stack_trace+0x1d/0x3b
> [    2.709588]  [<c0140a83>] ? save_trace+0x37/0x89
> [    2.709588]  [<c011987d>] ? kernel_map_pages+0x103/0x11c
> [    2.709588]  [<c0109803>] ? native_sched_clock+0xca/0xea
> [    2.709588]  [<c0142958>] ? mark_held_locks+0x41/0x5c
> [    2.709588]  [<c0382580>] ? kprobe_exceptions_notify+0x322/0x3af
> [    2.709588]  [<c0142aff>] ? trace_hardirqs_on+0xf1/0x119
> [    2.709588]  [<c03825b3>] ? kprobe_exceptions_notify+0x355/0x3af
> [    2.709588]  [<c0140823>] check_flags+0x4d/0x12c
> [    2.709588]  [<c0143c9d>] lock_release+0x58/0x195
> [    2.709588]  [<c038347c>] ? __atomic_notifier_call_chain+0x0/0x80
> [    2.709588]  [<c03834d6>] __atomic_notifier_call_chain+0x5a/0x80
> [    2.709588]  [<c0383508>] atomic_notifier_call_chain+0xc/0xe
> [    2.709588]  [<c013b6d4>] notify_die+0x2d/0x2f
> [    2.709588]  [<c038168a>] do_debug+0x67/0xfe
> [    2.709588]  [<c0381287>] debug_stack_correct+0x27/0x30
> [    2.709588]  [<c01564c0>] ? kprobe_target+0x1/0x34
> [    2.709588]  [<c0156572>] ? init_test_probes+0x50/0x186
> [    2.709588]  [<c04fae48>] init_kprobes+0x85/0x8c
> [    2.709588]  [<c04e947b>] kernel_init+0x13d/0x298
> [    2.709588]  [<c04e933e>] ? kernel_init+0x0/0x298
> [    2.709588]  [<c04e933e>] ? kernel_init+0x0/0x298
> [    2.709588]  [<c0105ef7>] kernel_thread_helper+0x7/0x10
> [    2.709588]  =======================
> [    2.709588] ---[ end trace 778e504de7e3b1e3 ]---
> [    2.709588] possible reason: unannotated irqs-off.
> [    2.709588] irq event stamp: 370065
> [    2.709588] hardirqs last  enabled at (370065): [<c0382580>]
> kprobe_exceptions_notify+0x322/0x3af
> [    2.709588] hardirqs last disabled at (370064): [<c0381bb7>]
> do_int3+0x1d/0x7d
> [    2.709588] softirqs last  enabled at (370050): [<c012b464>]
> __do_softirq+0xfa/0x100
> [    2.709588] softirqs last disabled at (370045): [<c0107438>]
> do_softirq+0x74/0xd9
> [    2.714751] Kprobe smoke test passed successfully

how I love this stuff...


Ok, do_debug() is a trap, this can happen at any time regardless of the
machine's IRQ state. So the first thing we do is fix up the IRQ state.
Then we call this die notifier stuff; and return with messed up IRQ
state... YAY.

So, kprobes fudges it..

  notify_die(DIE_DEBUG)
    kprobe_exceptions_notify()
      post_kprobe_handler()
        modify regs->flags
        trace_hardirqs_fixup_flags(regs->flags);  <--- must be it

So what's the use of modifying flags if they're not meant to take effect
at some point.

/me tries to reproduce issue; enable kprobes test thingy && boot

OK, that reproduces..

So the below makes it work - but I'm not getting this code; at the time
I wrote that stuff I CC'ed each and every kprobe maintainer listed in
the usual places but got no reposonse - can some please explain this
stuff to me?

Are the saved flags only for the TF bit or are they made in full effect
later (and if so, where) ?

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
diff --git a/arch/x86/kernel/kprobes.c b/arch/x86/kernel/kprobes.c
index 34a5912..fe71e64 100644
--- a/arch/x86/kernel/kprobes.c
+++ b/arch/x86/kernel/kprobes.c
@@ -865,7 +865,6 @@ static int __kprobes post_kprobe_handler(struct pt_regs *regs)
 
        resume_execution(cur, regs, kcb);
        regs->flags |= kcb->kprobe_saved_flags;
-       trace_hardirqs_fixup_flags(regs->flags);
 
        /* Restore back the original saved kprobes variables and continue. */
        if (kcb->kprobe_status == KPROBE_REENTER) {

Reply-To: peterz@infradead.org

On Tue, 2008-04-22 at 15:09 +0200, Peter Zijlstra wrote:
> On Mon, 2008-04-21 at 18:54 -0400, Masami Hiramatsu wrote:
> > Thank you for reporting.
> > 
> > Actually, kprobes tries to fixup thread's flags in post_kprobe_handler
> > (which is called from kprobe_exceptions_notify) by
> > trace_hardirqs_fixup_flags(pt_regs->flags). However, even the irq flag
> > is set in pt_regs->flags, true hardirq is still off until returning
> > from do_debug. Thus, lockdep assumes that hardirq is off without
> annotation.

Ah, can you clarrify? pt_regs->flags will only be set when returning to
the original trap site? in that case we should not need a lockdep
annotation I guess, unless its allowed and exptected for the int3 site
to change IRQ state.

Reply-To: mhiramat@redhat.com

Peter Zijlstra wrote:
> On Tue, 2008-04-22 at 15:09 +0200, Peter Zijlstra wrote:
>> On Mon, 2008-04-21 at 18:54 -0400, Masami Hiramatsu wrote:
>>> Thank you for reporting.
>>>
>>> Actually, kprobes tries to fixup thread's flags in post_kprobe_handler
>>> (which is called from kprobe_exceptions_notify) by
>>> trace_hardirqs_fixup_flags(pt_regs->flags). However, even the irq flag
>>> is set in pt_regs->flags, true hardirq is still off until returning
>>> from do_debug. Thus, lockdep assumes that hardirq is off without
>>> annotation.
> 
> Ah, can you clarrify? pt_regs->flags will only be set when returning to
> the original trap site? in that case we should not need a lockdep
> annotation I guess, unless its allowed and exptected for the int3 site
> to change IRQ state.

As far as I took a look at the lockdep, your suggestion is correct.
post_kprobe_handler should not set a lockdep annotation, because
processor's IF is not changed yet in that time.

Thanks,

Reply-To: peterz@infradead.org

On Tue, 2008-04-22 at 11:25 -0400, Masami Hiramatsu wrote:
> Peter Zijlstra wrote:
> > On Tue, 2008-04-22 at 15:09 +0200, Peter Zijlstra wrote:
> >> On Mon, 2008-04-21 at 18:54 -0400, Masami Hiramatsu wrote:
> >>> Thank you for reporting.
> >>>
> >>> Actually, kprobes tries to fixup thread's flags in post_kprobe_handler
> >>> (which is called from kprobe_exceptions_notify) by
> >>> trace_hardirqs_fixup_flags(pt_regs->flags). However, even the irq flag
> >>> is set in pt_regs->flags, true hardirq is still off until returning
> >>> from do_debug. Thus, lockdep assumes that hardirq is off without
> annotation.
> > 
> > Ah, can you clarrify? pt_regs->flags will only be set when returning to
> > the original trap site? in that case we should not need a lockdep
> > annotation I guess, unless its allowed and exptected for the int3 site
> > to change IRQ state.
> 
> As far as I took a look at the lockdep, your suggestion is correct.
> post_kprobe_handler should not set a lockdep annotation, because
> processor's IF is not changed yet in that time.

That much was clear; but when _will_ it be changed?

Reply-To: mhiramat@redhat.com

Hi Peter,

Thank you for the patch,

Peter Zijlstra wrote:
> So the below makes it work - but I'm not getting this code; at the time
> I wrote that stuff I CC'ed each and every kprobe maintainer listed in
> the usual places but got no reposonse - can some please explain this
> stuff to me?

Sure, I came to the same decision. It is enough to remove unnecessary
trace_hardirqs_fixup_flags() from post_kprobe_handler. pt_regs->flags is
just a variable on stack -- not effective flags in that time. So we don't
need to change thread's hardirq flag.

> Are the saved flags only for the TF bit or are they made in full effect
> later (and if so, where) ?

The saved flags is for TF and IF bits.
Actually, kprobes does following:

---
do_int3()
 kprobe_exceptions_notify()
  kprobe_handler()
   prepare_singlestep() : save regs->flags, set TF and clear IF on regs->flags
"iret" : pop regs->flags image to EFLAGS reg.

<single step an instruction>

do_debug()
 kprobe_exceptions_notify()
  post_kprobe_handler() : restore regs->flags (clearing TF and restoring IF)
"iret" : pop regs->flags image to EFLAGS reg.
---

While executing a single step, EFLAGS is different from the original EFLAGS.
However, it will be recovered soon by post_kprobe_handler.
NOTE: if the single-stepping instruction is a pushf, kprobes writes saved
     EFLAGS to the top of stack.

> Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>

I tested it on x86-64/i386.

Acked-by: Masami Hiramatsu <mhiramat@redhat.com>

> ---
> diff --git a/arch/x86/kernel/kprobes.c b/arch/x86/kernel/kprobes.c
> index 34a5912..fe71e64 100644
> --- a/arch/x86/kernel/kprobes.c
> +++ b/arch/x86/kernel/kprobes.c
> @@ -865,7 +865,6 @@ static int __kprobes post_kprobe_handler(struct pt_regs
> *regs)
>  
>         resume_execution(cur, regs, kcb);
>         regs->flags |= kcb->kprobe_saved_flags;
> -       trace_hardirqs_fixup_flags(regs->flags);
>  
>         /* Restore back the original saved kprobes variables and continue. */
>         if (kcb->kprobe_status == KPROBE_REENTER) {
> 
> 
> 

Reply-To: mhiramat@redhat.com

Peter Zijlstra wrote:
> On Tue, 2008-04-22 at 11:25 -0400, Masami Hiramatsu wrote:
>> Peter Zijlstra wrote:
>>> On Tue, 2008-04-22 at 15:09 +0200, Peter Zijlstra wrote:
>>>> On Mon, 2008-04-21 at 18:54 -0400, Masami Hiramatsu wrote:
>>>>> Thank you for reporting.
>>>>>
>>>>> Actually, kprobes tries to fixup thread's flags in post_kprobe_handler
>>>>> (which is called from kprobe_exceptions_notify) by
>>>>> trace_hardirqs_fixup_flags(pt_regs->flags). However, even the irq flag
>>>>> is set in pt_regs->flags, true hardirq is still off until returning
>>>>> from do_debug. Thus, lockdep assumes that hardirq is off without
>>>>> annotation.
>>> Ah, can you clarrify? pt_regs->flags will only be set when returning to
>>> the original trap site? in that case we should not need a lockdep
>>> annotation I guess, unless its allowed and exptected for the int3 site
>>> to change IRQ state.
>> As far as I took a look at the lockdep, your suggestion is correct.
>> post_kprobe_handler should not set a lockdep annotation, because
>> processor's IF is not changed yet in that time.
> 
> That much was clear; but when _will_ it be changed?

processor's IF bit is changed when an iret(q) is issued.
In other words, when returning from a debug/int3 exception.

Reply-To: mhiramat@redhat.com

Masami Hiramatsu wrote:
> processor's IF bit is changed when an iret(q) is issued.
> In other words, when returning from a debug/int3 exception.

By the way, when returning from an exception on x86-64, it seems
paranoidexit@entry_64.S doesn't use TRACE_IRQS_IRETQ except for
it executes swapgs, does it?

If not, I guess the lockdep on x86-64 may causes an warning
by below code:

spin_lock(...)
kprobe_target_function()
spin_unlock(...)

Thanks,