Just some even crazier results:

(venv)tools.video2commons-test@tools-bastion-02:~$ time pip -V
pip 8.1.2 from /data/project/video2commons-test/www/python/venv/local/lib/python2.7/site-packages (python 2.7)

real	0m53.807s
user	0m0.993s
sys	0m7.602s

vs

03:11:57 0 ✓ zhuyifei1999@encoding03: ~$ time pip -V
pip 8.1.2 from /usr/local/lib/python2.7/dist-packages (python 2.7)

real	0m0.308s
user	0m0.236s
sys	0m0.056s

They have a similar set of pip packages installed.

In T138742#2409211, @chasemp wrote:

I recall talking w/ yuvi last week that this was to stage a higher tc threshold for testing virtualenv which has been unmercifully slow as of late. [...] AFAIK upping the NFS thresholds had no effect, normally I would have looked at graphite to see if there was any concern but graphite was down at the time so we took a blind swing.

-nfs_write='12000kbps'
-nfs_read='15000kbps'
+nfs_write='7000kbps'
+nfs_read='9500kbps'

(newsopel)tools.piagetbot@tools-bastion-03:~$ time pip -V
pip 1.5.4 from /data/project/piagetbot/.virtualenvs/newsopel/local/lib/python2.7/site-packages (python 2.7)

real    0m23.821s
user    0m0.287s
sys     0m3.098s

That's another set of results, but note that the version of pip on my tool is pip 1.5.4 when @zhuyifei1999's results were with pip 8.1.2, so this might cause a difference. Pip 1.5.4 appears to be the default version on tool labs (just tested with a new virtualenv with no packages):

(testing)tom29739@tools-bastion-03:~$ time pip -V
pip 1.5.4 from /home/tom29739/envs/testing/local/lib/python2.7/site-packages (python 2.7)

real    0m19.562s
user    0m0.285s
sys     0m2.368s

In T136712#2410605, @tom29739 wrote:

That's another set of results, but note that the version of pip on my tool is pip 1.5.4 when @zhuyifei1999's results were with pip 8.1.2, so this might cause a difference. Pip 1.5.4 appears to be the default version on tool labs (just tested with a new virtualenv with no packages)

It's more likely that I simply have too many packages required to run my tool :)

19s is still a long time when it's supposed to run for less than a second.

In T136712#2410687, @zhuyifei1999 wrote:

In T136712#2410605, @tom29739 wrote:

That's another set of results, but note that the version of pip on my tool is pip 1.5.4 when @zhuyifei1999's results were with pip 8.1.2, so this might cause a difference. Pip 1.5.4 appears to be the default version on tool labs (just tested with a new virtualenv with no packages)

It's more likely that I simply have too many packages required to run my tool :)

19s is still a long time when it's supposed to run for less than a second.

It's only getting the version, so it should be super fast for that.

On running strace for pip -V (which took about 20s), I get:

$ strace -o /tmp/pip-strace-counts -f -c pip -V
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 73.62    1.648355         350      4716      4158 open
 24.50    0.548619         248      2209      2018 stat
  0.45    0.010146         122        83         4 lstat
  0.29    0.006464        3232         2           wait4
  0.17    0.003729           5       728           read
  0.16    0.003644           6       580           close
  0.16    0.003563         210        17           openat 
  0.12    0.002582          70        37        21 access
  0.09    0.002057           5       381           mmap
  0.08    0.001770          89        20           write
  0.07    0.001568           2       882           fstat
  0.07    0.001514           6       275           munmap
  0.06    0.001412         282         5         2 readlink
  0.06    0.001251          15        82           rt_sigaction
  0.04    0.000898          26        34           getdents
  0.02    0.000530           9        56           mprotect
  0.01    0.000307           7        42           brk
  0.00    0.000099          25         4           execve
  0.00    0.000096          16         6         1 ioctl
  0.00    0.000052          13         4           arch_prctl
  0.00    0.000044          22         2           set_robust_list
  0.00    0.000039          13         3           dup2
  0.00    0.000034          17         2           geteuid
  0.00    0.000028          14         2           getpid
  0.00    0.000026          13         2           getppid
  0.00    0.000025           8         3           fcntl
  0.00    0.000021           5         4           uname
  0.00    0.000017           9         2           getrlimit
  0.00    0.000016           8         2         1 futex

While it seems terrible that it's doing ~4k open calls for a -V, I guess the problem is just 'NFS has latency'?

I remember it was much faster in 2013. I mean general NFS usage

Indeed, or even a few months ago. The only significant thing I can think of as having changed since then is the NFS rate limiting, so I'd still like to maybe completely remove that and try testing this again to see if that's the cause.

Yes, and 'we don't cache anything'. See the task description for a comparison between tools-bastion-03 and relic. Your data suggests that an open() call only takes 350µs (which is really good for something that goes over the network, I'd say); my data suggested something in the direction of 4ms.

NFS was much faster about 5-6 months ago, when I joined. It's having an impact on the speed of other things too (e.g. the speed of webservices, especially with PHP).

In T136712#2410957, @yuvipanda wrote:

Indeed, or even a few months ago. The only significant thing I can think of as having changed since then is the NFS rate limiting, so I'd still like to maybe completely remove that and try testing this again to see if that's the cause.

Why are we rate limiting NFS? It's slow enough already (don't know whether that's down to the rate limiting).

In T136712#2410959, @tom29739 wrote:

NFS was much faster about 5-6 months ago, when I joined. It's having an impact on the speed of other things too (e.g. the speed of webservices, especially with PHP).

