[3.15-rc3] rtmutex-debug assertion.

[3.15-rc3] rtmutex-debug assertion.

[Dave Jones]

Just hit this while fuzzing the futex() syscall.


WARNING: CPU: 2 PID: 6202 at kernel/locking/rtmutex-debug.c:151 debug_rt_mutex_proxy_unlock+0x4e/0x60()
DEBUG_LOCKS_WARN_ON(!rt_mutex_owner(lock))
Modules linked in:
 tun fuse ipt_ULOG nfnetlink bnep can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 ieee802154 phonet af_rxrpc can_raw can pppoe pppox ppp_generic slhc irda crc_ccitt rds rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 cfg80211 coretemp hwmon x86_pkg_temp_thermal kvm_intel kvm xfs libcrc32c btusb bluetooth snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel snd_hda_controller snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm e1000e crct10dif_pclmul crc32c_intel ghash_clmulni_intel snd_timer snd microcode serio_raw pcspkr usb_debug 6lowpan_iphc rfkill shpchp ptp pps_core soundcore
CPU: 2 PID: 6202 Comm: trinity-c63 Not tainted 3.15.0-rc3+ #201
 0000000000000009 00000000de725d52 ffff880099befbd8 ffffffff92746dad
 ffff880099befc20 ffff880099befc10 ffffffff9206d46d ffff88020951c010
 ffff88009d718000 ffff88009d718000 ffffc90011408680 ffffc90011408688
Call Trace:
 [<ffffffff92746dad>] dump_stack+0x4e/0x7a
 [<ffffffff9206d46d>] warn_slowpath_common+0x7d/0xa0
 [<ffffffff9206d4ec>] warn_slowpath_fmt+0x5c/0x80
 [<ffffffff920c533e>] debug_rt_mutex_proxy_unlock+0x4e/0x60
 [<ffffffff920c4d77>] rt_mutex_proxy_unlock+0x17/0x40
 [<ffffffff920ead7a>] free_pi_state+0x6a/0xb0
 [<ffffffff920eade0>] unqueue_me_pi+0x20/0x40
 [<ffffffff920ebfc2>] futex_lock_pi.isra.18+0x262/0x3f0
 [<ffffffff92096910>] ? hrtimer_get_res+0x50/0x50
 [<ffffffff920edb2c>] do_futex+0x2ec/0xb60
 [<ffffffff92349897>] ? debug_smp_processor_id+0x17/0x20
 [<ffffffff920bf3ee>] ? put_lock_stats.isra.23+0xe/0x30
 [<ffffffff920bf756>] ? lock_release_holdtime.part.24+0xe6/0x160
 [<ffffffff920a3cdd>] ? get_parent_ip+0xd/0x50
 [<ffffffff9275698b>] ? preempt_count_sub+0x6b/0xf0
 [<ffffffff92751f51>] ? _raw_spin_unlock+0x31/0x50
 [<ffffffff920ee420>] SyS_futex+0x80/0x180
 [<ffffffff9275b0e4>] tracesys+0xdd/0xe2

Re: [3.15-rc3] rtmutex-debug assertion.

[Dave Jones]

