Strange performance bug

Strange performance bug

[Brighten Godfrey]

Hi,

I've encountered a very odd performance problem which I suspect is not  
a bug in my code.  Could it be the compiler, or maybe PCRE?

Here's the story.  I'm parsing a file (using the PCRE library in one  
step).  It goes quickly.  When I parse the same file a second time, it  
goes an order of magnitude more slowly.  Using Str instead of PCRE  
fixes the problem, but I'm not ready to blame PCRE, because various  
other minor changes make the problem disappear too.  I have tried to  
strip this program down to the smallest possible, but it appears to be  
sensitive to the details of the code in ways that I wouldn't expect,  
so I couldn't make it as small as I'd like.

Entire package to reproduce the problem (unpack, make, then run "./ 
problem fast" or "./problem slow"):

	http://www.cs.berkeley.edu/~pbg/tmp/ocaml_performance_problem.tar.bz2

Just the code:

	http://www.cs.berkeley.edu/~pbg/tmp/problem.ml


In case it matters, I am running OCaml 3.11.0 on Mac OS X 10.5.6 on  
Intel.  The problem seems to happen with both ocamlc and ocamlopt.

Can anyone else reproduce this problem or figure out what is going  
on?  Am I doing something silly?

Thanks so much,
~Brighten

Re: [Caml-list] Strange performance bug

[Markus Mottl]

On Tue, Apr 28, 2009 at 22:43, Brighten Godfrey <pbg@cs.berkeley.edu> wrote:
> I've encountered a very odd performance problem which I suspect is not a bug
> in my code.  Could it be the compiler, or maybe PCRE?

I'm not sure it solves your problem (haven't tried the example), but
just looking at the code there is clearly a performance bug: the
pattern is passed to Pcre.pmatch "on the fly" using label "~pat".
This is ok and convenient if it is used only once, but is bad if it
happens in a loop.  Precompile the regular expression outside of the
loop (let rex = Pcre.regexp "...") and pass it in with label "~rex" to
solve this problem.

Regards,
Markus

-- 
Markus Mottl        http://www.ocaml.info        markus.mottl@gmail.com

Re: [Caml-list] Strange performance bug

[Brighten Godfrey]

On Apr 28, 2009, at 8:37 PM, Markus Mottl wrote:
> On Tue, Apr 28, 2009 at 22:43, Brighten Godfrey  
> <pbg@cs.berkeley.edu> wrote:
>> I've encountered a very odd performance problem which I suspect is  
>> not a bug
>> in my code.  Could it be the compiler, or maybe PCRE?
>
> I'm not sure it solves your problem (haven't tried the example), but
> just looking at the code there is clearly a performance bug: the
> pattern is passed to Pcre.pmatch "on the fly" using label "~pat".
> This is ok and convenient if it is used only once, but is bad if it
> happens in a loop.  Precompile the regular expression outside of the
> loop (let rex = Pcre.regexp "...") and pass it in with label "~rex" to
> solve this problem.


I can't see how this explains the problem.  Why should the parsing get  
dramatically slower when starting to parse the file a *second* time?

(Changing to the precompiled regexp does make this bug go away -- but  
so do many other small changes, like commenting out the last line of  
the code, *after* the parsing is complete.)

Thanks very much,
~Brighten

Re: [Caml-list] Strange performance bug

[Alain Frisch]

Brighten Godfrey wrote:
> (Changing to the precompiled regexp does make this bug go away -- but so 
> do many other small changes, like commenting out the last line of the 
> code, *after* the parsing is complete.)

This last line (List.length first) + ...) forces the values first, 
second and third to remain alive. How big are these values in memory?

I would suggest to look closely at the memory usage and GC behavior of 
your program. I did not investigate your problem, so here is a random 
speculation: If the parsed file is big enough, PCRE will compile a lot 
of regexps; maybe the OCaml PCRE binding does not evaluate properly the 
memory usage of these regexps and so OCaml does not trigger a GC soon 
enough to release the compiled regexps; the process memory grows and the 
OS starts to swap your process.


Alain

Re: [Caml-list] Strange performance bug

[Brighten Godfrey]

On Apr 28, 2009, at 11:18 PM, Alain Frisch wrote:

> Brighten Godfrey wrote:
>> (Changing to the precompiled regexp does make this bug go away --  
>> but so do many other small changes, like commenting out the last  
>> line of the code, *after* the parsing is complete.)
>
> This last line (List.length first) + ...) forces the values first,  
> second and third to remain alive. How big are these values in memory?
>
> I would suggest to look closely at the memory usage and GC behavior  
> of your program. I did not investigate your problem, so here is a  
> random speculation: If the parsed file is big enough, PCRE will  
> compile a lot of regexps; maybe the OCaml PCRE binding does not  
> evaluate properly the memory usage of these regexps and so OCaml  
> does not trigger a GC soon enough to release the compiled regexps;  
> the process memory grows and the OS starts to swap your process.


