why this behavior in 3.16 kernel ?

why this behavior in 3.16 kernel ?

[cool linux]

Hi,

I have executed below script on 3.16 kernel and it took to finish almost
1.30sec to 2 minutes, where as in my older kernel(3.2.30) it took only 3
secs.

================================================
date

for (( i=1; i <= 2000; i++ ))
do
 ip netns exec gmk ip link show > /dev/null
done

date
================================================

Please guide me why this behavior in 3.16 kernel ?

Regards,
Madhu

Re: why this behavior in 3.16 kernel ?

[Eric W. Biederman]

cool linux <linux.cool.hot-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org> writes:

> Hi,
>
> I have executed below script on 3.16 kernel and it took to finish almost
> 1.30sec to 2 minutes, where as in my older kernel(3.2.30) it took only 3
> secs.
>
> ================================================
> date
>
> for (( i=1; i <= 2000; i++ ))
> do
>  ip netns exec gmk ip link show > /dev/null
> done
>
> date
> ================================================
>
> Please guide me why this behavior in 3.16 kernel ?

Good question.  What happens on a modern kernel? 4.7 is the most recent
release, 3.16 was released two years ago.  My hunch is that you just
started using systemd and it has changed the defaults with all of the
mounts.  But shrug.  I don't recall how all of those relevant kernel
pieces operated two years ago.

Eric

Re: why this behavior in 3.16 kernel ?

[Andrew Vagin]

On Wed, Aug 03, 2016 at 12:48:49PM -0500, Eric W. Biederman wrote:
> cool linux <linux.cool.hot-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org> writes:
> 
> > Hi,
> >
> > I have executed below script on 3.16 kernel and it took to finish almost
> > 1.30sec to 2 minutes, where as in my older kernel(3.2.30) it took only 3
> > secs.
> >
> > ================================================
> > date
> >
> > for (( i=1; i <= 2000; i++ ))
> > do
> >  ip netns exec gmk ip link show > /dev/null
> > done
> >
> > date
> > ================================================
> >
> > Please guide me why this behavior in 3.16 kernel ?
> 
> Good question.  What happens on a modern kernel? 4.7 is the most recent
> release, 3.16 was released two years ago.  My hunch is that you just
> started using systemd and it has changed the defaults with all of the
> mounts.  But shrug.  I don't recall how all of those relevant kernel
> pieces operated two years ago.

Hi,

I did a few experiments and saw the same degradation. I used rhel7 and
fedoara 23, they both uses systemd.

I executed this test on the rhel7 kernel (3.10++).
[ ~]# time for (( i=1; i <= 2000; i++ )); do ip netns exec gmk ip link show > /dev/null; done

real	0m4.837s
user	0m0.983s
sys	0m3.885s

Then I executed it in Fedora 23 (4.6.4-201.fc23.x86_64) in the same
hardware. The result time is much worse.
[ ~]# time for i in `seq 2000`; do ip netns exec gmk ip link show; done > /dev/null

real	0m36.067s
user	0m1.374s
sys	0m3.677s

Then I tried to exclude a mount namespace:
[ ~]# time for i in `seq 2000`; do nsenter --net=/run/netns/gmk ip link show; done > /dev/null

real	0m4.476s
user	0m1.039s
sys	0m3.438s

It helps, so the problem is defenetly about mount namespaces.

Then I tried to create a clean mount namespace, but this doesn't affect
results:
[ ~]# cat /proc/self/mountinfo 
84 83 253:0 / / rw,relatime - ext4 /dev/mapper/fedora-root rw,seclabel,data=ordered
90 84 0:4 / /proc rw,nosuid,nodev,noexec,relatime - proc proc rw
93 84 0:17 / /sys rw,nosuid,nodev,noexec,relatime - sysfs sysfs rw,seclabel
111 84 0:20 / /run rw,nosuid,nodev - tmpfs tmpfs rw,seclabel,mode=755

[ ~]# time for i in `seq 2000`; do ip netns exec gmk ip
link show; done > /dev/null

real	0m40.129s
user	0m1.272s
sys	0m3.898s

Then I boot the kernel with maxcpus=1. Surprise! Surprise! It works
fast.

[ ~]# ip netns add gmk
[ ~]# time for i in `seq 2000`; do ip netns exec gmk ip
link show; done > /dev/null

real	0m2.445s
user	0m0.604s
sys	0m1.778s


> 
> Eric
> _______________________________________________
> Containers mailing list
> Containers-cunTk1MwBs9QetFLy7KEm3xJsTq8ys+cHZ5vskTnxNA@public.gmane.org
> https://lists.linuxfoundation.org/mailman/listinfo/containers

Re: why this behavior in 3.16 kernel ?

[Andrew Vagin]

