Re: [kprobes/x86] a19b2e3d78: WARNING:at_kernel/locking/lockdep.c:#trace_hardirqs_off_caller

[Peter Zijlstra]

On Sun, Oct 01, 2017 at 07:12:51AM +0800, kernel test robot wrote:
>
> FYI, we noticed the following commit (built with gcc-6):
>
> commit: a19b2e3d783964d48d2b494439648e929bcdc976 ("kprobes/x86: Remove IRQ disabling from ftrace-based/optimized kprobes")
> https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git perf/core
>
> in testcase: boot
>
> on test machine: qemu-system-x86_64 -enable-kvm -cpu host -smp 2 -m 2G
>
> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
>
>
> +----------------------------------------------------------------+------------+------------+
> | | 5bb4fc2d86 | a19b2e3d78 |
> +----------------------------------------------------------------+------------+------------+
> | boot_successes | 12 | 0 |
> | boot_failures | 0 | 14 |
> | WARNING:at_kernel/locking/lockdep.c:#trace_hardirqs_off_caller | 0 | 14 |
> | BUG:kernel_hang_in_test_stage | 0 | 2 |
> +----------------------------------------------------------------+------------+------------+
>
>
>
> [ 86.794775] WARNING: CPU: 1 PID: 1 at kernel/locking/lockdep.c:2962 trace_hardirqs_off_caller+0x6a/0xa1
> [ 86.816156] Modules linked in:
> [ 86.823679] CPU: 1 PID: 1 Comm: swapper/0 Not tainted 4.14.0-rc2-00179-ga19b2e3 #139
> [ 86.839654] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-20161025_171302-gandalf 04/01/2014
> [ 86.860817] task: ffffa01adbd58040 task.stack: ffffc18ac0630000
> [ 86.873128] RIP: 0010:trace_hardirqs_off_caller+0x6a/0xa1
> [ 86.885573] RSP: 0000:ffffc18ac0633ca0 EFLAGS: 00010286
> [ 86.896944] RAX: 0000000000000025 RBX: ffffa01adbd58040 RCX: ffffa01adbd58040
> [ 86.912305] RDX: 0000000000000092 RSI: ffffffffa013cb72 RDI: 0000000000000293
> [ 86.927660] RBP: ffffc18ac0633cb0 R08: 0000000000000001 R09: 0000000000000001
> [ 86.942861] R10: ffffc18ac0633e28 R11: dead000000000200 R12: ffffffffa009c722
> [ 86.957936] R13: ffffa01adf40dbe0 R14: ffffffffa017f6ca R15: ffffffffa017f6ce
> [ 86.973045] FS: 0000000000000000(0000) GS:ffffa01adf400000(0000) knlGS:0000000000000000
> [ 86.990564] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 87.002751] CR2: ffffc18ac06cc000 CR3: 000000000b28f001 CR4: 00000000000206e0
> [ 87.018115] Call Trace:
> [ 87.025046] trace_hardirqs_off+0xd/0xf
> [ 87.034185] setjmp_pre_handler+0x6c/0x95
> [ 87.043738] kprobe_ftrace_handler+0xc3/0xf4


So setjmp_pre_handler() does:

regs->flags &= ~X86_EFLAGS_IF;
trace_hardirqs_off();
regs->ip = (unsigned long)(jp->entry);

Which clears IF on the regs, but those will only take effect after an
IRET, not instantly. This messes up he IRQ state tracing, which you're
telling it will instantly disable IRQs.

A possible 'fix' would be to do local_irq_disable() in front of that,
but I got pretty lost in that stuff so I can't say for sure if that
makes sense or not.

[Linus Torvalds]

On Mon, Oct 2, 2017 at 8:46 AM, Masami Hiramatsu <mhir...@kernel.org> wrote:
>
> I'm considering to remove disabling-irq itself from jprobe.
> (Frankly to say, I would like to remove jprobe itself...)

Please please please...

That would be lovely. The jprobe thing is really nasty, and despite
the thing having been around forever (looking at history, it does back
to 2004) there are very few users and they all look dubious to me.

I seriously doubt anybody uses them, and I suspect our current tracing
infrastructure is just *so* much better and more powerful than jprobes
was.

So I'd heartily recommend just getting rid of jprobes. Or at least
trying, and seeing if anybody actually even notices (and then
reverting the removal and looking at what the usage ends up actually
being).

Linus

[Masami Hiramatsu]

Thanks for analyzing!
And right, since IRQ should be off while jump handler, it changes
regs->flags. (but ...why?)

> A possible 'fix' would be to do local_irq_disable() in front of that,
> but I got pretty lost in that stuff so I can't say for sure if that
> makes sense or not.

I'm not sure how lockdep traces irq-disabling state, but it seems
that "enabling" irq state(trace_hardirqs_on()) is already missing
from kprobes.

I'm considering to remove disabling-irq itself from jprobe.
(Frankly to say, I would like to remove jprobe itself...)

Thank you,

--
Masami Hiramatsu <mhir...@kernel.org>

[Peter Zijlstra]

On Tue, Oct 03, 2017 at 12:46:05AM +0900, Masami Hiramatsu wrote:
> On Mon, 2 Oct 2017 09:33:16 +0200
> Peter Zijlstra <pet...@infradead.org> wrote:

> > > [ 87.018115] Call Trace:
> > > [ 87.025046] trace_hardirqs_off+0xd/0xf
> > > [ 87.034185] setjmp_pre_handler+0x6c/0x95
> > > [ 87.043738] kprobe_ftrace_handler+0xc3/0xf4
> >
> >
> > So setjmp_pre_handler() does:
> >
> > regs->flags &= ~X86_EFLAGS_IF;
> > trace_hardirqs_off();
> > regs->ip = (unsigned long)(jp->entry);
> >
> > Which clears IF on the regs, but those will only take effect after an
> > IRET, not instantly. This messes up he IRQ state tracing, which you're
> > telling it will instantly disable IRQs.
>
> Thanks for analyzing!
> And right, since IRQ should be off while jump handler, it changes
> regs->flags. (but ...why?)

Otherwise the IRET could re-enable interrupts?

> > A possible 'fix' would be to do local_irq_disable() in front of that,
> > but I got pretty lost in that stuff so I can't say for sure if that
> > makes sense or not.
>
> I'm not sure how lockdep traces irq-disabling state, but it seems
> that "enabling" irq state(trace_hardirqs_on()) is already missing
> from kprobes.

If you could point me at where that is supposed to happen I can have a
look at how that tracing works. I got lost in the code this morning.

> I'm considering to remove disabling-irq itself from jprobe.
> (Frankly to say, I would like to remove jprobe itself...)

That would obviously also solve all problems :-)