[perl #66762] Regex search time varies wildly with input
Andrew Daviel
# Please include the string: [perl #66762]
# in the subject line of all future correspondence about this issue.
# <URL: http://rt.perl.org/rt3/Ticket/Display.html?id=66762 >
This is a bug report for perl from ad...@triumf.ca,
generated with the help of perlbug 1.36 running under perl 5.10.0.
-----------------------------------------------------------------
I often use Perl to analyze logfiles, using capture in regex to extract
timestamps. Recently I found a variation in computation time of orders of
magnitude depending on the data being parsed and on apparently small
changes in the search pattern.
This may reflect my lack of full understanding of the regex mechanism,
but I am still surprised by the magnitude and apparent
unpredictability of the variation.
Case #1:
$_ = "Jun 19 11:17:59 foobar mountd[4321]: authenticated unmount request from radon.example.com\n" ;
pattern time Perl 5.8.8
/.*[\d]+.*radon/ 12us 10us
/(.*[\d]+).*radon/ 12.8us 10.4us
/.*[\d]+.*Radon/ 1.6us 1.6us
/(.*[\d]+).*radon/i 13.2us 11us
/(.*[\d]+).*mount.*radon/ 2ms 11us
Case #2
$_ = "Jun 19 11:30:12 gridadm /usr/bin/sudo: foobar : TTY=unknown ;
PWD=/home/foobar ; USER=root ; COMMAND=/usr/bin/gmetric
--conf=/etc/gmond.conf --tmax=600 --name=Power_Usage_fubar07
--value=3922 --type=float --units=W
--spoof=192.168.1.1:foobar.example.com\n" ;
pattern time Perl v5.8.8
/.*[\d]+.*radon/ 2us 10us
/(.*[\d]+).*radon/i 130us 8ms
/(.*[\d]+).* (?i:radon)/ 12ms 8ms
The variation is equally large for the earlier version 5.8.8, but
for different combinations. Including the /i case insensitive modifier
gave a 1700-fold increase in compute time for one logfile.
(Perl 5.10.0 and 5.8.8 are not running on the same hardware, so the
times above do not directly compare between versions. The times are
calculated from wallclock time for 5000 iterations.)
The perlre manpage says that capturing parentheses "may substantially
slow your program". However, I see relatively little change when
capturing parentheses are added compared to the change from "/i".
-----------------------------------------------------------------
---
Flags:
category=core
severity=low
---
This perlbug was built using Perl 5.10.0 in the Fedora build system.
It is being executed now by Perl 5.10.0 - Tue Apr 14 07:21:30 EDT 2009.
Site configuration information for perl 5.10.0:
Configured by Red Hat, Inc. at Tue Apr 14 07:21:30 EDT 2009.
Summary of my perl5 (revision 5 version 10 subversion 0) configuration:
Platform:
osname=linux, osvers=2.6.18-128.1.6.el5,
archname=x86_64-linux-thread-multi
uname='linux x86-4.fedora.phx.redhat.com 2.6.18-128.1.6.el5 #1 smp
tue mar 24 12:05:57 edt 2009 x86_64 x86_64 x86_64 gnulinux '
config_args='-des -Doptimize=-O2 -g -pipe -Wall
-Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector
--param=ssp-buffer-size=4 -m64 -mtune=generic -DPERL_USE_SAFE_PUTENV
-Dversion=5.10.0 -Dmyhostname=localhost -Dperladmin=root@localhost
-Dcc=gcc -Dcf_by=Red Hat, Inc. -Dprefix=/usr -Dvendorprefix=/usr
-Dsiteprefix=/usr/local -Dprivlib=/usr/lib/perl5/5.10.0
-Dsitelib=/usr/local/lib/perl5/site_perl/5.10.0
-Dvendorlib=/usr/lib/perl5/vendor_perl/5.10.0
-Darchlib=/usr/lib64/perl5/5.10.0/x86_64-linux-thread-multi
-Dsitearch=/usr/local/lib64/perl5/site_perl/5.10.0/x86_64-linux-thread-multi
-Dvendorarch=/usr/lib64/perl5/vendor_perl/5.10.0/x86_64-linux-thread-multi
-Dinc_version_list=none -Darchname=x86_64-linux-thread-multi
-Dlibpth=/usr/local/lib64 /lib64 /usr/lib64 -Duseshrplib -Dusethreads
-Duseithreads -Duselargefiles -Dd_dosuid -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
-Dotherlibdirs=/usr/lib/perl5/site_perl'
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 -DDEBUGGING
-fno-strict-aliasing -pipe -I/usr/local/include -D_LARGEFILE_SOURCE
-D_FILE_OFFSET_BITS=64 -I/usr/include/gdbm',
optimize='-O2 -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fexceptions
-fstack-protector --param=ssp-buffer-size=4 -m64 -mtune=generic
-DPERL_USE_SAFE_PUTENV',
cppflags='-D_REENTRANT -D_GNU_SOURCE -DDEBUGGING -fno-strict-aliasing
-pipe -I/usr/local/include -I/usr/include/gdbm'
ccversion='', gccversion='4.3.0 20080428 (Red Hat 4.3.0-8)',
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 =''
libpth=/usr/local/lib64 /lib64 /usr/lib64
libs=-lresolv -lnsl -lgdbm -ldb -ldl -lm -lcrypt -lutil -lpthread -lc
perllibs=-lresolv -lnsl -ldl -lm -lcrypt -lutil -lpthread -lc
libc=, so=so, useshrplib=true, libperl=libperl.so
gnulibc_version='2.8'
Dynamic Linking:
dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,-E
-Wl,-rpath,/usr/lib64/perl5/5.10.0/x86_64-linux-thread-multi/CORE'
cccdlflags='-fPIC', lddlflags='-shared -O2 -g -pipe -Wall
-Wp,-D_FORTIFY_SOURCE=2 -fexceptions -fstack-protector
--param=ssp-buffer-size=4 -m64 -mtune=generic -DPERL_USE_SAFE_PUTENV'
Locally applied patches:
---
@INC for perl 5.10.0:
/usr/local/lib64/perl5/site_perl/5.10.0/x86_64-linux-thread-multi
/usr/local/lib/perl5/site_perl/5.10.0
/usr/lib64/perl5/vendor_perl/5.10.0/x86_64-linux-thread-multi
/usr/lib/perl5/vendor_perl/5.10.0
/usr/lib/perl5/vendor_perl
/usr/lib64/perl5/5.10.0/x86_64-linux-thread-multi
/usr/lib/perl5/5.10.0
/usr/lib/perl5/site_perl
.
---
Environment for perl 5.10.0:
HOME=/home//andrew
LANG=en_US.UTF-8
LANGUAGE (unset)
LD_LIBRARY_PATH (unset)
LOGDIR (unset)
PATH=/home/andrew/bin:/usr/local/sbin:/usr/sbin:/sbin:/usr/local/bin:/bin:/usr/bin:/usr/X11R6/bin:.
PERL_BADLANG (unset)
SHELL=/bin/bash
--
Andrew Daviel, TRIUMF, Canada
Bram
>
> -----------------------------------------------------------------
> I often use Perl to analyze logfiles, using capture in regex to extract
> timestamps. Recently I found a variation in computation time of orders of
> magnitude depending on the data being parsed and on apparently small
> changes in the search pattern.
If the time it takes for your re to match (or fail) depends on the
length of the string your are matching then you wrote a not so good
regex.
See RT ticket 42721 (
http://rt.perl.org/rt3/Ticket/Display.html?id=42721 ) for some
explanation. (Read the first reply (it is best to click the download
link else you won't see the identations))
This is not the best explanation of course since it was written
especially for that bug report... It's still on my todo list to write
a better/more general explanation of this...
Note that this will not explain the difference in your bug report but
it might help you with the original regex.
Also note that your are not matching the same things in your bug report:
> pattern time Perl v5.8.8
> /.*[\d]+.*radon/ 2us 10us
> /(.*[\d]+).*radon/i 130us 8ms
> /(.*[\d]+).* (?i:radon)/ 12ms 8ms
=> The third wants to match a space before 'radon'; the first and the
second do not. (meaning: you are not comparing m/.../i with
m/(?i:...)/)
I would also suggest to use the Benchmark module to compare the
different versions and to post the resulst of that + the benchmarking
code you used
Best regards,
Bram
James E Keenan via RT
a Perl usage question than a report of a bug in Perl. The original
poster has not responded to Bram's comments made more than 3-1/2 years ago.
I recommend that the ticket be closed. I will do so in seven days
unless someone wishes to take the ticket over.
Thank you very much.
Jim Keenan
---
via perlbug: queue: perl5 status: open
https://rt.perl.org:443/rt3/Ticket/Display.html?id=66762
Andrew Daviel via RT
When I re-try my case #2 with Time::HiRes, now at least I get better
results from Perl 5.10 than from Perl 5.8
match Perl 5.8 5.10
/(.*[\d]+).*radon/ 0.72 us 0.51 us
/(.*[\d]+).*radon/i 5345.95 us 48.1 us
/.*[\d]+.*radon/i 77.23 us 45.16 us
/.*[\d]+.*(?i:radon)/ 55.63 us 45.06 us
/(.*[\d]+).* radon/i 5483.97 us 51.47 us
/(.*[\d]+).* (?i:radon)/ 5285.52 us 4432.8 us
/(.*[\d]+).* foobar.* radon/ 1428.14 us 1408.74 us
/(.*[\d]+).* foobar.* radon/i 4534.89 us 70.32 us
If I lowercase the input before matching, it's faster:
s/radon/radon/i ; /.*[\d]+.* radon/ 1.61 us 1.72 us
I still find it hard to see which patterns are going to be slow
demerphq
> I must have missed Bram's reply and then forgotten about this.
>
> When I re-try my case #2 with Time::HiRes, now at least I get better
> results from Perl 5.10 than from Perl 5.8
>
> match Perl 5.8 5.10
> /(.*[\d]+).*radon/ 0.72 us 0.51 us
> /(.*[\d]+).*radon/i 5345.95 us 48.1 us
> /.*[\d]+.*radon/i 77.23 us 45.16 us
> /.*[\d]+.*(?i:radon)/ 55.63 us 45.06 us
> /(.*[\d]+).* radon/i 5483.97 us 51.47 us
> /(.*[\d]+).* (?i:radon)/ 5285.52 us 4432.8 us
> /(.*[\d]+).* foobar.* radon/ 1428.14 us 1408.74 us
> /(.*[\d]+).* foobar.* radon/i 4534.89 us 70.32 us
>
> If I lowercase the input before matching, it's faster:
> s/radon/radon/i ; /.*[\d]+.* radon/ 1.61 us 1.72 us
>
> I still find it hard to see which patterns are going to be slow
can sometimes simplify things.
Note that A.*B is almost always a crap pattern. If you can change the
.* to something more specific you usually improve performance.
A.*B.*C is an even worse pattern. Same advice as above.
If the pattern contains a long fixed string at a useful position in
the pattern then it can use that to both fail fast, and to bound the
search space. Case insensitive text will often not be useful to this
optimization.
Capturing text will slow things down.
Anyway, please use blead to compare with, we aren't going to change
the 5.10 regex engine.
Yves
--
perl -Mre=debug -e "/just|another|perl|hacker/"
James E Keenan via RT
usage question best handled in other forums. So I'm closing this
ticket. (If anyone has evidence of regression in regex performance
between 5.16 or blead and earlier versions, that should be the subject
of a new ticket.)
Thank you very much.
Jim Keenan