Skip Menu |

Preferred bug tracker

Please visit the preferred bug tracker to report your issue.

This queue is for tickets about the devel-nytprof CPAN distribution.

Report information
The Basics
Id: 61954
Status: resolved
Priority: 0/
Queue: devel-nytprof
People
Owner: Nobody in particular
Requestors: brianski [...] cpan.org
Cc:
AdminCc:
Bug Information
Severity: Wishlist
Broken in: (no value)
Fixed in: (no value)

History Show all quoted text
  Thu Oct 07 00:51:02 2010 brianski [...] cpan.org - Ticket created
Subject: regular expression performance oddities
Devel::NYTProf (which I love, keep up the good work!) just sent me off optimizing what turned out to be profiling overhead error :-/ -- I've boiled down the behavior I was bitten by to a simple test case - it appears that regular expressions perform very significantly slower with Devel::NYTProf enabled. All versions were tested on a 64-bit ubuntu 10.04 (perl 5.10.1) install. 4.04 was also tested on a 64-bit debian etch (perl 5.8.8) install. ski@portege:~$ time perl -le 'my @x = (0..100_000); @x = grep { rand() < 1/2 } @x' real 0m0.076s user 0m0.050s sys 0m0.030s ski@portege:~$ time perl -d:NYTProf -le 'my @x = (0..100_000); @x = grep { rand() < 1/2 } @x' real 0m0.108s user 0m0.070s sys 0m0.020s ski@portege:~$ ski@portege:~$ time perl -le 'my @x = (0..100_000); @x = grep { /234/ } @x' real 0m0.197s user 0m0.110s sys 0m0.040s ski@portege:~$ time NYTPROF=slowops=2 perl -d:NYTProf -le 'my @x = (0..100_000); @x = grep { /234/ } @x' #default real 0m1.744s user 0m1.530s sys 0m0.040s ski@portege:~$ time NYTPROF=slowops=0 perl -d:NYTProf -le 'my @x = (0..100_000); @x = grep { /234/ } @x' #default real 0m0.801s user 0m0.720s sys 0m0.020s Why is the slowdown large? I noticed that even using qr//, regular expressions seem to get re-CORE::regcomp'd every run (although this may be intended behavior, it's certainly counter-intuitive) - perhaps there is a regular expression in the hooked-in code that deletes the optimizations that perl does for when the last regular expression is repeated? Any ideas? Thanks again! Brian Szymanski
  Mon Oct 11 16:39:12 2010 TIMB [...] cpan.org - Correspondence added
Show quoted text
> Why is the slowdown large?
Because the profiler has to do a lot of work on each entry and return from a subroutine or 'slowop'. That cost gets bigger, relatively, the fast the opcode is. A trivial regex on a short string is very fast indeed so the slow down appears large. It's still only about 8 micro seconds! (In the slowops=2 vs =0 case). I'll add a note to the docs. Show quoted text
> I noticed that even using qr//, regular expressions seem to get re-CORE::regcomp'd every run
I don't see that in the examples you've given above. perl -MO=Concise,-exec -e 'warn scalar grep { /12/ } (0..100);' shows a 'match' opcode being generated. If you mean code like perl -MO=Concise -e '$q=qr/12/; warn scalar grep { /$q/ } (0..100);' then yes, regcomp is called each time but has little to do (it just takes a temp copy of the regex). I hope that helps. Sorry for any disappointment. Tim.
  Mon Oct 11 16:39:13 2010 The RT System itself - Status changed from 'new' to 'open'
  Mon Oct 11 16:39:13 2010 TIMB [...] cpan.org - Status changed from 'open' to 'resolved'
  Tue Oct 12 23:10:04 2010 brianski [...] cpan.org - Correspondence added
On Mon Oct 11 16:39:12 2010, TIMB wrote: Show quoted text
> > Why is the slowdown large?
> > Because the profiler has to do a lot of work on each entry and return > from a subroutine or 'slowop'. > > That cost gets bigger, relatively, the fast the opcode is. A trivial > regex on a short string is very fast > indeed so the slow down appears large. It's still only about 8 micro > seconds! (In the slowops=2 vs > =0 case). > > I'll add a note to the docs.
Well, NYTProf 1.x only slows the regular-expression-y code down by a factor of 3, whereas in NYTProf 3/4.x the overhead is closer to a factor of 5 even with slowops=0. I understand why the overhead of tracking subroutines has to be high, but (and perhaps this is my lack of knowledge of perl internals), I don't understand why regexes would have to be so slow. Perhaps there should be an option for "proportional overhead" ? IE do all the (extraneous) work we would do for a slow opcode even for fast opcodes that we would otherwise skip lots of unnecessary bookkeeping for?
  Tue Oct 12 23:10:05 2010 The RT System itself - Status changed from 'resolved' to 'open'
  Wed Oct 13 07:56:46 2010 Tim.Bunce [...] pobox.com - Correspondence added
Subject: Re: [rt.cpan.org #61954] regular expression performance oddities
Date: Wed, 13 Oct 2010 12:56:34 +0100
To: Brian Szymanski via RT <bug-devel-nytprof [...] rt.cpan.org>
From: Tim Bunce <Tim.Bunce [...] pobox.com>
On Tue, Oct 12, 2010 at 11:10:05PM -0400, Brian Szymanski via RT wrote: Show quoted text
> > Well, NYTProf 1.x only slows the regular-expression-y code down by a > factor of 3, whereas in NYTProf 3/4.x the overhead is closer to a factor > of 5 even with slowops=0. > > I understand why the overhead of tracking subroutines has to be high, > but (and perhaps this is my lack of knowledge of perl internals), I > don't understand why regexes would have to be so slow.
With slowops=0 NYTProf is not involved with regexes at all. Any difference in performance you're seeing between NYTProf versions is due to other changes, such as additional logic when leaving a block (see leave=0 in the docs) and more detail/accuracy in general. Tim.
  Wed Oct 13 20:01:13 2010 brianski [...] cpan.org - Correspondence added
On Wed Oct 13 07:56:46 2010, Tim.Bunce@pobox.com wrote: Show quoted text
> On Tue, Oct 12, 2010 at 11:10:05PM -0400, Brian Szymanski via RT wrote:
> > > > Well, NYTProf 1.x only slows the regular-expression-y code down by a > > factor of 3, whereas in NYTProf 3/4.x the overhead is closer to a factor > > of 5 even with slowops=0. > > > > I understand why the overhead of tracking subroutines has to be high, > > but (and perhaps this is my lack of knowledge of perl internals), I > > don't understand why regexes would have to be so slow.
> > With slowops=0 NYTProf is not involved with regexes at all.
I'm not sure I understand what you are saying here... Something is definitely affecting regex performance in ways many orders of magnitude worse than DProf: ski@editorial1:~$ time perl -le 'my @x = (0..1_000_000); @x = grep { rand() < 1/2 } @x' #non-regexp real 0m0.453s user 0m0.404s sys 0m0.052s ski@editorial1:~$ time perl -d:DProf -le 'my @x = (0..1_000_000); @x = grep { rand() < 1/2 } @x' #non-regexp, dprof real 0m0.489s user 0m0.424s sys 0m0.064s ski@editorial1:~$ time perl -d:NYTProf -le 'my @x = (0..1_000_000); @x = grep { rand() < 1/2 } @x' #non-regexp, nytprof real 0m0.462s user 0m0.376s sys 0m0.088s ski@editorial1:~$ time perl -le 'my @x = (0..1_000_000); @x = grep { /123/ } @x' #regexp real 0m0.950s user 0m0.764s sys 0m0.192s ski@editorial1:~$ time perl -d:DProf -le 'my @x = (0..1_000_000); @x = grep { /123/ } @x' #regexp, dprof real 0m1.016s user 0m0.828s sys 0m0.176s ski@editorial1:~$ time perl -d:NYTProf -le 'my @x = (0..1_000_000); @x = grep { /123/ } @x' #regexp, nytprof real 0m8.251s user 0m4.412s sys 0m3.836s
  Thu Oct 14 05:15:12 2010 Tim.Bunce [...] pobox.com - Correspondence added
Subject: Re: [rt.cpan.org #61954] regular expression performance oddities
Date: Thu, 14 Oct 2010 10:14:35 +0100
To: Brian Szymanski via RT <bug-devel-nytprof [...] rt.cpan.org>
From: Tim Bunce <Tim.Bunce [...] pobox.com>
On Wed, Oct 13, 2010 at 08:01:13PM -0400, Brian Szymanski via RT wrote: Show quoted text
> > > > With slowops=0 NYTProf is not involved with regexes at all.
> > I'm not sure I understand what you are saying here...
I'm simply saying that with slowops enabled (as it is by default) NYTProf specifically intercepts the regex opcodes and so adds extra overhead to every regex. With slowops=0 it doesn't do that: $ NYTPROF=slowops=1 time perl -d:NYTProf -le 'my @x = (0..1_000_000); @x = grep { /123/ } @x' user 16.69 $ NYTPROF=slowops=0 time perl -d:NYTProf -le 'my @x = (0..1_000_000); @x = grep { /123/ } @x' user 7.76 Of course any profiling adds overheads. With slowops=0 the remaining profiling overheads come mostly from the *statement* profiler. Show quoted text
> Something is definitely affecting regex performance in ways many > orders of magnitude worse than DProf:
Naturally, because DProf is only a *subroutine* profiler but there are no sub calls, so it's hardly involved in profiling that code at all. (DProf is also so badly broken it's not worth using.) You can achieve a similar effect with NYTProf by turning off the statement profiler as well as slowops: $ NYTPROF=slowops=0:stmts=0 time perl -d:NYTProf -le 'my @x = (0..1_000_000); @x = grep { /123/ } @x' user 4.06 Then, for this example, NYTProf is almost as fast as not profiling at all: $ time perl -le 'my @x = (0..1_000_000); @x = grep { /123/ } @x' user 4.04 Tim. p.s. I presume you've read http://search.cpan.org/~timb/Devel-NYTProf/lib/Devel/NYTProf.pm#MAKING_NYTPROF_FASTER If you have any suggestions for clarifying the docs please let me know.
  Tue Jul 02 10:44:42 2013 TIMB [...] cpan.org - Broken in 1.12 deleted
  Tue Jul 02 10:44:42 2013 TIMB [...] cpan.org - Broken in 1.15 deleted
  Tue Jul 02 10:44:42 2013 TIMB [...] cpan.org - Broken in 3.01 deleted
  Tue Jul 02 10:44:42 2013 TIMB [...] cpan.org - Broken in 4.00 deleted
  Tue Jul 02 10:44:42 2013 TIMB [...] cpan.org - Broken in 4.04 deleted
  Tue Jul 02 10:44:43 2013 TIMB [...] cpan.org - Broken in 4.05 deleted
  Sun Feb 22 08:34:35 2015 TIMB [...] cpan.org - Correspondence added
Ticket migrated to github as https://github.com/timbunce/devel-nytprof/issues/51
  Sun Feb 22 08:34:43 2015 TIMB [...] cpan.org - Status changed from 'open' to 'resolved'