In February this year when my tool (video2commons) is first up, the time taken to start its webservice is about as much as now (i.e. a few minutes).

In T136712#2410960, @tom29739 wrote:

Why are we rate limiting NFS? It's slow enough already (don't know whether that's down to the rate limiting).

Because people hammer NFS a lot? And NFS is basically a single point of failure for a large part of labs.

In T136712#2410960, @tom29739 wrote:

Why are we rate limiting NFS? It's slow enough already (don't know whether that's down to the rate limiting).

NFS is rate-limited per host. Otherwise, a single host can overload the NFS server so badly that other hosts (and thus other users) suffer (and this has happened more than once).

Exact repro steps for me is, on any bastion host:

become lolrrit-wm
time ./testing-virtualenv/bin/pip -V

Ok, with @chasemp's help I cleared the tc settings on bastion-03:

tc qdisc del dev eth0 root
tc qdisc del dev eth0 handle ffff: ingress
tc qdisc del dev ifb0 root

running pip -V still takes a while:

tools.lolrrit-wm@tools-bastion-03:~$ time ./testing-virtualenv/bin/pip -V
pip 1.5.4 from /data/project/lolrrit-wm/testing-virtualenv/local/lib/python2.7/site-packages (python 2.7)

real    0m16.337s
user    0m0.310s
sys     0m1.855s

So I think we can rule out the rate limiting.

Perhaps ulimits are causing it?

tom29739@tools-bastion-03:~$ ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 128316
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) unlimited
open files                      (-n) 512
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) 43200
max user processes              (-u) 30
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

The open files limit might be causing it (I'm guessing, ulimits were not set/changed that long ago if I recall).

In T136712#2410709, @yuvipanda wrote:

On running strace for pip -V (which took about 20s), I get:

$ strace -o /tmp/pip-strace-counts -f -c pip -V
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 73.62    1.648355         350      4716      4158 open
 24.50    0.548619         248      2209      2018 stat
  0.45    0.010146         122        83         4 lstat
  0.29    0.006464        3232         2           wait4
  0.17    0.003729           5       728           read
  0.16    0.003644           6       580           close
  0.16    0.003563         210        17           openat 
  0.12    0.002582          70        37        21 access
  0.09    0.002057           5       381           mmap
  0.08    0.001770          89        20           write
  0.07    0.001568           2       882           fstat
  0.07    0.001514           6       275           munmap
  0.06    0.001412         282         5         2 readlink
  0.06    0.001251          15        82           rt_sigaction
  0.04    0.000898          26        34           getdents
  0.02    0.000530           9        56           mprotect
  0.01    0.000307           7        42           brk
  0.00    0.000099          25         4           execve
  0.00    0.000096          16         6         1 ioctl
  0.00    0.000052          13         4           arch_prctl
  0.00    0.000044          22         2           set_robust_list
  0.00    0.000039          13         3           dup2
  0.00    0.000034          17         2           geteuid
  0.00    0.000028          14         2           getpid
  0.00    0.000026          13         2           getppid
  0.00    0.000025           8         3           fcntl
  0.00    0.000021           5         4           uname
  0.00    0.000017           9         2           getrlimit
  0.00    0.000016           8         2         1 futex

There's 4716 open calls there, which means that it's opening files (open - open and possibly create a file or device) and there's 728 read calls (read - read from a file descriptor), which tallies with the open files limit because

In T136712#2411442, @tom29739 wrote:

open files (-n) 512

because these read/open calls are failing because of those ulimits and thus slowing the command down (another guess).

best way to eliminate is to edit /etc/security/limits.conf, logout,login, verify new limits and test

No effect.

tools.lolrrit-wm@tools-bastion-03:~$ ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 128316
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) unlimited
open files                      (-n) 5120
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) 43200
max user processes              (-u) 30
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited
tools.lolrrit-wm@tools-bastion-03:~$ time ./testing-virtualenv/bin/pip -V
pip 1.5.4 from /data/project/lolrrit-wm/testing-virtualenv/local/lib/python2.7/site-packages (python 2.7)
 
real    0m16.715s
user    0m0.285s
sys     0m1.993s

I set hard and soft limits high up as well.

I finally fixed up the test bastion host enough, and @valhallasw is right as usual - turning off lookupcache=none speeds this up to 2s. Removing nofsc had no effect though.

I tested the lookupcache enabling yesterday on tools-bastion-05 (it wasn't enabled there) and an exec node(tools-exec-1402), through instance hiera. One puppet run - which was clean, and the mounts didn't need remounting. Currently on tools, tools-worker* have them enabled through prefix hiera, and bastion 02 and 03 had it on through instance hiera.

Early next week, I'll roll it out through project hiera on tools, and then may be making it the default param to the class to apply across labs

Mentioned in SAL (#wikimedia-labs) [2017-03-30T17:29:10Z] <madhuvishy> Disabled puppet across tools in prep for T136712

Mentioned in SAL (#wikimedia-labs) [2017-03-30T17:30:52Z] <madhuvishy> Updating tools project hiera config to add role::labs::nfsclient::lookupcache: all via Horizon (T136712)

I've now rolled out lookupcache:all to all of tools.

Change 346177 had a related patch set uploaded (by Madhuvishy):
[operations/puppet@production] nfsclient: Enable lookupcache by default for all nfs client instances

https://gerrit.wikimedia.org/r/346177

Change 346177 merged by Madhuvishy:
[operations/puppet@production] nfsclient: Enable lookupcache by default for all nfs client instances

https://gerrit.wikimedia.org/r/346177