• [kprobes/x86] a19b2e3d78: WARNING:at_kernel/locking/lockdep.c:#trac

    From Linus Torvalds@21:1/5 to Masami Hiramatsu on Mon Oct 2 22:50:14 2017
    On Mon, Oct 2, 2017 at 8:46 AM, Masami Hiramatsu <mhiramat@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

    --- SoupGate-Win32 v1.05
    * Origin: fsxNet Usenet Gateway (21:1/5)
  • From Masami Hiramatsu@21:1/5 to Peter Zijlstra on Mon Oct 2 22:50:17 2017
    On Mon, 2 Oct 2017 09:33:16 +0200
    Peter Zijlstra <peterz@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 <mhiramat@kernel.org>

    --- SoupGate-Win32 v1.05
    * Origin: fsxNet Usenet Gateway (21:1/5)