Re: xfrm_policy_kill: inconsistent {softirq-on-W} -> {in-softirq-W} usage - Kernel

This is a discussion on Re: xfrm_policy_kill: inconsistent {softirq-on-W} -> {in-softirq-W} usage - Kernel ; On Mon, Nov 03, 2008 at 05:59:36PM +0000, Simon Arlott wrote: > [163040.503328] ================================= > [163040.504264] [ INFO: inconsistent lock state ] > [163040.504264] 2.6.28-rc2-git #19424-g083ead5 > [163040.504264] --------------------------------- > [163040.504264] inconsistent {softirq-on-W} -> {in-softirq-W} usage. > [163040.504264] swapper/0 [HC0[0]:SC1[1]:HE1:SE0] ...

+ Reply to Thread
Results 1 to 3 of 3

Thread: Re: xfrm_policy_kill: inconsistent {softirq-on-W} -> {in-softirq-W} usage

  1. Re: xfrm_policy_kill: inconsistent {softirq-on-W} -> {in-softirq-W} usage

    On Mon, Nov 03, 2008 at 05:59:36PM +0000, Simon Arlott wrote:
    > [163040.503328] =================================
    > [163040.504264] [ INFO: inconsistent lock state ]
    > [163040.504264] 2.6.28-rc2-git #19424-g083ead5
    > [163040.504264] ---------------------------------
    > [163040.504264] inconsistent {softirq-on-W} -> {in-softirq-W} usage.
    > [163040.504264] swapper/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
    > [163040.531914] (xfrm_policy_gc_lock){-+..}, at: [<7846bf3f>] xfrm_policy_kill+0x46/0x7e
    > [163040.531914] {softirq-on-W} state was registered at:
    > [163040.531914] [<782430ea>] __lock_acquire+0x4d2/0x653
    > [163040.531914] [<782432b3>] lock_acquire+0x48/0x64
    > [163040.531914] [<784ca073>] _spin_lock+0x25/0x34
    > [163040.531914] [<7846bf3f>] xfrm_policy_kill+0x46/0x7e
    > [163040.531914] [<7846c052>] xfrm_policy_delete+0x44/0x4a
    > [163040.531914] [<783fadc7>] sk_common_release+0x61/0x9f
    > [163040.531914] [<784480fe>] udp_lib_close+0x8/0xa
    > [163040.531914] [<7844f0b6>] inet_release+0x42/0x48
    > [163040.531914] [<783f90d2>] sock_release+0x14/0x8a
    > [163040.531914] [<783f95a0>] sock_close+0x29/0x30
    > [163040.531914] [<782707c7>] __fput+0xad/0x159
    > [163040.531914] [<78270afa>] fput+0x17/0x19
    > [163040.531914] [<7826e247>] filp_close+0x50/0x5a
    > [163040.531914] [<7826e2b9>] sys_close+0x68/0xa7
    > [163040.531914] [<78202e11>] sysenter_do_call+0x12/0x35
    > [163040.531914] [] 0xffffffff
    > [163040.531914] irq event stamp: 1417665572
    > [163040.531914] hardirqs last enabled at (1417665572): [<7822ace6>] local_bh_enable_ip+0xa7/0xbd
    > [163040.531914] hardirqs last disabled at (1417665571): [<7822ac84>] local_bh_enable_ip+0x45/0xbd
    > [163040.531914] softirqs last enabled at (1417665530): [<7822abe2>] __do_softirq+0x114/0x11c
    > [163040.531914] softirqs last disabled at (1417665541): [<7822ac23>] do_softirq+0x39/0x55
    > [163040.531914]
    > [163040.531914] other info that might help us debug this:
    > [163040.531914] no locks held by swapper/0.
    > [163040.531914]
    > [163040.531914] stack backtrace:
    > [163040.531914] Pid: 0, comm: swapper Not tainted 2.6.28-rc2-git #19424-g083ead5
    > [163040.531914] Call Trace:
    > [163040.531914] [<78240aa7>] print_usage_bug+0x144/0x150
    > [163040.531914] [<78241599>] mark_lock+0x2f9/0x7e7
    > [163040.531914] [<78243072>] __lock_acquire+0x45a/0x653
    > [163040.531914] [<782432b3>] lock_acquire+0x48/0x64
    > [163040.531914] [<7846bf3f>] ? xfrm_policy_kill+0x46/0x7e
    > [163040.531914] [<784ca073>] _spin_lock+0x25/0x34
    > [163040.531914] [<7846bf3f>] ? xfrm_policy_kill+0x46/0x7e
    > [163040.531914] [<7846bf3f>] xfrm_policy_kill+0x46/0x7e
    > [163040.531914] [<7846c052>] xfrm_policy_delete+0x44/0x4a
    > [163040.531914] [<7846d556>] xfrm_policy_timer+0x197/0x1c9
    > [163040.531914] [<78241c34>] ? trace_hardirqs_on_caller+0xca/0x101
    > [163040.531914] [<7822e3c3>] run_timer_softirq+0x102/0x15d
    > [163040.531914] [<7846d3bf>] ? xfrm_policy_timer+0x0/0x1c9
    > [163040.531914] [<7822ab4b>] __do_softirq+0x7d/0x11c
    > [163040.531914] [<7822ac23>] do_softirq+0x39/0x55


    If it's easily reproducible, try this patch:

    --- a/net/xfrm/xfrm_policy.c
    +++ b/net/xfrm/xfrm_policy.c
    @@ -315,9 +315,9 @@ static void xfrm_policy_kill(struct xfrm_policy *policy)
    return;
    }

    - spin_lock(&xfrm_policy_gc_lock);
    + spin_lock_bh(&xfrm_policy_gc_lock);
    hlist_add_head(&policy->bydst, &xfrm_policy_gc_list);
    - spin_unlock(&xfrm_policy_gc_lock);
    + spin_unlock_bh(&xfrm_policy_gc_lock);

    schedule_work(&xfrm_policy_gc_work);
    }
    --
    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/

  2. Re: xfrm_policy_kill: inconsistent {softirq-on-W} -> {in-softirq-W} usage

    On 03/11/08 20:57, Alexey Dobriyan wrote:
    > On Mon, Nov 03, 2008 at 05:59:36PM +0000, Simon Arlott wrote:
    >> [163040.503328] =================================
    >> [163040.504264] [ INFO: inconsistent lock state ]
    >> [163040.504264] 2.6.28-rc2-git #19424-g083ead5
    >> [163040.504264] ---------------------------------
    >> [163040.504264] inconsistent {softirq-on-W} -> {in-softirq-W} usage.
    >> [163040.504264] swapper/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
    >> [163040.531914] (xfrm_policy_gc_lock){-+..}, at: [<7846bf3f>] xfrm_policy_kill+0x46/0x7e

    >
    > If it's easily reproducible, try this patch:


    Unfortunately I don't know how to reproduce it and I won't reboot that system
    to apply a patch. I've checked my logs and can find only one other instance
    of that message, from 5 months ago:

    12 00:56:17 [461680.399422] =================================
    12 00:56:17 [461680.405467] [ INFO: inconsistent lock state ]
    12 00:56:17 [461680.409910] 2.6.23.9-git #44
    12 00:56:17 [461680.412876] ---------------------------------
    12 00:56:17 [461680.417315] inconsistent {softirq-on-W} -> {in-softirq-W} usage.
    12 00:56:17 [461680.423403] swapper/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
    12 00:56:17 [461680.428450] (xfrm_policy_gc_lock){-+..}, at: [<803355f6>] xfrm_policy_kill+0x63/0x9e
    12 00:56:17 [461680.436442] {softirq-on-W} state was registered at:
    12 00:56:17 [461680.441401] [<80131712>] __lock_acquire+0x471/0xb96
    12 00:56:18 [461680.446591] [<80132200>] lock_acquire+0x5d/0x75
    12 00:56:18 [461680.451431] [<8038b2e7>] _spin_lock+0x35/0x42
    12 00:56:18 [461680.456098] [<803355f6>] xfrm_policy_kill+0x63/0x9e
    12 00:56:18 [461680.461287] [<8033570b>] xfrm_policy_delete+0x43/0x49
    12 00:56:18 [461680.466648] [<802c0ef7>] sk_common_release+0x61/0x9e
    12 00:56:18 [461680.471925] [<80310328>] udp_lib_close+0x8/0xa
    12 00:56:18 [461680.476677] [<8031709d>] inet_release+0x42/0x48
    12 00:56:18 [461680.481519] [<802bf269>] sock_release+0x17/0x80
    12 00:56:18 [461680.486453] [<802bf726>] sock_close+0x2d/0x33
    12 00:56:18 [461680.491119] [<80158838>] __fput+0xb9/0x185
    12 00:56:18 [461680.495527] [<8015891a>] fput+0x16/0x18
    12 00:56:18 [461680.499668] [<801561d3>] filp_close+0x54/0x5c
    12 00:56:18 [461680.504341] [<80157334>] sys_close+0x6e/0xa6
    12 00:56:18 [461680.508916] [<80102702>] sysenter_past_esp+0x5f/0x99
    12 00:56:18 [461680.514189] [] 0xffffffff
    12 00:56:18 [461680.517995] irq event stamp: 2352088264
    12 00:56:18 [461680.521915] hardirqs last enabled at (2352088264): [<8011c626>] local_bh_enable_ip+0xc5/0xe1
    12 00:56:18 [461680.530552] hardirqs last disabled at (2352088263): [<8011c5bf>] local_bh_enable_ip+0x5e/0xe1
    12 00:56:18 [461680.539205] softirqs last enabled at (2352088198): [<8011c07e>] __do_softirq+0xa3/0xa8
    12 00:56:18 [461680.547318] softirqs last disabled at (2352088207): [<8011c0b2>] do_softirq+0x2f/0x47
    12 00:56:18 [461680.555262]
    12 00:56:18 [461680.555263] other info that might help us debug this:
    12 00:56:18 [461680.562055] no locks held by swapper/0.
    12 00:56:18 [461680.565975]
    12 00:56:18 [461680.565977] stack backtrace:
    12 00:56:18 [461680.570523] [<80103694>] show_trace_log_lvl+0x1a/0x2f
    12 00:56:18 [461680.575762] [<8010421b>] show_trace+0x12/0x14
    12 00:56:18 [461680.580308] [<80104232>] dump_stack+0x15/0x17
    12 00:56:18 [461680.584853] [<801302fc>] print_usage_bug+0x143/0x14d
    12 00:56:18 [461680.590005] [<8013093a>] mark_lock+0x125/0x44f
    12 00:56:18 [461680.594637] [<801316a0>] __lock_acquire+0x3ff/0xb96
    12 00:56:18 [461680.599702] [<80132200>] lock_acquire+0x5d/0x75
    12 00:56:18 [461680.604421] [<8038b2e7>] _spin_lock+0x35/0x42
    12 00:56:18 [461680.608962] [<803355f6>] xfrm_policy_kill+0x63/0x9e
    12 00:56:18 [461680.614027] [<8033570b>] xfrm_policy_delete+0x43/0x49
    12 00:56:18 [461680.619267] [<80336c54>] xfrm_policy_timer+0x199/0x1cc
    12 00:56:18 [461680.624590] [<8011f1bd>] run_timer_softirq+0xf1/0x14e
    12 00:56:18 [461680.629828] [<8011c02c>] __do_softirq+0x51/0xa8
    12 00:56:18 [461680.634548] [<8011c0b2>] do_softirq+0x2f/0x47
    12 00:56:18 [461680.639093] [<8011c2de>] irq_exit+0x3b/0x47
    12 00:56:18 [461680.643466] [<8010d252>] smp_apic_timer_interrupt+0x69/0x74
    12 00:56:18 [461680.649228] [<801031af>] apic_timer_interrupt+0x33/0x38
    12 00:56:18 [461680.654640] [<8020b28b>] acpi_processor_idle+0x157/0x3e8
    12 00:56:18 [461680.660141] [<80100b8e>] cpu_idle+0x46/0x6f
    12 00:56:18 [461680.664510] [<803889e8>] rest_init+0x60/0x62
    12 00:56:18 [461680.668972] [<804c2a16>] start_kernel+0x239/0x23f
    12 00:56:18 [461680.673870] [<00000000>] 0x0
    12 00:56:18 [461680.677025] =======================

    --
    Simon Arlott
    --
    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/

  3. Re: xfrm_policy_kill: inconsistent {softirq-on-W} -> {in-softirq-W} usage

    From: Alexey Dobriyan
    Date: Mon, 3 Nov 2008 23:57:26 +0300

    > If it's easily reproducible, try this patch:
    >
    > --- a/net/xfrm/xfrm_policy.c
    > +++ b/net/xfrm/xfrm_policy.c
    > @@ -315,9 +315,9 @@ static void xfrm_policy_kill(struct xfrm_policy *policy)


    This looks clearly like the correct fix for this lockdep
    warning, so I'm adding it to net-2.6 as follows even though
    Simon can't readily test it.

    Thanks.

    commit bbb770e7ab9a436752babfc8765e422d7481be1f
    Author: Alexey Dobriyan
    Date: Mon Nov 3 19:11:29 2008 -0800

    xfrm: Fix xfrm_policy_gc_lock handling.

    From: Alexey Dobriyan

    Based upon a lockdep trace by Simon Arlott.

    xfrm_policy_kill() can be called from both BH and
    non-BH contexts, so we have to grab xfrm_policy_gc_lock
    with BH disabling.

    Signed-off-by: David S. Miller

    diff --git a/net/xfrm/xfrm_policy.c b/net/xfrm/xfrm_policy.c
    index 2587274..058f04f 100644
    --- a/net/xfrm/xfrm_policy.c
    +++ b/net/xfrm/xfrm_policy.c
    @@ -315,9 +315,9 @@ static void xfrm_policy_kill(struct xfrm_policy *policy)
    return;
    }

    - spin_lock(&xfrm_policy_gc_lock);
    + spin_lock_bh(&xfrm_policy_gc_lock);
    hlist_add_head(&policy->bydst, &xfrm_policy_gc_list);
    - spin_unlock(&xfrm_policy_gc_lock);
    + spin_unlock_bh(&xfrm_policy_gc_lock);

    schedule_work(&xfrm_policy_gc_work);
    }
    --
    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/

+ Reply to Thread