large crew slow-down some time after rev 1a4330e30017
Giorgos Keramidas
keramida at ceid.upatras.gr
Tue Jan 18 01:06:41 UTC 2011
I noticed a *very* large loss in performance of common commands,
e.g. "hg incoming" and "hg heads" some time after rev 1a4330e30017.
Running a snapshot built from crew at rev 1a4330e30017 (faster), shows
the following output for a repository of 157946 revisions, 45966 files
and a changelog/manifest of around 40 MB:
$ ls -l .hg/store
...
-rw-rw-r-- 1 keramida users - 46608073 18 Ιαν 01:47 00changelog.d
-rw-rw-r-- 1 keramida users - 10108608 18 Ιαν 01:47 00changelog.i
-rw-rw-r-- 1 keramida users - 35634405 18 Ιαν 01:47 00manifest.d
-rw-rw-r-- 1 keramida users - 10108608 18 Ιαν 01:47 00manifest.i
crew at rev 1a4330e30017 (faster)
=================================
> hg --profile heads
# Profiling info sorted by decreasing Total(ms).
CallCount Recursive Total(ms) Inline(ms) module:lineno(function)
2 0 5.7828 1.6217 mercurial.revlog:823(heads)
387206 0 5.0238 3.0632 mercurial.revlog:280(__getitem__)
+315894 0 4.1599 2.5025 +mercurial.revlog:280(__getitem__)
76 0 3.3080 0.2597 mercurial.revlog:1042(revision)
+17594 0 2.5566 0.2089 +mercurial.revlog:1021(_chunk)
17594 0 2.5566 0.2089 mercurial.revlog:1021(_chunk)
17668 0 1.8865 0.2851 mercurial.revlog:1014(_chunkraw)
+17594 0 1.8337 0.2839 +mercurial.revlog:1014(_chunkraw)
387208 0 1.5692 1.5692 <_struct.unpack>
+387206 0 1.5692 1.5692 +<_struct.unpack>
+17668 0 0.9391 0.2085 +mercurial.revlog:545(end)
17668 0 0.9391 0.2085 mercurial.revlog:545(end)
35336 0 0.7521 0.3255 mercurial.revlog:543(start)
+17594 0 0.5141 0.1022 +mercurial.revlog:111(decompress)
+35336 0 0.4266 0.2783 +mercurial.revlog:280(__getitem__)
231 0 0.4206 0.3979 mercurial.revlog:175(loadblock)
7249 0 0.4119 0.4119 <zlib.decompress>
+157 0 0.3913 0.0015 +mercurial.revlog:275(load)
+17668 0 0.3794 0.1656 +mercurial.revlog:543(start)
+17668 0 0.3727 0.1598 +mercurial.revlog:543(start)
+17668 0 0.3578 0.1469 +mercurial.revlog:547(length)
+17668 0 0.2829 0.1742 +mercurial.revlog:1000(_getchunk)
+17635 0 0.2114 0.1388 +mercurial.revlog:280(__getitem__)
+74 0 0.0879 0.0879 +<mercurial.mpatch.patches>
+17561 0 0.0649 0.0649 +<method 'append' of 'list' objects>
+74 0 0.0528 0.0012 +mercurial.revlog:1014(_chunkraw)
+231 0 0.0186 0.0186 +<method 'read' of 'file' objects>
+231 0 0.0023 0.0023 +<method 'seek' of 'file' objects>
+462 0 0.0017 0.0017 +<len>
+2 0 0.0010 0.0005 +mercurial.revlog:533(node)
+2 0 0.0001 0.0000 +<len>
+2 0 0.0000 0.0000 +<max>
crew at rev 57d433f632b7 (much much slower)
===========================================
> hg --profile heads
# The python process running for 2 min 41 sec at 100% CPU
PID USERNAME THR PRI NICE SIZE RES STATE TIME WCPU COMMAND
1261 keramida 1 103 0 44664K 38140K RUN 2:42 100.00% python
# Interrupted by ^C at terminal. I got bored after about 3.5 minutes,
# and I stopped the Python process.
# Profiling info sorted by decreasing Total(ms).
CallCount Recursive Total(ms) Inline(ms) module:lineno(function)
4044 0 214.4924 0.4700 mercurial.changelog:160(read)
+4044 0 213.0908 3.0944 +mercurial.revlog:825(revision)
4044 0 213.0908 3.0944 mercurial.revlog:825(revision)
8088 0 203.6850 203.6538 mercurial.revlog:304(rev)
+4044 0 106.1006 0.7968 +mercurial.revlog:879(_checkhash)
4044 0 106.1006 0.7968 mercurial.revlog:879(_checkhash)
+4044 0 104.0241 2.1288 +mercurial.revlog:316(parents)
4044 0 104.0241 2.1288 mercurial.revlog:316(parents)
+4044 0 101.8952 101.8795 +mercurial.revlog:304(rev)
+4044 0 101.7898 101.7743 +mercurial.revlog:304(rev)
+4043 0 1.2798 0.7240 +mercurial.revlog:59(hash)
4043 0 1.2798 0.7240 mercurial.revlog:59(hash)
12130 0 0.8709 0.2495 mercurial.encoding:61(tolocal)
+4044 0 0.7577 0.7577 +mercurial.revlog:328(base)
4044 0 0.7577 0.7577 mercurial.revlog:328(base)
+8086 0 0.6227 0.1755 +mercurial.encoding:61(tolocal)
+4044 0 0.4240 0.1308 +mercurial.revlog:797(_chunkraw)
+12130 0 0.3649 0.1428 +<method 'decode' of 'str' objects>
+4043 0 0.2823 0.2823 +<method 'copy' of '_hashlib.HASH' objects>
4043 0 0.2823 0.2823 <method 'copy' of '_hashlib.HASH' objects>
+4044 0 0.2453 0.2453 +mercurial.revlog:330(flags)
4044 0 0.2453 0.2453 mercurial.revlog:330(flags)
+8086 0 0.2095 0.2095 +<method 'update' of '_hashlib.HASH' objects>
+12130 0 0.1760 0.1095 +mercurial.encoding:54(__new__)
+4043 0 0.1618 0.0888 +mercurial.changelog:26(decodeextra)
+12130 0 0.0806 0.0806 +<method 'encode' of 'unicode' objects>
+4043 0 0.0639 0.0639 +<method 'digest' of '_hashlib.HASH' objects>
+8086 0 0.0534 0.0534 +<method 'split' of 'str' objects>
+8088 0 0.0313 0.0313 +<len>
+4043 0 0.0284 0.0284 +<method 'index' of 'str' objects>
interrupted!
216.248 real 140.295 user 68.489 sys
More information about the Mercurial-devel
mailing list