On Wed, Aug 03, 2016 at 06:14:02PM -0700, Andrew Vagin wrote:
> On Wed, Aug 03, 2016 at 12:48:49PM -0500, Eric W. Biederman wrote:
> > cool linux <linux.cool.hot-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org> writes:
> > 
> > > Hi,
> > >
> > > I have executed below script on 3.16 kernel and it took to finish almost
> > > 1.30sec to 2 minutes, where as in my older kernel(3.2.30) it took only 3
> > > secs.
> > >
> > > ================================================
> > > date
> > >
> > > for (( i=1; i <= 2000; i++ ))
> > > do
> > >  ip netns exec gmk ip link show > /dev/null
> > > done
> > >
> > > date
> > > ================================================
> > >
> > > Please guide me why this behavior in 3.16 kernel ?
> > 
> > Good question.  What happens on a modern kernel? 4.7 is the most recent
> > release, 3.16 was released two years ago.  My hunch is that you just
> > started using systemd and it has changed the defaults with all of the
> > mounts.  But shrug.  I don't recall how all of those relevant kernel
> > pieces operated two years ago.
> 

[snip]

> [ ~]# time for i in `seq 2000`; do ip netns exec gmk ip
> link show; done > /dev/null
> 
> real	0m40.129s
> user	0m1.272s
> sys	0m3.898s
> 
> Then I boot the kernel with maxcpus=1. Surprise! Surprise! It works
> fast.
> 
> [ ~]# ip netns add gmk
> [ ~]# time for i in `seq 2000`; do ip netns exec gmk ip
> link show; done > /dev/null
> 
> real	0m2.445s
> user	0m0.604s
> sys	0m1.778s

This degradations is due to synchronize_rcu() in namespace_unlock(),
which was added in 48a066e72d9 ("RCU'd vfsmounts").

Here is timings for all calls during sys_unshare():
https://gist.github.com/avagin/3811fbbb553795a78fc6ae602f86866a

> 
> 
> > 
> > Eric
> > _______________________________________________
> > Containers mailing list
> > Containers-cunTk1MwBs9QetFLy7KEm3xJsTq8ys+cHZ5vskTnxNA@public.gmane.org
> > https://lists.linuxfoundation.org/mailman/listinfo/containers

Re: why this behavior in 3.16 kernel ?

[cool linux]

Hi Eric/Andrew,

Thanks for your response.

I have commented out the synchronize_rcu()  in namespace_unlock() which is
located in /fs/namespace.c namespace_unlock()

now am able to see the result in fraction of seconds.

Regards
Madhu

On Thu, Aug 4, 2016 at 11:51 AM, Andrew Vagin <avagin-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org> wrote:

> On Wed, Aug 03, 2016 at 06:14:02PM -0700, Andrew Vagin wrote:
> > On Wed, Aug 03, 2016 at 12:48:49PM -0500, Eric W. Biederman wrote:
> > > cool linux <linux.cool.hot-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org> writes:
> > >
> > > > Hi,
> > > >
> > > > I have executed below script on 3.16 kernel and it took to finish
> almost
> > > > 1.30sec to 2 minutes, where as in my older kernel(3.2.30) it took
> only 3
> > > > secs.
> > > >
> > > > ================================================
> > > > date
> > > >
> > > > for (( i=1; i <= 2000; i++ ))
> > > > do
> > > >  ip netns exec gmk ip link show > /dev/null
> > > > done
> > > >
> > > > date
> > > > ================================================
> > > >
> > > > Please guide me why this behavior in 3.16 kernel ?
> > >
> > > Good question.  What happens on a modern kernel? 4.7 is the most recent
> > > release, 3.16 was released two years ago.  My hunch is that you just
> > > started using systemd and it has changed the defaults with all of the
> > > mounts.  But shrug.  I don't recall how all of those relevant kernel
> > > pieces operated two years ago.
> >
>
> [snip]
>
> > [ ~]# time for i in `seq 2000`; do ip netns exec gmk ip
> > link show; done > /dev/null
> >
> > real  0m40.129s
> > user  0m1.272s
> > sys   0m3.898s
> >
> > Then I boot the kernel with maxcpus=1. Surprise! Surprise! It works
> > fast.
> >
> > [ ~]# ip netns add gmk
> > [ ~]# time for i in `seq 2000`; do ip netns exec gmk ip
> > link show; done > /dev/null
> >
> > real  0m2.445s
> > user  0m0.604s
> > sys   0m1.778s
>
> This degradations is due to synchronize_rcu() in namespace_unlock(),
> which was added in 48a066e72d9 ("RCU'd vfsmounts").
>
> Here is timings for all calls during sys_unshare():
> https://gist.github.com/avagin/3811fbbb553795a78fc6ae602f86866a
>
> >
> >
> > >
> > > Eric
> > > _______________________________________________
> > > Containers mailing list
> > > Containers-cunTk1MwBs9QetFLy7KEm3xJsTq8ys+cHZ5vskTnxNA@public.gmane.org
> > > https://lists.linuxfoundation.org/mailman/listinfo/containers
>

Re: why this behavior in 3.16 kernel ?

[Eric W. Biederman]

cool linux <linux.cool.hot-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org> writes:

> Hi Eric/Andrew,
>
> Thanks for your response.
>
> I have commented out the synchronize_rcu() in namespace_unlock() which is
> located in /fs/namespace.c namespace_unlock() 
>
> now am able to see the result in fraction of seconds.

Interesting.   So it is just the fact you are serializing things in the
loop that makes things slow.

I would recommend syncrhonize_rcu_expidited but in this case since we
aren't holding a lock this is a case that looks like it will only show
up when testing (because things are needlessly serialized) and not in
the real world.

Eric