cleanup_net()/net_mutex hung tasks + kobject release debugging

cleanup_net()/net_mutex hung tasks + kobject release debugging

[Vegard Nossum]

Hi Dave + list,

I've started doing some trinity fuzzing and I'm seeing quite a few hung
tasks ("blocked for more than 120 seconds").

It started with unshare()/net_mutex which I found a few others running
into as well:

http://www.spinics.net/lists/trinity/msg00724.html
http://www.spinics.net/lists/netdev/msg192073.html
https://lkml.org/lkml/2014/10/20/538

The rules for net_mutex are very simple, it's used in very few places so
I don't see how the locking could get messed up there. I'll buy your
theory that the lock is held for a long time if there are a lot of
namespaces to iterate over. I decided to time it myself and it seems
that cleanup_net() can hold the mutex for 30-40 seconds at a time, which
is surely wrong.

However, I also noticed that cleanup_net() was always preceded by a lot
of kobject_release messages, like this:

kobject: 'rx-0' (ffff881ac6277460): kobject_release, parent 
ffff881ac6272e08 (delayed 3000)
kobject: 'tx-0' (ffff881ba9951ff8): kobject_release, parent 
ffff881ac6272e08 (delayed 2000)
kobject: 'rx-0' (ffff881baed9b650): kobject_release, parent 
ffff881ba91429a8 (delayed 1000)
kobject: 'tx-0' (ffff881ba88262e8): kobject_release, parent 
ffff881ba91429a8 (delayed 4000)
kobject: 'rx-0' (ffff8819361c28c0): kobject_release, parent 
ffff881b124376c8 (delayed 4000)
kobject: 'tx-0' (ffff881a5fcc8018): kobject_release, parent 
ffff881b124376c8 (delayed 1000)
kobject: 'queues' (ffff881ac6272e08): kobject_release, parent 
(null) (delayed 3000)
kobject: 'lo' (ffff881b12762960): kobject_release, parent 
(null) (delayed 1000)
kobject: 'queues' (ffff881ba91429a8): kobject_release, parent 
(null) (delayed 1000)
kobject: 'queues' (ffff881b124376c8): kobject_release, parent 
(null) (delayed 4000)
kobject: 'lo' (ffff881baeec32a0): kobject_release, parent 
(null) (delayed 3000)
kobject: 'lo' (ffff881a8749e080): kobject_release, parent 
(null) (delayed 1000)
kobject: 'cgroup' (ffff881ac6270b08): kobject_release, parent 
(null) (delayed 3000)
kobject: 'topology_server' (ffff881baf5ac540): kobject_release, parent 
          (null) (delayed 200
0)
kobject: 'cgroup' (ffff881ba91420e8): kobject_release, parent 
(null) (delayed 1000)
kobject: 'topology_server' (ffff881baf5ac800): kobject_release, parent 
          (null) (delayed 400
0)
kobject: 'cgroup' (ffff881ac61429a8): kobject_release, parent 
(null) (delayed 3000)
kobject: 'topology_server' (ffff881baf5abfc0): kobject_release, parent 
          (null) (delayed 200
0)
@@@ cleanup_net took 32574 jiffes

so on a hunch I disabled DEBUG_KOBJECT_RELEASE, and that does indeed
solve the problem -- cleanup_net() still holds the mutex for fairly
long, but only up to max ~5 seconds at a time as opposed to 30-40.

It looks to me like the kobject release debugging is causing
cleanup_net() to have a lot more work to do whenever it gets called
and that's why it's taking longer.

There's maybe a case for cleanup_net() to release the mutex every now
and again during cleanup, but I was also seeing a few other hung tasks
unrelated to net_mutex when I disabled the unshare() system call in
trinity, which makes me wonder if we need a more general solution.

Maybe we can limit the number of workqueue items that kobject_release()
can delay, i.e. if there are more than, say, 100 pending delayed works
then we start processing the first ones queued immediately?

Or maybe trinity should just check whether DEBUG_KOBJECT_RELEASE is set
in /proc/config and throw a warning if that's the case?

(Added some more Ccs for good measure.)


Vegard

Re: cleanup_net()/net_mutex hung tasks + kobject release debugging

[Dave Jones]

On Thu, Jul 21, 2016 at 02:43:34PM +0200, Vegard Nossum wrote:

 > The rules for net_mutex are very simple, it's used in very few places so
 > I don't see how the locking could get messed up there. I'll buy your
 > theory that the lock is held for a long time if there are a lot of
 > namespaces to iterate over. I decided to time it myself and it seems
 > that cleanup_net() can hold the mutex for 30-40 seconds at a time, which
 > is surely wrong.

 > so on a hunch I disabled DEBUG_KOBJECT_RELEASE, and that does indeed
 > solve the problem -- cleanup_net() still holds the mutex for fairly
 > long, but only up to max ~5 seconds at a time as opposed to 30-40.

Yeah, I never ran with that option enabled (it used to cause my testbox
to not boot, and I never got around to debugging why). I thought five seconds
was painful enough. I guess we have different thresholds for acceptable
behaviour here :-)

Could be one of the other debug options I had enabled exacerbates the
cleanup_net problem in a similar way though.

 > There's maybe a case for cleanup_net() to release the mutex every now
 > and again during cleanup, but I was also seeing a few other hung tasks
 > unrelated to net_mutex when I disabled the unshare() system call in
 > trinity, which makes me wonder if we need a more general solution.

Not sure. We may have to just look at these on a case by case basis.

	Dave

Re: cleanup_net()/net_mutex hung tasks + kobject release debugging

[Eric W. Biederman]

Dave Jones <davej@codemonkey.org.uk> writes:

> On Thu, Jul 21, 2016 at 02:43:34PM +0200, Vegard Nossum wrote:
>
>  > The rules for net_mutex are very simple, it's used in very few places so
>  > I don't see how the locking could get messed up there. I'll buy your
>  > theory that the lock is held for a long time if there are a lot of
>  > namespaces to iterate over. I decided to time it myself and it seems
>  > that cleanup_net() can hold the mutex for 30-40 seconds at a time, which
>  > is surely wrong.
>
>  > so on a hunch I disabled DEBUG_KOBJECT_RELEASE, and that does indeed
>  > solve the problem -- cleanup_net() still holds the mutex for fairly
>  > long, but only up to max ~5 seconds at a time as opposed to 30-40.
>
> Yeah, I never ran with that option enabled (it used to cause my testbox
> to not boot, and I never got around to debugging why). I thought five seconds
> was painful enough. I guess we have different thresholds for acceptable
> behaviour here :-)
>
> Could be one of the other debug options I had enabled exacerbates the
> cleanup_net problem in a similar way though.
>
>  > There's maybe a case for cleanup_net() to release the mutex every now
>  > and again during cleanup, but I was also seeing a few other hung tasks
>  > unrelated to net_mutex when I disabled the unshare() system call in
>  > trinity, which makes me wonder if we need a more general solution.
>
> Not sure. We may have to just look at these on a case by case basis.

The best you can easily do in cleanup_net with net_mutex is to reduce
the number of net namespaces you free at once.  Which sounds attractive
except that last I looked most of the time was spent in syncrhonize_rcu.

Because the namespaces can share those synchronize_rcu calls cleaning up
a bunch of network namespaces all at once is actually a pretty big
optimization in terms of system performance.

Though if someone wants to dig in and point out non-shared
synchronize_rcu calls or other obvious sillies happening in cleanup_net
I will be happy to see what we can do.

Eric