Skip to contentSkip to conversation

MAX_LOCKDEP_ENTRIES too low (called from ioc_release_fn)

DISCUSSION Dave Jones 4 participants 15 messages Oct 18, 2012 – Nov 21, 2012

lore
Share & tools
lore

Dave Jones

author
#0 lore raw

Triggered while fuzz testing..

BUG: MAX_LOCKDEP_ENTRIES too low!
turning off the locking correctness validator.
Pid: 22788, comm: kworker/2:1 Not tainted 3.7.0-rc1+ #34
Call Trace:
 [<ffffffff810decdd>] add_lock_to_list.isra.29.constprop.45+0xdd/0xf0
 [<ffffffff810e2871>] __lock_acquire+0x1121/0x1ba0
 [<ffffffff810e3a12>] lock_acquire+0xa2/0x220
 [<ffffffff8117bad2>] ? free_one_page+0x32/0x450
 [<ffffffff816c5a59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff816c0800>] _raw_spin_lock+0x40/0x80
 [<ffffffff8117bad2>] ? free_one_page+0x32/0x450
 [<ffffffff8117bad2>] free_one_page+0x32/0x450
 [<ffffffff8117bf41>] ? __free_pages_ok.part.58+0x51/0x110
 [<ffffffff8117bf9c>] __free_pages_ok.part.58+0xac/0x110
 [<ffffffff8117cd73>] __free_pages+0x73/0x90
 [<ffffffff811cb4f3>] __free_slab+0xd3/0x1b0
 [<ffffffff811cb609>] discard_slab+0x39/0x50
 [<ffffffff816b77db>] __slab_free+0x378/0x3a3
 [<ffffffff81341289>] ? ioc_release_fn+0x99/0xe0
 [<ffffffff81341289>] ? ioc_release_fn+0x99/0xe0
 [<ffffffff811cd4e2>] kmem_cache_free+0x2f2/0x320
 [<ffffffff816c5a59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff81341289>] ioc_release_fn+0x99/0xe0
 [<ffffffff81095a37>] process_one_work+0x207/0x780
 [<ffffffff810959c7>] ? process_one_work+0x197/0x780
 [<ffffffff813411f0>] ? get_io_context+0x20/0x20
 [<ffffffff8109638e>] worker_thread+0x15e/0x440
 [<ffffffff81096230>] ? rescuer_thread+0x240/0x240
 [<ffffffff8109d0cd>] kthread+0xed/0x100
 [<ffffffff810de02e>] ? put_lock_stats.isra.25+0xe/0x40
 [<ffffffff8109cfe0>] ? kthread_create_on_node+0x160/0x160
 [<ffffffff816c9dac>] ret_from_fork+0x7c/0xb0
 [<ffffffff8109cfe0>] ? kthread_create_on_node+0x160/0x160
#1 lore raw
Quoted 28 lines · Dave Jones

Triggered while fuzz testing..

BUG: MAX_LOCKDEP_ENTRIES too low!
turning off the locking correctness validator.
Pid: 22788, comm: kworker/2:1 Not tainted 3.7.0-rc1+ #34
Call Trace:
 [<ffffffff810decdd>] add_lock_to_list.isra.29.constprop.45+0xdd/0xf0
 [<ffffffff810e2871>] __lock_acquire+0x1121/0x1ba0
 [<ffffffff810e3a12>] lock_acquire+0xa2/0x220
 [<ffffffff8117bad2>] ? free_one_page+0x32/0x450
 [<ffffffff816c5a59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff816c0800>] _raw_spin_lock+0x40/0x80
 [<ffffffff8117bad2>] ? free_one_page+0x32/0x450
 [<ffffffff8117bad2>] free_one_page+0x32/0x450
 [<ffffffff8117bf41>] ? __free_pages_ok.part.58+0x51/0x110
 [<ffffffff8117bf9c>] __free_pages_ok.part.58+0xac/0x110
 [<ffffffff8117cd73>] __free_pages+0x73/0x90
 [<ffffffff811cb4f3>] __free_slab+0xd3/0x1b0
 [<ffffffff811cb609>] discard_slab+0x39/0x50
 [<ffffffff816b77db>] __slab_free+0x378/0x3a3
 [<ffffffff81341289>] ? ioc_release_fn+0x99/0xe0
 [<ffffffff81341289>] ? ioc_release_fn+0x99/0xe0
 [<ffffffff811cd4e2>] kmem_cache_free+0x2f2/0x320
 [<ffffffff816c5a59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff81341289>] ioc_release_fn+0x99/0xe0
 [<ffffffff81095a37>] process_one_work+0x207/0x780
 [<ffffffff810959c7>] ? process_one_work+0x197/0x780
Quoted 8 lines
 [<ffffffff813411f0>] ? get_io_context+0x20/0x20
 [<ffffffff8109638e>] worker_thread+0x15e/0x440
 [<ffffffff81096230>] ? rescuer_thread+0x240/0x240
 [<ffffffff8109d0cd>] kthread+0xed/0x100
 [<ffffffff810de02e>] ? put_lock_stats.isra.25+0xe/0x40
 [<ffffffff8109cfe0>] ? kthread_create_on_node+0x160/0x160
 [<ffffffff816c9dac>] ret_from_fork+0x7c/0xb0
 [<ffffffff8109cfe0>] ? kthread_create_on_node+0x160/0x160

Not sure why you are CC'ing a call site, rather than the maintainers of the code. Just looks like lockdep is using too small a static value. Though it is pretty darn large...

Signature · 1 line
Jens Axboe
author
#2 lore raw
Quoted 38 lines · Jens Axboe
Quoted 28 lines · Dave Jones

Triggered while fuzz testing..

