lkml.org 
[lkml]   [2006]   [May]   [30]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    SubjectRe: 2.6.17-rc5-mm1
    From
    Date
    On Tue, 2006-05-30 at 20:39 +0200, Michal Piotrowski wrote:
    > Hi,
    >
    > On 30/05/06, Andrew Morton <akpm@osdl.org> wrote:
    > >
    > > ftp://ftp.kernel.org/pub/linux/kernel/people/akpm/patches/2.6/2.6.17-rc5/2.6.17-rc5-mm1/
    > >
    >
    > I get this on 2.6.17-rc5-mm1 + hot fixes + Arjan's net/ipv4/igmp.c patch.

    since Andrew asked how to read this stuff.....
    >
    > May 30 20:25:56 ltg01-fedora kernel:
    > May 30 20:25:56 ltg01-fedora kernel:
    > =====================================================
    > May 30 20:25:56 ltg01-fedora kernel: [ BUG: possible circular locking
    > deadlock detected! ]

    this message means basically an AB-BA deadlock is found

    > May 30 20:25:56 ltg01-fedora kernel:
    > -----------------------------------------------------
    > May 30 20:25:56 ltg01-fedora kernel: umount/2322 is trying to acquire lock:
    > May 30 20:25:56 ltg01-fedora kernel: (sb_security_lock){--..}, at:
    > [<c01d6400>] selinux_sb_free_security+0x17/0x4e
    > May 30 20:25:56 ltg01-fedora kernel:
    > May 30 20:25:56 ltg01-fedora kernel: but task is already holding lock:
    > May 30 20:25:56 ltg01-fedora kernel: (sb_lock){--..}, at:

    we're holding "sb_lock" already, and are trying to get sb_security_lock

    > [<c0178a89>] put_super+0x10/0x24
    > May 30 20:25:56 ltg01-fedora kernel:
    > May 30 20:25:56 ltg01-fedora kernel: which lock already depends on the new lock,

    ... but there was an observed code sequence before which was the other
    way around ...
    > May 30 20:25:56 ltg01-fedora kernel: which could lead to circular deadlocks!

    yes.

    > May 30 20:25:56 ltg01-fedora kernel:
    > May 30 20:25:56 ltg01-fedora kernel: the existing dependency chain (in
    > reverse order) is:

    now it's going to print the previously observed behavior (backwards),
    and give a backtrace of where that was acquired
    > May 30 20:25:56 ltg01-fedora kernel:
    > May 30 20:25:56 ltg01-fedora kernel: -> #1 (sb_lock){--..}:

    since it prints backwards, this is the latest of the 2 locks taken in
    the old situaion

    > May 30 20:25:56 ltg01-fedora kernel: [<c0139a56>]
    > lockdep_acquire+0x69/0x82
    > May 30 20:25:56 ltg01-fedora kernel: [<c02f2171>] _spin_lock+0x21/0x2f
    > May 30 20:25:56 ltg01-fedora kernel: [<c01d72de>]
    > selinux_complete_init+0x45/0xda

    and it was in selinux_complete_init

    for some reason the #0 is not being printed here (it normally is), which
    would give a simliar backtrace. In this case it was ok,
    selinux_complete_init was the sole guilty party.

    > May 30 20:25:56 ltg01-fedora kernel:
    > May 30 20:25:56 ltg01-fedora kernel: other info that might help us debug this:
    > May 30 20:25:56 ltg01-fedora kernel:
    now it's going to print all the locks we own currently, and where those
    were taken; not just the ones that are part of the deadlock (that was
    printed before)

    > May 30 20:25:56 ltg01-fedora kernel: 1 locks held by umount/2322:
    > May 30 20:25:56 ltg01-fedora kernel: #0: (sb_lock){--..}, at:
    > [<c0178a89>] put_super+0x10/0x24

    ok so in put_super we took sb_lock. [*]

    > May 30 20:25:56 ltg01-fedora kernel:
    > May 30 20:25:56 ltg01-fedora kernel: stack backtrace:
    > May 30 20:25:56 ltg01-fedora kernel: [<c0103e52>] show_trace_log_lvl+0x4b/0xf4
    > May 30 20:25:56 ltg01-fedora kernel: [<c01044b3>] show_trace+0xd/0x10
    > May 30 20:25:56 ltg01-fedora kernel: [<c010457b>] dump_stack+0x19/0x1b
    > May 30 20:25:56 ltg01-fedora kernel: [<c0138bd6>]
    > print_circular_bug_tail+0x59/0x64
    > May 30 20:25:56 ltg01-fedora kernel: [<c0139429>] __lockdep_acquire+0x848/0xa39
    > May 30 20:25:56 ltg01-fedora kernel: [<c0139a56>] lockdep_acquire+0x69/0x82
    > May 30 20:25:56 ltg01-fedora kernel: [<c02f2171>] _spin_lock+0x21/0x2f

    these are just the lockdep printing stuff

    > May 30 20:25:56 ltg01-fedora kernel: [<c01d6400>]
    > selinux_sb_free_security+0x17/0x4e

    but here it gets interesting; this is the function that triggered the
    final deadlock message (well we knew that already from the first line of
    the message), which gets called from

    > May 30 20:25:56 ltg01-fedora kernel: [<c0178a68>] __put_super+0x24/0x35
    which gets called from

    > May 30 20:25:56 ltg01-fedora kernel: [<c0178a90>] put_super+0x17/0x24

    ... but wait we know this one already from where I put [*], so we're now
    done. put_super takes sb_lock, then calls __put_super which calls
    selinux_sb_free_security which takes sb_security lock.

    >From the old pattern we knew the opposite order in
    selinux_complete_init(), and we have our AB-BA deadlock


    > May 30 20:25:56 ltg01-fedora kernel: [<c01793a3>] deactivate_super+0xa3/0xad
    > May 30 20:25:56 ltg01-fedora kernel: [<c018e010>] mntput_no_expire+0x52/0x85
    > May 30 20:25:56 ltg01-fedora kernel: [<c017fcb0>]
    > path_release_on_umount+0x15/0x18
    > May 30 20:25:56 ltg01-fedora kernel: [<c018f535>] sys_umount+0x292/0x2aa

    well we also now know that it came from a sys_umount; that might help
    chasing stuff down if it's more fuzzy than this example


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

    \
     
     \ /
      Last update: 2006-05-30 21:58    [W:0.027 / U:87.108 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site