linux-kernel - Re: [ANNOUNCE] 3.0-rt3 (futex

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <4E2F70A6.6070008@linux.intel.com>
Date:	Tue, 26 Jul 2011 18:57:58 -0700
From:	Darren Hart <dvhart@...ux.intel.com>
To:	Maarten Lankhorst <m.b.lankhorst@...il.com>
CC:	Thomas Gleixner <tglx@...utronix.de>,
	LKML <linux-kernel@...r.kernel.org>,
	linux-rt-users <linux-rt-users@...r.kernel.org>
Subject: Re: [ANNOUNCE] 3.0-rt3 (futex_requeue bad spinlock magic)

On 07/26/2011 10:11 AM, Maarten Lankhorst wrote:
> On 07/26/2011 07:01 PM, Darren Hart wrote:
>>
>> On 07/26/2011 04:44 AM, Maarten Lankhorst wrote:
>>> On 07/26/2011 08:00 AM, Darren Hart wrote:
>>>> On 07/25/2011 03:20 PM, Darren Hart wrote:
>>>>> On 07/24/2011 09:12 AM, Thomas Gleixner wrote:
>>>>>> On Sun, 24 Jul 2011, Maarten Lankhorst wrote:
>>>>> ...
>>>>>
>>>>>>> Also not sure where this one came from:
>>>>>>> [   37.456688] BUG: spinlock bad magic on CPU#3, threaded-ml/1619
>>>>>>> [   37.456690]  lock: ffff8801fdc74d50, .magic: 00000000, .owner: <none>/-1, .owner_cpu: 0
>>>>>>> [   37.456692] Pid: 1619, comm: threaded-ml Tainted: G         C  3.0.0-rt3-patser+ #39
>> Maarten, I'm finding fairly little out there on what threaded-ml might
>> be. What I do find suggests 3D visualization and real-time audio
>> playback. Are you working with something like this? If so, which
>> libraries are you using? If not, any idea what this is?
> threaded ml = from pulseaudio,
> src/pulse/thread-mainloop.c to be exact. But like I said it occurs with the functional broadcast test too, on the waker thread.
>>>>>>> [   37.456693] Call Trace:
>>>>>>> [   37.456697]  [<ffffffff81607a78>] spin_bug+0xa0/0xa8
>>>>>>> [   37.456699]  [<ffffffff8132b412>] do_raw_spin_lock+0xa2/0x170
>>>>>>> [   37.456702]  [<ffffffff8104a201>] ? get_parent_ip+0x11/0x50
>>>>>>> [   37.456704]  [<ffffffff8160d783>] _raw_spin_lock+0x23/0x30
>>>>>>> [   37.456706]  [<ffffffff810931ce>] rt_mutex_start_proxy_lock+0x2e/0xd0
>>>>>>> [   37.456708]  [<ffffffff8109093a>] futex_requeue+0x47a/0x850
>>>>>>> [   37.456710]  [<ffffffff8109138e>] do_futex+0xae/0xb00
>> Maarten, could you provide the addr2line of the addresses from do_futex
>> to spin_bug ? This will help me trace the path.
> decodes to:
> linux/lib/spinlock_debug.c:72
> linux/lib/spinlock_debug.c:79
> linux/kernel/sched.c:4114
> linux/kernel/spinlock.c:141
> linux/kernel/rtmutex.c:100
> linux/kernel/futex.c:1378
> linux/kernel/futex.c:2662

OK, so we're entering with a FUTEX_CMP_REQUEUE op (not FUTEX_CMP_REQUEUE_PI),
and land inside an "if (requeue_pi)" block in the futex_requeue() function -
that should never happen. The interesting thing about this is pulse is only
using the non PI pthread_cond calls, and thus FUTEX_CMP_REQUEUE,
(http://gitorious.org/~elmarco/pulseaudio/pa-work/blobs/1ca76031092ab07682843fd70607696f6af7216f/src/pulsecore/mutex-posix.c). I have not been able reproduce this path.

My best guess at the moment is that we are somehow stomping on the requeue_pi
value causing the waker to enter the wrong code paths. A simple test would be to
print the value of requeue_pi throughout futex_requeue() and see if it changes
(it shouldn't) and if it is something other than 0 or 1 (which it should never
be). Are you able to reliably reproduce the pulse audio failure?

The futex_requeue_pi test is of course using FUTEX_CMP_REQUEUE_PI, and it will
reproduce a similar path (except via the FUTEX_CMP_REQUEUE_PI demux path as it
should be) on the first time run, as Maarten observed. I have seen this with
and without the -b (broadcast) option to the test.

I was able to reproduce this on my system by adding the following to my config:
+CONFIG_DEBUG_RT_MUTEXES=y
+CONFIG_DEBUG_PI_LIST=y
+CONFIG_DEBUG_SPINLOCK=y

With a similar config, this does not occur on 2.6.33.9-rt31. Nothing jumps out
as obviously wrong in the futex delta from 33-rt to now.

I tried with 3.0.0 (non rt) with a similar .config and the problem is not
reproducible. I'll continue to try and isolate the problem, focusing mainly on
the futex delta from 3.0.0. Right after I get the kids to bed...

-- 
Darren Hart
Intel Open Source Technology Center
Yocto Project - Linux Kernel
--
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/