BUG: MAX_LOCKDEP_ENTRIES too low!
turning off the locking correctness validator.
Pid: 22788, comm: kworker/2:1 Not tainted 3.7.0-rc1+ #34
Call Trace:
 [<ffffffff810decdd>] add_lock_to_list.isra.29.constprop.45+0xdd/0xf0
 [<ffffffff810e2871>] __lock_acquire+0x1121/0x1ba0
 [<ffffffff810e3a12>] lock_acquire+0xa2/0x220
 [<ffffffff8117bad2>] ? free_one_page+0x32/0x450
 [<ffffffff816c5a59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff816c0800>] _raw_spin_lock+0x40/0x80
 [<ffffffff8117bad2>] ? free_one_page+0x32/0x450
 [<ffffffff8117bad2>] free_one_page+0x32/0x450
 [<ffffffff8117bf41>] ? __free_pages_ok.part.58+0x51/0x110
 [<ffffffff8117bf9c>] __free_pages_ok.part.58+0xac/0x110
 [<ffffffff8117cd73>] __free_pages+0x73/0x90
 [<ffffffff811cb4f3>] __free_slab+0xd3/0x1b0
 [<ffffffff811cb609>] discard_slab+0x39/0x50
 [<ffffffff816b77db>] __slab_free+0x378/0x3a3
 [<ffffffff81341289>] ? ioc_release_fn+0x99/0xe0
 [<ffffffff81341289>] ? ioc_release_fn+0x99/0xe0
 [<ffffffff811cd4e2>] kmem_cache_free+0x2f2/0x320
 [<ffffffff816c5a59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff81341289>] ioc_release_fn+0x99/0xe0
 [<ffffffff81095a37>] process_one_work+0x207/0x780
 [<ffffffff810959c7>] ? process_one_work+0x197/0x780
Quoted 8 lines
 [<ffffffff813411f0>] ? get_io_context+0x20/0x20
 [<ffffffff8109638e>] worker_thread+0x15e/0x440
 [<ffffffff81096230>] ? rescuer_thread+0x240/0x240
 [<ffffffff8109d0cd>] kthread+0xed/0x100
 [<ffffffff810de02e>] ? put_lock_stats.isra.25+0xe/0x40
 [<ffffffff8109cfe0>] ? kthread_create_on_node+0x160/0x160
 [<ffffffff816c9dac>] ret_from_fork+0x7c/0xb0
 [<ffffffff8109cfe0>] ? kthread_create_on_node+0x160/0x160
Quoted 3 lines

Not sure why you are CC'ing a call site, rather than the maintainers of the code. Just looks like lockdep is using too small a static value. Though it is pretty darn large...

You're right, it's a huge chunk of memory.
It looks like I can trigger this from multiple callsites.. Another different trace below.

Not sure why this suddenly got a lot worse in 3.7

Peter, Ingo ?

Dave

BUG: MAX_LOCKDEP_ENTRIES too low!
turning off the locking correctness validator.
Pid: 22350, comm: trinity-child0 Not tainted 3.7.0-rc1+ #36
Call Trace:
 [<ffffffff810decdd>] add_lock_to_list.isra.29.constprop.45+0xdd/0xf0
 [<ffffffff810e2871>] __lock_acquire+0x1121/0x1ba0
 [<ffffffff810b6f89>] ? local_clock+0x89/0xa0
 [<ffffffff811b84a5>] ? __swap_duplicate+0xb5/0x190
 [<ffffffff810dea58>] ? trace_hardirqs_off_caller+0x28/0xd0
 [<ffffffff810e3a12>] lock_acquire+0xa2/0x220
 [<ffffffff811b663d>] ? __add_to_swap_cache+0x6d/0x180
 [<ffffffff816c0f79>] ? _raw_spin_lock_irq+0x29/0x90
 [<ffffffff816c0fa6>] _raw_spin_lock_irq+0x56/0x90
 [<ffffffff811b663d>] ? __add_to_swap_cache+0x6d/0x180
 [<ffffffff811b663d>] __add_to_swap_cache+0x6d/0x180
 [<ffffffff811b6c45>] read_swap_cache_async+0xb5/0x220
 [<ffffffff811b6e4e>] swapin_readahead+0x9e/0xf0
 [<ffffffff811a2c86>] handle_pte_fault+0x6d6/0xae0
 [<ffffffff816c5ad9>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff8136d37e>] ? delay_tsc+0xae/0x120
 [<ffffffff8136d268>] ? __const_udelay+0x28/0x30
 [<ffffffff811a4919>] handle_mm_fault+0x289/0x350
 [<ffffffff816c538e>] __do_page_fault+0x18e/0x530
 [<ffffffff810b6f89>] ? local_clock+0x89/0xa0
 [<ffffffff816b77e1>] ? __slab_free+0x32e/0x3a3
 [<ffffffff8112d2e9>] ? rcu_user_exit+0xc9/0xf0
 [<ffffffffa0000020>] ? 0xffffffffa000001f
 [<ffffffffa0000020>] ? 0xffffffffa000001f
 [<ffffffff816c575b>] do_page_fault+0x2b/0x50
 [<ffffffff816c1e38>] page_fault+0x28/0x30
 [<ffffffffa0000020>] ? 0xffffffffa000001f
 [<ffffffff813885ac>] ? strncpy_from_user+0x6c/0x120
 [<ffffffffa0000020>] ? 0xffffffffa000001f
 [<ffffffff8120e94f>] setxattr+0x6f/0x1d0
 [<ffffffff816c5ad9>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff8137e8b5>] ? __percpu_counter_add+0x75/0xc0
 [<ffffffff811e92d1>] ? __sb_start_write+0x101/0x1d0
 [<ffffffff81209d94>] ? mnt_want_write+0x24/0x50
 [<ffffffff81209d94>] ? mnt_want_write+0x24/0x50
 [<ffffffff810b0de1>] ? get_parent_ip+0x11/0x50
 [<ffffffff816c5ad9>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff81209d30>] ? __mnt_want_write+0x60/0xa0
 [<ffffffffa0000020>] ? 0xffffffffa000001f
 [<ffffffff8120ecd5>] sys_setxattr+0x95/0xb0
 [<ffffffff816ca108>] tracesys+0xe1/0xe6
 [<ffffffffa0000020>] ? 0xffffffffa000001f
#3 lore raw
Quoted 9 lines · Dave Jones
Quoted 3 lines

Not sure why you are CC'ing a call site, rather than the maintainers of the code. Just looks like lockdep is using too small a static value. Though it is pretty darn large...

You're right, it's a huge chunk of memory.
It looks like I can trigger this from multiple callsites.. Another different trace below.

Not sure why this suddenly got a lot worse in 3.7

Did we add a static array of structures with locks in somewhere? Doing that is a great way of blowing up the number of lock classes and the resulting amount of lock dependency chains.

Quoted 1 line

From Documentation/lockdep-design.txt; it talks about overflowing

MAX_LOCKDEP_KEYS, but I suppose its a good starts for overflowing the dependency entries too, more classes means more dependencies after all.

---
Of course, if you do run out of lock classes, the next thing to do is to find the offending lock classes. First, the following command gives you the number of lock classes currently in use along with the maximum:

