ack 2.12 about 10 times slower than grep 2.18 (Linux 64 bit)

[kmansoft]

I just learned about ack, and absolutely love it (for file types, output format, and the ignore list).

However, it seems it's really not faster than grep: on my development system, it's about 10 times slower.

This is not really an issue for me, but I thought I'd mention it.

Environment: Fedora 20 + testing updates, 64 bit, kernel 3.14.4 Hardware: Intel i7 4770, 16 G RAM, SSD's File system: ext4

ack version: 2.12 from distro repos grep version: 2.18 from distro repos

Source file set: a subdirectory of Android framework source code from the master branch.

.../frameworks/base/core/java

1895 files taking 28 megabytes (1400 of them Java)

I performed multiple runs to get the files into system memory caches, even though the disk drive is an SSD.

grep, all files

$ time grep -r getWidth . | wc
    305    2128   32201

real    0m0.060s
user    0m0.050s
sys 0m0.012s

grep, Java files

$ time grep  getWidth $(find . -name "*.java") | wc
    304    2125   32140

real    0m0.077s
user    0m0.069s
sys 0m0.010s

ack config

$ cat ~/.ackrc 
--ignore-directory=is:build
--ignore-directory=is:bin
--ignore-directory=is:gen

ack, all files

$ time ack  getWidth | wc
    305    2128   32908

real    0m0.614s
user    0m0.582s
sys 0m0.030s

ack, Java files

$ time ack  --java getWidth | wc
    304    2125   32846

real    0m0.584s
user    0m0.572s
sys 0m0.012s

Piping to wc or not produces slightly different numbers, but overall it's the same: ack is slower by about 10 times.

I also tried Ubuntu 14.04 64 bit on same hardware, with grep 2.16. The results are very close.

[petdance]

What version of Perl are you using? Can you paste a perl -V in your ticket, please?

[kmansoft]

PS - tried ack 2.12_06 built from source, performance is pretty much the same.

[kmansoft]

perl -V output. This is Fedora 20 x64

$ perl -V
Summary of my perl5 (revision 5 version 18 subversion 2) configuration:

  Platform:
    osname=linux, osvers=3.11.9-200.fc19.x86_64, archname=x86_64-linux-thread-multi
    uname='linux buildvm-12.phx2.fedoraproject.org 3.11.9-200.fc19.x86_64 #1 smp wed nov 20 21:22:24 utc 2013 x86_64 x86_64 x86_64 gnulinux '
    config_args='-des -Doptimize=-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches  -m64 -mtune=generic -Dccdlflags=-Wl,--enable-new-dtags -Dlddlflags=-shared -O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches  -m64 -mtune=generic -Wl,-z,relro  -Dshrpdir=/usr/lib64 -DDEBUGGING=-g -Dversion=5.18.2 -Dmyhostname=localhost -Dperladmin=root@localhost -Dcc=gcc -Dcf_by=Red Hat, Inc. -Dprefix=/usr -Dvendorprefix=/usr -Dsiteprefix=/usr/local -Dsitelib=/usr/local/share/perl5 -Dsitearch=/usr/local/lib64/perl5 -Dprivlib=/usr/share/perl5 -Dvendorlib=/usr/share/perl5/vendor_perl -Darchlib=/usr/lib64/perl5 -Dvendorarch=/usr/lib64/perl5/vendor_perl -Darchname=x86_64-linux-thread-multi -Dlibpth=/usr/local/lib64 /lib64 /usr/lib64 -Duseshrplib -Dusethreads -Duseithreads -Dusedtrace=/usr/bin/dtrace -Duselargefiles -Dd_semctl_semun -Di_db -Ui_ndbm -Di_gdbm -Di_shadow -Di_syslog -Dman3ext=3pm -Duseperlio -Dinstallusrbinperl=n -Ubincompat5005 -Uversiononly -Dpager=/usr/bin/less -isr -Dd_gethostent_r_proto -Ud_endhostent_r_proto -Ud_sethostent_r_proto -Ud_endprotoent_r_proto -Ud_setprotoent_r_proto -Ud_endservent_r_proto -Ud_setservent_r_proto -Dscriptdir=/usr/bin -Dusesitecustomize'
    hint=recommended, useposix=true, d_sigaction=define
    useithreads=define, usemultiplicity=define
    useperlio=define, d_sfio=undef, uselargefiles=define, usesocks=undef
    use64bitint=define, use64bitall=define, uselongdouble=undef
    usemymalloc=n, bincompat5005=undef
  Compiler:
    cc='gcc', ccflags ='-D_REENTRANT -D_GNU_SOURCE -fno-strict-aliasing -pipe -fstack-protector -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64',
    optimize='-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches -m64 -mtune=generic',
    cppflags='-D_REENTRANT -D_GNU_SOURCE -fno-strict-aliasing -pipe -fstack-protector -I/usr/local/include'
    ccversion='', gccversion='4.8.2 20131212 (Red Hat 4.8.2-7)', gccosandvers=''
    intsize=4, longsize=8, ptrsize=8, doublesize=8, byteorder=12345678
    d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=16
    ivtype='long', ivsize=8, nvtype='double', nvsize=8, Off_t='off_t', lseeksize=8
    alignbytes=8, prototype=define
  Linker and Libraries:
    ld='gcc', ldflags =' -fstack-protector'
    libpth=/usr/local/lib64 /lib64 /usr/lib64
    libs=-lresolv -lnsl -lgdbm -ldb -ldl -lm -lcrypt -lutil -lpthread -lc -lgdbm_compat
    perllibs=-lresolv -lnsl -ldl -lm -lcrypt -lutil -lpthread -lc
    libc=, so=so, useshrplib=true, libperl=libperl.so
    gnulibc_version='2.18'
  Dynamic Linking:
    dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,--enable-new-dtags'
    cccdlflags='-fPIC', lddlflags='-shared -O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector-strong --param=ssp-buffer-size=4 -grecord-gcc-switches -m64 -mtune=generic -Wl,-z,relro '

