Patchwork [2,of,4] obsstore: disable garbage collection during initialisation (issue4456)

login
register
mail settings
Submitter Pierre-Yves David
Date Nov. 30, 2014, 1:57 a.m.
Message ID <d0f3dac4ea2b4aff5194.1417312662@marginatus.alto.octopoid.net>
Download mbox | patch
Permalink /patch/6890/
State Superseded
Headers show

Comments

Pierre-Yves David - Nov. 30, 2014, 1:57 a.m.
# HG changeset patch
# User Pierre-Yves David <pierre-yves.david@fb.com>
# Date 1417049911 28800
#      Wed Nov 26 16:58:31 2014 -0800
# Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
# Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
obsstore: disable garbage collection during initialisation (issue4456)

Python garbage collection is triggered by contained creation. So code that
creates a lot of tuple tends to trigger GC a lot. We disable the gc during
obsolescence marker parsing and associated initialization. The provide and
interesting speedup (25%).

On my 58758 markers repo:
before: 0.468247 seconds
after:  0.344362 seconds

Thanks goes to Siddharth Agarwal for the lead.
Martin von Zweigbergk - Nov. 30, 2014, 6:29 a.m.
On Sat Nov 29 2014 at 5:58:52 PM Pierre-Yves David <
pierre-yves.david@ens-lyon.org> wrote:

> # HG changeset patch
> # User Pierre-Yves David <pierre-yves.david@fb.com>
> # Date 1417049911 28800
> #      Wed Nov 26 16:58:31 2014 -0800
> # Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
> # Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
> obsstore: disable garbage collection during initialisation (issue4456)
>
> Python garbage collection is triggered by contained creation. So code that
> creates a lot of tuple tends to trigger GC a lot. We disable the gc during
> obsolescence marker parsing and associated initialization.


On your repo, do you know the peak memory usage before and after? My gut
feeling is that the amount of garbage that's now not collected until later
is nothing to be concerned about, but it would be nice to confirm that.


> The provide and
> interesting speedup (25%).
>
> On my 58758 markers repo:
> before: 0.468247 seconds
> after:  0.344362 seconds
>

Do you see similar values from 'time hg ...'? Without trying to understand
the patch, it sounds like you could just be moving the GC out of the method
that's being timed. I just want to make sure it's an overall gain.