grep "lock-classes" /proc/lockdep_stats

This command produces the following output on a modest system:

lock-classes: 748 [max: 8191]

If the number allocated (748 above) increases continually over time, then there is likely a leak. The following command can be used to identify the leaking lock classes:

grep "BD" /proc/lockdep

Run the command and save the output, then compare against the output from a later run of this command to identify the leakers. This same output can also help you find situations where runtime lock initialization has been omitted.

author
#4 lore raw
Quoted 9 lines · Peter Zijlstra

Of course, if you do run out of lock classes, the next thing to do is to find the offending lock classes. First, the following command gives you the number of lock classes currently in use along with the maximum:

grep "lock-classes" /proc/lockdep_stats

This command produces the following output on a modest system:

lock-classes: 748 [max: 8191]

After the BUG gets hit..

lock-classes: 1726 [max: 8191]

Quoted 10 lines

If the number allocated (748 above) increases continually over time, then there is likely a leak. The following command can be used to identify the leaking lock classes:

grep "BD" /proc/lockdep

Run the command and save the output, then compare against the output from a later run of this command to identify the leakers. This same output can also help you find situations where runtime lock initialization has been omitted.

I've not had chance to do this, because after the BUG, lockdep turns itself off, and I've not rebooted. I'm probably not going to get to this until after the weekend.

There's just a *lot* of dependancies.

Here's the full output http://codemonkey.org.uk/junk/lockdep

the top few backwards deps..

ffffffff81c8f218 FD:    1 BD: 1201 -.-.-.: pool_lock
ffffffff82ae1210 FD:    2 BD: 1200 -.-.-.: &obj_hash[i].lock
ffffffff820677c1 FD:    1 BD: 1131 -.-.-.: &rt_rq->rt_runtime_lock
ffffffff82066949 FD:    3 BD: 1131 -.-.-.: &cpu_base->lock
ffffffff820221c0 FD:    1 BD: 1130 -.-.-.: &sig->cputimer.lock
ffffffff820677b8 FD:    5 BD: 1129 -.-.-.: &rt_b->rt_runtime_lock
ffffffff82067675 FD:    3 BD: 1129 ..-.-.: &rq->lock/1
ffffffff82067674 FD:    8 BD: 1128 -.-.-.: &rq->lock
ffffffff8298bbd0 FD:    1 BD: 1006 -.-.-.: &(&n->list_lock)->rlock

Dave

author
#5 lore raw

Re: MAX_LOCKDEP_ENTRIES too low

In reply to Peter Zijlstra
Quoted 5 lines · Peter Zijlstra
Quoted 1 line

Not sure why this suddenly got a lot worse in 3.7

Did we add a static array of structures with locks in somewhere? Doing that is a great way of blowing up the number of lock classes and the resulting amount of lock dependency chains.

So I hit it again, but didn't see anything that I hadn't seen already in /proc/lockdep. I so tried doubling MAX_LOCKDEP_ENTRIES again.

A while later, I got this oops. I'm unsure now if this is a genuine bug, or a side-effect of lockdep not working with such a large MAX_LOCKDEP_ENTRIES

opinions ?

BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
IP: [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
PGD 8e72c067 PUD 34f07067 PMD 0 
Oops: 0000 [#1] PREEMPT SMP 
Modules linked in: fuse nfnetlink ipt_ULOG binfmt_misc nfc caif_socket caif phonet can llc2 pppoe pppox ppp_generic slhc irda crc_ccitt rds af_key decnet rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 lockd sunrpc bluetooth rfkill ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_conntrack ip6table_filter ip6_tables kvm_intel kvm usb_debug crc32c_intel ghash_clmulni_intel microcode pcspkr i2c_i801 e1000e uinput i915 video i2c_algo_bit drm_kms_helper drm i2c_core
CPU 7 
Pid: 27513, comm: trinity-child0 Not tainted 3.7.0-rc2+ #43 Intel Corporation 2012 Client Platform/Emerald Lake 2
RIP: 0010:[<ffffffff810e185e>]  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
RSP: 0018:ffff8800803f7b28  EFLAGS: 00010046
RAX: 0000000000000086 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000018
RBP: ffff8800803f7c18 R08: 0000000000000002 R09: 0000000000000000
R10: 0000000000000000 R11: 2222222222222222 R12: 0000000000000002
R13: ffff880051dd8000 R14: 0000000000000002 R15: 0000000000000018
FS:  00007f9fc6ccb740(0000) GS:ffff880148a00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000018 CR3: 000000008e6fb000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process trinity-child0 (pid: 27513, threadinfo ffff8800803f6000, task ffff880051dd8000)
Stack:
 ffff8800803f7b48 ffffffff816c5c59 ffff8800803f7b48 ffff88014840ebc0
 ffff8800803f7b68 ffffffff816c18e3 ffff8800803f7d10 0000000000000001
 ffff8800803f7ba8 ffffffff810a1e62 ffff8800803f7d10 0000000000000282
Call Trace:
 [<ffffffff816c5c59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff816c18e3>] ? _raw_spin_unlock_irqrestore+0x73/0xa0
 [<ffffffff810a1e62>] ? hrtimer_try_to_cancel+0x52/0x210
 [<ffffffff810eb9e5>] ? debug_rt_mutex_free_waiter+0x15/0x180
 [<ffffffff816c0107>] ? rt_mutex_slowlock+0x127/0x1b0
 [<ffffffff810b7039>] ? local_clock+0x89/0xa0
 [<ffffffff810e3ac2>] lock_acquire+0xa2/0x220
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff816c09e0>] _raw_spin_lock+0x40/0x80
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810e812c>] futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810a1980>] ? update_rmtp+0x70/0x70
 [<ffffffff810e99e4>] do_futex+0x394/0xa50
 [<ffffffff8119ec43>] ? might_fault+0x53/0xb0
 [<ffffffff810ea12d>] sys_futex+0x8d/0x190
 [<ffffffff816ca288>] tracesys+0xe1/0xe6
Code: d8 45 0f 45 e0 4c 89 75 f0 4c 89 7d f8 85 c0 0f 84 f8 00 00 00 8b 05 22 fe f3 00 49 89 ff 89 f3 41 89 d2 85 c0 0f 84 02 01 00 00 <49> 8b 07 ba 01 00 00 00 48 3d c0 81 06 82 44 0f 44 e2 83 fb 01 
RIP  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
 RSP <ffff8800803f7b28>

