On 06/28/2010 07:42 AM, Michal Hocko wrote:
quoted text
> Hi Darren,
>
> On Fri 25-06-10 16:35:14, Darren Hart wrote:
> [...]
>> # trace-cmd record -p nop ./runSimple.sh
>> <snip>
>>
>> # 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

quoted text
>
> 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<mhocko@suse.cz>
> 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
--
unsubscribe notice
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/