Date:	Mon, 12 Oct 2009 21:54:36 -0700
From:	Darren Hart <dvhltc@...ibm.com>
To:	Blaise Gassend <blaise@...lowgarage.com>
CC:	Jeremy Leibs <leibs@...lowgarage.com>,
	Thomas Gleixner <tglx@...utronix.de>,
	Peter Zijlstra <peterz@...radead.org>,
	"lkml, " <linux-kernel@...r.kernel.org>
Subject: Re: ERESTARTSYS escaping from sem_wait with RTLinux patch

Darren Hart wrote:
> Resending, hopefully with fixed whitespace mangling in the trace this
> time...
> 
> Darren Hart wrote:
>> Darren Hart wrote:
>>> Blaise Gassend wrote:
>>>> A few more questions you may have answers to:
>>>>
>>>> Do you have any idea what this comment in futex.c could be referring 
>>>> to?
>>>>
>>>> /*  * We expect signal_pending(current), but another thread may  * 
>>>> have handled it for us already.  */
>>>> As far as I have been able to understand, signals are thread-specific,
>>>> and hence it doesn't make sense to me that another thread could have
>>>> handled it.
>>>
>>> Signals are only thread specific when using something like
>>> pthread_kill() to send the signal, otherwise they are process wide.
>>>
>>>>
>>>>> OK, so I suspect one of two things.
>>>>>
>>>>> 1) Recent changes to futex.c have somehow created a wakeup race and
>>>>>     unqueue_me() doesn't detect it was woken with FUTEX_WAKE, then 
>>>>> falls
>>>>>     out through the ERESTARTSYS path.
>>>>>
>>>>> 2) Recent changes have exposed an existing race in unqueue_me().
>>>>
>>>> Is it possible that there aren't many people using PREEMPT RT on 8 CPU
>>>> machines, and hence this is a bug that just has't been observed yet?
>>>
>>> We actually do extensive testing on 8way systems with some large apps
>>> that beat on futexes pretty badly.  You've simply uncovered a nasty
>>> little race in the wakeup path.
>>>
>>> I believe I have identified the patch where this became possible (I
>>> don't say the cause of the bug, because it's possible this patch simply
>>> exposed an existing race):
>>>
>>> 928686b77ab275fd7f828ff24bd510baca995425 futex: Wake up waiter outside
>>> the hb->lock section
>>>
>>> I am currently instrumenting the futex code and trying to identify how
>>> the race occurs.
> 
> ...
> 
>>> Full output here:
> 
> ...
> 
>> http://dvhart.com/darren/files/futex_wake_function.trace.gz
>>
>> It's a tad difficult to navigate, but I believe I am seeing 
>> wake_futex_list() try and wake python-3490 without previously adding 
>> it to the wake-list.  If we are somehow not cleaning up our wake_list, 
>> this would explain why unqueue_me() sees the q->lock_ptr as non-null - 
>> wake_futex() wasn't called to clear it.
> 
> OK, I believe I can confirm this with this subset of the trace. It follows
> three futex_wait and wake-up cycles. The third wake-up occurs without the
> python-3490 thread ever having been added to the wake_list (at least, there
> is not record of it in the trace). Now to see why this might be the case...
> 
>         python-3490  [002]   259.041420: futex_wait <-do_futex
>         python-3490  [002]   259.041420: futex_wait_setup <-futex_wait
>         python-3490  [002]   259.043888: futex_wait_queue_me <-futex_wait
>         python-3490  [002]   259.043888: queue_me <-futex_wait_queue_me
>         python-3490  [002]   259.043920: schedule <-futex_wait_queue_me
>      python-3507  [004]   259.043929: wake_futex: adding python-3490 to 
> wake_list
>      python-3507  [004]   259.043957: wake_futex_list: wake_futex_list: 
> waking python-3490
>      python-3490  [002]   259.043981: futex_wait: normal futex wake-up 
> detected for python-3490
> 
>         python-3490  [002]   259.043987: futex_wait <-do_futex
>      python-3490  [002]   259.043987: futex_wait_setup <-futex_wait
>      python-3490  [002]   259.044323: futex_wait_queue_me <-futex_wait
>      python-3490  [002]   259.044323: queue_me <-futex_wait_queue_me
>      python-3495  [002]   259.044571: wake_futex: adding python-3490 to 
> wake_list

Interesting, here we never see a wake_futex_list: waking python-3490.
So the task wakes here and thinks it is a normal wakeup, when perhaps it is
not. If a timeout or a signal were to occur here, we would not detect them
as unqueue_me() would see the lock_ptr had been nulled by wake_futex(). The
task returns to userspace ignoring the timeout or signal.

>      python-3490  [002]   259.044843: futex_wait: normal futex wake-up 
> detected for python-3490
> 
>      python-3490  [002]   259.044848: futex_wait <-do_futex

The app then puts it back to sleep here.


>      python-3490  [002]   259.044848: futex_wait_setup <-futex_wait
>      python-3490  [002]   259.046648: futex_wait_queue_me <-futex_wait
>      python-3490  [002]   259.046648: queue_me <-futex_wait_queue_me
>      python-3490  [002]   259.046664: schedule <-futex_wait_queue_me
>           ********* python-3490 was never added to the wake_list !!!!!!! 
> *********
> 
>      python-3495  [002]   259.046680: wake_futex_list: wake_futex_list: 
> waking python-3490

When 3495 finally get's to run and complete it's futex_wake() call, the task
still needs to be woken, so we wake it - but now it's enqueued with a different
futex_q, which now has a valid lock_ptr, so upon wake-up we expect a signal!

OK, I believe this establishes root cause.  Now to come up with a fix...

>      python-3490  [002]   259.046816: futex_wait: returning 1, non-futex 
> wakeup for python-3490
>      python-3490  [002]   259.046817: futex_wait: p->futex_wakeup: (null)
>      python-3490  [002]   259.046819: futex_wait: error in wake-up 
> detection, no signal pending for python-3490

Thanks,

-- 
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@...r.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Powered by blists - more mailing lists