CR2: 0000000000000018

author
#6 lore raw

pi futex oops in __lock_acquire

I've been able to trigger this for the last week or so. Unclear whether this is a new bug, or my fuzzer got smarter, but I see the pi-futex code hasn't changed since the last time it found something..

Quoted 43 lines
BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
IP: [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
PGD 8e72c067 PUD 34f07067 PMD 0 
Oops: 0000 [#1] PREEMPT SMP 
CPU 7 
Pid: 27513, comm: trinity-child0 Not tainted 3.7.0-rc2+ #43
RIP: 0010:[<ffffffff810e185e>]  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
RSP: 0018:ffff8800803f7b28  EFLAGS: 00010046
RAX: 0000000000000086 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000018
RBP: ffff8800803f7c18 R08: 0000000000000002 R09: 0000000000000000
R10: 0000000000000000 R11: 2222222222222222 R12: 0000000000000002
R13: ffff880051dd8000 R14: 0000000000000002 R15: 0000000000000018
FS:  00007f9fc6ccb740(0000) GS:ffff880148a00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000018 CR3: 000000008e6fb000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process trinity-child0 (pid: 27513, threadinfo ffff8800803f6000, task ffff880051dd8000)
Stack:
 ffff8800803f7b48 ffffffff816c5c59 ffff8800803f7b48 ffff88014840ebc0
 ffff8800803f7b68 ffffffff816c18e3 ffff8800803f7d10 0000000000000001
 ffff8800803f7ba8 ffffffff810a1e62 ffff8800803f7d10 0000000000000282
Call Trace:
 [<ffffffff816c5c59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff816c18e3>] ? _raw_spin_unlock_irqrestore+0x73/0xa0
 [<ffffffff810a1e62>] ? hrtimer_try_to_cancel+0x52/0x210
 [<ffffffff810eb9e5>] ? debug_rt_mutex_free_waiter+0x15/0x180
 [<ffffffff816c0107>] ? rt_mutex_slowlock+0x127/0x1b0
 [<ffffffff810b7039>] ? local_clock+0x89/0xa0
 [<ffffffff810e3ac2>] lock_acquire+0xa2/0x220
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff816c09e0>] _raw_spin_lock+0x40/0x80
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810e812c>] futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810a1980>] ? update_rmtp+0x70/0x70
 [<ffffffff810e99e4>] do_futex+0x394/0xa50
 [<ffffffff8119ec43>] ? might_fault+0x53/0xb0
 [<ffffffff810ea12d>] sys_futex+0x8d/0x190
 [<ffffffff816ca288>] tracesys+0xe1/0xe6
Code: d8 45 0f 45 e0 4c 89 75 f0 4c 89 7d f8 85 c0 0f 84 f8 00 00 00 8b 05 22 fe f3 00 49 89 ff 89 f3 41 89 d2 85 c0 0f 84 02 01 00 00 <49> 8b 07 ba 01 00 00 00 48 3d c0 81 06 82 44 0f 44 e2 83 fb 01 
RIP  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
 RSP <ffff8800803f7b28>
Quoted 1 line

CR2: 0000000000000018

It looks like we got all the way to lock_acquire with a NULL 'lock' somehow.

Darren, any idea how this could happen ?

Dave

#7 lore raw

Re: pi futex oops in __lock_acquire

Quoted 49 lines · Dave Jones

I've been able to trigger this for the last week or so. Unclear whether this is a new bug, or my fuzzer got smarter, but I see the pi-futex code hasn't changed since the last time it found something..

Quoted 43 lines
BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
IP: [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
PGD 8e72c067 PUD 34f07067 PMD 0 
Oops: 0000 [#1] PREEMPT SMP 
CPU 7 
Pid: 27513, comm: trinity-child0 Not tainted 3.7.0-rc2+ #43
RIP: 0010:[<ffffffff810e185e>]  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
RSP: 0018:ffff8800803f7b28  EFLAGS: 00010046
RAX: 0000000000000086 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000018
RBP: ffff8800803f7c18 R08: 0000000000000002 R09: 0000000000000000
R10: 0000000000000000 R11: 2222222222222222 R12: 0000000000000002
R13: ffff880051dd8000 R14: 0000000000000002 R15: 0000000000000018
FS:  00007f9fc6ccb740(0000) GS:ffff880148a00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000018 CR3: 000000008e6fb000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process trinity-child0 (pid: 27513, threadinfo ffff8800803f6000, task ffff880051dd8000)
Stack:
 ffff8800803f7b48 ffffffff816c5c59 ffff8800803f7b48 ffff88014840ebc0
 ffff8800803f7b68 ffffffff816c18e3 ffff8800803f7d10 0000000000000001
 ffff8800803f7ba8 ffffffff810a1e62 ffff8800803f7d10 0000000000000282
Call Trace:
 [<ffffffff816c5c59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff816c18e3>] ? _raw_spin_unlock_irqrestore+0x73/0xa0
 [<ffffffff810a1e62>] ? hrtimer_try_to_cancel+0x52/0x210
 [<ffffffff810eb9e5>] ? debug_rt_mutex_free_waiter+0x15/0x180
 [<ffffffff816c0107>] ? rt_mutex_slowlock+0x127/0x1b0
 [<ffffffff810b7039>] ? local_clock+0x89/0xa0
 [<ffffffff810e3ac2>] lock_acquire+0xa2/0x220
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff816c09e0>] _raw_spin_lock+0x40/0x80
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810e812c>] futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810a1980>] ? update_rmtp+0x70/0x70
 [<ffffffff810e99e4>] do_futex+0x394/0xa50
 [<ffffffff8119ec43>] ? might_fault+0x53/0xb0
 [<ffffffff810ea12d>] sys_futex+0x8d/0x190
 [<ffffffff816ca288>] tracesys+0xe1/0xe6
Code: d8 45 0f 45 e0 4c 89 75 f0 4c 89 7d f8 85 c0 0f 84 f8 00 00 00 8b 05 22 fe f3 00 49 89 ff 89 f3 41 89 d2 85 c0 0f 84 02 01 00 00 <49> 8b 07 ba 01 00 00 00 48 3d c0 81 06 82 44 0f 44 e2 83 fb 01 
RIP  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
 RSP <ffff8800803f7b28>
Quoted 1 line

CR2: 0000000000000018

Quoted 3 lines

It looks like we got all the way to lock_acquire with a NULL 'lock' somehow.

