Re: futex: race in lock and unlock&exit for robust futex with PI?
From: Darren Hart
Date: Mon Jun 28 2010 - 10:57:11 EST
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
<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
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@xxxxxxx>
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@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/