[Bug 4201] New: Rebasing slowed down drastically after 2.9.1
mercurial-bugs at selenic.com
mercurial-bugs at selenic.com
Fri Mar 21 16:10:41 CDT 2014
http://bz.selenic.com/show_bug.cgi?id=4201
Priority: normal
Bug ID: 4201
CC: mercurial-devel at selenic.com
Assignee: bugzilla at selenic.com
Summary: Rebasing slowed down drastically after 2.9.1
Severity: bug
Classification: Unclassified
OS: All
Reporter: gregory.szorc at gmail.com
Hardware: All
Status: UNCONFIRMED
Version: unspecified
Component: Mercurial
Product: Mercurial
I'm running hg default and I've noticed a significant slowdown in the
performance of rebase in the last week or two. I think the revset optimization
work is to blame. The regression definitely happened after 2.9.1.
Results in this bug are from the https://hg.stage.mozaws.net/gecko/ repository,
which has nearly 200k changesets. The disparity in rebase performance seems to
be greater the more intermediate changesets there are. e.g. rebasing 1000
changesets forward is slower than 100 changesets forward is slower than 10.
~/src/hg/hg is 1.9.1. `hg` is 2.9.1+158-131f7fe06e9e. I am using
mutable-history 0ea9cecbbd28 (current default).
# Operation with 1.9.1
$ ~/src/hg/hg --time rebase -s . -d fx-team/default
time: real 10.060 secs (user 9.710+0.000 sys 0.310+0.000)
# Undo the rebase
$ ~/src/hg/hg rebase -s . -d 8629b33918d4
# Now with @
$ hg --time rebase -s . -d fx-team/default
time: real 13.530 secs (user 13.140+0.000 sys 0.330+0.000)
# Let's profile it with 2.9.1:
$ ~/src/hg/hg --time --profile rebase -s . -d fx-team/default
CallCount Recursive Total(s) Inline(s) module:lineno(function)
4361697 0 8.5855 3.9947
mercurial.ancestor:329(__iter__)
4361697 0 3.7227 2.4776
mercurial.changelog:202(parentrevs)
4361651 0 0.3394 0.3394 <method 'add' of 'set'
objects>
4361651 0 0.2709 0.2709 <method 'append' of
'collections.deque' objects>
4361697 0 0.2577 0.2577 <method 'popleft' of
'collections.deque' objects>
1 0 0.0000 0.0000
mercurial.demandimport:99(__getattribute__)
4845965 0 4.0956 2.7399
mercurial.changelog:202(parentrevs)
4845965 0 1.3557 1.3557
mercurial.revlog:335(parentrevs)
4845965 0 1.3557 1.3557
mercurial.revlog:335(parentrevs)
1 0 9.3431 0.7425
mercurial.branchmap:222(update)
4361697 0 8.5855 3.9947
mercurial.ancestor:329(__iter__)
1 0 0.0019 0.0006
mercurial.branchmap:137(_hashfiltered)
46 0 0.0005 0.0005 <min>
46 0 0.0006 0.0002
mercurial.revlog:362(ancestors)
653 0 0.0014 0.0002 <max>
142583 0 0.4944 0.4944 <_heapq.heappop>
142454 0 0.4361 0.4361 <_heapq.heappush>
4545505 0 0.3567 0.3567 <method 'add' of 'set'
objects>
839937 0 0.4968 0.2970 mercurial.phases:180(phase)
839935 0 0.0478 0.0478 <len>
3 0 0.1520 0.0039
mercurial.phases:166(getphaserevs)
4361683 0 0.2709 0.2709 <method 'append' of
'collections.deque' objects>
4361697 0 0.2577 0.2577 <method 'popleft' of
'collections.deque' objects>
2798 0 0.2339 0.2339 <zlib.decompress>
300570 0 0.2131 0.1855 <method 'decode' of 'str'
objects>
16043 0 0.0273 0.0047
encodings.utf_8:15(decode)
2 0 0.0003 0.0000
encodings:71(search_function)
286821 0 0.1687 0.1687 <method 'lower' of 'str'
objects>
4 0 0.2060 0.1421
mercurial.dicthelpers:8(diff)
189611 0 0.0639 0.0639 <method 'get' of 'dict'
objects>
time: real 14.920 secs (user 14.470+0.000 sys 0.380+0.000)
# Again again with @
$ hg --time --profile rebase -s . -d fx-team/default
CallCount Recursive Total(s) Inline(s) module:lineno(function)
4361697 0 8.3644 3.9457
mercurial.ancestor:327(__iter__)
4361697 0 3.5707 2.3688
mercurial.changelog:202(parentrevs)
4361651 0 0.3319 0.3319 <method 'add' of 'set'
objects>
4361651 0 0.2655 0.2655 <method 'append' of
'collections.deque' objects>
4361697 0 0.2506 0.2506 <method 'popleft' of
'collections.deque' objects>
1 0 0.0000 0.0000
mercurial.demandimport:99(__getattribute__)
1183166 0 5.8009 3.5049
mercurial.revset:2679(__contains__)
29026398 0 2.2960 2.2470
mercurial.revset:2642(__iter__)
4845989 0 3.9380 2.6253
mercurial.changelog:202(parentrevs)
4845989 0 1.3126 1.3126
mercurial.revlog:335(parentrevs)
29026398 0 2.2960 2.2470
mercurial.revset:2642(__iter__)
1725 0 0.0487 0.0182
mercurial.revset:55(iterate)
1723 0 0.0002 0.0002 <method 'append' of
'list' objects>
4845989 0 1.3126 1.3126
mercurial.revlog:335(parentrevs)
1 0 9.0656 0.6870
mercurial.branchmap:222(update)
4361697 0 8.3644 3.9457
mercurial.ancestor:327(__iter__)
1 0 0.0019 0.0006
mercurial.branchmap:137(_hashfiltered)
46 0 0.0005 0.0005 <min>
46 0 0.0005 0.0002
mercurial.revlog:362(ancestors)
653 0 0.0014 0.0002 <max>
142583 0 0.4879 0.4879 <_heapq.heappop>
142454 0 0.4307 0.4307 <_heapq.heappush>
7377 4831 7.7467 0.3993
mercurial.revset:2339(__iter__)
1183166 0 6.1942 0.3933
mercurial.revset:665(<lambda>)
1382313 0 0.1580 0.1580
mercurial.revset:2752(__iter__)
398281 0 0.9796 0.1469
mercurial.revset:2788(<lambda>)
4831 0 1.1306 0.1130
mercurial.revset:2339(__iter__)
4829 0 0.0156 0.0018
mercurial.revset:2413(<lambda>)
1183166 0 6.1942 0.3933
mercurial.revset:665(<lambda>)
1183166 0 5.8009 3.5049
mercurial.revset:2679(__contains__)
time: real 22.480 secs (user 22.000+0.000 sys 0.420+0.000)
If I run with --traceback and ctrl+c a few seconds in, I get a stack trace
like:
File "/Users/gps/lib/python2.7/site-packages/hgext/rebase.py", line 241, in
rebase
base, dest, base)
File "/Users/gps/lib/python2.7/site-packages/mercurial/localrepo.py", line
431, in revs
return m(self, revset.spanset(self))
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 2060,
in mfunc
return getset(repo, subset, tree)
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 237,
in getset
s = methods[x[0]](repo, subset, *x[1:])
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 304,
in func
return symbols[a[1]](repo, subset, b)
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 671,
in descendants
return _descendants(repo, subset, x)
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 660,
in _descendants
args = getset(repo, spanset(repo), x)
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 237,
in getset
s = methods[x[0]](repo, subset, *x[1:])
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 289,
in andset
return getset(repo, getset(repo, subset, x), y)
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 237,
in getset
s = methods[x[0]](repo, subset, *x[1:])
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 304,
in func
return symbols[a[1]](repo, subset, b)
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 577,
in children
cs = _children(repo, subset, s)
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 564,
in _children
for r in narrow:
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 2342,
in __iter__
if cond(x):
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 354,
in <lambda>
return subset.filter(lambda r: r in s)
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 2705,
in __contains__
for l in self:
File "/Users/gps/lib/python2.7/site-packages/mercurial/revset.py", line 2647,
in __iter__
yield l
KeyboardInterrupt
I could bisect this if you need leads. But I'm pretty sure it's related to lazy
revsets. Possibly some iteration somewhere that's causing multiple evaluations
of the same revset query.
--
You are receiving this mail because:
You are on the CC list for the bug.
More information about the Mercurial-devel
mailing list