Characteristics of this binary (from libperl): 
  Compile-time options: HAS_TIMES MULTIPLICITY PERLIO_LAYERS
                        PERL_DONT_CREATE_GVSV
                        PERL_HASH_FUNC_ONE_AT_A_TIME_HARD
                        PERL_IMPLICIT_CONTEXT PERL_MALLOC_WRAP
                        PERL_PRESERVE_IVUV PERL_SAWAMPERSAND USE_64_BIT_ALL
                        USE_64_BIT_INT USE_ITHREADS USE_LARGE_FILES
                        USE_LOCALE USE_LOCALE_COLLATE USE_LOCALE_CTYPE
                        USE_LOCALE_NUMERIC USE_PERLIO USE_PERL_ATOF
                        USE_REENTRANT_API USE_SITECUSTOMIZE
  Locally applied patches:
    Fedora Patch1: Removes date check, Fedora/RHEL specific
    Fedora Patch3: support for libdir64
    Fedora Patch4: use libresolv instead of libbind
    Fedora Patch5: USE_MM_LD_RUN_PATH
    Fedora Patch6: Skip hostname tests, due to builders not being network capable
    Fedora Patch7: Dont run one io test due to random builder failures
    Fedora Patch9: Fix find2perl to translate ? glob properly (RT#113054)
    Fedora Patch10: Update h2ph(1) documentation (RT#117647)
    Fedora Patch11: Update pod2html(1) documentation (RT#117623)
    Fedora Patch12: Disable ornaments on perl5db AutoTrace tests (RT#118817)
    Fedora Patch14: Do not use system Term::ReadLine::Gnu in tests (RT#118821)
    Fedora Patch15: Define SONAME for libperl.so
    Fedora Patch16: Install libperl.so to -Dshrpdir value
    Fedora Patch18: Fix crash with \&$glob_copy (RT#119051)
    Fedora Patch19: Fix coreamp.t rand test (RT#118237)
    Fedora Patch20: Reap child in case where exception has been thrown (RT#114722)
    Fedora Patch21: Fix using regular expressions containing multiple code blocks (RT#117917)
    Fedora Patch200: Link XS modules to libperl.so with EU::CBuilder on Linux
    Fedora Patch201: Link XS modules to libperl.so with EU::MM on Linux
  Built under linux
  Compiled at Jan  7 2014 14:47:21
  @INC:
    /usr/local/lib64/perl5
    /usr/local/share/perl5
    /usr/lib64/perl5/vendor_perl
    /usr/share/perl5/vendor_perl
    /usr/lib64/perl5
    /usr/share/perl5
    .

[petdance]

You're not the first person to post that ack is significantly slower than grep on your machine, or in your specific source tree, or whatever it may be that is causing the slowdown, but we've been unable to track it down to a given reason. Here's hoping that your case can give us some insight.

[kmansoft]

I'm open to running more tests, just let me know (I've cloned the current ack2 source repo already).

Would you like to see the output of perl -V under Ubuntu? Same hardware, same performance, but different OS?

[petdance]

Can you please give me a URL that I do a git clone from for the source tree that you're working on? repo apparently doesn't like my version of Python.

[kmansoft]

This is a github mirror of the Google repository.

You'll want the core/java subdirectory.

In the original, that's 1895 files taking 28 megabytes (1400 of them Java), not sure how far behind the github clone is.

[petdance]

I just ran the time test on my iMac

(master) alester:~/platform_frameworks_base/core/java $ time grep -r getWidth .  | wc
     305    2128   32201

real    0m0.342s
user    0m0.323s
sys     0m0.022s
(master) alester:~/platform_frameworks_base/core/java $ time grep -r getWidth $(find . -name '*.java') | wc
     304    2125   32140

real    0m0.362s
user    0m0.315s
sys     0m0.022s
(master) alester:~/platform_frameworks_base/core/java $ time ack  getWidth | wc
     305    2128   32908

real    0m1.427s
user    0m0.927s
sys     0m0.098s
(master) alester:~/platform_frameworks_base/core/java $  time ack  --java getWidth | wc
     304    2125   32846

real    0m1.010s
user    0m0.962s
sys     0m0.047s

Slower, yes, but not 10x.

[kmansoft]

Well, on your system, grep is slower than it is on mine by abut 5x (0.342s vs 0.060s) -- and ack is slower by about 2x. So overall, on your system, ack vs. grep looks like a 3-4x.

So where do we go from here? "Everyone, get a Mac"?

[petdance]

So where do we go from here? "Everyone, get a Mac"?

No, not at all. We don't work that way here on the ack project. I'm just adding a data point that shows that while there is a time difference, it's not 10x on this specific machine. We also know that for the timings between you and me, we're working on the same corpus, so we can eliminate that difference.

My gut tells me that there's something different between how grep is opening files and how Perl is opening files, but I have nothing to base that on.

[hoelzro]

This might provide some insight:

$ strace ack  getWidth 2>&1 >/dev/null | grep open | wc -l
3728
$ strace grep -r getWidth . 2>&1 >/dev/null | grep open | wc -l
1904

ack is opening twice as many files as grep, or is perhaps opening the same files twice. Granted, this doesn't mean anything without further analysis, but it's a starting point!

[hoelzro]

@kmansoft By the way, thanks for providing so much information, as well as a codebase we can actually work with and reproduce this behavior on. It really makes tracking down performance issues a lot easier!

[kmansoft]

Sure, my pleasure.

About the different way of opening files.

grepfile uses openat_safer:

http://git.savannah.gnu.org/cgit/grep.git/tree/src/grep.c#n1352

openat_safer is a wrapper for openat: http://fossies.org/dox/coreutils-8.22/openat-safer_8c_source.html

openat is a Linux / POSIX syscall, that takes an already open directory handle (from what I can tell from the man page):

http://linux.die.net/man/2/openat

My impression is that this avoids the overhead in the kernel of having to resolve a full file name, walking through the directories starting at the root, checking permissions, possibly across mount points, etc.

[hoelzro]

I'd be interested to see how much overhead open has versus openat; that merits an experiment. But I can confirm that ack does indeed open each file twice; that would likely result in a huge win.

[kmansoft]

strace was great idea, @hoelzro !

Ran it with openat instead of just open:

$ strace ack  getWidth 2>&1 >/dev/null | grep openat | wc -l
103

$ strace grep -r getWidth 2>&1 >/dev/null | grep openat | wc -l
1897

And plain open for comparison (which of course matches openat too):

$ strace grep -r getWidth 2>&1 >/dev/null | grep open | wc -l
1923

So grep uses open just for 26 files (wonder what they are), but the vast majority of searched files are open with openat

Even withfind, openat dominates:

$ strace grep getWidth $(find . -name "*.java") 2>&1 >/dev/null | grep open | wc -l
1426

$ strace grep getWidth $(find . -name "*.java") 2>&1 >/dev/null | grep openat | wc -l
1400

[hoelzro]

I'm guessing grep uses open for opening the directories themselves, as well as shared libraries for dynamic linking.

[hoelzro]

So I eliminated the duplicate calls to open (it's an invocation of -T that's causing it); however, this only speeds up the search by 50 ms on my machine. It's more likely a speed problem with Perl (or how we're using it), considering most of the time is spent in userspace.

[alexandnpu]

Is it possible to bring multi-thread to ack?

[hoelzro]

@alexandnpu This has been mentioned before: #152 The problem is that threading and Perl don't often mix well, and much of ack's slowness is due to the amount of I/O it does rather than time spent on the CPU.

[petdance]

See also #610

[petdance]

There's work being done on optimization in ack 3. I'm closing this old ticket as there will be no more ack 2 releases.