"hg log -q" performance (was: API question: ancestors of B that are not ancestors of A)

Greg Ward greg-hg at gerg.ca
Wed Dec 9 16:53:32 CST 2009


On Wed, Dec 9, 2009 at 5:34 PM, Matt Mackall <mpm at selenic.com> wrote:
>>   $ time hg log --follow -q -rtip:0 -P 104325
>>   104339:cf603b1018fb
>>   104336:9d06300772ae
>>   [...several hundred more...]
>>   101660:7f617f192df1
>>   hg log --follow -q -rtip:0 -P 104325  128.85s user 0.50s system 98%
>> cpu 2:11.68 total
>
> Hmm, that's odd. We can probably improve that. How long do 'hg log -q
>> /dev/null' take?

"hg log -q > /dev/null": ~47 sec, 99% cpu.
"hg log --follow -q > /dev/null": ~108 sec, 99% cpu.

So I profiled "log -q" of the last ~24000 changesets:

"""
time hg --profile log -q -r 80000:tip > /dev/null
   CallCount    Recursive    Total(ms)   Inline(ms) module:lineno(function)
       24340            0     17.5399      1.8263   mercurial.cmdutil:805(_show)
      +24340            0      4.7440      0.3199
+mercurial.templatefilters:11(stringify)
      +24340            0      0.2121      0.1857
+mercurial.templater:185(__call__)
      +97360            0      0.1663      0.1663
+mercurial.templater:172(__contains__)
      +24340            0      0.1862      0.1557   +mercurial.ui:228(write)
      +24340            0      0.1273      0.1273   +<method 'update'
of 'dict' objects>
      121700            0      3.2390      1.0202
mercurial.templater:53(process)
     +121700            0      1.9259      0.7851
+mercurial.templater:99(_process)
      +97360            0      0.1153      0.1153   +<isinstance>
      +24340            0      0.0878      0.0878   +<hasattr>
      +24340            0      0.0501      0.0501
+mercurial.templater:175(load)
      +24340            0      0.0397      0.0397   +<method 'pop' of
'list' objects>
      316426            0      1.7139      0.9783
mercurial.revlog:269(__getitem__)
     +316426            0      0.6586      0.6586   +<_struct.unpack>
         +28            0      0.0769      0.0001   +mercurial.revlog:264(load)
       24340            0      9.5049      0.8450
mercurial.changelog:160(read)
      +24340            0      6.9379      0.8438
+mercurial.revlog:971(revision)
      +48680            0      1.1508      0.2880
+mercurial.encoding:31(tolocal)
      +48680            0      0.1409      0.1409   +<method 'split'
of 'str' objects>
      +13214            0      0.2308      0.1247
+mercurial.changelog:26(decodeextra)
      +24340            0      0.0674      0.0674   +<binascii.unhexlify>
       24340            0      6.9379      0.8438
mercurial.revlog:971(revision)
      +24340            0      0.7640      0.2530
+mercurial.revlog:514(parents)
      +24340            0      0.5593      0.2439   +mercurial.revlog:50(hash)
      +24340            0      1.2927      0.1897
+mercurial.revlog:950(_chunkraw)
      +24340            0      0.8916      0.1283
+mercurial.revlog:480(_loadindex)
      +24341            0      2.0217      0.1102
+mercurial.revlog:957(_chunk)
      121700            0      1.9259      0.7851
mercurial.templater:99(_process)
      +73020            0      0.2438      0.2438   +<built-in method search>
      +24340            0      0.2622      0.1196
+mercurial.templater:102(get)
      +24340            0      0.5085      0.0942
+mercurial.templater:83(_filter)
      +48680            0      0.0686      0.0686   +<built-in method groups>
      +48680            0      0.0576      0.0576   +<built-in method span>
       48680            0      4.1351      0.6834
mercurial.util:206(increasingchunks)
     +121700            0      3.2390      1.0202
+mercurial.templater:53(process)
      +97360            0      0.0968      0.0968   +<method 'append'
of 'list' objects>
      +97360            0      0.0765      0.0765   +<len>
      +24340            0      0.0395      0.0395   +<method 'join' of
'str' objects>
      316427            0      0.6586      0.6586   <_struct.unpack>
       24338            0      0.6195      0.6195   <zlib.decompress>
       97362            0      1.1141      0.6086   mercurial.revlog:520(start)
      +97362            0      0.5056      0.3006
+mercurial.revlog:269(__getitem__)
hg --profile log -q -r 80000:tip > /dev/null  17.88s user 3.20s system
98% cpu 21.383 total
"""

This is with current hg-crew.

Greg


More information about the Mercurial-devel mailing list