On Mon, 2 Oct 2017 09:33:16 +0200
Peter Zijlstra <pet...@infradead.org> wrote:
> 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.
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 <mhira...@kernel.org>