> Thanks goes to Siddharth Agarwal for the lead.
>
> diff --git a/mercurial/obsolete.py b/mercurial/obsolete.py
> --- a/mercurial/obsolete.py
> +++ b/mercurial/obsolete.py
> @@ -66,10 +66,11 @@ The file starts with a version header:
>  The header is followed by the markers. Marker format depend of the
> version. See
>  comment associated with each format for details.
>
>  """
>  import struct
> +import gc
>  import util, base85, node
>  import phases
>  from i18n import _
>
>  _pack = struct.pack
> @@ -466,12 +467,28 @@ class obsstore(object):
>          self.sopener = sopener
>          data = sopener.tryread('obsstore')
>          self._version = defaultformat
>          self._readonly = readonly
>          if data:
> -            self._version, markers = _readmarkers(data)
> -            self._load(markers)
> +            # Python's garbage collector triggers a GC each time a certain
> +            # number of container objects (the number being defined by
> +            # gc.get_threshold()) are allocated. Markers parsing creates
> +            # multiple tuples while parsing each markers so the gc is
> triggered
> +            # a lot while parsing an high number of markers. As a
> workaround,
> +            # disable GC during initialisation.
>

What was gc.get_threshold() in your case? Do you know how much memory was
allocated? How many times GC was forced before this patch?


> +            #
> +            # This would probably marker parsing during exchange but I do
> not
> +            # expect the order of magnitude to matter outside of
> initialisation
> +            # case.
> +            gcenabled = gc.isenabled()
> +            gc.disable()
> +            try:
> +                self._version, markers = _readmarkers(data)
> +                self._load(markers)
> +            finally:
> +                if gcenabled:
> +                    gc.enable()
>
>      def __iter__(self):
>          return iter(self._all)
>
>      def __len__(self):
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@selenic.com
> http://selenic.com/mailman/listinfo/mercurial-devel
>
Pierre-Yves David - Nov. 30, 2014, 7:46 a.m.
On 11/29/2014 10:29 PM, Martin von Zweigbergk wrote:
>
>
> On Sat Nov 29 2014 at 5:58:52 PM Pierre-Yves David
> <pierre-yves.david@ens-lyon.org <mailto:pierre-yves.david@ens-lyon.org>>
> wrote:
>
>     # HG changeset patch
>     # User Pierre-Yves David <pierre-yves.david@fb.com
>     <mailto:pierre-yves.david@fb.com>>
>     # Date 1417049911 28800
>     #      Wed Nov 26 16:58:31 2014 -0800
>     # Node ID d0f3dac4ea2b4aff51946c7db0834a__a4e5c3e82a
>     # Parent  04eb7e49d2b6f90f71aa85de9ad0b4__d70670d688
>     obsstore: disable garbage collection during initialisation (issue4456)
>
>     Python garbage collection is triggered by contained creation. So
>     code that
>     creates a lot of tuple tends to trigger GC a lot. We disable the gc
>     during
>     obsolescence marker parsing and associated initialization.
>
>
> On your repo, do you know the peak memory usage before and after? My gut
> feeling is that the amount of garbage that's now not collected until
> later is nothing to be concerned about, but it would be nice to confirm
> that.

no relevant peak detected.

>
>     The provide and
>     interesting speedup (25%).
>
>     On my 58758 markers repo:
>     before: 0.468247 seconds
>     after:  0.344362 seconds
>
>
> Do you see similar values from 'time hg ...'? Without trying to
> understand the patch, it sounds like you could just be moving the GC out
> of the method that's being timed. I just want to make sure it's an
> overall gain.

I do see similar gain, the overall time is much more unstable, but I get 
about the same benefit 0.05s

>
>     Thanks goes to Siddharth Agarwal for the lead.
>
>     diff --git a/mercurial/obsolete.py b/mercurial/obsolete.py
>     --- a/mercurial/obsolete.py
>     +++ b/mercurial/obsolete.py
>     @@ -66,10 +66,11 @@ The file starts with a version header:
>       The header is followed by the markers. Marker format depend of the
>     version. See
>       comment associated with each format for details.
>
>       """
>       import struct
>     +import gc
>       import util, base85, node
>       import phases
>       from i18n import _
>
>       _pack = struct.pack
>     @@ -466,12 +467,28 @@ class obsstore(object):
>               self.sopener = sopener
>               data = sopener.tryread('obsstore')
>               self._version = defaultformat
>               self._readonly = readonly
>               if data:
>     -            self._version, markers = _readmarkers(data)
>     -            self._load(markers)
>     +            # Python's garbage collector triggers a GC each time a
>     certain
>     +            # number of container objects (the number being defined by
>     +            # gc.get_threshold()) are allocated. Markers parsing
>     creates
>     +            # multiple tuples while parsing each markers so the gc
>     is triggered
>     +            # a lot while parsing an high number of markers. As a
>     workaround,
>     +            # disable GC during initialisation.
>
>
> What was gc.get_threshold() in your case? Do you know how much memory
> was allocated? How many times GC was forced before this patch?

Nope. I did not digged that far. The whole thing should be reimplemented 
in C anyway.
Antoine Pitrou - Nov. 30, 2014, 1:06 p.m.
On Sat, 29 Nov 2014 17:57:42 -0800
Pierre-Yves David <pierre-yves.david@ens-lyon.org> wrote:
> # HG changeset patch
> # User Pierre-Yves David <pierre-yves.david@fb.com>
> # Date 1417049911 28800
> #      Wed Nov 26 16:58:31 2014 -0800
> # Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
> # Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
> obsstore: disable garbage collection during initialisation (issue4456)
> 
> Python garbage collection is triggered by contained creation. So code that
> creates a lot of tuple tends to trigger GC a lot. We disable the gc during
> obsolescence marker parsing and associated initialization. The provide and
> interesting speedup (25%).
> 
> On my 58758 markers repo:
> before: 0.468247 seconds
> after:  0.344362 seconds

Which Python version is that?

Regards

Antoine.
Pierre-Yves David - Nov. 30, 2014, 1:17 p.m.
On 11/30/2014 05:06 AM, Antoine Pitrou wrote:
> On Sat, 29 Nov 2014 17:57:42 -0800
> Pierre-Yves David <pierre-yves.david@ens-lyon.org> wrote:
>> # HG changeset patch
>> # User Pierre-Yves David <pierre-yves.david@fb.com>
>> # Date 1417049911 28800
>> #      Wed Nov 26 16:58:31 2014 -0800
>> # Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
>> # Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
>> obsstore: disable garbage collection during initialisation (issue4456)
>>
>> Python garbage collection is triggered by contained creation. So code that
>> creates a lot of tuple tends to trigger GC a lot. We disable the gc during
>> obsolescence marker parsing and associated initialization. The provide and
>> interesting speedup (25%).
>>
>> On my 58758 markers repo:
>> before: 0.468247 seconds
>> after:  0.344362 seconds
>
> Which Python version is that?

