Performance issues when merging branches (1000+ files being merged takes 75~ seconds)

[Idan K]

Running the same hg merge command with time returned this:

real    1m50.802s
> user    1m45.210s
> sys    0m3.390s
>

Indeed there are 4 files that can't be auto-merged, but looking for the
external merge-tool can't be the main reason for the slow down. I also tried
removing the 4 binary files and running the test again, no dramatic change.


I found another interesting thing, don't know if it helps: I took Mercurial
1.5.4 source without history, put it in a new repository and ran the test
again, the runtime dropped down to about 15 seconds. Still quite a bit but
doesn't compare to the one with all the history (I attached the output of
the merge).


On Thu, Jun 17, 2010 at 5:37 PM, Matt Mackall <mpm at selenic.com> wrote:

> On Thu, 2010-06-17 at 09:15 -0500, Matt Mackall wrote:
> > On Thu, 2010-06-17 at 00:46 +0300, Idan K wrote:
> > > Hi,
> > >
> > > As part of choosing a SCM, the usual debate between Mercurial and Git
> > > has begun in our work place, we decided to do some benchmarks. One of
> > > the tests was this:
> > >
> > > 1. Clone Mercurial's repository (http://hg.intevation.org/mercurial/),
> > > updated to default.
> > > 2. Create a named branch "branch-a".
> > > 3. For every file in the repository, insert a new line after line #3
> > > (if the file contains 3 lines), containing "### ADDED TEXT ###".
> > > 4. Commit.
> > > 5. Update back to default.
> > > 6. Create a named branch "branch-b".
> > > 7. Repeat step 3, but for line #9.
> > > 8. Commit.
> > > 9. Merge "branch-a" to "branch-b".
> > >
> > > I ran this test on a Ubuntu 10.04 with Mercurial 1.5.4 and the result
> > > was quite surprising to say the least: Step #9 took about 75 seconds
> > > (average of 5 runs) on a Q6600 with 4GB RAM, ext4 drive.
> > > I also ran the same test with Git (using fast-export to covert
> > > Mercurial's repository to Git) to get an idea of what I should be
> > > getting, and this time step #9 took an average of 1 second. That's
> > > quite a difference. I know Mercurial is written in Python (with some C
> > > modules) and Git in C, but can the gap be that big?
> >
> > Oh, probably. This is the first time the performance of file-level
> > merging has been raised as a performance issue in our history, so it's
> > not exactly been something we've put time into optimizing.
> >
> > Your profile didn't show anything interesting, I'm afraid - all the
> > numbers are way too small to account for the slowness. Can you send the
> > result of using time(1) too? Perhaps there's a lot of extra I/O
> > happening.
>
> It looks like for every merged file, we:
>
> - do a fairly extensive merge-tool selection process that tries to find
> the best tool on your system (with no caching)
> - back up the local pre-merge state in .hg/merge/ for later resolve
> - writes out two temporary files (other and ancestor)
> - make a backup .orig file in the working directory
> - do a pre-merge (read three files in, merge, write one out)
>
> Most of that time (except the second step) could be eliminated for
> internal merge.
>
> --
> Mathematics is the supreme nostalgia of our time.
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://selenic.com/pipermail/mercurial-devel/attachments/20100617/bda555be/attachment.htm>
-------------- next part --------------
idan at idan:~/benchmark/mercurial-1.5.4$ time hg merge --profile -q -y branch-a
tool gvimdiff can't handle binary
tool vimdiff can't handle binary
 no tool found to merge contrib/wix/COPYING.rtf
keep (l)ocal or take (o)ther? l
tool gvimdiff can't handle binary
tool vimdiff can't handle binary
 no tool found to merge mercurial/templates/static/hglogo.png
keep (l)ocal or take (o)ther? l
tool gvimdiff can't handle binary
tool vimdiff can't handle binary
 no tool found to merge tests/binfile.bin
keep (l)ocal or take (o)ther? l
tool gvimdiff can't handle binary
tool vimdiff can't handle binary
 no tool found to merge tests/gpg/trustdb.gpg
keep (l)ocal or take (o)ther? l
   CallCount    Recursive    Total(ms)   Inline(ms) module:lineno(function)
       18306            0      2.3798      2.3798   <open>
        2136            0      6.9766      2.2151   mercurial.merge:38(_write)
    +1713606            0      1.5521      1.5521   +<method 'write' of 'file' objects>
    +1711470            0      0.9900      0.9900   +<method 'join' of 'str' objects>
       +2136            0      2.2152      0.0155   +mercurial.util:833(__call__)
       +2136            0      0.0030      0.0030   +<binascii.hexlify>
       +2136            0      0.0013      0.0013   +<method 'iteritems' of 'dict' objects>
     1968543            0      1.7993      1.7993   <method 'write' of 'file' objects>
     1732626            0      1.0037      1.0037   <method 'join' of 'str' objects>
      117718            0      0.5347      0.5347   <posix.stat>
        1064            0      2.0671      0.4499   mercurial.simplemerge:403(simplemerge)
     +249229            0      0.1678      0.1678   +<method 'write' of 'file' objects>
     +249229            0      0.1852      0.1300   +mercurial.util:777(__getattr__)
     +250293            0      0.4791      0.0987   +mercurial.simplemerge:79(merge_lines)
       +1064            0      0.1523      0.0255   +posixpath:351(realpath)
       +3192            0      0.1162      0.0119   +mercurial.simplemerge:404(readfile)
      112236            0      0.8445      0.3499   genericpath:15(exists)
     +112236            0      0.4946      0.4946   +<posix.stat>
      113621            0      0.3429      0.3429   <method 'split' of 'str' objects>
      142088            0      0.4267      0.2869   posixpath:59(join)
     +166447            0      0.0858      0.0858   +<method 'startswith' of 'str' objects>
     +166447            0      0.0539      0.0539   +<method 'endswith' of 'str' objects>
        2128            0      0.2422      0.2422   <mercurial.bdiff.blocks>

real	0m14.691s
user	0m10.200s
sys	0m2.260s