Recently I've been seeing graft commands take minutes of cpu time to execute. For example, grafting f7954ef8f0ba from https://hg.mozilla.org/mozilla-central onto 089b5e6cd72e from https://hg.mozilla.org/releases/mozilla-aurora. profile and traceback from an interrupted run: tamias:mozilla-aurora giles$ hg graft f7954ef8f0ba grafting 253444:f7954ef8f0ba "Bug 1127171 - Put mozCaptureStream operations in the same lock. r=roc" ^Cinterrupted! tamias:mozilla-aurora giles$ hg graft --profile --traceback f7954ef8f0ba grafting 253444:f7954ef8f0ba "Bug 1127171 - Put mozCaptureStream operations in the same lock. r=roc" ^C CallCount Recursive Total(s) Inline(s) module:lineno(function) 3293 0 73.6047 19.6231 mercurial.ancestor:326(__contains__) 15386914 0 19.0057 19.0057 <_heapq.heappop> 15387315 0 17.5160 17.5160 <_heapq.heappush> 15386914 0 15.9571 11.7175 mercurial.changelog:215(parentrevs) 15387315 0 1.5027 1.5027 <method 'add' of 'set' objects> 15607426 0 19.4952 19.4952 <_heapq.heappop> 15607835 0 17.9633 17.9633 <_heapq.heappush> 15854499 0 16.6344 12.1537 mercurial.changelog:215(parentrevs) 15854499 0 4.4807 4.4807 mercurial.revlog:345(parentrevs) 15854543 0 4.4808 4.4808 mercurial.revlog:345(parentrevs) 296303 0 2.0809 2.0809 <zlib.decompress> 15865845 0 1.5583 1.5583 <method 'add' of 'set' objects> 168401 0 13.7771 1.1035 mercurial.changelog:299(read) 168401 0 11.0100 1.0151 mercurial.revlog:1030(revision) 336802 0 0.2666 0.2666 <method 'split' of 'str' objects> 336802 0 1.0131 0.1910 mercurial.encoding:83(tolocal) 168401 0 0.1569 0.1569 <binascii.unhexlify> 168401 0 0.1183 0.1183 <method 'index' of 'str' objects> 169262 0 11.4604 1.0493 mercurial.revlog:1030(revision) 169262 0 7.7300 0.8782 mercurial.revlog:971(_chunks) 169262 0 0.1934 0.1934 <mercurial.mpatch.patches> 169262 0 1.9659 0.1774 mercurial.revlog:1104(_checkhash) 168401 0 0.2137 0.1592 mercurial.changelog:203(node) 168401 0 0.2068 0.1411 mercurial.changelog:221(flags) 169262 0 7.7300 0.8782 mercurial.revlog:971(_chunks) 241005 0 4.2448 0.2976 mercurial.revlog:959(_chunkraw) 297477 0 2.2998 0.2249 mercurial.revlog:81(decompress) 297477 0 0.1892 0.1892 mercurial.revlog:347(start) 297477 0 0.0741 0.0741 mercurial.revlog:351(length) 297477 0 0.0439 0.0439 <method 'append' of 'list' objects> Traceback (most recent call last): File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/dispatch.py", line 140, in _runcatch return _dispatch(req) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/dispatch.py", line 860, in _dispatch cmdpats, cmdoptions) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/dispatch.py", line 621, in runcommand ret = _runcommand(ui, options, cmd, d) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/extensions.py", line 194, in wrap return wrapper(origfn, *args, **kwargs) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/hgext/pager.py", line 158, in pagecmd return orig(ui, options, cmd, cmdfunc) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/extensions.py", line 194, in wrap return wrapper(origfn, *args, **kwargs) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/hgext/color.py", line 491, in colorcmd return orig(ui_, opts, cmd, cmdfunc) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/dispatch.py", line 944, in _runcommand return lsprofile(ui, checkargs, fp) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/dispatch.py", line 885, in lsprofile return func() File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/dispatch.py", line 922, in checkargs return cmdfunc() File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/dispatch.py", line 857, in <lambda> d = lambda: util.checksignature(func)(ui, *args, **cmdoptions) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/util.py", line 711, in check return func(*args, **kwargs) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/extensions.py", line 149, in wrap util.checksignature(origfn), *args, **kwargs) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/util.py", line 711, in check return func(*args, **kwargs) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/hgext/mq.py", line 3483, in mqcommand return orig(ui, repo, *args, **kwargs) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/util.py", line 711, in check return func(*args, **kwargs) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/commands.py", line 3531, in graft ['local', 'graft']) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/merge.py", line 1191, in graft labels=labels) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/merge.py", line 1098, in update followcopies) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/merge.py", line 567, in calculateupdates acceptremote, followcopies) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/merge.py", line 421, in manifestmerge ret = copies.mergecopies(repo, wctx, p2, pa) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/copies.py", line 275, in mergecopies checkcopies(ctx, f, m1, m2, ca, limit, diverge, copy, fullcopy) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/copies.py", line 431, in checkcopies ocr = oc.rev() File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/context.py", line 698, in rev return self._changeid File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/util.py", line 450, in __get__ result = self.func(obj) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/context.py", line 640, in _changeid self._filenode, self._descendantrev) File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/context.py", line 781, in _adjustlinkrev if lkr not in memberanc: File "/usr/local/Cellar/mercurial/3.3/lib/python2.7/site-packages/mercurial/ancestor.py", line 344, in __contains__ for parent in parentrevs(-heappop(visit)): KeyboardInterrupt interrupted!
Here's a complete profile from the command. tamias:mozilla-aurora giles$ hg graft --profile --traceback f7954ef8f0ba grafting 253444:f7954ef8f0ba "Bug 1127171 - Put mozCaptureStream operations in the same lock. r=roc" merging dom/html/HTMLMediaElement.cpp merging dom/media/MediaDecoder.cpp merging dom/media/MediaDecoder.h merging dom/media/MediaDecoderStateMachine.cpp merging dom/media/MediaDecoderStateMachine.h CallCount Recursive Total(s) Inline(s) module:lineno(function) 8170 0 252.0085 66.4608 mercurial.ancestor:326(__contains__) 52351791 0 65.6497 65.6497 <_heapq.heappop> 52353083 0 60.5915 60.5915 <_heapq.heappush> 52351791 0 54.1842 39.8158 mercurial.changelog:215(parentrevs) 52353083 0 5.1223 5.1223 <method 'add' of 'set' objects> 52572304 0 66.1284 66.1284 <_heapq.heappop> 52573603 0 61.0326 61.0326 <_heapq.heappush> 53134237 0 55.3460 40.6060 mercurial.changelog:215(parentrevs) 53134237 0 14.7401 14.7401 mercurial.revlog:345(parentrevs) 53134371 0 14.7401 14.7401 mercurial.revlog:345(parentrevs) 859696 0 5.9861 5.9861 <zlib.decompress> 53135359 0 5.2255 5.2255 <method 'add' of 'set' objects> 469991 0 37.9009 3.0623 mercurial.changelog:299(read) 469991 0 30.1636 2.8532 mercurial.revlog:1030(revision) 939980 0 0.7585 0.7585 <method 'split' of 'str' objects> 939980 0 2.8415 0.5228 mercurial.encoding:83(tolocal) 469990 0 0.4250 0.4250 <binascii.unhexlify> 469990 0 0.3703 0.3703 <method 'index' of 'str' objects> 471486 0 31.0357 2.8978 mercurial.revlog:1030(revision) 471468 0 20.5693 2.3988 mercurial.revlog:971(_chunks) 471468 0 0.5215 0.5215 <mercurial.mpatch.patches> 471468 0 5.6106 0.4928 mercurial.revlog:1104(_checkhash) 469991 0 0.6011 0.4538 mercurial.changelog:203(node) 469984 0 0.5690 0.3905 mercurial.changelog:221(flags) 471468 0 20.5693 2.3988 mercurial.revlog:971(_chunks) 645672 0 10.6405 0.7745 mercurial.revlog:959(_chunkraw) 862721 0 6.6260 0.6464 mercurial.revlog:81(decompress) 862721 0 0.5649 0.5649 mercurial.revlog:347(start) 862721 0 0.2117 0.2117 mercurial.revlog:351(length) 862721 0 0.1274 0.1274 <method 'append' of 'list' objects>
Still hitting this with every cross-repo graft. It's faster to cycle patches through git.
(In reply to comment #2) As a very hacky workaround, you can `hg up <dest> && hg export <rev> | hg import --partial -` to simulate a graft, albeit without the 3-way merge. Bumping to confirmed since a stack trace and profile result points to a performance problem. I suspect the stack trace involving linkrev will interest Pierre-Yves.
Thanks. I started doing the graft because qimport without the 3-way merge wasn't always adequate. I've just downgraded 3.2.4 for now.
Regression from 3.2 to 3.3 -> urgent.
I'm pretty sure this is a consequence of ff070a53ee74 and a duplicate / variant of the other _adjustlinkrev people have seen.
Bug marked urgent for 5 days, bumping
182.840
The issue is similar to issue4532 where we recompute the same ancestry over and over and over. quick and dirty patching of the merge logic bring back the timing to 8s using _ancestrycontext. I'm working on a clean patch.
Fixed by http://selenic.com/repo/hg/rev/9372180b8c9b Pierre-Yves David <pierre-yves.david@fb.com> mergecopies: reuse ancestry context when traversing file history (issue4537) Merge copies is traversing file history in search for copies and renames. Since 3.3 we are doing "linkrev adjustment" to ensure duplicated filelog entry does not confuse the traversal. This "linkrev adjustment" involved ancestry testing and walking in the changeset graph. If we do such walk in the changesets graph for each file, we end up with a 'O(<changesets>x<files>)' complexity that create massive issue. For examples, grafting a changeset in Mozilla's repo moved from 6 seconds to more than 3 minutes. There is a mechanism to reuse such ancestors computation between all files. But it has to be manually set up in situation were it make sense to take such shortcut. This changesets set this mechanism up and bring back the graph time from 3 minutes to 8 seconds. To do so, we need a bigger control on the way 'filectx' are instantiated during each 'checkcopies' calls that 'mergecopies' is doing. We add a new 'setupctx' that configure and return a 'filectx' factory. The function make sure the ancestry context is properly created and the factory make sure it is properly installed on returned 'filectx'. (please test the fix)
Simulating the original repro case of grafting f7954ef8f0ba onto 089b5e6cd72e: 3.2.4: 7.600s 3.3.2: 139.300s @: 9.710s stable: 10.100s The fix looks verified!
Thanks for fixing!