Python 2.7.8 (default, Oct 18 2014, 12:50:18)
[GCC 4.9.1]
Martin von Zweigbergk - Dec. 1, 2014, 6:27 a.m.
On Sat Nov 29 2014 at 11:47:09 PM Pierre-Yves David <
pierre-yves.david@ens-lyon.org> wrote:

>
>
> On 11/29/2014 10:29 PM, Martin von Zweigbergk wrote:
> >
> >     The provide and
> >     interesting speedup (25%).
> >
> >     On my 58758 markers repo:
> >     before: 0.468247 seconds
> >     after:  0.344362 seconds
> >
> >
> > Do you see similar values from 'time hg ...'? Without trying to
> > understand the patch, it sounds like you could just be moving the GC out
> > of the method that's being timed. I just want to make sure it's an
> > overall gain.
>
> I do see similar gain, the overall time is much more unstable, but I get
> about the same benefit 0.05s
>

0.05s is less than 0.12s and more like 10-15% than 25%, assuming you're
still talking about the same baseline of ~0.46s. It's still a significant
speedup, so it seems worthwhile, but you may want to include the
"end-to-end" times in the description.

Thanks for checking and for spending time on this. It's one of the most
noticeable performance problems I see in day-to-day use.
Siddharth Agarwal - Dec. 2, 2014, 12:35 a.m.
On 11/29/2014 05:57 PM, Pierre-Yves David wrote:
> # HG changeset patch
> # User Pierre-Yves David <pierre-yves.david@fb.com>
> # Date 1417049911 28800
> #      Wed Nov 26 16:58:31 2014 -0800
> # Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
> # Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
> obsstore: disable garbage collection during initialisation (issue4456)

