[Bug 5414] New: hgweb annotate spends a lot of time in _adjustlinkrev
bugzilla at mercurial-scm.org
bugzilla at mercurial-scm.org
Fri Nov 4 19:46:07 UTC 2016
https://bz.mercurial-scm.org/show_bug.cgi?id=5414
Bug ID: 5414
Summary: hgweb annotate spends a lot of time in _adjustlinkrev
Product: Mercurial
Version: default branch
Hardware: All
OS: All
Status: UNCONFIRMED
Keywords: regression
Severity: bug
Priority: normal
Component: hgweb
Assignee: bugzilla at selenic.com
Reporter: gregory.szorc at gmail.com
CC: mercurial-devel at selenic.com
A user at Mozilla reported very slow renderings of annotate pages in hgweb.
Upon further examination, the server is spending a lot of time in
_adjustlinkrev. Here is statprof output for a page view:
| 85.4% server.py: do_hgweb line 92: self.do_hgweb()
| 85.4% hgweb_mod.py: run_wsgi line 160: for chunk in
self.server.ap...
| 85.4% __init__.py: _runwsgi line 310: for r in
self._runwsgi(req,...
| 85.6% util.py: increasingchunks line 272: for what in
super(hgwebwrap...
| 85.1% templater.py: _flatten line 849: for chunk in
source:
| 85.1% templater.py: _flatten line 1012: for j in
_flatten(i):
\ 77.7% templater.py: _flatten line 1012: for j in
_flatten(i):
| 77.7% templater.py: _flatten line 1012: for j in
_flatten(i):
| 77.7% templater.py: runmap line 1004: for i in thing:
| 77.7% webcommands.py: parents line 410: for i in diter:
| 77.7% context.py: hex line 867: "node": p.hex(),
| 77.7% util.py: __get__ line 748: return
self._changectx.hex()
| 77.7% context.py: _changectx line 770: result =
self.func(obj)
| 77.7% util.py: __get__ line 1084: return
changectx(self._repo...
| 77.7% context.py: _changeid line 770: result =
self.func(obj)
| 77.7% context.py: _adjustlinkrev line 684: self._filenode,
self._desce...
| 77.6% changelog.py: read line 848: ac = cl.read(a) #
get chang...
| 77.0% changelog.py: __new__ line 467: c =
changelogrevision(self....
| 76.0% revlog.py: _chunks line 1218: bins =
self._chunks(chain, ...
\ 39.2% revlog.py: decompress line 1153:
ladd(decompress(buffer(data...
\ 36.6% revlog.py: _chunkraw line 1142: offset, data =
self._chunkr...
| 36.4% revlog.py: _getchunk line 1104: return start,
self._getchun...
| 36.3% revlog.py: _loadchunk line 1079: return
self._loadchunk(offs...
| 26.8% store.py: __call__ line 1038: df =
self.opener(self.dataf...
| 26.8% scmutil.py: __call__ line 490: return
self.vfs(self.encode...
And lsprof showing call counts:
CallCount Recursive Total(s) Inline(s) module:lineno(function)
2763955 0 17.6032 17.6032 <zlib.decompress>
1473387 0 94.8229 7.2480
mercurial.revlog:1179(revision)
1473312 0 131.7183 6.4628
mercurial.changelog:451(read)
1473355 0 64.8692 5.6589
mercurial.revlog:1117(_chunks)
720357 0 5.7417 5.5927
mercurial.revlog:1009(_addchunk)
720390 0 5.4356 5.4356 <method 'read' of 'file'
objects>
720394 0 5.3107 5.3107 <open>
2946710 0 3.4474 3.4474 <method 'update' of
'_hashlib.HASH' objects>
1473330 0 5.9458 3.3268
mercurial.changelog:159(__new__)
720357 0 31.1398 3.2806
mercurial.revlog:1021(_loadchunk)
1473446 0 5.1924 3.2667
mercurial.changelog:226(date)
720368 0 2.7331 2.7331 <method 'close' of 'file'
objects>
5714319 0 2.6471 2.6471 mercurial.revlog:393(start)
1473336 0 5.0520 2.6042
mercurial.ancestor:299(__iter__)
3497959 0 6.1730 2.5544 <method 'decode' of 'str'
objects>
5387032 0 2.5525 2.5525 <method 'split' of 'str'
objects>
2947481 0 2.4774 2.4774 <_codecs.utf_8_decode>
125 0 140.2148 2.3813
mercurial.context:811(_adjustlinkrev)
1473355 0 2.8145 2.3654
mercurial.revlog:446(_deltachain)
5868792 0 2.2142 2.2142 <method 'index' of 'str'
objects>
720357 0 2.1344 2.1344 <method 'seek' of 'file'
objects>
1473355 0 7.4096 2.0823 mercurial.revlog:79(hash)
1473379 0 37.5823 2.0608
mercurial.revlog:1081(_chunkraw)
720370 0 10.3258 1.9492
mercurial.scmutil:520(__call__)
2767585 0 19.3675 1.7643
mercurial.revlog:100(decompress)
1473379 0 32.9512 1.6613
mercurial.revlog:1057(_getchunk)
1474067 0 1.6273 1.6273 mercurial.revlog:360(rev)
1473355 0 1.5244 1.5244 <mercurial.mpatch.patches>
1473402 0 3.1243 1.5031
mercurial.changelog:333(rev)
1473665 0 4.5666 1.5007
mercurial.revlog:387(parents)
We're loading 1,473,312 changelog revisions on a repository that only has
340,903 changesets. So there's some redundant work there.
STR:
$ hg clone -U --uncompressed https://hg.mozilla.org/releases/mozilla-aurora
$ cd mozilla-aurora
$ hg serve
$ curl
http://localhost:8000/annotate/96ca0ecdcfa/browser/locales/en-US/chrome/browser/downloads/downloads.dtd
This repository does not have obsolescence markers.
This is a regression in 3.9, presumably due to the hgweb annotate improvements
querying more changeset data.
3.8.2: ~10s wall time
3.9.2: ~98s wall time
--
You are receiving this mail because:
You are on the CC list for the bug.
More information about the Mercurial-devel
mailing list