On Tue, Apr 29, 2014 at 11:16:55AM -0400, Dave Jones wrote:
 > Just hit this while fuzzing the futex() syscall.
 > 
 > 
 > WARNING: CPU: 2 PID: 6202 at kernel/locking/rtmutex-debug.c:151 debug_rt_mutex_proxy_unlock+0x4e/0x60()
 > DEBUG_LOCKS_WARN_ON(!rt_mutex_owner(lock))
 > Modules linked in:
 >  tun fuse ipt_ULOG nfnetlink bnep can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 ieee802154 phonet af_rxrpc can_raw can pppoe pppox ppp_generic slhc irda crc_ccitt rds rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 cfg80211 coretemp hwmon x86_pkg_temp_thermal kvm_intel kvm xfs libcrc32c btusb bluetooth snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel snd_hda_controller snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm e1000e crct10dif_pclmul crc32c_intel ghash_clmulni_intel snd_timer snd microcode serio_raw pcspkr usb_debug 6lowpan_iphc rfkill shpchp ptp pps_core soundcore
 > CPU: 2 PID: 6202 Comm: trinity-c63 Not tainted 3.15.0-rc3+ #201
 >  0000000000000009 00000000de725d52 ffff880099befbd8 ffffffff92746dad
 >  ffff880099befc20 ffff880099befc10 ffffffff9206d46d ffff88020951c010
 >  ffff88009d718000 ffff88009d718000 ffffc90011408680 ffffc90011408688
 > Call Trace:
 >  [<ffffffff92746dad>] dump_stack+0x4e/0x7a
 >  [<ffffffff9206d46d>] warn_slowpath_common+0x7d/0xa0
 >  [<ffffffff9206d4ec>] warn_slowpath_fmt+0x5c/0x80
 >  [<ffffffff920c533e>] debug_rt_mutex_proxy_unlock+0x4e/0x60
 >  [<ffffffff920c4d77>] rt_mutex_proxy_unlock+0x17/0x40
 >  [<ffffffff920ead7a>] free_pi_state+0x6a/0xb0
 >  [<ffffffff920eade0>] unqueue_me_pi+0x20/0x40
 >  [<ffffffff920ebfc2>] futex_lock_pi.isra.18+0x262/0x3f0
 >  [<ffffffff92096910>] ? hrtimer_get_res+0x50/0x50
 >  [<ffffffff920edb2c>] do_futex+0x2ec/0xb60
 >  [<ffffffff92349897>] ? debug_smp_processor_id+0x17/0x20
 >  [<ffffffff920bf3ee>] ? put_lock_stats.isra.23+0xe/0x30
 >  [<ffffffff920bf756>] ? lock_release_holdtime.part.24+0xe6/0x160
 >  [<ffffffff920a3cdd>] ? get_parent_ip+0xd/0x50
 >  [<ffffffff9275698b>] ? preempt_count_sub+0x6b/0xf0
 >  [<ffffffff92751f51>] ? _raw_spin_unlock+0x31/0x50
 >  [<ffffffff920ee420>] SyS_futex+0x80/0x180
 >  [<ffffffff9275b0e4>] tracesys+0xdd/0xe2

This is trickier to reproduce than it first seemed, as logging slows
things down so much.  But after a few hours, it logged that the
call that triggered this was..

futex(uaddr=0x7f55ff8c4000, op=0x6, val=0x200000006223800b, utime=0x7f55ff8c4000, uaddr2=0x7f55ff8c4000, val3=-123)

Those addresses come from an mmap we made on startup..

[init] mapping[3]: (zeropage PROT_READ | PROT_WRITE) 0x7f55ff8c4000 (1MB)

op = FUTEX_LOCK_PI

val seems to be garbage.

I'll do another run, just to see if it's always the same set of values,
but it's going to probably take an overnight run.

	Dave

Re: [3.15-rc3] rtmutex-debug assertion.

[Davidlohr Bueso]

