[Bug 4031] New: huge regression in bundle performance

mercurial-bugs at selenic.com mercurial-bugs at selenic.com
Fri Sep 6 21:25:07 CDT 2013


http://bz.selenic.com/show_bug.cgi?id=4031

          Priority: normal
            Bug ID: 4031
                CC: mercurial-devel at selenic.com
          Assignee: bugzilla at selenic.com
           Summary: huge regression in bundle performance
          Severity: bug
    Classification: Unclassified
                OS: Linux
          Reporter: pitrou at free.fr
          Hardware: PC
            Status: UNCONFIRMED
           Version: 2.7
         Component: Mercurial
           Product: Mercurial

After upgrading hg.python.org to 2.7, we witnessed worrying increases in CPU
activity.
(see here:
http://hg.python.org/munin/localdomain/localhost.localdomain/cpu.html - the
upgrade was done on Sep 1st around 19h).

Investigating points to bundling speed. Bundling the CPython repo (and cloning
it using either hgweb or "hg clone --pull") became horrendously slow, and the
serving hg process would eat 100% CPU for tens of minutes (as can be seen on
the graphes).

Bisecting shows the regression in "hg bundle" performance to occur at the
following changeset:

changeset:   19396:ec896f9e8894
user:        Matt Mackall <mpm at selenic.com>
date:        Wed Jun 19 14:17:03 2013 -0500
summary:     changegroup: fix fastpath during commit


Here is a profile run of "hg bundle" with 2.7. I stopped it before the end (as
you can see, only 17% of the files were bundled after 10 minutes):

$ time hg --debug --profile bundle -a ~/cpy.bundle

[...]

bundling: Doc/library/ttk.rst 1682/9933 files (16.93%)
bundling: Doc/library/tty.rst 1683/9933 files (16.94%)
bundling: Doc/library/turtle-star.pdf 1684/9933 files (16.95%)
bundling: Doc/library/turtle-star.png 1685/9933 files (16.96%)
bundling: Doc/library/turtle-star.ps 1686/9933 files (16.97%)
^C   CallCount    Recursive     Total(s)    Inline(s) module:lineno(function)
   144792142            0    332.9991    205.7596  
mercurial.changelog:182(rev)
   144792141            0    127.2395    127.2395      
mercurial.revlog:296(rev)
   144375042            0    485.4131    153.7092  
mercurial.changegroup:361(<genexpr>)
   144373356            0    331.7038    204.9294      
mercurial.changelog:182(rev)
   145145552            0    127.6158    127.6158   mercurial.revlog:296(rev)
        1687            0    542.9073     57.2158  
mercurial.changegroup:358(linknodes)
   144375042            0    485.4131    153.7092      
mercurial.changegroup:361(<genexpr>)
       31012            0      0.2772      0.1031      
mercurial.changegroup:362(genfilenodes)
        1686            0      0.0013      0.0013       <method 'get' of 'dict'
objects>
      405870            0     15.0286     15.0286   <method 'compress' of
'bz2.BZ2Compressor' objects>
      664271            0      8.5781      8.5781   <method 'write' of 'file'
objects>
      431324            0      7.8296      7.8296   <zlib.decompress>
       41018            0      4.6015      4.6015   <mercurial.bdiff.bdiff>
      338244            0      2.8564      2.8564   <method 'update' of
'_hashlib.HASH' objects>
      405871            0    603.5276      2.5226   mercurial.util:951(read)
      604743            0    599.8229      0.9020      
mercurial.util:938(splitbig)
     1211025            0      0.3627      0.3627       <len>
      606283            0      0.2324      0.2324       <method 'append' of
'list' objects>
      405870            0      0.2053      0.2053       <method 'join' of 'str'
objects>
      604742            0      0.2017      0.2017       <method 'append' of
'collections.deque' objects>
      169306            0     23.8471      2.4474  
