Rollback performance

Greg Ward greg-hg at gerg.ca
Fri Nov 13 08:43:55 CST 2009


I'm debugging a 'changegroup' hook right now, so am repeatedly running
'hg rollback' to undo a push in a large repository.  And it's slow!  I
wondered why, so I profiled it:

"""
$ hg --time --profile rollback
rolling back last transaction
   CallCount    Recursive    Total(ms)   Inline(ms) module:lineno(function)
     2036992            0      9.7273      5.5561
mercurial.revlog:269(__getitem__)
    +2036992            0      3.8905      3.8905   +<_struct.unpack>
        +104            0      0.2807      0.0004   +mercurial.revlog:264(load)
     2036996            0      3.8905      3.8905   <_struct.unpack>
      103723            0     37.5915      3.4224
mercurial.changelog:160(read)
     +103723            0     27.6585      3.3420
+mercurial.revlog:971(revision)
     +207446            0      4.3977      1.1590
+mercurial.encoding:31(tolocal)
     +207446            0      0.5310      0.5310   +<method 'split'
of 'str' objects>
      +46702            0      0.7626      0.4149
+mercurial.changelog:26(decodeextra)
     +103723            0      0.2798      0.2798   +<binascii.unhexlify>
      103725            0     27.8392      3.3444
mercurial.revlog:971(revision)
     +103725            0      3.0635      1.0668
+mercurial.revlog:514(parents)
     +103725            0      1.9794      0.8658   +mercurial.revlog:50(hash)
     +103725            0      5.3183      0.7780
+mercurial.revlog:950(_chunkraw)
     +103725            0      3.4861      0.5235
+mercurial.revlog:480(_loadindex)
     +104882            0      8.3518      0.4530
+mercurial.revlog:957(_chunk)
      996546            0      4.6497      3.0472   mercurial.revlog:505(rev)
     +996543            0      1.6025      1.6024
+mercurial.revlog:303(__getitem__)
      297652            0      8.3092      2.9059
mercurial.revlog:514(parents)
     +892953            0      3.9462      2.3602
+mercurial.revlog:269(__getitem__)
     +297652            0      1.4571      0.9843   +mercurial.revlog:505(rev)
      417216            0      4.6799      2.5365   mercurial.revlog:520(start)
     +417212            0      2.1434      1.2303
+mercurial.revlog:269(__getitem__)
      104748            0      2.4978      2.4978   <zlib.decompress>
         102            0      9.9636      2.3932
mercurial.revlog:558(reachable)
     +193927            0      5.2457      1.8391
+mercurial.revlog:514(parents)
     +387956            0      1.7210      1.1080   +mercurial.revlog:505(rev)
     +194029            0      0.3086      0.3086   +<method 'pop' of
'list' objects>
     +193927            0      0.1614      0.1614   +<method 'add' of
'set' objects>
     +193927            0      0.1337      0.1337   +<method 'append'
of 'list' objects>
           1            0     58.2553      2.0313
mercurial.localrepo:396(_updatebranchcache)
        +102            0      9.9636      2.3932
+mercurial.revlog:558(reachable)
     +207121            0      6.3517      0.9269
+mercurial.localrepo:126(__getitem__)
     +103511            0     39.4204      0.5696
+mercurial.context:101(branch)
     +103613            0      0.1283      0.1283   +mercurial.context:95(node)
     +103508            0      0.0991      0.0991   +mercurial.context:94(rev)
Time: real 60.310 secs (user 49.780+0.000 sys 10.500+0.000)
"""

Huh?  I thought rollback just had to read .hg/store/undo and then
truncate the files listed there.  What's going on?

The repo in question has 103515 changesets before rollback (103510
after), so I'm guessing a lot of the call counts up there are related
to that.

This is with current hg-crew (a033929bd34e).

Greg


More information about the Mercurial-devel mailing list