Bug 4537 - regression in hg graft performance from _adjustlinkrev (6 seconds → 3 minutes)
Summary: regression in hg graft performance from _adjustlinkrev (6 seconds → 3 minutes)
Status: VERIFIED FIXED
Alias: None
Product: Mercurial
Classification: Unclassified
Component: Mercurial (show other bugs)
Version: 3.3
Hardware: PC Mac OS
: urgent bug
Assignee: Bugzilla
URL:
Keywords: regression
Depends on:
Blocks:
 
Reported: 2015-02-13 14:24 UTC by Ralph Giles
Modified: 2015-03-23 15:37 UTC (History)
6 users (show)

See Also:
Python Version: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Ralph Giles 2015-02-13 14:24 UTC
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!
Comment 1 Ralph Giles 2015-02-13 14:25 UTC
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>
Comment 2 Ralph Giles 2015-02-18 17:19 UTC
Still hitting this with every cross-repo graft. It's faster to cycle patches through git.
Comment 3 Gregory Szorc 2015-02-18 22:02 UTC
(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.
Comment 4 Ralph Giles 2015-02-19 00:06 UTC
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.
Comment 5 Augie Fackler 2015-03-13 10:32 UTC
Regression from 3.2 to 3.3 -> urgent.
Comment 6 kiilerix 2015-03-13 10:39 UTC
I'm pretty sure this is a consequence of ff070a53ee74 and a duplicate / variant of the other _adjustlinkrev people have seen.
Comment 7 Bugzilla 2015-03-19 01:01 UTC
Bug marked urgent for 5 days, bumping
Comment 8 Pierre-Yves David 2015-03-19 23:30 UTC
182.840
Comment 9 Pierre-Yves David 2015-03-20 00:04 UTC
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.
Comment 10 HG Bot 2015-03-20 18:46 UTC
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)
Comment 11 Gregory Szorc 2015-03-23 14:32 UTC
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!
Comment 12 Ralph Giles 2015-03-23 15:37 UTC
Thanks for fixing!