Jeremy Chadwick
2011-Mar-05 23:45 UTC
Strange performance issue with grep -r -i as non-root user
This is a strange one, and the more I started debugging it (starting
with truss, comparing fast vs. slow results, where all that appears
different is read() operations are taking a lot longer -- I haven't had
time to check with ktrace yet), the more strange it got: that's when I
found out the behaviour changes depending on if you're a user or root.
Easy to reproduce:
- grep -r string /usr/src, as non-root, is fast
- grep -r -i string /usr/src, as non-root, is 8x slower than without -i
- grep -r string /usr/src, as root, is fast
- grep -r -i string /usr/src, as root, is fast
$ id
uid=1000(jdc) gid=1000(users) groups=1000(users),0(wheel)
$ for i in {0..9}; do /usr/bin/time -h grep -r PAE /usr/src/sys/dev >
/dev/null ; done
0.17s real 0.11s user 0.05s sys
0.12s real 0.06s user 0.05s sys
0.12s real 0.09s user 0.02s sys
0.12s real 0.07s user 0.04s sys
0.12s real 0.10s user 0.01s sys
0.12s real 0.08s user 0.03s sys
0.12s real 0.07s user 0.04s sys
0.12s real 0.10s user 0.01s sys
0.12s real 0.06s user 0.05s sys
0.12s real 0.07s user 0.04s sys
$ for i in {0..9}; do /usr/bin/time -h grep -r -i PAE /usr/src/sys/dev >
/dev/null ; done
8.85s real 8.78s user 0.05s sys
8.80s real 8.76s user 0.00s sys
8.82s real 8.77s user 0.01s sys
8.81s real 8.75s user 0.02s sys
^Ctime: command terminated abnormally
$ for i in {0..9}; do sudo /usr/bin/time -h grep -r PAE /usr/src/sys/dev >
/dev/null ; done
0.19s real 0.11s user 0.08s sys
0.11s real 0.09s user 0.02s sys
0.11s real 0.09s user 0.02s sys
0.11s real 0.07s user 0.04s sys
0.11s real 0.09s user 0.02s sys
0.11s real 0.08s user 0.02s sys
0.11s real 0.07s user 0.04s sys
0.11s real 0.08s user 0.02s sys
0.11s real 0.07s user 0.04s sys
0.11s real 0.07s user 0.04s sys
$ for i in {0..9}; do sudo /usr/bin/time -h grep -r -i PAE /usr/src/sys/dev >
/dev/null ; done
0.19s real 0.10s user 0.08s sys
0.16s real 0.10s user 0.05s sys
0.13s real 0.08s user 0.05s sys
0.13s real 0.09s user 0.03s sys
0.13s real 0.11s user 0.02s sys
0.13s real 0.10s user 0.03s sys
0.13s real 0.11s user 0.02s sys
0.13s real 0.09s user 0.04s sys
0.13s real 0.09s user 0.03s sys
0.13s real 0.09s user 0.04s sys
I can reproduce the issue on 3 different physical machines, with a 4th
being completely immune to it (the machine runs a very old 7.0-STABLE,
uses i386, and does not use ahci.ko (AHCI->CAM)). It's reproducible at
any time (e.g. unrelated to disk I/O), and is unrelated to system
uptime.
All machines are using UFS2+softupdates for their /usr filesystem, which
is where /usr/src lives.
All machines use base system gcc and base system grep, which all appear
to be gcc version 4.2.1 20070719 and grep (GNU grep) 2.5.1-FreeBSD.
Hardware in the machines is slightly different (some with faster CPUs
than others, and some use SSDs instead of mechanical HDDs), but the
SATA controllers/etc. are all the same (ICH9R).
When reading part of the uname string, please trust me when I say that
the kernel build time is basically synonymous when with src-all was
csup'd. :-)
* System #1: FreeBSD 8.2-STABLE #0: Tue Mar 1 00:17:25 PST 2011 amd64
Supermicro X7SBA, 8GB ECC RAM
3:43pm up 1 day, 9:12, 2 users, load averages: 0.06, 0.02, 0.00
ada0: <INTEL SSDSA2M040G2GC 2CV102M3> ATA-7 SATA 2.x device
Filesystem 1024-blocks Used Avail Capacity Mounted on
/dev/ada0s1f 8395622 3376560 4347414 44% /usr
make.conf contains: CPUTYPE?=core2
* System #2: FreeBSD 8.2-STABLE #0: Thu Feb 24 22:06:45 PST 2011 amd64
Supermicro PDSMi+, 8GB ECC RAM
3:43pm up 8 days, 15:26, 1 user, load averages: 0.00, 0.00, 0.00
ada0: <WDC WD3000HLFS-01G6U0 04.04V01> ATA-8 SATA 2.x device
Filesystem 1024-blocks Used Avail Capacity Mounted on
/dev/ada0s1f 217798292 2761536 197612894 1% /usr
make.conf contains: CPUTYPE?=core2
* System #3: FreeBSD 8.1-STABLE #0: Wed Oct 20 00:54:42 PDT 2010 amd64
Supermicro PDSMi+, 8GB ECC RAM
3:43pm up 136 days, 13:46, 1 user, load averages: 0.02, 0.05, 0.00
ada0: <WDC WD3201ABYS-01B9A0 13.01C02> ATA-8 SATA 2.x device
Filesystem 1024-blocks Used Avail Capacity Mounted on
/dev/ada0s1f 8122126 3043260 4429096 41% /usr
make.conf contains: CPUTYPE?=core2
Finally, the box which doesn't exhibit any problems:
* System #4: FreeBSD 7.0-STABLE #0: Sat Apr 19 04:52:03 PDT 2008 i386
Supermicro PDSMi+, 8GB ECC RAM (only 4GB usable due to i386)
3:43pm up 341 days, 21:41, 2 users, load averages: 0.00, 0.02, 0.05
ad4: 238475MB <Seagate ST3250620NS 3.AEG> at ata2-master SATA300
Filesystem 1024-blocks Used Avail Capacity Mounted on
/dev/ad4s1f 32494668 1984234 27910862 7% /usr
make.conf contains: CPUTYPE?=nocona
There are lots of things I can try to see if I can narrow down the
behaviour to a certain piece (such as removing CPUTYPE optimisations),
but I wanted to see if others could reproduce this as well.
--
| Jeremy Chadwick jdc@parodius.com |
| Parodius Networking http://www.parodius.com/ |
| UNIX Systems Administrator Mountain View, CA, USA |
| Making life hard for others since 1977. PGP 4BD6C0CB |
Clifton Royston
2011-Mar-06 01:01 UTC
Strange performance issue with grep -r -i as non-root user
On Sat, Mar 05, 2011 at 03:45:14PM -0800, Jeremy Chadwick wrote:> This is a strange one, and the more I started debugging it (starting > with truss, comparing fast vs. slow results, where all that appears > different is read() operations are taking a lot longer -- I haven't had > time to check with ktrace yet), the more strange it got: that's when I > found out the behaviour changes depending on if you're a user or root. > > Easy to reproduce: > > - grep -r string /usr/src, as non-root, is fast > - grep -r -i string /usr/src, as non-root, is 8x slower than without -iFrom your results below, I think you mean *80* x slower!> - grep -r string /usr/src, as root, is fast > - grep -r -i string /usr/src, as root, is fastI can not reproduce this on 7.3-RELEASE-p4; I get consistent results between root and non-root, with -i being only marginally slower (about 15%) for each; results below. Just to satisfy my peace of mind, can you do 'which grep' and 'sudo sh -c "which grep"' as jdc to make sure it's not path-related weirdness? -- Clifton [cliftonr@oz ~]$ id uid=1001(cliftonr) gid=1001(cliftonr) groups=1001(cliftonr),0(wheel),1002(svn-user),1000(users) [cliftonr@oz ~]$ for i in {0..9}; do /usr/bin/time -h /usr/bin/grep -r \ PAE /usr/src/sys/dev > /dev/null; done 12.10s real 0.16s user 0.21s sys 0.20s real 0.12s user 0.08s sys ... [cliftonr@oz ~]$ for i in {0..9}; do /usr/bin/time -h /usr/bin/grep -r \ PAE /usr/src/sys/dev > /dev/null; done 0.20s real 0.11s user 0.09s sys 0.20s real 0.13s user 0.06s sys 0.20s real 0.12s user 0.08s sys 0.20s real 0.12s user 0.07s sys 0.20s real 0.14s user 0.06s sys 0.20s real 0.15s user 0.05s sys 0.20s real 0.12s user 0.08s sys 0.20s real 0.09s user 0.11s sys 0.20s real 0.14s user 0.06s sys 0.20s real 0.12s user 0.07s sys [cliftonr@oz ~]$ for i in {0..9}; do /usr/bin/time -h /usr/bin/grep -r \ -i PAE /usr/src/sys/dev > /dev/null; done 0.23s real 0.14s user 0.08s sys 0.23s real 0.15s user 0.07s sys 0.23s real 0.18s user 0.05s sys 0.23s real 0.14s user 0.08s sys 0.23s real 0.19s user 0.03s sys 0.23s real 0.18s user 0.04s sys 0.23s real 0.14s user 0.08s sys 0.23s real 0.13s user 0.09s sys 0.23s real 0.16s user 0.06s sys 0.22s real 0.17s user 0.05s sys [cliftonr@oz ~]$ sudo -v [cliftonr@oz ~]$ for i in {0..9}; do sudo /usr/bin/time -h \ /usr/bin/grep -r PAE /usr/src/sys/dev > /dev/null; done 0.20s real 0.18s user 0.02s sys 0.20s real 0.10s user 0.10s sys 0.20s real 0.14s user 0.06s sys 0.20s real 0.13s user 0.06s sys 0.20s real 0.12s user 0.08s sys 0.20s real 0.12s user 0.07s sys 0.20s real 0.12s user 0.08s sys 0.20s real 0.12s user 0.08s sys 0.20s real 0.16s user 0.03s sys 0.20s real 0.15s user 0.05s sys [cliftonr@oz ~]$ for i in {0..9}; do sudo /usr/bin/time -h \ /usr/bin/grep -r -i PAE /usr/src/sys/dev > /dev/null; done 0.23s real 0.17s user 0.05s sys 0.23s real 0.16s user 0.06s sys 0.23s real 0.17s user 0.05s sys 0.23s real 0.17s user 0.06s sys 0.23s real 0.17s user 0.06s sys 0.23s real 0.18s user 0.05s sys 0.23s real 0.17s user 0.05s sys 0.23s real 0.14s user 0.08s sys 0.23s real 0.15s user 0.08s sys 0.22s real 0.13s user 0.09s sys [cliftonr@oz ~]$ which grep /usr/bin/grep [cliftonr@oz ~]$ sudo sh -c "which grep" /usr/bin/grep -- Clifton Royston -- cliftonr@iandicomputing.com / cliftonr@lava.net President - I and I Computing * http://www.iandicomputing.com/ Custom programming, network design, systems and network consulting services
Gary Palmer
2011-Mar-06 02:46 UTC
Strange performance issue with grep -r -i as non-root user
On Sat, Mar 05, 2011 at 03:45:14PM -0800, Jeremy Chadwick wrote:> This is a strange one, and the more I started debugging it (starting > with truss, comparing fast vs. slow results, where all that appears > different is read() operations are taking a lot longer -- I haven't had > time to check with ktrace yet), the more strange it got: that's when I > found out the behaviour changes depending on if you're a user or root. > > Easy to reproduce: > > - grep -r string /usr/src, as non-root, is fast > - grep -r -i string /usr/src, as non-root, is 8x slower than without -i > - grep -r string /usr/src, as root, is fast > - grep -r -i string /usr/src, as root, is fastThis is a stab in the dark, but are there any differences in your shell environment variables between root and non-root? Specifically LANG or LC_ style variables. I ran into issues in the past with grep being horrendously slow and traced it to LANG or LC_* in the environment causing a much longer code path than without the settings. Regards, Gary