On Tue, 2014-04-29 at 20:14 -0400, Dave Jones wrote:
> On Tue, Apr 29, 2014 at 11:16:55AM -0400, Dave Jones wrote:
>  > Just hit this while fuzzing the futex() syscall.
>  > 
>  > 
>  > WARNING: CPU: 2 PID: 6202 at kernel/locking/rtmutex-debug.c:151 debug_rt_mutex_proxy_unlock+0x4e/0x60()
>  > DEBUG_LOCKS_WARN_ON(!rt_mutex_owner(lock))
>  > Modules linked in:
>  >  tun fuse ipt_ULOG nfnetlink bnep can_bcm scsi_transport_iscsi nfc caif_socket caif af_802154 ieee802154 phonet af_rxrpc can_raw can pppoe pppox ppp_generic slhc irda crc_ccitt rds rose x25 atm netrom appletalk ipx p8023 psnap p8022 llc ax25 cfg80211 coretemp hwmon x86_pkg_temp_thermal kvm_intel kvm xfs libcrc32c btusb bluetooth snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel snd_hda_controller snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm e1000e crct10dif_pclmul crc32c_intel ghash_clmulni_intel snd_timer snd microcode serio_raw pcspkr usb_debug 6lowpan_iphc rfkill shpchp ptp pps_core soundcore
>  > CPU: 2 PID: 6202 Comm: trinity-c63 Not tainted 3.15.0-rc3+ #201
>  >  0000000000000009 00000000de725d52 ffff880099befbd8 ffffffff92746dad
>  >  ffff880099befc20 ffff880099befc10 ffffffff9206d46d ffff88020951c010
>  >  ffff88009d718000 ffff88009d718000 ffffc90011408680 ffffc90011408688
>  > Call Trace:
>  >  [<ffffffff92746dad>] dump_stack+0x4e/0x7a
>  >  [<ffffffff9206d46d>] warn_slowpath_common+0x7d/0xa0
>  >  [<ffffffff9206d4ec>] warn_slowpath_fmt+0x5c/0x80
>  >  [<ffffffff920c533e>] debug_rt_mutex_proxy_unlock+0x4e/0x60
>  >  [<ffffffff920c4d77>] rt_mutex_proxy_unlock+0x17/0x40
>  >  [<ffffffff920ead7a>] free_pi_state+0x6a/0xb0
>  >  [<ffffffff920eade0>] unqueue_me_pi+0x20/0x40
>  >  [<ffffffff920ebfc2>] futex_lock_pi.isra.18+0x262/0x3f0
>  >  [<ffffffff92096910>] ? hrtimer_get_res+0x50/0x50
>  >  [<ffffffff920edb2c>] do_futex+0x2ec/0xb60
>  >  [<ffffffff92349897>] ? debug_smp_processor_id+0x17/0x20
>  >  [<ffffffff920bf3ee>] ? put_lock_stats.isra.23+0xe/0x30
>  >  [<ffffffff920bf756>] ? lock_release_holdtime.part.24+0xe6/0x160
>  >  [<ffffffff920a3cdd>] ? get_parent_ip+0xd/0x50
>  >  [<ffffffff9275698b>] ? preempt_count_sub+0x6b/0xf0
>  >  [<ffffffff92751f51>] ? _raw_spin_unlock+0x31/0x50
>  >  [<ffffffff920ee420>] SyS_futex+0x80/0x180
>  >  [<ffffffff9275b0e4>] tracesys+0xdd/0xe2

I suspect this issue is at least a few months old. There hasn't been
much change in rtmutexes or pi futexes lately.

> This is trickier to reproduce than it first seemed, as logging slows
> things down so much.  But after a few hours, it logged that the
> call that triggered this was..
> 
> futex(uaddr=0x7f55ff8c4000, op=0x6, val=0x200000006223800b, utime=0x7f55ff8c4000, uaddr2=0x7f55ff8c4000, val3=-123)

Perhaps because of chance. Even for pi futexes, if the lock is
uncontended, the kernel will never take part.

> Those addresses come from an mmap we made on startup..
> 
> [init] mapping[3]: (zeropage PROT_READ | PROT_WRITE) 0x7f55ff8c4000 (1MB)
> 
> op = FUTEX_LOCK_PI
> 
> val seems to be garbage.
> 
> I'll do another run, just to see if it's always the same set of values,
> but it's going to probably take an overnight run.

Would reverting commit c365c292d059 (sched: Consider pi boosting in
setscheduler()) fix this?

Re: [3.15-rc3] rtmutex-debug assertion.

[Dave Jones]

On Tue, Apr 29, 2014 at 07:24:30PM -0700, Davidlohr Bueso wrote:

 > > futex(uaddr=0x7f55ff8c4000, op=0x6, val=0x200000006223800b, utime=0x7f55ff8c4000, uaddr2=0x7f55ff8c4000, val3=-123)
 > 
 > Perhaps because of chance. Even for pi futexes, if the lock is
 > uncontended, the kernel will never take part.

Ok, once more..

futex(uaddr=0x25fe000[page_rand], op=0x6, val=0xffff4e2644b3dfcb, utime=0x25fe004[page_rand], uaddr2=0x25fe008[page_rand], val3=0xffffffff440fcd80)

FUTEX_LOCK_PI again.

 > Would reverting commit c365c292d059 (sched: Consider pi boosting in
 > setscheduler()) fix this?

I'll try and write a standalone reproducer in the morning.
Then I'll be able to tell you for sure if that commit is good/bad.

	Dave