Darren, any idea how this could happen ?

I'm digging. Can you get trinity to provide the arguments it used that trigger the crash? That might help hone in on the exact path.

Signature · 3 lines
Darren Hart
Intel Open Source Technology Center
Yocto Project - Technical Lead - Linux Kernel
author
#8 lore raw

Re: pi futex oops in __lock_acquire

Quoted 7 lines · Darren Hart
Quoted 4 lines · Dave Jones

I've been able to trigger this for the last week or so. Unclear whether this is a new bug, or my fuzzer got smarter, but I see the pi-futex code hasn't changed since the last time it found something..

Quoted 8 lines
Quoted 5 lines
Quoted 1 line
BUG: unable to handle kernel NULL pointer dereference at 0000000000000018

It looks like we got all the way to lock_acquire with a NULL 'lock' somehow.

Darren, any idea how this could happen ?

I'm digging. Can you get trinity to provide the arguments it used that trigger the crash? That might help hone in on the exact path.

Happens pretty quickly with -c futex for me. (30 seconds or so)

Dave

author
#9 lore raw

Re: pi futex oops in __lock_acquire

In reply to Darren Hart
Quoted 49 lines · Darren Hart
Quoted 49 lines

I've been able to trigger this for the last week or so. Unclear whether this is a new bug, or my fuzzer got smarter, but I see the pi-futex code hasn't changed since the last time it found something..

Quoted 44 lines
BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
IP: [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
PGD 8e72c067 PUD 34f07067 PMD 0 
Oops: 0000 [#1] PREEMPT SMP 
CPU 7 
Pid: 27513, comm: trinity-child0 Not tainted 3.7.0-rc2+ #43
RIP: 0010:[<ffffffff810e185e>]  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
RSP: 0018:ffff8800803f7b28  EFLAGS: 00010046
RAX: 0000000000000086 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000018
RBP: ffff8800803f7c18 R08: 0000000000000002 R09: 0000000000000000
R10: 0000000000000000 R11: 2222222222222222 R12: 0000000000000002
R13: ffff880051dd8000 R14: 0000000000000002 R15: 0000000000000018
FS:  00007f9fc6ccb740(0000) GS:ffff880148a00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000018 CR3: 000000008e6fb000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process trinity-child0 (pid: 27513, threadinfo ffff8800803f6000, task ffff880051dd8000)
Stack:
 ffff8800803f7b48 ffffffff816c5c59 ffff8800803f7b48 ffff88014840ebc0
 ffff8800803f7b68 ffffffff816c18e3 ffff8800803f7d10 0000000000000001
 ffff8800803f7ba8 ffffffff810a1e62 ffff8800803f7d10 0000000000000282
Call Trace:
 [<ffffffff816c5c59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff816c18e3>] ? _raw_spin_unlock_irqrestore+0x73/0xa0
 [<ffffffff810a1e62>] ? hrtimer_try_to_cancel+0x52/0x210
 [<ffffffff810eb9e5>] ? debug_rt_mutex_free_waiter+0x15/0x180
 [<ffffffff816c0107>] ? rt_mutex_slowlock+0x127/0x1b0
 [<ffffffff810b7039>] ? local_clock+0x89/0xa0
 [<ffffffff810e3ac2>] lock_acquire+0xa2/0x220
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff816c09e0>] _raw_spin_lock+0x40/0x80
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810e812c>] futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810a1980>] ? update_rmtp+0x70/0x70
 [<ffffffff810e99e4>] do_futex+0x394/0xa50
 [<ffffffff8119ec43>] ? might_fault+0x53/0xb0
 [<ffffffff810ea12d>] sys_futex+0x8d/0x190
 [<ffffffff816ca288>] tracesys+0xe1/0xe6
Code: d8 45 0f 45 e0 4c 89 75 f0 4c 89 7d f8 85 c0 0f 84 f8 00 00 00 8b 05 22 fe f3 00 49 89 ff 89 f3 41 89 d2 85 c0 0f 84 02 01 00 00 <49> 8b 07 ba 01 00 00 00 48 3d c0 81 06 82 44 0f 44 e2 83 fb 01 
RIP  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
 RSP <ffff8800803f7b28>

CR2: 0000000000000018

Quoted 6 lines
Quoted 3 lines

It looks like we got all the way to lock_acquire with a NULL 'lock' somehow.

Darren, any idea how this could happen ?

I'm digging. Can you get trinity to provide the arguments it used that trigger the crash?u That might help hone in on the exact path.

Still seeing this on rc6. It happens very quickly when I run with "-c futex" I just pushed out all the pending trinity changes I was running with, but I don't think they would have been responsible.

Dave

#10 lore raw

Re: pi futex oops in __lock_acquire

Quoted 53 lines · Dave Jones
Quoted 51 lines · Darren Hart
Quoted 51 lines

I've been able to trigger this for the last week or so. Unclear whether this is a new bug, or my fuzzer got smarter, but I see the pi-futex code hasn't changed since the last time it found something..

Quoted 43 lines
BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
IP: [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
PGD 8e72c067 PUD 34f07067 PMD 0 
Oops: 0000 [#1] PREEMPT SMP 
CPU 7 
Pid: 27513, comm: trinity-child0 Not tainted 3.7.0-rc2+ #43
RIP: 0010:[<ffffffff810e185e>]  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
RSP: 0018:ffff8800803f7b28  EFLAGS: 00010046
RAX: 0000000000000086 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000018
RBP: ffff8800803f7c18 R08: 0000000000000002 R09: 0000000000000000
R10: 0000000000000000 R11: 2222222222222222 R12: 0000000000000002
R13: ffff880051dd8000 R14: 0000000000000002 R15: 0000000000000018
FS:  00007f9fc6ccb740(0000) GS:ffff880148a00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000018 CR3: 000000008e6fb000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process trinity-child0 (pid: 27513, threadinfo ffff8800803f6000, task ffff880051dd8000)
Stack:
 ffff8800803f7b48 ffffffff816c5c59 ffff8800803f7b48 ffff88014840ebc0
 ffff8800803f7b68 ffffffff816c18e3 ffff8800803f7d10 0000000000000001
 ffff8800803f7ba8 ffffffff810a1e62 ffff8800803f7d10 0000000000000282
Call Trace:
 [<ffffffff816c5c59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff816c18e3>] ? _raw_spin_unlock_irqrestore+0x73/0xa0
 [<ffffffff810a1e62>] ? hrtimer_try_to_cancel+0x52/0x210
 [<ffffffff810eb9e5>] ? debug_rt_mutex_free_waiter+0x15/0x180
 [<ffffffff816c0107>] ? rt_mutex_slowlock+0x127/0x1b0
 [<ffffffff810b7039>] ? local_clock+0x89/0xa0
 [<ffffffff810e3ac2>] lock_acquire+0xa2/0x220
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff816c09e0>] _raw_spin_lock+0x40/0x80
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810e812c>] futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810a1980>] ? update_rmtp+0x70/0x70
 [<ffffffff810e99e4>] do_futex+0x394/0xa50
 [<ffffffff8119ec43>] ? might_fault+0x53/0xb0
 [<ffffffff810ea12d>] sys_futex+0x8d/0x190
 [<ffffffff816ca288>] tracesys+0xe1/0xe6