We also disable the GC while loading the dirstate, for the same reason. 
Can we factor the disable-GC logic out, into a decorator perhaps? (I did 
the same thing for hgsubversion recently for a ~3x perf win on a large 
repo, and I suspect we're going to have to do this more soon.)


>
> Python garbage collection is triggered by contained

"container"

>   creation. So code that
> creates a lot of tuple tends to trigger GC a lot. We disable the gc during
> obsolescence marker parsing and associated initialization. The provide and

"This provides an"

> interesting speedup (25%).
>
> On my 58758 markers repo:
> before: 0.468247 seconds
> after:  0.344362 seconds
>
> Thanks goes to Siddharth Agarwal for the lead.
>
> diff --git a/mercurial/obsolete.py b/mercurial/obsolete.py
> --- a/mercurial/obsolete.py
> +++ b/mercurial/obsolete.py
> @@ -66,10 +66,11 @@ The file starts with a version header:
>   The header is followed by the markers. Marker format depend of the version. See
>   comment associated with each format for details.
>   
>   """
>   import struct
> +import gc
>   import util, base85, node
>   import phases
>   from i18n import _
>   
>   _pack = struct.pack
> @@ -466,12 +467,28 @@ class obsstore(object):
>           self.sopener = sopener
>           data = sopener.tryread('obsstore')
>           self._version = defaultformat
>           self._readonly = readonly
>           if data:
> -            self._version, markers = _readmarkers(data)
> -            self._load(markers)
> +            # Python's garbage collector triggers a GC each time a certain
> +            # number of container objects (the number being defined by
> +            # gc.get_threshold()) are allocated. Markers parsing creates
> +            # multiple tuples while parsing each markers so the gc is triggered
> +            # a lot while parsing an high number of markers. As a workaround,
> +            # disable GC during initialisation.
> +            #
> +            # This would probably marker parsing during exchange but I do not
> +            # expect the order of magnitude to matter outside of initialisation
> +            # case.

I'm unable to parse this last sentence.

> +            gcenabled = gc.isenabled()
> +            gc.disable()
> +            try:
> +                self._version, markers = _readmarkers(data)
> +                self._load(markers)
> +            finally:
> +                if gcenabled:
> +                    gc.enable()
>   
>       def __iter__(self):
>           return iter(self._all)
>   
>       def __len__(self):
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@selenic.com
> http://selenic.com/mailman/listinfo/mercurial-devel
Pierre-Yves David - Dec. 2, 2014, 9:30 p.m.
On 11/30/2014 10:27 PM, Martin von Zweigbergk wrote:
>
>
> On Sat Nov 29 2014 at 11:47:09 PM Pierre-Yves David
> <pierre-yves.david@ens-lyon.org <mailto:pierre-yves.david@ens-lyon.org>>
> wrote:
>
>
>
>     On 11/29/2014 10:29 PM, Martin von Zweigbergk wrote:
>      >
>      >     The provide and
>      >     interesting speedup (25%).
>      >
>      >     On my 58758 markers repo:
>      >     before: 0.468247 seconds
>      >     after:  0.344362 seconds
>      >
>      >
>      > Do you see similar values from 'time hg ...'? Without trying to
>      > understand the patch, it sounds like you could just be moving the
>     GC out
>      > of the method that's being timed. I just want to make sure it's an
>      > overall gain.
>
>     I do see similar gain, the overall time is much more unstable, but I get
>     about the same benefit 0.05s
>
>
> 0.05s is less than 0.12s and more like 10-15% than 25%, assuming you're
> still talking about the same baseline of ~0.46s. It's still a
> significant speedup, so it seems worthwhile, but you may want to include
> the "end-to-end" times in the description.

I cannot read… I though the speedup was 8 so 5 is not too bad.

I did some more time testing and I cannot see a time different form 
small operation like 'hg id'. So we should probably drop that patches 
from the series (the rest is okay)
Pierre-Yves David - Dec. 2, 2014, 9:32 p.m.
On 12/01/2014 04:35 PM, Siddharth Agarwal wrote:
> On 11/29/2014 05:57 PM, Pierre-Yves David wrote:
>> # HG changeset patch
>> # User Pierre-Yves David <pierre-yves.david@fb.com>
>> # Date 1417049911 28800
>> #      Wed Nov 26 16:58:31 2014 -0800
>> # Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
>> # Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
>> obsstore: disable garbage collection during initialisation (issue4456)
>
> We also disable the GC while loading the dirstate, for the same reason.
> Can we factor the disable-GC logic out, into a decorator perhaps? (I did
> the same thing for hgsubversion recently for a ~3x perf win on a large
> repo, and I suspect we're going to have to do this more soon.)

So I've come to the conclusion that we do not actually save time by 
doing this (just moving the time somewhere else). But I this this 
decorator idea is great
Matt Mackall - Dec. 3, 2014, 11:31 p.m.
On Sun, 2014-11-30 at 05:17 -0800, Pierre-Yves David wrote:
> 
> On 11/30/2014 05:06 AM, Antoine Pitrou wrote:
> > On Sat, 29 Nov 2014 17:57:42 -0800
> > Pierre-Yves David <pierre-yves.david@ens-lyon.org> wrote:
> >> # HG changeset patch
> >> # User Pierre-Yves David <pierre-yves.david@fb.com>
> >> # Date 1417049911 28800
> >> #      Wed Nov 26 16:58:31 2014 -0800
> >> # Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
> >> # Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
> >> obsstore: disable garbage collection during initialisation (issue4456)
> >>
> >> Python garbage collection is triggered by contained creation. So code that
> >> creates a lot of tuple tends to trigger GC a lot. We disable the gc during
> >> obsolescence marker parsing and associated initialization. The provide and
> >> interesting speedup (25%).
> >>
> >> On my 58758 markers repo:
> >> before: 0.468247 seconds
> >> after:  0.344362 seconds
> >
> > Which Python version is that?
> 
> Python 2.7.8 (default, Oct 18 2014, 12:50:18)
> [GCC 4.9.1]

Python's GC behavior while building large containers is quite
questionable (aka quadratic). We habitually knee-cap it. We'd have
probably complained about it upstream years ago, but we discovered it
around the time all the versions of Python Mercurial runs on were
officially declared abandonware by PEP 404.

http://www.selenic.com/hg/file/756376ec6c12/mercurial/dirstate.py#l310
Antoine Pitrou - Dec. 4, 2014, 12:44 a.m.
On Wed, 03 Dec 2014 17:31:25 -0600
Matt Mackall <mpm@selenic.com> wrote:
> On Sun, 2014-11-30 at 05:17 -0800, Pierre-Yves David wrote:
> > 
> > On 11/30/2014 05:06 AM, Antoine Pitrou wrote:
> > > On Sat, 29 Nov 2014 17:57:42 -0800
> > > Pierre-Yves David <pierre-yves.david@ens-lyon.org> wrote:
> > >> # HG changeset patch
> > >> # User Pierre-Yves David <pierre-yves.david@fb.com>
> > >> # Date 1417049911 28800
> > >> #      Wed Nov 26 16:58:31 2014 -0800
> > >> # Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
> > >> # Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
> > >> obsstore: disable garbage collection during initialisation (issue4456)
> > >>
> > >> Python garbage collection is triggered by contained creation. So code that
> > >> creates a lot of tuple tends to trigger GC a lot. We disable the gc during
> > >> obsolescence marker parsing and associated initialization. The provide and
> > >> interesting speedup (25%).
> > >>
> > >> On my 58758 markers repo:
> > >> before: 0.468247 seconds
> > >> after:  0.344362 seconds
> > >
> > > Which Python version is that?
> > 
> > Python 2.7.8 (default, Oct 18 2014, 12:50:18)
> > [GCC 4.9.1]
> 
> Python's GC behavior while building large containers is quite
> questionable (aka quadratic).

It shouldn't, see https://hg.python.org/cpython/rev/79276316b94b/

If you have a reproducer, please open an issue at bugs.python.org.

Regards

Antoine.
Matt Mackall - Dec. 4, 2014, 2 a.m.
On Thu, 2014-12-04 at 01:44 +0100, Antoine Pitrou wrote:
> On Wed, 03 Dec 2014 17:31:25 -0600
> Matt Mackall <mpm@selenic.com> wrote:
> > On Sun, 2014-11-30 at 05:17 -0800, Pierre-Yves David wrote:
> > > 
> > > On 11/30/2014 05:06 AM, Antoine Pitrou wrote:
> > > > On Sat, 29 Nov 2014 17:57:42 -0800
> > > > Pierre-Yves David <pierre-yves.david@ens-lyon.org> wrote:
> > > >> # HG changeset patch
> > > >> # User Pierre-Yves David <pierre-yves.david@fb.com>
> > > >> # Date 1417049911 28800
> > > >> #      Wed Nov 26 16:58:31 2014 -0800
> > > >> # Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
> > > >> # Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
> > > >> obsstore: disable garbage collection during initialisation (issue4456)
> > > >>
> > > >> Python garbage collection is triggered by contained creation. So code that
> > > >> creates a lot of tuple tends to trigger GC a lot. We disable the gc during
> > > >> obsolescence marker parsing and associated initialization. The provide and
> > > >> interesting speedup (25%).
> > > >>
> > > >> On my 58758 markers repo:
> > > >> before: 0.468247 seconds
> > > >> after:  0.344362 seconds
> > > >
> > > > Which Python version is that?
> > > 
> > > Python 2.7.8 (default, Oct 18 2014, 12:50:18)
> > > [GCC 4.9.1]
> > 
> > Python's GC behavior while building large containers is quite
> > questionable (aka quadratic).
> 
> It shouldn't, see https://hg.python.org/cpython/rev/79276316b94b/
> 
> If you have a reproducer, please open an issue at bugs.python.org.

You're right, the quadratic behavior appears to be gone in 2.7. In 2.7,
it's down to O(n): generic construction of lists of tuples gets about 4x
slower. So it's still definitely worth disabling for any potentially
large list or dict we might build. And obsolete markers are in that
category.

And the quadratic behavior is still present in 2.6 (aka "the current
Python" for people running enterprise distros) which we'll probably be
supporting for a few years still.
Pierre-Yves David - Dec. 4, 2014, 11:45 a.m.
On 12/03/2014 06:00 PM, Matt Mackall wrote:
> On Thu, 2014-12-04 at 01:44 +0100, Antoine Pitrou wrote:
>> On Wed, 03 Dec 2014 17:31:25 -0600
>> Matt Mackall <mpm@selenic.com> wrote:
>>> On Sun, 2014-11-30 at 05:17 -0800, Pierre-Yves David wrote:
>>>>
>>>> On 11/30/2014 05:06 AM, Antoine Pitrou wrote:
>>>>> On Sat, 29 Nov 2014 17:57:42 -0800
>>>>> Pierre-Yves David <pierre-yves.david@ens-lyon.org> wrote:
>>>>>> # HG changeset patch
>>>>>> # User Pierre-Yves David <pierre-yves.david@fb.com>
>>>>>> # Date 1417049911 28800
>>>>>> #      Wed Nov 26 16:58:31 2014 -0800
>>>>>> # Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
>>>>>> # Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
>>>>>> obsstore: disable garbage collection during initialisation (issue4456)
>>>>>>
>>>>>> Python garbage collection is triggered by contained creation. So code that
>>>>>> creates a lot of tuple tends to trigger GC a lot. We disable the gc during
>>>>>> obsolescence marker parsing and associated initialization. The provide and
>>>>>> interesting speedup (25%).
>>>>>>
>>>>>> On my 58758 markers repo:
>>>>>> before: 0.468247 seconds
>>>>>> after:  0.344362 seconds
>>>>>
>>>>> Which Python version is that?
>>>>
>>>> Python 2.7.8 (default, Oct 18 2014, 12:50:18)
>>>> [GCC 4.9.1]
>>>
>>> Python's GC behavior while building large containers is quite
>>> questionable (aka quadratic).
>>
>> It shouldn't, see https://hg.python.org/cpython/rev/79276316b94b/
>>
>> If you have a reproducer, please open an issue at bugs.python.org.
>
> You're right, the quadratic behavior appears to be gone in 2.7. In 2.7,
> it's down to O(n): generic construction of lists of tuples gets about 4x
> slower. So it's still definitely worth disabling for any potentially
> large list or dict we might build. And obsolete markers are in that
> category.
>
> And the quadratic behavior is still present in 2.6 (aka "the current
> Python" for people running enterprise distros) which we'll probably be
> supporting for a few years still.

Interesting, lets go for disabling GC during obsmarker loading then.
Antoine Pitrou - Dec. 4, 2014, 11:49 a.m.
On Wed, 03 Dec 2014 20:00:23 -0600
Matt Mackall <mpm@selenic.com> wrote:
> On Thu, 2014-12-04 at 01:44 +0100, Antoine Pitrou wrote:
> > On Wed, 03 Dec 2014 17:31:25 -0600
> > Matt Mackall <mpm@selenic.com> wrote:
> > > On Sun, 2014-11-30 at 05:17 -0800, Pierre-Yves David wrote:
> > > > 
> > > > On 11/30/2014 05:06 AM, Antoine Pitrou wrote:
> > > > > On Sat, 29 Nov 2014 17:57:42 -0800
> > > > > Pierre-Yves David <pierre-yves.david@ens-lyon.org> wrote:
> > > > >> # HG changeset patch
> > > > >> # User Pierre-Yves David <pierre-yves.david@fb.com>
> > > > >> # Date 1417049911 28800
> > > > >> #      Wed Nov 26 16:58:31 2014 -0800
> > > > >> # Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
> > > > >> # Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
> > > > >> obsstore: disable garbage collection during initialisation (issue4456)
> > > > >>
> > > > >> Python garbage collection is triggered by contained creation. So code that
> > > > >> creates a lot of tuple tends to trigger GC a lot. We disable the gc during
> > > > >> obsolescence marker parsing and associated initialization. The provide and
> > > > >> interesting speedup (25%).
> > > > >>
> > > > >> On my 58758 markers repo:
> > > > >> before: 0.468247 seconds
> > > > >> after:  0.344362 seconds
> > > > >
> > > > > Which Python version is that?
> > > > 
> > > > Python 2.7.8 (default, Oct 18 2014, 12:50:18)
> > > > [GCC 4.9.1]
> > > 
> > > Python's GC behavior while building large containers is quite
> > > questionable (aka quadratic).
> > 
> > It shouldn't, see https://hg.python.org/cpython/rev/79276316b94b/
> > 
> > If you have a reproducer, please open an issue at bugs.python.org.
> 
> You're right, the quadratic behavior appears to be gone in 2.7. In 2.7,
> it's down to O(n): generic construction of lists of tuples gets about 4x
> slower. So it's still definitely worth disabling for any potentially
> large list or dict we might build. And obsolete markers are in that
> category.

Thanks. I'm wondering if there would be a way to improve our current
heuristics to alleviate such issues.

Regards

Antoine.
Pierre-Yves David - Dec. 4, 2014, 2:42 p.m.
On 12/01/2014 04:35 PM, Siddharth Agarwal wrote:
> On 11/29/2014 05:57 PM, Pierre-Yves David wrote:
>> # HG changeset patch
>> # User Pierre-Yves David <pierre-yves.david@fb.com>
>> # Date 1417049911 28800
>> #      Wed Nov 26 16:58:31 2014 -0800
>> # Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
>> # Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
>> obsstore: disable garbage collection during initialisation (issue4456)
>
> We also disable the GC while loading the dirstate, for the same reason.
> Can we factor the disable-GC logic out, into a decorator perhaps? (I did
> the same thing for hgsubversion recently for a ~3x perf win on a large
> repo, and I suspect we're going to have to do this more soon.)
>
>
>>
>> Python garbage collection is triggered by contained
>
> "container"
>
>>   creation. So code that
>> creates a lot of tuple tends to trigger GC a lot. We disable the gc
>> during
>> obsolescence marker parsing and associated initialization. The provide
>> and
>
> "This provides an"
>
>> interesting speedup (25%).
>>
>> On my 58758 markers repo:
>> before: 0.468247 seconds
>> after:  0.344362 seconds
>>
>> Thanks goes to Siddharth Agarwal for the lead.
>>
>> diff --git a/mercurial/obsolete.py b/mercurial/obsolete.py
>> --- a/mercurial/obsolete.py
>> +++ b/mercurial/obsolete.py
>> @@ -66,10 +66,11 @@ The file starts with a version header:
>>   The header is followed by the markers. Marker format depend of the
>> version. See
>>   comment associated with each format for details.
>>   """
>>   import struct
>> +import gc
>>   import util, base85, node
>>   import phases
>>   from i18n import _
>>   _pack = struct.pack
>> @@ -466,12 +467,28 @@ class obsstore(object):
>>           self.sopener = sopener
>>           data = sopener.tryread('obsstore')
>>           self._version = defaultformat
>>           self._readonly = readonly
>>           if data:
>> -            self._version, markers = _readmarkers(data)
>> -            self._load(markers)
>> +            # Python's garbage collector triggers a GC each time a
>> certain
>> +            # number of container objects (the number being defined by
>> +            # gc.get_threshold()) are allocated. Markers parsing creates
>> +            # multiple tuples while parsing each markers so the gc is
>> triggered
>> +            # a lot while parsing an high number of markers. As a
>> workaround,
>> +            # disable GC during initialisation.
>> +            #
>> +            # This would probably marker parsing during exchange but
>> I do not
>> +            # expect the order of magnitude to matter outside of
>> initialisation
>> +            # case.
>
> I'm unable to parse this last sentence.

unmarmouted as:

   # This could probaly also speed up marker parsing during exchange
   # but I do not expect the order of magnitude to matter outside of
   # initialisation case.

But I've dropped it from the V2 with decorator with
I
Matt Mackall - Dec. 5, 2014, 8:50 p.m.
On Thu, 2014-12-04 at 12:49 +0100, Antoine Pitrou wrote:
> On Wed, 03 Dec 2014 20:00:23 -0600
> Matt Mackall <mpm@selenic.com> wrote:
> > On Thu, 2014-12-04 at 01:44 +0100, Antoine Pitrou wrote:
> > > On Wed, 03 Dec 2014 17:31:25 -0600
> > > Matt Mackall <mpm@selenic.com> wrote:
> > > > On Sun, 2014-11-30 at 05:17 -0800, Pierre-Yves David wrote:
> > > > > 
> > > > > On 11/30/2014 05:06 AM, Antoine Pitrou wrote:
> > > > > > On Sat, 29 Nov 2014 17:57:42 -0800
> > > > > > Pierre-Yves David <pierre-yves.david@ens-lyon.org> wrote:
> > > > > >> # HG changeset patch
> > > > > >> # User Pierre-Yves David <pierre-yves.david@fb.com>
> > > > > >> # Date 1417049911 28800
> > > > > >> #      Wed Nov 26 16:58:31 2014 -0800
> > > > > >> # Node ID d0f3dac4ea2b4aff51946c7db0834aa4e5c3e82a
> > > > > >> # Parent  04eb7e49d2b6f90f71aa85de9ad0b4d70670d688
> > > > > >> obsstore: disable garbage collection during initialisation (issue4456)
> > > > > >>
> > > > > >> Python garbage collection is triggered by contained creation. So code that
> > > > > >> creates a lot of tuple tends to trigger GC a lot. We disable the gc during
> > > > > >> obsolescence marker parsing and associated initialization. The provide and
> > > > > >> interesting speedup (25%).
> > > > > >>
> > > > > >> On my 58758 markers repo:
> > > > > >> before: 0.468247 seconds
> > > > > >> after:  0.344362 seconds
> > > > > >
> > > > > > Which Python version is that?
> > > > > 
> > > > > Python 2.7.8 (default, Oct 18 2014, 12:50:18)
> > > > > [GCC 4.9.1]
> > > > 
> > > > Python's GC behavior while building large containers is quite
> > > > questionable (aka quadratic).
> > > 
> > > It shouldn't, see https://hg.python.org/cpython/rev/79276316b94b/
> > > 
> > > If you have a reproducer, please open an issue at bugs.python.org.
> > 
> > You're right, the quadratic behavior appears to be gone in 2.7. In 2.7,
> > it's down to O(n): generic construction of lists of tuples gets about 4x
> > slower. So it's still definitely worth disabling for any potentially
> > large list or dict we might build. And obsolete markers are in that
> > category.
> 
> Thanks. I'm wondering if there would be a way to improve our current
> heuristics to alleviate such issues.

Maybe adapt the GC threshold proportional to the number of active
objects seen at the last GC. "You've got a million objects already? I
shouldn't make a fuss when you create another 100000 objects.."
Antoine Pitrou - Dec. 5, 2014, 9:34 p.m.
On Fri, 05 Dec 2014 14:50:02 -0600
Matt Mackall <mpm@selenic.com> wrote:
> > > You're right, the quadratic behavior appears to be gone in 2.7. In 2.7,
> > > it's down to O(n): generic construction of lists of tuples gets about 4x
> > > slower. So it's still definitely worth disabling for any potentially
> > > large list or dict we might build. And obsolete markers are in that
> > > category.
> > 
> > Thanks. I'm wondering if there would be a way to improve our current
> > heuristics to alleviate such issues.
> 
> Maybe adapt the GC threshold proportional to the number of active
> objects seen at the last GC. "You've got a million objects already? I
> shouldn't make a fuss when you create another 100000 objects.."

I'd still like to be sure there's a problem, with a simple reproducer.

Let's see a microbenchmark. First, it's clear that building up a list
of tuples /looks/ faster when the GC is disabled:

$ python2.7 -m timeit -s "import gc" "gc.enable(); l = [(x, x) for x in range(1000000)]"
10 loops, best of 3: 137 msec per loop
$ python2.7 -m timeit -s "import gc" "gc.disable(); l = [(x, x) for x in range(1000000)]"
10 loops, best of 3: 107 msec per loop

But, when the next full collection comes, and if the container hasn't
been deleted in the meantime, the full price is paid by the
GC-disabling version:

$ python2.7 -m timeit -s "import gc" "gc.enable(); l = [(x, x) for x in range(1000000)]; gc.collect()"
10 loops, best of 3: 155 msec per loop
$ python2.7 -m timeit -s "import gc" "gc.disable(); l = [(x, x) for x in range(1000000)]; gc.collect()"
10 loops, best of 3: 160 msec per loop

As you mentioned (or was it marmoute?), this may be due to the cost of
walking and untracking the tuples; temporarily disabling the GC merely
delays that operation, it doesn't eliminate it.

Regards

Antoine.
Matt Mackall - Dec. 8, 2014, 11:51 p.m.
On Fri, 2014-12-05 at 22:34 +0100, Antoine Pitrou wrote:
> On Fri, 05 Dec 2014 14:50:02 -0600
> Matt Mackall <mpm@selenic.com> wrote:
> > > > You're right, the quadratic behavior appears to be gone in 2.7. In 2.7,
> > > > it's down to O(n): generic construction of lists of tuples gets about 4x
> > > > slower. So it's still definitely worth disabling for any potentially
> > > > large list or dict we might build. And obsolete markers are in that
> > > > category.
> > > 
> > > Thanks. I'm wondering if there would be a way to improve our current
> > > heuristics to alleviate such issues.
> > 
> > Maybe adapt the GC threshold proportional to the number of active
> > objects seen at the last GC. "You've got a million objects already? I
> > shouldn't make a fuss when you create another 100000 objects.."
> 
> I'd still like to be sure there's a problem, with a simple reproducer.

Here's a test:

import gc
import time

baseline = []

for x in xrange(10000):
    baseline.append((x, time.time()))
gc.collect()

b2 = []
begin = time.time()
#gc.disable()
for x in xrange(1000000):
    b2.append((x, []))
gc.enable()
gc.collect()

print time.time() - begin

Patch

diff --git a/mercurial/obsolete.py b/mercurial/obsolete.py
--- a/mercurial/obsolete.py
+++ b/mercurial/obsolete.py
@@ -66,10 +66,11 @@  The file starts with a version header:
 The header is followed by the markers. Marker format depend of the version. See
 comment associated with each format for details.
 
 """
 import struct
+import gc
 import util, base85, node
 import phases
 from i18n import _
 
 _pack = struct.pack
@@ -466,12 +467,28 @@  class obsstore(object):
         self.sopener = sopener
         data = sopener.tryread('obsstore')
         self._version = defaultformat
         self._readonly = readonly
         if data:
-            self._version, markers = _readmarkers(data)
-            self._load(markers)
+            # Python's garbage collector triggers a GC each time a certain
+            # number of container objects (the number being defined by
+            # gc.get_threshold()) are allocated. Markers parsing creates
+            # multiple tuples while parsing each markers so the gc is triggered
+            # a lot while parsing an high number of markers. As a workaround,
+            # disable GC during initialisation.
+            #
+            # This would probably marker parsing during exchange but I do not
+            # expect the order of magnitude to matter outside of initialisation
+            # case.
+            gcenabled = gc.isenabled()
+            gc.disable()
+            try:
+                self._version, markers = _readmarkers(data)
+                self._load(markers)
+            finally:
+                if gcenabled:
+                    gc.enable()
 
     def __iter__(self):
         return iter(self._all)
 
     def __len__(self):