Patchwork revset: don't create changectx when matching for files

login
register
mail settings
Submitter Durham Goode
Date March 17, 2015, 4:57 p.m.
Message ID <5d4d0a97ccd85132bb5b.1426611432@dev2000.prn2.facebook.com>
Download mbox | patch
Permalink /patch/8123/
State Deferred
Headers show

Comments

Durham Goode - March 17, 2015, 4:57 p.m.
# HG changeset patch
# User Durham Goode <durham@fb.com>
# Date 1426610443 25200
#      Tue Mar 17 09:40:43 2015 -0700
# Node ID 5d4d0a97ccd85132bb5b1a640543cd24350b36c8
# Parent  567ae53657544744155897ada91f16f8af61ad8a
revset: don't create changectx when matching for files

When running 'hg log some/dir/' on a large repo about 25% of the time was spent
just creating changectxs to call ctx.files() on. Let's just skip that part.

On a large repo, running 'hg log some/path/ -l 200' went from 12s to 8.8s (27%
better) while traversing 90,000 commits.
Matt Mackall - March 17, 2015, 5:26 p.m.
On Tue, 2015-03-17 at 09:57 -0700, Durham Goode wrote:
> # HG changeset patch
> # User Durham Goode <durham@fb.com>
> # Date 1426610443 25200
> #      Tue Mar 17 09:40:43 2015 -0700
> # Node ID 5d4d0a97ccd85132bb5b1a640543cd24350b36c8
> # Parent  567ae53657544744155897ada91f16f8af61ad8a
> revset: don't create changectx when matching for files
> 
> When running 'hg log some/dir/' on a large repo about 25% of the time was spent
> just creating changectxs to call ctx.files() on. 

Can't repro. I get this profile on mozilla-central:

  %   cumulative      self          
 time    seconds   seconds  name    
 16.78      2.62      2.62  revlog.py:90:decompress
  3.85      0.60      0.60  match.py:108:__call__
  2.72      0.42      0.42  utf_8.py:16:decode
  2.67      0.71      0.42  changelog.py:212:node
  2.41      0.38      0.38  revlog.py:78:hash
  2.00      0.31      0.31  changelog.py:322:read
  1.74      0.46      0.27  changelog.py:142:tip
  1.69      0.26      0.26  revlog.py:1091:revision
  1.69      0.26      0.26  utf_8.py:15:decode
  1.69      0.26      0.26  revlog.py:350:start
  1.69      0.26      0.26  revlog.py:282:__len__
  1.49     11.00      0.23  context.py:485:_changeset
  1.44      0.22      0.22  revlog.py:283:__len__
  1.39      0.22      0.22  revlog.py:340:node
  1.39      0.22      0.22  match.py:107:__call__
  1.28      0.20      0.20  changelog.py:331:read
  1.28      0.39      0.20  localrepo.py:30:__get__
  1.23      0.72      0.19  changelog.py:144:tip
  1.23      2.90      0.19  revlog.py:1007:_chunks
  1.13     14.30      0.18  revset.py:1074:matches
  1.08      0.98      0.17  revset.py:1075:matches
  0.97      0.15      0.15  revlog.py:318:rev
  0.97      0.15      0.15  revlog.py:940:_loadchunk
  0.97      2.03      0.15  context.py:374:__init__
  0.92      0.65      0.14  changelog.py:321:read
  0.92      0.14      0.14  revlog.py:79:hash
  0.92      0.14      0.14  revlog.py:70:hash

> Let's just skip that part.

I'd really like to see an analysis of why this crucial code path
(creating context objects) is slow before simply patching around it in
one of the thousand spots it's used.
Durham Goode - March 17, 2015, 5:51 p.m.
A more detailed breakdown of the profiling is here: 
https://bpaste.net/show/1affea0af5e4

It looks like repoview introduces some overhead (simply switching to an 
unfiltered repo gets us from 12s to 9.9s, despite this repo not having 
any obsolescence) and the remaining time is in the changectx constructor.

What are you running on the mozilla repo?  I'm doing 'time hg log 
editor/ -l 600 > /dev/null' which traverse about 100k commits:

Without my change:
~/local/mozilla-central> time hg log editor -l 600 > /dev/null
real    0m12.584s
user    0m12.451s
sys     0m0.131s

With my change:
~/local/mozilla-central> time hg log editor -l 600 > /dev/null
real    0m8.297s
user    0m8.180s
sys     0m0.115s