Code: d8 45 0f 45 e0 4c 89 75 f0 4c 89 7d f8 85 c0 0f 84 f8 00 00 00 8b 05 22 fe f3 00 49 89 ff 89 f3 41 89 d2 85 c0 0f 84 02 01 00 00 <49> 8b 07 ba 01 00 00 00 48 3d c0 81 06 82 44 0f 44 e2 83 fb 01 
RIP  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
 RSP <ffff8800803f7b28>
Quoted 1 line

CR2: 0000000000000018

It looks like we got all the way to lock_acquire with a NULL 'lock' somehow.

Quoted 8 lines
Quoted 4 lines
Quoted 1 line

Darren, any idea how this could happen ?

I'm digging. Can you get trinity to provide the arguments it used that trigger the crash?u That might help hone in on the exact path.

Still seeing this on rc6. It happens very quickly when I run with "-c futex" I just pushed out all the pending trinity changes I was running with, but I don't think they would have been responsible.

Thanks for the poke - I've been away on vacations and conferences and tied up with other things. I'll do a build a testrun today.

Signature · 3 lines
Darren Hart
Intel Open Source Technology Center
Yocto Project - Technical Lead - Linux Kernel
#11 lore raw

Re: pi futex oops in __lock_acquire

In reply to Dave Jones
Quoted 55 lines · Dave Jones
Quoted 53 lines · Darren Hart
Quoted 52 lines

I've been able to trigger this for the last week or so. Unclear whether this is a new bug, or my fuzzer got smarter, but I see the pi-futex code hasn't changed since the last time it found something..

Quoted 43 lines
BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
IP: [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
PGD 8e72c067 PUD 34f07067 PMD 0 
Oops: 0000 [#1] PREEMPT SMP 
CPU 7 
Pid: 27513, comm: trinity-child0 Not tainted 3.7.0-rc2+ #43
RIP: 0010:[<ffffffff810e185e>]  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
RSP: 0018:ffff8800803f7b28  EFLAGS: 00010046
RAX: 0000000000000086 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000018
RBP: ffff8800803f7c18 R08: 0000000000000002 R09: 0000000000000000
R10: 0000000000000000 R11: 2222222222222222 R12: 0000000000000002
R13: ffff880051dd8000 R14: 0000000000000002 R15: 0000000000000018
FS:  00007f9fc6ccb740(0000) GS:ffff880148a00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000018 CR3: 000000008e6fb000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process trinity-child0 (pid: 27513, threadinfo ffff8800803f6000, task ffff880051dd8000)
Stack:
 ffff8800803f7b48 ffffffff816c5c59 ffff8800803f7b48 ffff88014840ebc0
 ffff8800803f7b68 ffffffff816c18e3 ffff8800803f7d10 0000000000000001
 ffff8800803f7ba8 ffffffff810a1e62 ffff8800803f7d10 0000000000000282
Call Trace:
 [<ffffffff816c5c59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff816c18e3>] ? _raw_spin_unlock_irqrestore+0x73/0xa0
 [<ffffffff810a1e62>] ? hrtimer_try_to_cancel+0x52/0x210
 [<ffffffff810eb9e5>] ? debug_rt_mutex_free_waiter+0x15/0x180
 [<ffffffff816c0107>] ? rt_mutex_slowlock+0x127/0x1b0
 [<ffffffff810b7039>] ? local_clock+0x89/0xa0
 [<ffffffff810e3ac2>] lock_acquire+0xa2/0x220
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff816c09e0>] _raw_spin_lock+0x40/0x80
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810e812c>] futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810a1980>] ? update_rmtp+0x70/0x70
 [<ffffffff810e99e4>] do_futex+0x394/0xa50
 [<ffffffff8119ec43>] ? might_fault+0x53/0xb0
 [<ffffffff810ea12d>] sys_futex+0x8d/0x190
 [<ffffffff816ca288>] tracesys+0xe1/0xe6
Code: d8 45 0f 45 e0 4c 89 75 f0 4c 89 7d f8 85 c0 0f 84 f8 00 00 00 8b 05 22 fe f3 00 49 89 ff 89 f3 41 89 d2 85 c0 0f 84 02 01 00 00 <49> 8b 07 ba 01 00 00 00 48 3d c0 81 06 82 44 0f 44 e2 83 fb 01 
RIP  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
 RSP <ffff8800803f7b28>
Quoted 1 line

CR2: 0000000000000018

It looks like we got all the way to lock_acquire with a NULL 'lock' somehow.

Darren, any idea how this could happen ?

Quoted 9 lines
Quoted 2 lines

I'm digging. Can you get trinity to provide the arguments it used that trigger the crash?u That might help hone in on the exact path.

Still seeing this on rc6. It happens very quickly when I run with "-c futex" I just pushed out all the pending trinity changes I was running with, but I don't think they would have been responsible.

Dave

OK, so some instrumentation yields:

[ 1320.762028] futex_lock_pi: timed lock
[ 1320.762488] futex_lock_pi: hb=ffffffff81e89e28,
hb->lock=ffffffff81e89e28, &q=ffff880181fa5cd8, q.lock_ptr=ffffffff81e89e28
[ 1320.763647] q.lock_ptr=ffffffff81e89e28
[ 1320.764132] fixup_owner: uaddr=00007f05465ac000, q=ffff880181fa5cd8,
locked=0
[ 1323.066371] futex_lock_pi: hb=ffffffff81e89e28,
hb->lock=ffffffff81e89e28, &q=ffff880181fc5cd8, q.lock_ptr=          (null)
[ 1323.069032] ------------[ cut here ]------------
[ 1323.069817] kernel BUG at kernel/futex.c:2052!