mercurial.revlog:880(revision)
      357857            0      7.6280      0.6135      
mercurial.revlog:853(_chunk)
      169122            0      0.5953      0.5953      
<mercurial.mpatch.patches>
      169122            0      1.8819      0.4760      
mercurial.revlog:846(_chunkraw)
      169122            0      5.0975      0.4283      
mercurial.revlog:944(_checkhash)
      162020            0      0.4248      0.2991      
mercurial.changelog:207(flags)
      803871            0      7.6448      2.1306  
mercurial.revlog:846(_chunkraw)
      803871            0      2.2051      1.5831      
mercurial.revlog:832(_getchunk)
      803871            0      2.4746      1.3434      
mercurial.revlog:329(end)
      803871            0      0.8346      0.8346      
mercurial.revlog:327(start)
interrupted!

real    10m29.000s
user    7m44.741s
sys     2m37.094s


By contrast, here is the profile of a successful "hg bundle" run with 2.6.3:


bundling: setup.py 9933/9933 files (100.00%)
bundling: setup.py 9933/9933 files (100.00%)
   CallCount    Recursive     Total(s)    Inline(s) module:lineno(function)
      750034            0     72.8346     72.8346   <method 'compress' of
'bz2.BZ2Compressor' objects>
     1195728            0     20.3457     20.3457   <method 'write' of 'file'
objects>
      713223            0     13.8080     13.8080   <zlib.decompress>
       49570            0     11.2885     11.2885   <mercurial.bdiff.bdiff>
      233670            0      4.8232      4.8232   <method 'update' of
'_hashlib.HASH' objects>
      750018            0    101.6833      4.8060   mercurial.util:951(read)
     1100262            0     94.5480      1.7170      
mercurial.util:938(splitbig)
     2210455            0      0.6890      0.6890       <len>
      750018            0      0.4648      0.4648       <method 'join' of 'str'
objects>
     1110194            0      0.4363      0.4363       <method 'append' of
'list' objects>
     1100261            0      0.3937      0.3937       <method 'append' of
'collections.deque' objects>
     1440432            0     83.6890      3.9859  
mercurial.changegroup:234(revchunk)
      360108            0     27.1468      1.9565      
mercurial.localrepo:2168(lookup)
      350173            0     46.7079      0.9656      
mercurial.revlog:867(revdiff)
      360108            0      1.2599      0.6709      
mercurial.revlog:321(parents)
      360108            0      0.8004      0.5030      
mercurial.changegroup:254(builddeltaheader)
      360108            0      0.6690      0.4076      
mercurial.changegroup:34(chunkheader)
     1143568            0     11.2400      3.2241  
mercurial.revlog:841(_chunkraw)
     1143568            0      3.2960      2.2438      
mercurial.revlog:827(_getchunk)
     1143568            0      3.5130      1.9007      
mercurial.revlog:329(end)
     1143568            0      1.2069      1.2069      
mercurial.revlog:327(start)
      194657            0     31.9097      2.4732  
mercurial.revlog:875(revision)
      666634            0     14.6111      1.1395      
mercurial.revlog:848(_chunk)
      116835            0      1.0296      1.0296      
<mercurial.mpatch.patches>
      116835            0      1.5347      0.3567      
mercurial.revlog:841(_chunkraw)
      116835            0      6.3601      0.2993      
mercurial.revlog:939(_checkhash)
      666634            0      0.2225      0.2225       <method 'append' of
'list' objects>
           1            0    182.4890      2.4295  
mercurial.changegroup:60(writebundle)
      750034            0     72.8346     72.8346       <method 'compress' of
'bz2.BZ2Compressor' objects>
      379977            0    105.2491      0.9591      
mercurial.changegroup:24(getchunk)

real    3m15.489s
user    2m36.006s
sys     0m21.933s

-- 
You are receiving this mail because:
You are on the CC list for the bug.


More information about the Mercurial-devel mailing list