Mercurial > hg
view hgext/blackbox.py @ 20182:04036798ebed
branches: avoid unnecessary changectx.branch() calls
This requires reading from the changelog, which can be costly over NFS.
Note that this does not totally remove reading from the changelog; we
still do that when calling changectx.closesbranch(). That call will be
removed in a later patch.
Running hg branches on the PyPy repo (with 996) over a busy NFS server,
before this change:
$ time hg --profile branches > /dev/null
CallCount Recursive Total(s) Inline(s) module:lineno(function)
2042 0 2.2827 2.2827 <open>
2036 0 0.9840 0.9840 <method 'close' of 'file' objects>
2036 0 0.0464 0.0464 <method 'read' of 'file' objects>
5233 0 0.1985 0.0453 mercurial.repoview:161(changelog)
10462 0 0.0791 0.0314 mercurial.changelog:133(tip)
5233 0 0.0388 0.0176 mercurial.localrepo:26(__get__)
10462 0 0.0250 0.0126 <len>
5233 0 0.0059 0.0039 mercurial.repoview:112(filterrevs)
10462 0 0.0029 0.0029 <hash>
2034 0 0.0444 0.0444 <method 'seek' of 'file' objects>
5340 0 0.0390 0.0390 mercurial.revlog:296(rev)
2582 0 0.0371 0.0371 <zlib.decompress>
3155 0 0.1963 0.0366 mercurial.context:202(__init__)
3155 0 0.1238 0.0306 mercurial.repoview:161(changelog)
3155 0 0.0261 0.0080 mercurial.changelog:183(rev)
9465 0 0.0061 0.0061 <isinstance>
1096 0 0.0023 0.0023 <binascii.unhexlify>
4251 0 0.0014 0.0014 <len>
2059 0 3.7341 0.0332 mercurial.changelog:270(read)
2059 0 3.6304 0.0307 mercurial.revlog:907(revision)
2057 0 0.0262 0.0137 mercurial.changelog:28(decodeextra)
4118 0 0.0094 0.0094 <method 'split' of 'str' objects>
4118 0 0.0270 0.0048 mercurial.encoding:61(tolocal)
2059 0 0.0040 0.0040 <method 'index' of 'str' objects>
10462 0 0.0791 0.0314 mercurial.changelog:133(tip)
10462 0 0.0289 0.0207 mercurial.changelog:190(node)
10462 0 0.0188 0.0091 <len>
52433 20932 0.0478 0.0310 <len>
20932 0 0.0221 0.0168 mercurial.revlog:262(__len__)
2059 0 3.6304 0.0307 mercurial.revlog:907(revision)
real 0m4.361s
user 0m0.986s
sys 0m0.237s
After this change:
$ time hg --profile branches > /dev/null
CallCount Recursive Total(s) Inline(s) module:lineno(function)
1069 0 1.1098 1.1098 <open>
1063 0 0.4865 0.4865 <method 'close' of 'file' objects>
4122 0 0.1811 0.0404 mercurial.repoview:161(changelog)
8240 0 0.0712 0.0272 mercurial.changelog:133(tip)
4122 0 0.0378 0.0177 mercurial.localrepo:26(__get__)
8240 0 0.0221 0.0115 <len>
4122 0 0.0057 0.0033 mercurial.repoview:112(filterrevs)
8240 0 0.0025 0.0025 <hash>
3029 0 0.1979 0.0371 mercurial.context:202(__init__)
3029 0 0.1278 0.0310 mercurial.repoview:161(changelog)
3029 0 0.0230 0.0081 mercurial.changelog:183(rev)
9087 0 0.0061 0.0061 <isinstance>
1096 0 0.0026 0.0026 <binascii.unhexlify>
4125 0 0.0014 0.0014 <len>
4229 0 0.0337 0.0337 mercurial.revlog:296(rev)
1061 0 0.0296 0.0296 <method 'seek' of 'file' objects>
1063 0 0.0292 0.0292 <method 'read' of 'file' objects>
8240 0 0.0712 0.0272 mercurial.changelog:133(tip)
8240 0 0.0271 0.0196 mercurial.changelog:190(node)
8240 0 0.0169 0.0083 <len>
40476 16488 0.0422 0.0271 <len>
16488 0 0.0193 0.0152 mercurial.revlog:262(__len__)
1342 0 0.0241 0.0241 <zlib.decompress>
9445 0 0.0336 0.0224 mercurial.changelog:190(node)
9445 0 0.0112 0.0112 mercurial.revlog:317(node)
1074 0 1.9102 0.0224 mercurial.changelog:270(read)
1074 0 1.8397 0.0202 mercurial.revlog:907(revision)
1073 0 0.0187 0.0099 mercurial.changelog:28(decodeextra)
2148 0 0.0061 0.0061 <method 'split' of 'str' objects>
2148 0 0.0184 0.0034 mercurial.encoding:61(tolocal)
real 0m2.402s
user 0m0.735s
sys 0m0.177s
author | Brodie Rao <brodie@sf.io> |
---|---|
date | Fri, 15 Nov 2013 23:18:08 -0500 |
parents | 6d6f148cada9 |
children | 7cc77030c557 |
line wrap: on
line source
# blackbox.py - log repository events to a file for post-mortem debugging # # Copyright 2010 Nicolas Dumazet # Copyright 2013 Facebook, Inc. # # This software may be used and distributed according to the terms of the # GNU General Public License version 2 or any later version. """log repository events to a blackbox for debugging Logs event information to .hg/blackbox.log to help debug and diagnose problems. The events that get logged can be configured via the blackbox.track config key. Examples:: [blackbox] track = * [blackbox] track = command, commandfinish, commandexception, exthook, pythonhook [blackbox] track = incoming [blackbox] # limit the size of a log file maxsize = 1.5 MB # rotate up to N log files when the current one gets too big maxfiles = 3 """ from mercurial import util, cmdutil from mercurial.i18n import _ import errno, os, re cmdtable = {} command = cmdutil.command(cmdtable) testedwith = 'internal' lastblackbox = None def wrapui(ui): class blackboxui(ui.__class__): @util.propertycache def track(self): return self.configlist('blackbox', 'track', ['*']) def _openlogfile(self): def rotate(oldpath, newpath): try: os.unlink(newpath) except OSError, err: if err.errno != errno.ENOENT: self.debug("warning: cannot remove '%s': %s\n" % (newpath, err.strerror)) try: if newpath: os.rename(oldpath, newpath) except OSError, err: if err.errno != errno.ENOENT: self.debug("warning: cannot rename '%s' to '%s': %s\n" % (newpath, oldpath, err.strerror)) fp = self._bbopener('blackbox.log', 'a') maxsize = self.configbytes('blackbox', 'maxsize', 1048576) if maxsize > 0: st = os.fstat(fp.fileno()) if st.st_size >= maxsize: path = fp.name fp.close() maxfiles = self.configint('blackbox', 'maxfiles', 7) for i in xrange(maxfiles - 1, 1, -1): rotate(oldpath='%s.%d' % (path, i - 1), newpath='%s.%d' % (path, i)) rotate(oldpath=path, newpath=maxfiles > 0 and path + '.1') fp = self._bbopener('blackbox.log', 'a') return fp def log(self, event, *msg, **opts): global lastblackbox super(blackboxui, self).log(event, *msg, **opts) if not '*' in self.track and not event in self.track: return if util.safehasattr(self, '_blackbox'): blackbox = self._blackbox elif util.safehasattr(self, '_bbopener'): try: self._blackbox = self._openlogfile() except (IOError, OSError), err: self.debug('warning: cannot write to blackbox.log: %s\n' % err.strerror) del self._bbopener self._blackbox = None blackbox = self._blackbox else: # certain ui instances exist outside the context of # a repo, so just default to the last blackbox that # was seen. blackbox = lastblackbox if blackbox: date = util.datestr(None, '%Y/%m/%d %H:%M:%S') user = util.getuser() formattedmsg = msg[0] % msg[1:] try: blackbox.write('%s %s> %s' % (date, user, formattedmsg)) except IOError, err: self.debug('warning: cannot write to blackbox.log: %s\n' % err.strerror) lastblackbox = blackbox def setrepo(self, repo): self._bbopener = repo.opener ui.__class__ = blackboxui def uisetup(ui): wrapui(ui) def reposetup(ui, repo): # During 'hg pull' a httppeer repo is created to represent the remote repo. # It doesn't have a .hg directory to put a blackbox in, so we don't do # the blackbox setup for it. if not repo.local(): return if util.safehasattr(ui, 'setrepo'): ui.setrepo(repo) @command('^blackbox', [('l', 'limit', 10, _('the number of events to show')), ], _('hg blackbox [OPTION]...')) def blackbox(ui, repo, *revs, **opts): '''view the recent repository events ''' if not os.path.exists(repo.join('blackbox.log')): return limit = opts.get('limit') blackbox = repo.opener('blackbox.log', 'r') lines = blackbox.read().split('\n') count = 0 output = [] for line in reversed(lines): if count >= limit: break # count the commands by matching lines like: 2013/01/23 19:13:36 root> if re.match('^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} .*> .*', line): count += 1 output.append(line) ui.status('\n'.join(reversed(output)))