So somewhere between blocking on the lock and waking, q.lock_ptr is getting set to NULL. The only legitimate place this happens in is wake_futex, and I see some wake_futex calls after the futex_lock_pi calls with the same uaddr in the trinity log. We are supposed to be protected by the q lock_ptr here and wake_futex aborts any wakes of q's with a pi_state or rt_waiter.... but .... there appears to be a window in there. I say a window because I see a similar failure where the instrumentation doesn't catch the lock_ptr as NULL and fails at a later point on the same lock. Nice nasty parallel locking race. Digging in.

Signature · 3 lines
Darren Hart
Intel Open Source Technology Center
Yocto Project - Technical Lead - Linux Kernel
#12 lore raw

Re: pi futex oops in __lock_acquire

Quoted 81 lines · Darren Hart
Quoted 55 lines · Dave Jones
Quoted 53 lines · Darren Hart
Quoted 52 lines

I've been able to trigger this for the last week or so. Unclear whether this is a new bug, or my fuzzer got smarter, but I see the pi-futex code hasn't changed since the last time it found something..

Quoted 43 lines
BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
IP: [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
PGD 8e72c067 PUD 34f07067 PMD 0 
Oops: 0000 [#1] PREEMPT SMP 
CPU 7 
Pid: 27513, comm: trinity-child0 Not tainted 3.7.0-rc2+ #43
RIP: 0010:[<ffffffff810e185e>]  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
RSP: 0018:ffff8800803f7b28  EFLAGS: 00010046
RAX: 0000000000000086 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000018
RBP: ffff8800803f7c18 R08: 0000000000000002 R09: 0000000000000000
R10: 0000000000000000 R11: 2222222222222222 R12: 0000000000000002
R13: ffff880051dd8000 R14: 0000000000000002 R15: 0000000000000018
FS:  00007f9fc6ccb740(0000) GS:ffff880148a00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000018 CR3: 000000008e6fb000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process trinity-child0 (pid: 27513, threadinfo ffff8800803f6000, task ffff880051dd8000)
Stack:
 ffff8800803f7b48 ffffffff816c5c59 ffff8800803f7b48 ffff88014840ebc0
 ffff8800803f7b68 ffffffff816c18e3 ffff8800803f7d10 0000000000000001
 ffff8800803f7ba8 ffffffff810a1e62 ffff8800803f7d10 0000000000000282
Call Trace:
 [<ffffffff816c5c59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff816c18e3>] ? _raw_spin_unlock_irqrestore+0x73/0xa0
 [<ffffffff810a1e62>] ? hrtimer_try_to_cancel+0x52/0x210
 [<ffffffff810eb9e5>] ? debug_rt_mutex_free_waiter+0x15/0x180
 [<ffffffff816c0107>] ? rt_mutex_slowlock+0x127/0x1b0
 [<ffffffff810b7039>] ? local_clock+0x89/0xa0
 [<ffffffff810e3ac2>] lock_acquire+0xa2/0x220
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff816c09e0>] _raw_spin_lock+0x40/0x80
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810e812c>] futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810a1980>] ? update_rmtp+0x70/0x70
 [<ffffffff810e99e4>] do_futex+0x394/0xa50
 [<ffffffff8119ec43>] ? might_fault+0x53/0xb0
 [<ffffffff810ea12d>] sys_futex+0x8d/0x190
 [<ffffffff816ca288>] tracesys+0xe1/0xe6
Code: d8 45 0f 45 e0 4c 89 75 f0 4c 89 7d f8 85 c0 0f 84 f8 00 00 00 8b 05 22 fe f3 00 49 89 ff 89 f3 41 89 d2 85 c0 0f 84 02 01 00 00 <49> 8b 07 ba 01 00 00 00 48 3d c0 81 06 82 44 0f 44 e2 83 fb 01 
RIP  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
 RSP <ffff8800803f7b28>
Quoted 1 line

CR2: 0000000000000018

It looks like we got all the way to lock_acquire with a NULL 'lock' somehow.

Darren, any idea how this could happen ?

Quoted 9 lines
Quoted 2 lines

I'm digging. Can you get trinity to provide the arguments it used that trigger the crash?u That might help hone in on the exact path.

Still seeing this on rc6. It happens very quickly when I run with "-c futex" I just pushed out all the pending trinity changes I was running with, but I don't think they would have been responsible.

Dave

OK, so some instrumentation yields:

[ 1320.762028] futex_lock_pi: timed lock
[ 1320.762488] futex_lock_pi: hb=ffffffff81e89e28,
hb->lock=ffffffff81e89e28, &q=ffff880181fa5cd8, q.lock_ptr=ffffffff81e89e28
[ 1320.763647] q.lock_ptr=ffffffff81e89e28
[ 1320.764132] fixup_owner: uaddr=00007f05465ac000, q=ffff880181fa5cd8,
locked=0
[ 1323.066371] futex_lock_pi: hb=ffffffff81e89e28,
hb->lock=ffffffff81e89e28, &q=ffff880181fc5cd8, q.lock_ptr=          (null)
[ 1323.069032] ------------[ cut here ]------------
[ 1323.069817] kernel BUG at kernel/futex.c:2052!
Quoted 10 lines

So somewhere between blocking on the lock and waking, q.lock_ptr is getting set to NULL. The only legitimate place this happens in is wake_futex, and I see some wake_futex calls after the futex_lock_pi calls with the same uaddr in the trinity log. We are supposed to be protected by the q lock_ptr here and wake_futex aborts any wakes of q's with a pi_state or rt_waiter.... but .... there appears to be a window in there. I say a window because I see a similar failure where the instrumentation doesn't catch the lock_ptr as NULL and fails at a later point on the same lock. Nice nasty parallel locking race. Digging in.

OK, the problem is a futex_wake_op() calling wake_futex() without checking for a pi_state or rt_waiters. I'm looking at the best way to fix it, considering moving the check out of futex_wake and into wake_futex... some more analysis needed for the best fix, but will have one by tomorrow.

Signature · 3 lines
Darren Hart
Intel Open Source Technology Center
Yocto Project - Technical Lead - Linux Kernel
#13 lore raw

Re: pi futex oops in __lock_acquire

Quoted 95 lines · Darren Hart
Quoted 81 lines · Darren Hart
Quoted 55 lines · Dave Jones
Quoted 53 lines · Darren Hart
Quoted 52 lines

