Date: Sat, 5 Mar 2011 15:45:14 -0800 From: Jeremy Chadwick <freebsd@jdc.parodius.com> To: freebsd-stable@freebsd.org Subject: Strange performance issue with grep -r -i as non-root user Message-ID: <20110305234514.GA34594@icarus.home.lan>
next in thread | raw e-mail | index | archive | help
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 |
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20110305234514.GA34594>