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
python-3490 [002] 259.044843: futex_wait: normal futex wake-up detected for python-3490
python-3490 [002] 259.044848: futex_wait <-do_futex
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
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