Re: [3.15-rc3] rtmutex-debug assertion.

[Thomas Gleixner]

On Tue, 29 Apr 2014, Davidlohr Bueso wrote:
> On Tue, 2014-04-29 at 20:14 -0400, Dave Jones wrote:
> > 
> > futex(uaddr=0x7f55ff8c4000, op=0x6, val=0x200000006223800b, utime=0x7f55ff8c4000, uaddr2=0x7f55ff8c4000, val3=-123)
> 
> Perhaps because of chance. Even for pi futexes, if the lock is
> uncontended, the kernel will never take part.

Well, that's a syscall fuzzer. It feeds the kernel random crap.
 

Re: [3.15-rc3] rtmutex-debug assertion.

[Thomas Gleixner]

On Tue, 29 Apr 2014, Dave Jones wrote:
> This is trickier to reproduce than it first seemed, as logging slows
> things down so much.  But after a few hours, it logged that the
> call that triggered this was..
> 
> futex(uaddr=0x7f55ff8c4000, op=0x6, val=0x200000006223800b, utime=0x7f55ff8c4000, uaddr2=0x7f55ff8c4000, val3=-123)
> 
> Those addresses come from an mmap we made on startup..
> 
> [init] mapping[3]: (zeropage PROT_READ | PROT_WRITE) 0x7f55ff8c4000 (1MB)
> 
> op = FUTEX_LOCK_PI
> 
> val seems to be garbage.
> 
> I'll do another run, just to see if it's always the same set of values,
> but it's going to probably take an overnight run.

Do you have the full fuzzing log, so I can see what happened
before/around that?

Thanks,

	tglx

Re: [3.15-rc3] rtmutex-debug assertion.

[Dave Jones]

On Wed, Apr 30, 2014 at 11:13:57AM +0200, Thomas Gleixner wrote:
 > On Tue, 29 Apr 2014, Dave Jones wrote:
 > > This is trickier to reproduce than it first seemed, as logging slows
 > > things down so much.  But after a few hours, it logged that the
 > > call that triggered this was..
 > > 
 > > futex(uaddr=0x7f55ff8c4000, op=0x6, val=0x200000006223800b, utime=0x7f55ff8c4000, uaddr2=0x7f55ff8c4000, val3=-123)
 > > 
 > > Those addresses come from an mmap we made on startup..
 > > 
 > > [init] mapping[3]: (zeropage PROT_READ | PROT_WRITE) 0x7f55ff8c4000 (1MB)
 > > 
 > > op = FUTEX_LOCK_PI
 > > 
 > > val seems to be garbage.
 > > 
 > > I'll do another run, just to see if it's always the same set of values,
 > > but it's going to probably take an overnight run.
 > 
 > Do you have the full fuzzing log, so I can see what happened
 > before/around that?

This is tough, because it takes a long time to reproduce when the
logging is enabled, and that ends up generating a lot of output.
I've tried to cut it down some using just 4 threads, but that's
still over 30M of logs.
http://www.codemonkey.org.uk/junk/futex.tar.xz

In this run, child0 was the pid that faulted.
You can see the last line in trinity-child0.log has a similar
fingerprint to the trace above.

One thing that does look suspicious, is that all 4 threads were doing
op=0x6 right before the kernel went south.

Hope this helps.

	Dave

Re: [3.15-rc3] rtmutex-debug assertion.

[Thomas Gleixner]