That occurred to me too, but there is no swapping.  The process uses  
less than 40 MB of memory.  Also, this wouldn't explain why it  
suddenly becomes slow exactly when it starts parsing the file the  
second time.

~Brighten

Re: [Caml-list] Strange performance bug

[Alain Frisch]

Brighten Godfrey wrote:
> That occurred to me too, but there is no swapping.  The process uses 
> less than 40 MB of memory.  Also, this wouldn't explain why it suddenly 
> becomes slow exactly when it starts parsing the file the second time.

This point is interesting: it is where PCRE starts compiling a lot of 
regexps while the OCaml heap is already full of non-garbage value (the 
value bound to first). For each allocated regexp, the OCaml PCRE binding 
pushes some pressure on the OCaml GC; maybe, then, the GC runs too often 
for the amount of memory it can really release.

-- Alain

Re: [Caml-list] Strange performance bug

[Brighten Godfrey]

On Apr 28, 2009, at 11:37 PM, Alain Frisch wrote:
> Brighten Godfrey wrote:
>> That occurred to me too, but there is no swapping.  The process  
>> uses less than 40 MB of memory.  Also, this wouldn't explain why it  
>> suddenly becomes slow exactly when it starts parsing the file the  
>> second time.
>
> This point is interesting: it is where PCRE starts compiling a lot  
> of regexps while the OCaml heap is already full of non-garbage value  
> (the value bound to first). For each allocated regexp, the OCaml  
> PCRE binding pushes some pressure on the OCaml GC; maybe, then, the  
> GC runs too often for the amount of memory it can really release.


I know nothing about the internals of these libraries.  But, the  
program is continuously reading lines from the file.  Thus, isn't  
there about the same amount of memory on the heap just before the  
problem starts and just after the problem starts?  I guess it is  
plausible that somehow, closing the file and re-opening it triggers a  
bad interaction with the GC...

But in comparison, using Str in the same way (i.e., compiling the  
regexp every time it is used) works fine.

Thanks,
~Brighten

Re: [Caml-list] Strange performance bug

[Markus Mottl]

On Wed, Apr 29, 2009 at 04:29, Brighten Godfrey <pbg@cs.berkeley.edu> wrote:
> I know nothing about the internals of these libraries.  But, the program is
> continuously reading lines from the file.  Thus, isn't there about the same
> amount of memory on the heap just before the problem starts and just after
> the problem starts?  I guess it is plausible that somehow, closing the file
> and re-opening it triggers a bad interaction with the GC...
>
> But in comparison, using Str in the same way (i.e., compiling the regexp
> every time it is used) works fine.

Note that the effect of not precompiling the regular expressions is
not just the overhead of this computation, but also vastly greater
GC-pressure.

The current GC-settings in Pcre will trigger a full GC-cycle every 500
regular expressions allocated, i.e. would perform a full major
collection every 500 lines in your case.  This setting works fine for
just about any application I've seen, because virtually nobody has to
create patterns dynamically at rates so high that this matters.

Thus, try hoisting out the compilation of the regexp first...

Markus

-- 
Markus Mottl        http://www.ocaml.info        markus.mottl@gmail.com

Re: [Caml-list] Strange performance bug

[Damien Doligez]

On 2009-04-29, at 15:58, Markus Mottl wrote:

> Note that the effect of not precompiling the regular expressions is
> not just the overhead of this computation, but also vastly greater
> GC-pressure.
>
> The current GC-settings in Pcre will trigger a full GC-cycle every 500
> regular expressions allocated, i.e. would perform a full major
> collection every 500 lines in your case.  This setting works fine for
> just about any application I've seen, because virtually nobody has to
> create patterns dynamically at rates so high that this matters.


Markus, you put your finger right on the problem.  That program doesn't
suddenly start to get slow, it gets steadily slower as it runs.  The
heap also gets steadily bigger, and the major GC does way too much
work.

Alain's explanation (about why changing the last line changes the
speed of the rest of the program) looks right to me.  When you remove
that last line, the GC still does too much work, but the heap doesn't
grow, so it doesn't get slower.

To see the problem, you should play with the GC verbosity settings,
for example, see the difference between
   OCAMLRUNPARAM=v=1 ./problem slow
and
   OCAMLRUNPARAM=v=1 ./problem fast

Maybe PCRE should change its settings to trigger GCs less often but,
as Markus said, this doesn't look really important.

-- Damien

Re: [Caml-list] Strange performance bug

[Markus Mottl]

