Re: [SOLVED-ish] Performance weirdness with netbsd-9 /usr/bin/grep

[Paul Ripke <stix%stix.id.au@localhost>]

On Sat, May 23, 2020 at 01:54:55PM +0100, Sad Clouds wrote:
> On Sat, 23 May 2020 14:04:56 +0200
> Martin Husemann <martin%duskware.de@localhost> wrote:
> 
> > On Sat, May 23, 2020 at 10:19:28AM +0100, Sad Clouds wrote:
> > > rp3$ locale
> > > LANG=""
> > > LC_CTYPE="C"
> > > LC_COLLATE="C"
> > > LC_TIME="C"
> > > LC_NUMERIC="C"
> > > LC_MONETARY="C"
> > > LC_MESSAGES="C"
> > > LC_ALL=""
> > 
> > I get the same for netbsd-8 and netbsd-7.
> > 
> > Martin
> 
> Probably nothing to do with locales. First time grep is run, data is
> read from disk into page cache, which takes time. Second time grep is
> run with LC_ALL=C but there is no disk I/O, as data is read straight
> from page cache, so much faster.

No, as I noted in my original email, it's all user time. If it was indeed
reading from disk, or paging in from a swaped out tmpfs, or pulling over
NFS, etc, the time should be mostly seen as system time. Besides, this
machine has 16GiB of RAM, and easily caches the ~500MiB log.

Additionally, the test is quite repeatable from a tmpfs:

slave:ksh$ cp /home/httpd/log/access.log /tmp
slave:ksh$ time wc -l /tmp/access.log
 2053050 /tmp/access.log
    1.42s real     0.84s user     0.58s system
slave:ksh$ LANG=en_US.UTF-8 time grep -c Jan/2020 /tmp/access.log
407186
      102.74 real       101.87 user         0.56 sys
slave:ksh$ LANG=C time grep -c Jan/2020 /tmp/access.log
407186
        1.28 real         0.51 user         0.77 sys
slave:ksh$ LANG=en_US.UTF-8 time grep -c Jan/2020 /tmp/access.log
407186
      115.39 real       114.54 user         0.57 sys
slave:ksh$ LANG=C time grep -c Jan/2020 /tmp/access.log
407186
        0.88 real         0.36 user         0.51 sys

And even /usr/share/dict/words:

slave:ksh$ LANG=C time grep -c ^e /usr/share/dict/words
7820
        0.01 real         0.01 user         0.00 sys
slave:ksh$ LANG=en_US.UTF-8 time grep -c ^e /usr/share/dict/words
7820
        2.34 real         2.32 user         0.00 sys
slave:ksh$ LANG=C time grep -c ^e /usr/share/dict/words
7820
        0.01 real         0.01 user         0.00 sys
slave:ksh$ LANG=en_US.UTF-8 time grep -c ^e /usr/share/dict/words
7820
        2.02 real         2.01 user         0.00 sys

And especially on a little ARM system:

thing1:ksh$ uname -a
NetBSD thing1 9.0_STABLE NetBSD 9.0_STABLE (GENERIC) #8: Sun Mar  8 23:07:35 AEDT 2020  stix@slave:/home/netbsd/netbsd-9/obj.evbarm-earmv7hf/home/netbsd/netbsd-9/src/sys/arch/evbarm/compile/GENERIC evbarm
thing1:ksh$ LANG=C time grep -c ^e /usr/share/dict/words
7820
        0.13 real         0.08 user         0.01 sys
thing1:ksh$ LANG=en_US.UTF-8 time grep -c ^e /usr/share/dict/words
7820
       23.99 real        23.93 user         0.01 sys
thing1:ksh$ LANG=C time grep -c ^e /usr/share/dict/words
7820
        0.09 real         0.09 user         0.00 sys
thing1:ksh$ LANG=en_US.UTF-8 time grep -c ^e /usr/share/dict/words
7820
       24.06 real        23.97 user         0.03 sys

-- 
Paul Ripke
"Great minds discuss ideas, average minds discuss events, small minds
 discuss people."
-- Disputed: Often attributed to Eleanor Roosevelt. 1948.