B1;3202;0cOn Fri, 2 May 2014, Dave Jones wrote:
> On Wed, Apr 30, 2014 at 11:13:57AM +0200, Thomas Gleixner wrote:
>  > On Tue, 29 Apr 2014, Dave Jones wrote:
>  > > This is trickier to reproduce than it first seemed, as logging slows
>  > > things down so much.  But after a few hours, it logged that the
>  > > call that triggered this was..
>  > > 
>  > > futex(uaddr=0x7f55ff8c4000, op=0x6, val=0x200000006223800b, utime=0x7f55ff8c4000, uaddr2=0x7f55ff8c4000, val3=-123)
>  > > 
>  > > Those addresses come from an mmap we made on startup..
>  > > 
>  > > [init] mapping[3]: (zeropage PROT_READ | PROT_WRITE) 0x7f55ff8c4000 (1MB)
>  > > 
>  > > op = FUTEX_LOCK_PI
>  > > 
>  > > val seems to be garbage.
>  > > 
>  > > I'll do another run, just to see if it's always the same set of values,
>  > > but it's going to probably take an overnight run.
>  > 
>  > Do you have the full fuzzing log, so I can see what happened
>  > before/around that?
> 
> This is tough, because it takes a long time to reproduce when the
> logging is enabled, and that ends up generating a lot of output.
> I've tried to cut it down some using just 4 threads, but that's
> still over 30M of logs.
> http://www.codemonkey.org.uk/junk/futex.tar.xz
> 
> In this run, child0 was the pid that faulted.
> You can see the last line in trinity-child0.log has a similar
> fingerprint to the trace above.
> 
> One thing that does look suspicious, is that all 4 threads were doing
> op=0x6 right before the kernel went south.
> 
> Hope this helps.

I twisted my brain around that for a fricking long time, but I really
can't see the failure in the code.

Neither did I succeed to trigger the issue in a VM (with and without
function tracing) on Linus latest.

I grabbed trinity source and did:

# ./trinity -l off -c futex -q

That should be enough, right?

All I see in dmesg are occasional ooms which kill random trinity
childs. 

I ran that stuff for almost two days now with a total of 629656086
syscalls. :(

Thanks,

	tglx

Re: [3.15-rc3] rtmutex-debug assertion.

[Thomas Gleixner]

On Mon, 5 May 2014, Dave Jones wrote:

> On Mon, May 05, 2014 at 08:08:02PM +0200, Thomas Gleixner wrote:
>  
>  > I twisted my brain around that for a fricking long time, but I really
>  > can't see the failure in the code.
>  > 
>  > Neither did I succeed to trigger the issue in a VM (with and without
>  > function tracing) on Linus latest.
>  > 
>  > I grabbed trinity source and did:
>  > 
>  > # ./trinity -l off -c futex -q
>  > 
>  > That should be enough, right?
> 
> yeah, that should do it.  That's with the version from git, or the
> last tarball ?  (I really should do another tarball release)

git
 
> Maybe try with -c <some number bigger than processor count>.
> On my 4 way haswell, I run with -C40 just to keep things busy while some
> processes idle. For something like futex, which sleeps a lot, this might
> be important.
> 
>  > All I see in dmesg are occasional ooms which kill random trinity
>  > childs. 
> 
> hm, that sounds odd. if it's only fuzzing futex, it shouldn't be
> doing much memory allocation.

It has a fast memory leak of some sort.

9271 tglx      20   0  198908  75320   2992 S   0.7  7.4   0:01.94 trinity-c0
9271 tglx      20   0  256888 104368   2992 S   3.3 10.2   0:02.78 trinity-c0

Thanks,

	tglx

Re: [3.15-rc3] rtmutex-debug assertion.

[Dave Jones]

On Thu, May 08, 2014 at 05:28:54PM +0200, Thomas Gleixner wrote:

 > >  > All I see in dmesg are occasional ooms which kill random trinity
 > >  > childs. 
 > > 
 > > hm, that sounds odd. if it's only fuzzing futex, it shouldn't be
 > > doing much memory allocation.
 > 
 > It has a fast memory leak of some sort.
 > 
 > 9271 tglx      20   0  198908  75320   2992 S   0.7  7.4   0:01.94 trinity-c0
 > 9271 tglx      20   0  256888 104368   2992 S   3.3 10.2   0:02.78 trinity-c0
 
ah, it's probably where it generates a random address.
See random-address.c:get_writable_address.  This is hitting the 'zmalloc' case.
For the most time, leaking this isn't a big deal, as the child usually
crashes in some way before it becomes a problem. But when we narrow the
possible syscalls it can run as we have in this case, it runs and runs..
until oom.

You could either chop out that case of the switch, or do something like
this..

while [ 1 ];
do
  ./trinity -c futex -l off -q -n 1000000
done

Which forces it to quit and restart every million syscalls.

Kinda hacky, but I've not had motivation to get around to fixing this
(and similar) leaks so far because I keep finding more interesting
things to work on..

	Dave