On Wed, Apr 29, 2009 at 10:48, Damien Doligez <damien.doligez@inria.fr> wrote:
> Markus, you put your finger right on the problem.  That program doesn't
> suddenly start to get slow, it gets steadily slower as it runs.  The
> heap also gets steadily bigger, and the major GC does way too much
> work.

Right, the combination of forcing the GC very often through PCRE and
keeping an ever increasing number of values around obviously leads to
this slowdown.

> Maybe PCRE should change its settings to trigger GCs less often but,
> as Markus said, this doesn't look really important.

I've never seen a case in practice where correctly done regexp
allocations happen so often that excessive full major collections are
triggered.  There is no optimal "general" setting for how aggressive
the GC should be with regexps, but the current value should work fine
for just about anybody.  A still reasonable higher setting would
probably not solve performance bugs of the sort above anyway.

Regards,
Markus

-- 
Markus Mottl        http://www.ocaml.info        markus.mottl@gmail.com

Re: [Caml-list] Strange performance bug

[Brighten Godfrey]

On Apr 29, 2009, at 9:03 AM, Markus Mottl wrote:
> On Wed, Apr 29, 2009 at 10:48, Damien Doligez  
> <damien.doligez@inria.fr> wrote:
>> Markus, you put your finger right on the problem.  That program  
>> doesn't
>> suddenly start to get slow, it gets steadily slower as it runs.  The
>> heap also gets steadily bigger, and the major GC does way too much
>> work.
>
> Right, the combination of forcing the GC very often through PCRE and
> keeping an ever increasing number of values around obviously leads to
> this slowdown.

Makes sense.  (Though, i'd point out that there *are* discrete moments  
of sudden slowdown -- after each parse completes.  Maybe the GC  
doesn't scan through the results until they are returned by the parse  
function...?)

>> Maybe PCRE should change its settings to trigger GCs less often but,
>> as Markus said, this doesn't look really important.
>
> I've never seen a case in practice where correctly done regexp
> allocations happen so often that excessive full major collections are
> triggered.  There is no optimal "general" setting for how aggressive
> the GC should be with regexps, but the current value should work fine
> for just about anybody.  A still reasonable higher setting would
> probably not solve performance bugs of the sort above anyway.

You seem to have solved my problem.  But out of curiosity:  Do you  
know how the GC settings in the Str library differ from PCRE's, and  
why?  Why does PCRE need to explicitly trigger GCs at all?

Thanks for your replies,
~Brighten

Re: [Caml-list] Strange performance bug

[Markus Mottl]

On Wed, Apr 29, 2009 at 15:19, Brighten Godfrey <pbg@cs.berkeley.edu> wrote:
> You seem to have solved my problem.  But out of curiosity:  Do you know how
> the GC settings in the Str library differ from PCRE's, and why?  Why does
> PCRE need to explicitly trigger GCs at all?

Str regular expressions are pure OCaml-values, whereas PCRE regexps
are allocated on the C-heap.  Since C-heap values need to be
deallocated explicitly, a finalizer has to be installed that does the
job if the OCaml-value is not reachable anymore.  The OCaml-runtime
needs hints about how large these C-values are.  Otherwise it may not
scan the OCaml-heap aggressively enough, leaving a lot of those
C-values floating around and eating up your memory.

Right now the PCRE-library guarantees that not more than 500 regular
expressions will float around at any one time.  This can lead to
considerable slowdowns if your OCaml-heap is large and you allocate
regular expressions at very high rates.

Regards,
Markus

-- 
Markus Mottl        http://www.ocaml.info        markus.mottl@gmail.com

Re: [Caml-list] Strange performance bug

[Brighten Godfrey]

On Apr 29, 2009, at 12:38 PM, Markus Mottl wrote:

> On Wed, Apr 29, 2009 at 15:19, Brighten Godfrey  
> <pbg@cs.berkeley.edu> wrote:
>> You seem to have solved my problem.  But out of curiosity:  Do you  
>> know how
>> the GC settings in the Str library differ from PCRE's, and why?   
>> Why does
>> PCRE need to explicitly trigger GCs at all?
>
> Str regular expressions are pure OCaml-values, whereas PCRE regexps
> are allocated on the C-heap.  Since C-heap values need to be
> deallocated explicitly, a finalizer has to be installed that does the
> job if the OCaml-value is not reachable anymore.  The OCaml-runtime
> needs hints about how large these C-values are.  Otherwise it may not
> scan the OCaml-heap aggressively enough, leaving a lot of those
> C-values floating around and eating up your memory.
>
> Right now the PCRE-library guarantees that not more than 500 regular
> expressions will float around at any one time.  This can lead to
> considerable slowdowns if your OCaml-heap is large and you allocate
> regular expressions at very high rates.

Got it.  Thank you all for your replies!

~Brighten