I've been able to trigger this for the last week or so. Unclear whether this is a new bug, or my fuzzer got smarter, but I see the pi-futex code hasn't changed since the last time it found something..

Quoted 43 lines
BUG: unable to handle kernel NULL pointer dereference at 0000000000000018
IP: [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
PGD 8e72c067 PUD 34f07067 PMD 0 
Oops: 0000 [#1] PREEMPT SMP 
CPU 7 
Pid: 27513, comm: trinity-child0 Not tainted 3.7.0-rc2+ #43
RIP: 0010:[<ffffffff810e185e>]  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
RSP: 0018:ffff8800803f7b28  EFLAGS: 00010046
RAX: 0000000000000086 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000018
RBP: ffff8800803f7c18 R08: 0000000000000002 R09: 0000000000000000
R10: 0000000000000000 R11: 2222222222222222 R12: 0000000000000002
R13: ffff880051dd8000 R14: 0000000000000002 R15: 0000000000000018
FS:  00007f9fc6ccb740(0000) GS:ffff880148a00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000018 CR3: 000000008e6fb000 CR4: 00000000001407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process trinity-child0 (pid: 27513, threadinfo ffff8800803f6000, task ffff880051dd8000)
Stack:
 ffff8800803f7b48 ffffffff816c5c59 ffff8800803f7b48 ffff88014840ebc0
 ffff8800803f7b68 ffffffff816c18e3 ffff8800803f7d10 0000000000000001
 ffff8800803f7ba8 ffffffff810a1e62 ffff8800803f7d10 0000000000000282
Call Trace:
 [<ffffffff816c5c59>] ? sub_preempt_count+0x79/0xd0
 [<ffffffff816c18e3>] ? _raw_spin_unlock_irqrestore+0x73/0xa0
 [<ffffffff810a1e62>] ? hrtimer_try_to_cancel+0x52/0x210
 [<ffffffff810eb9e5>] ? debug_rt_mutex_free_waiter+0x15/0x180
 [<ffffffff816c0107>] ? rt_mutex_slowlock+0x127/0x1b0
 [<ffffffff810b7039>] ? local_clock+0x89/0xa0
 [<ffffffff810e3ac2>] lock_acquire+0xa2/0x220
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff816c09e0>] _raw_spin_lock+0x40/0x80
 [<ffffffff810e812c>] ? futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810e812c>] futex_lock_pi.isra.18+0x1cc/0x390
 [<ffffffff810a1980>] ? update_rmtp+0x70/0x70
 [<ffffffff810e99e4>] do_futex+0x394/0xa50
 [<ffffffff8119ec43>] ? might_fault+0x53/0xb0
 [<ffffffff810ea12d>] sys_futex+0x8d/0x190
 [<ffffffff816ca288>] tracesys+0xe1/0xe6
Code: d8 45 0f 45 e0 4c 89 75 f0 4c 89 7d f8 85 c0 0f 84 f8 00 00 00 8b 05 22 fe f3 00 49 89 ff 89 f3 41 89 d2 85 c0 0f 84 02 01 00 00 <49> 8b 07 ba 01 00 00 00 48 3d c0 81 06 82 44 0f 44 e2 83 fb 01 
RIP  [<ffffffff810e185e>] __lock_acquire+0x5e/0x1ba0
 RSP <ffff8800803f7b28>
Quoted 1 line

CR2: 0000000000000018

It looks like we got all the way to lock_acquire with a NULL 'lock' somehow.

Darren, any idea how this could happen ?

Quoted 9 lines
Quoted 2 lines

I'm digging. Can you get trinity to provide the arguments it used that trigger the crash?u That might help hone in on the exact path.

Still seeing this on rc6. It happens very quickly when I run with "-c futex" I just pushed out all the pending trinity changes I was running with, but I don't think they would have been responsible.

Dave

OK, so some instrumentation yields:

[ 1320.762028] futex_lock_pi: timed lock
[ 1320.762488] futex_lock_pi: hb=ffffffff81e89e28,
hb->lock=ffffffff81e89e28, &q=ffff880181fa5cd8, q.lock_ptr=ffffffff81e89e28
[ 1320.763647] q.lock_ptr=ffffffff81e89e28
[ 1320.764132] fixup_owner: uaddr=00007f05465ac000, q=ffff880181fa5cd8,
locked=0
[ 1323.066371] futex_lock_pi: hb=ffffffff81e89e28,
hb->lock=ffffffff81e89e28, &q=ffff880181fc5cd8, q.lock_ptr=          (null)
[ 1323.069032] ------------[ cut here ]------------
[ 1323.069817] kernel BUG at kernel/futex.c:2052!
Quoted 10 lines

So somewhere between blocking on the lock and waking, q.lock_ptr is getting set to NULL. The only legitimate place this happens in is wake_futex, and I see some wake_futex calls after the futex_lock_pi calls with the same uaddr in the trinity log. We are supposed to be protected by the q lock_ptr here and wake_futex aborts any wakes of q's with a pi_state or rt_waiter.... but .... there appears to be a window in there. I say a window because I see a similar failure where the instrumentation doesn't catch the lock_ptr as NULL and fails at a later point on the same lock. Nice nasty parallel locking race. Digging in.

Quoted 5 lines

OK, the problem is a futex_wake_op() calling wake_futex() without checking for a pi_state or rt_waiters. I'm looking at the best way to fix it, considering moving the check out of futex_wake and into wake_futex... some more analysis needed for the best fix, but will have one by tomorrow.

I've sent a patch to address this. It has now been running "trinity -c futex" for about 12 hours. I haven't seen any more futex failures, but I have seen a few OOMs. Is that expected from trinity?

Signature · 3 lines
Darren Hart
Intel Open Source Technology Center
Yocto Project - Technical Lead - Linux Kernel
author
#14 lore raw

Re: pi futex oops in __lock_acquire

Quoted 2 lines · Darren Hart

I've sent a patch to address this. It has now been running "trinity -c futex" for about 12 hours. I haven't seen any more futex failures

Looks good here too.

Quoted 2 lines

but I
have seen a few OOMs. Is that expected from trinity?

Yeah, seems there's some leaks (both in trinity and the kernel).
Oddly enough someone else emailed me about that this morning, which prompted me to write up this: http://codemonkey.org.uk/2012/11/21/fuzz-testing-oom-killer/
Which is just part of the problem. There are other issues too it seems. Fun.

Dave