On 3/17/15 10:26 AM, Matt Mackall wrote:
> On Tue, 2015-03-17 at 09:57 -0700, Durham Goode wrote:
>> # HG changeset patch
>> # User Durham Goode <durham@fb.com>
>> # Date 1426610443 25200
>> #      Tue Mar 17 09:40:43 2015 -0700
>> # Node ID 5d4d0a97ccd85132bb5b1a640543cd24350b36c8
>> # Parent  567ae53657544744155897ada91f16f8af61ad8a
>> revset: don't create changectx when matching for files
>>
>> When running 'hg log some/dir/' on a large repo about 25% of the time was spent
>> just creating changectxs to call ctx.files() on.
> Can't repro. I get this profile on mozilla-central:
>
>    %   cumulative      self
>   time    seconds   seconds  name
>   16.78      2.62      2.62  revlog.py:90:decompress
>    3.85      0.60      0.60  match.py:108:__call__
>    2.72      0.42      0.42  utf_8.py:16:decode
>    2.67      0.71      0.42  changelog.py:212:node
>    2.41      0.38      0.38  revlog.py:78:hash
>    2.00      0.31      0.31  changelog.py:322:read
>    1.74      0.46      0.27  changelog.py:142:tip
>    1.69      0.26      0.26  revlog.py:1091:revision
>    1.69      0.26      0.26  utf_8.py:15:decode
>    1.69      0.26      0.26  revlog.py:350:start
>    1.69      0.26      0.26  revlog.py:282:__len__
>    1.49     11.00      0.23  context.py:485:_changeset
>    1.44      0.22      0.22  revlog.py:283:__len__
>    1.39      0.22      0.22  revlog.py:340:node
>    1.39      0.22      0.22  match.py:107:__call__
>    1.28      0.20      0.20  changelog.py:331:read
>    1.28      0.39      0.20  localrepo.py:30:__get__
>    1.23      0.72      0.19  changelog.py:144:tip
>    1.23      2.90      0.19  revlog.py:1007:_chunks
>    1.13     14.30      0.18  revset.py:1074:matches
>    1.08      0.98      0.17  revset.py:1075:matches
>    0.97      0.15      0.15  revlog.py:318:rev
>    0.97      0.15      0.15  revlog.py:940:_loadchunk
>    0.97      2.03      0.15  context.py:374:__init__
>    0.92      0.65      0.14  changelog.py:321:read
>    0.92      0.14      0.14  revlog.py:79:hash
>    0.92      0.14      0.14  revlog.py:70:hash
>
>> Let's just skip that part.
> I'd really like to see an analysis of why this crucial code path
> (creating context objects) is slow before simply patching around it in
> one of the thousand spots it's used.
>
Matt Mackall - March 20, 2015, 6:41 p.m.
On Tue, 2015-03-17 at 10:51 -0700, Durham Goode wrote:
> A more detailed breakdown of the profiling is here: 
> https://bpaste.net/show/1affea0af5e4
> 
> It looks like repoview introduces some overhead (simply switching to an 
> unfiltered repo gets us from 12s to 9.9s, despite this repo not having 
> any obsolescence) and the remaining time is in the changectx constructor.

Perhaps we should fast-path that instead.
Durham Goode - March 20, 2015, 7:43 p.m.
On 3/20/15 11:41 AM, Matt Mackall wrote:
> On Tue, 2015-03-17 at 10:51 -0700, Durham Goode wrote:
>> A more detailed breakdown of the profiling is here:
>> https://urldefense.proofpoint.com/v1/url?u=https://bpaste.net/show/1affea0af5e4&k=ZVNjlDMF0FElm4dQtryO4A%3D%3D%0A&r=pHOG6Hz51SkYmYr%2FxoTFzw%3D%3D%0A&m=JBD9noTgZxxkE1x0gleLTZvXo7v30tZZB0IIgGLjenw%3D%0A&s=4d6f5d76347e2a86763013a5b788bf968294e44fe363188c56b3d767186231b9
>>
>> It looks like repoview introduces some overhead (simply switching to an
>> unfiltered repo gets us from 12s to 9.9s, despite this repo not having
>> any obsolescence) and the remaining time is in the changectx constructor.
> Perhaps we should fast-path that instead.
>
I talked with Pierre-Yves and it's non-trivial to fast path 
repoview.changelog when working with repositories that do have filtered 
changes (which will soon be all of ours).  So if the current work around 
is too hacky, we'll have to come back and revisit this when we have more 
time.
Matt Mackall - March 23, 2015, 7:23 p.m.
On Fri, 2015-03-20 at 12:43 -0700, Durham Goode wrote:
> 
> On 3/20/15 11:41 AM, Matt Mackall wrote:
> > On Tue, 2015-03-17 at 10:51 -0700, Durham Goode wrote:
> >> A more detailed breakdown of the profiling is here:
> >> https://urldefense.proofpoint.com/v1/url?u=https://bpaste.net/show/1affea0af5e4&k=ZVNjlDMF0FElm4dQtryO4A%3D%3D%0A&r=pHOG6Hz51SkYmYr%2FxoTFzw%3D%3D%0A&m=JBD9noTgZxxkE1x0gleLTZvXo7v30tZZB0IIgGLjenw%3D%0A&s=4d6f5d76347e2a86763013a5b788bf968294e44fe363188c56b3d767186231b9
> >>
> >> It looks like repoview introduces some overhead (simply switching to an
> >> unfiltered repo gets us from 12s to 9.9s, despite this repo not having
> >> any obsolescence) and the remaining time is in the changectx constructor.
> > Perhaps we should fast-path that instead.
> >
> I talked with Pierre-Yves and it's non-trivial to fast path 
> repoview.changelog when working with repositories that do have filtered 
> changes (which will soon be all of ours).

Yes, you definitely can't fast-path the slow path. I'll take a stab at
fixing the fast path.

>   So if the current work around 
> is too hacky, we'll have to come back and revisit this when we have more 
> time.

Just keep in mind that even small improvements in the performance of the
filtering layer and contexts apply everywhere.

Patch

diff --git a/mercurial/revset.py b/mercurial/revset.py
--- a/mercurial/revset.py
+++ b/mercurial/revset.py
@@ -1070,8 +1070,13 @@  def _matchfiles(repo, subset, x):
     m = matchmod.match(repo.root, repo.getcwd(), pats, include=inc,
                        exclude=exc, ctx=repo[rev], default=default)
 
+    changelog = repo.changelog
     def matches(x):
-        for f in repo[x].files():
+        # Creating a ctx and calling ctx.files() is expensive when iterating
+        # over every commit in the changelog. We can save 30% or so by avoiding
+        # the ctx creation.
+        c = changelog.read(x)
+        for f in c[3]:
             if m(f):
                 return True
         return False