Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755011Ab0F1O5I (ORCPT ); Mon, 28 Jun 2010 10:57:08 -0400 Received: from e35.co.us.ibm.com ([32.97.110.153]:38621 "EHLO e35.co.us.ibm.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751456Ab0F1O5D (ORCPT ); Mon, 28 Jun 2010 10:57:03 -0400 Message-ID: <4C28B825.3000506@us.ibm.com> Date: Mon, 28 Jun 2010 07:56:37 -0700 From: Darren Hart User-Agent: Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.1.9) Gecko/20100423 Thunderbird/3.0.4 MIME-Version: 1.0 To: Michal Hocko CC: Thomas Gleixner , Peter Zijlstra , LKML , Nick Piggin , Alexey Kuznetsov , Linus Torvalds Subject: Re: futex: race in lock and unlock&exit for robust futex with PI? References: <20100623091307.GA11072@tiehlicka.suse.cz> <4C2417AA.4030306@us.ibm.com> <20100625082711.GA32765@tiehlicka.suse.cz> <4C24ED34.9040808@us.ibm.com> <4C253D32.6040304@us.ibm.com> <20100628144246.GA14201@tiehlicka.suse.cz> In-Reply-To: <20100628144246.GA14201@tiehlicka.suse.cz> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 8805 Lines: 183 On 06/28/2010 07:42 AM, Michal Hocko wrote: > Hi Darren, > > On Fri 25-06-10 16:35:14, Darren Hart wrote: > [...] >> # trace-cmd record -p nop ./runSimple.sh >> >> >> # ps -eLo pid,comm,wchan | grep "simple " >> 20636 simple pause >> 20876 simple pause >> >> # trace-cmd report >> version = 6 >> CPU 0 is empty >> cpus=4 >> field->offset = 24 size=8 >> <...>-20636 [003] 1778.965860: bprint: futex_lock_pi_atomic : lookup_pi_state: -ESRCH >> <...>-20636 [003] 1778.965865: bprint: futex_lock_pi_atomic : ownerdied not detected, returning -ESRCH >> <...>-20636 [003] 1778.965866: bprint: futex_lock_pi_atomic : lookup_pi_state: -3 >>>> ---> <...>-20636 [003] 1778.965867: bprint: futex_lock_pi : returning -ESRCH to userspace >> <...>-20876 [001] 1780.199394: bprint: futex_lock_pi_atomic : cmpxchg failed, retrying >> <...>-20876 [001] 1780.199400: bprint: futex_lock_pi_atomic : lookup_pi_state: -ESRCH >> <...>-20876 [001] 1780.199401: bprint: futex_lock_pi_atomic : ownerdied not detected, returning -ESRCH >> <...>-20876 [001] 1780.199402: bprint: futex_lock_pi_atomic : lookup_pi_state: -3 >>>> ---> <...>-20876 [001] 1780.199403: bprint: futex_lock_pi : returning -ESRCH to userspace >> <...>-21316 [002] 1782.300695: bprint: futex_lock_pi_atomic : cmpxchg failed, retrying >> <...>-21316 [002] 1782.300698: bprint: futex_lock_pi_atomic : cmpxchg failed, retrying >> > [...] > > I have updated the test case slightly (reduced the number of lock/unlock > cycles to 1). > > Then, I have used the additional patch (see bellow) on top of the one > you have posted and here is the log I am getting: Interesting. I'm going to start pouring over lookup_pi_state() and futex_lock_pi() to see if I can spot any races. I'm also wondering about glibc's usage of the FUTEX_WAITERS bit. While I investigate that, could you do a git bisect from 2.6.31 (after which a lot of the most recent futex changes hit) and see if you can identify a particular patch, or even kernel version, where this broke? Thanks, Darren > > version = 6 > cpus=2 > field->offset = 16 size=4 > <...>-13232 [001] 226.693880: bprint: do_futex : futex_lock_pi start > <...>-13232 [001] 226.693886: bprint: do_futex : futex_lock_pi done ret=0 > <...>-13235 [001] 226.700204: bprint: do_futex : futex_lock_pi start > <...>-13235 [001] 226.700210: bprint: futex_lock_pi_atomic : lookup_pi_state: -ESRCH for pid=13242 > <...>-13235 [001] 226.700211: bprint: futex_lock_pi_atomic : ownerdied not detected, returning -ESRCH > <...>-13235 [001] 226.700211: bprint: futex_lock_pi_atomic : lookup_pi_state: -3 > <...>-13235 [001] 226.700212: bprint: futex_lock_pi : returning -ESRCH to userspace > <...>-13235 [001] 226.700212: bprint: do_futex : futex_lock_pi done ret=-3 > <...>-13240 [000] 226.705574: bprint: do_futex : futex_lock_pi start > <...>-13240 [000] 226.705580: bprint: futex_lock_pi_atomic : lookup_pi_state: -ESRCH for pid=13242 > <...>-13240 [000] 226.705581: bprint: futex_lock_pi_atomic : ownerdied not detected, returning -ESRCH > <...>-13240 [000] 226.705582: bprint: futex_lock_pi_atomic : lookup_pi_state: -3 > <...>-13240 [000] 226.705582: bprint: futex_lock_pi : returning -ESRCH to userspace > <...>-13240 [000] 226.705583: bprint: do_futex : futex_lock_pi done ret=-3 > <...>-13231 [000] 226.708095: bprint: do_futex : futex_lock_pi start > <...>-13231 [000] 226.708101: bprint: futex_lock_pi_atomic : lookup_pi_state: -ESRCH for pid=13242 > <...>-13231 [000] 226.708102: bprint: futex_lock_pi_atomic : ownerdied not detected, returning -ESRCH > <...>-13231 [000] 226.708102: bprint: futex_lock_pi_atomic : lookup_pi_state: -3 > <...>-13231 [000] 226.708103: bprint: futex_lock_pi : returning -ESRCH to userspace > <...>-13231 [000] 226.708103: bprint: do_futex : futex_lock_pi done ret=-3 > <...>-13242 [001] 226.709246: bprint: do_futex : futex_unlock_pi start > <...>-13242 [001] 226.709249: bprint: do_futex : futex_unlock_pi: TID->0 transition 2147496890 > <...>-13242 [001] 226.709250: bprint: do_futex : futex_unlock_pi: no waiters, unlock the futex ret=0 uval=-2147470406 > <...>-13242 [001] 226.709250: bprint: do_futex : futex_unlock_pi done ret=0 > > As you can see lookup_pi_state fails for the pid (13242) which is at the very > bottom and that is unlocking the futex. This smells fishy to me. I can > see this pattern consistently for all failures. Maybe I am doing > something wrong or the timestamps are not precise enough but from what I > can see this looks like a bug in lookup_pi_state which doesn't find an > existing PID. > > -- > From 733816347db91670f27d206382b8c2e57e5ef125 Mon Sep 17 00:00:00 2001 > From: Michal Hocko > Date: Mon, 28 Jun 2010 13:42:29 +0200 > Subject: [PATCH] futex pi unlock tracing added > > --- > kernel/futex.c | 24 +++++++++++++++++++----- > 1 files changed, 19 insertions(+), 5 deletions(-) > > diff --git a/kernel/futex.c b/kernel/futex.c > index 24ac437..d114fee 100644 > --- a/kernel/futex.c > +++ b/kernel/futex.c > @@ -716,7 +716,8 @@ retry: > if (unlikely(ret)) { > switch (ret) { > case -ESRCH: > - trace_printk("lookup_pi_state: -ESRCH\n"); > + trace_printk("lookup_pi_state: -ESRCH for pid=%u\n", > + uval& FUTEX_TID_MASK); > /* > * No owner found for this futex. Check if the > * OWNER_DIED bit is set to figure out whether > @@ -2070,8 +2071,10 @@ retry: > * again. If it succeeds then we can return without waking > * anyone else up: > */ > - if (!(uval& FUTEX_OWNER_DIED)) > + if (!(uval& FUTEX_OWNER_DIED)) { > uval = cmpxchg_futex_value_locked(uaddr, task_pid_vnr(current), 0); > + trace_printk("futex_unlock_pi: TID->0 transition %u\n", uval); > + } > > > if (unlikely(uval == -EFAULT)) > @@ -2080,8 +2083,10 @@ retry: > * Rare case: we managed to release the lock atomically, > * no need to wake anyone else up: > */ > - if (unlikely(uval == task_pid_vnr(current))) > + if (unlikely(uval == task_pid_vnr(current))) { > + trace_printk("futex_unlock_pi: release without wakeup\n"); > goto out_unlock; > + } > > /* > * Ok, other tasks may need to be woken up - check waiters > @@ -2093,6 +2098,7 @@ retry: > if (!match_futex (&this->key,&key)) > continue; > ret = wake_futex_pi(uaddr, uval, this); > + trace_printk("futex_unlock_pi: wake ret=%d uval=%u this=%p\n", ret, uval, this); > /* > * The atomic access to the futex value > * generated a pagefault, so retry the > @@ -2107,6 +2113,8 @@ retry: > */ > if (!(uval& FUTEX_OWNER_DIED)) { > ret = unlock_futex_pi(uaddr, uval); > + trace_printk("futex_unlock_pi: no waiters, unlock the futex ret=%d uval=%d\n", > + ret, uval); > if (ret == -EFAULT) > goto pi_faulted; > } > @@ -2600,12 +2608,18 @@ long do_futex(u32 __user *uaddr, int op, u32 val, ktime_t *timeout, > ret = futex_wake_op(uaddr, fshared, uaddr2, val, val2, val3); > break; > case FUTEX_LOCK_PI: > - if (futex_cmpxchg_enabled) > + if (futex_cmpxchg_enabled) { > + trace_printk("futex_lock_pi start\n"); > ret = futex_lock_pi(uaddr, fshared, val, timeout, 0); > + trace_printk("futex_lock_pi done ret=%d\n", ret); > + } > break; > case FUTEX_UNLOCK_PI: > - if (futex_cmpxchg_enabled) > + if (futex_cmpxchg_enabled) { > + trace_printk("futex_unlock_pi start\n"); > ret = futex_unlock_pi(uaddr, fshared); > + trace_printk("futex_unlock_pi done ret=%d\n", ret); > + } > break; > case FUTEX_TRYLOCK_PI: > if (futex_cmpxchg_enabled) -- Darren Hart IBM Linux Technology Center Real-Time Linux Team -- 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/