Mercurial > hg
view hgext/blackbox.py @ 46018:8b0a3ff5ed12
statprof: separate functions and "line", assume 4 digit line numbers
Previously, the profile output looked like this (I've removed many lines that
are mostly inconsequential):
```
| 100.0% 0.02s hg: <module> line 43: dispatch.run()
| 100.0% 0.02s dispatch.py: run line 115: status = dispatch(req)
| 100.0% 0.02s dispatch.py: _runcatchfunc line 432: return _dispatch(req)
\ 50.0% 0.01s dispatch.py: _dispatch line 1228: return runcommand(
| 50.0% 0.01s dispatch.py: runcommand line 883: ret = _runcommand(ui, optio...
| 50.0% 0.01s dispatch.py: _runcommand line 1240: return cmdfunc()
| 50.0% 0.01s localrepo.py: __getitem__ line 1670: quick_access = self._quick_...
| 50.0% 0.01s localrepo.py: _quick_access_changeidline 1650: return self._quick_access_c...
| 50.0% 0.01s localrepo.py: __get__ line 179: return getattr(unfi, self.n...
| 50.0% 0.01s util.py: __get__ line 1747: result = self.func(obj)
| 50.0% 0.01s localrepo.py: _quick_access_changeid_wcline 1611: cl = self.unfiltered().chan...
| 50.0% 0.01s localrepo.py: __get__ line 110: return super(_basefilecache...
| 50.0% 0.01s util.py: __getattribute__line 245: self.__spec__.loader.exec_m...
| 50.0% 0.01s <frozen importlib._bootstrap_external>: exec_moduleline 783:
| 50.0% 0.01s <frozen importlib._bootstrap>: _call_with_frames_removedline 219:
| 50.0% 0.01s changelog.py: <module> line 376: class changelog(revlog.revl...
| 50.0% 0.01s util.py: __getattribute__line 245: self.__spec__.loader.exec_m...
| 50.0% 0.01s <frozen importlib._bootstrap_external>: exec_moduleline 779:
| 50.0% 0.01s <frozen importlib._bootstrap_external>: get_codeline 868:
| 50.0% 0.01s <frozen importlib._bootstrap_external>: path_statsline 1012:
| 50.0% 0.01s <frozen importlib._bootstrap_external>: _path_statline 87:
```
This has a few problems, though I'm only addressing some of them.
1. If the stuff before "line ###" is long, there's no separation between the
function name and the "line" string.
2. If the stuff before "line ###" is really long, there's excessive separation
between the "line" string and the line number.
3. We frequently have 4-digit line numbers, the code on the right wasn't
dynamically indented and ended up quite messy looking.
To solve these problems, I've added a ", " prefix before "line" iff it would
otherwise not have any separation such as spaces. I've added a 'max' so that we
never use a negative width (which is the cause of problem #2 above), and I've
added a default assumption of 4 digit line numbers (but again using a 'max' so
this shouldn't cause problems if we go beyond that.
With these changes, it now looks like this:
```
| 100.0% 0.02s hg: <module> line 43: dispatch.run()
| 100.0% 0.02s dispatch.py: run line 115: status = dispatch(req)
| 100.0% 0.02s dispatch.py: _runcatchfunc line 432: return _dispatch(req)
\ 50.0% 0.01s dispatch.py: _dispatch line 1228: return runcommand(
| 50.0% 0.01s dispatch.py: runcommand line 883: ret = _runcommand(ui, optio...
| 50.0% 0.01s dispatch.py: _runcommand line 1240: return cmdfunc()
| 50.0% 0.01s localrepo.py: __getitem__ line 1670: quick_access = self._quick_...
| 50.0% 0.01s localrepo.py: _quick_access_changeid, line 1650: return self._quick_access_c...
| 50.0% 0.01s localrepo.py: __get__ line 179: return getattr(unfi, self.n...
| 50.0% 0.01s util.py: __get__ line 1747: result = self.func(obj)
| 50.0% 0.01s localrepo.py: _quick_access_changeid_wc, line 1611: cl = self.unfiltered().chan...
| 50.0% 0.01s localrepo.py: __get__ line 110: return super(_basefilecache...
| 50.0% 0.01s util.py: __getattribute__, line 245: self.__spec__.loader.exec_m...
| 50.0% 0.01s <frozen importlib._bootstrap_external>: exec_module, line 783:
| 50.0% 0.01s <frozen importlib._bootstrap>: _call_with_frames_removed, line 219:
| 50.0% 0.01s changelog.py: <module> line 376: class changelog(revlog.revl...
| 50.0% 0.01s util.py: __getattribute__, line 245: self.__spec__.loader.exec_m...
| 50.0% 0.01s <frozen importlib._bootstrap_external>: exec_module, line 779:
| 50.0% 0.01s <frozen importlib._bootstrap_external>: get_code, line 868:
| 50.0% 0.01s <frozen importlib._bootstrap_external>: path_stats, line 1012:
| 50.0% 0.01s <frozen importlib._bootstrap_external>: _path_stat, line 87:
```
Differential Revision: https://phab.mercurial-scm.org/D9511
author | Kyle Lippincott <spectral@google.com> |
---|---|
date | Wed, 02 Dec 2020 12:33:51 -0800 |
parents | 89a2afe31e82 |
children | 36f3a64846c8 |
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 and blackbox.ignore config keys. Examples:: [blackbox] track = * ignore = pythonhook # dirty is *EXPENSIVE* (slow); # each log entry indicates `+` if the repository is dirty, like :hg:`id`. dirty = True # record the source of log messages logsource = True [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 [blackbox] # Include nanoseconds in log entries with %f (see Python function # datetime.datetime.strftime) date-format = '%Y-%m-%d @ %H:%M:%S.%f' """ from __future__ import absolute_import import re from mercurial.i18n import _ from mercurial.node import hex from mercurial import ( encoding, loggingutil, registrar, ) from mercurial.utils import ( dateutil, procutil, ) # Note for extension authors: ONLY specify testedwith = 'ships-with-hg-core' for # extensions which SHIP WITH MERCURIAL. Non-mainline extensions should # be specifying the version(s) of Mercurial they are tested with, or # leave the attribute unspecified. testedwith = b'ships-with-hg-core' cmdtable = {} command = registrar.command(cmdtable) configtable = {} configitem = registrar.configitem(configtable) configitem( b'blackbox', b'dirty', default=False, ) configitem( b'blackbox', b'maxsize', default=b'1 MB', ) configitem( b'blackbox', b'logsource', default=False, ) configitem( b'blackbox', b'maxfiles', default=7, ) configitem( b'blackbox', b'track', default=lambda: [b'*'], ) configitem( b'blackbox', b'ignore', default=lambda: [b'chgserver', b'cmdserver', b'extension'], ) configitem( b'blackbox', b'date-format', default=b'%Y/%m/%d %H:%M:%S', ) _lastlogger = loggingutil.proxylogger() class blackboxlogger(object): def __init__(self, ui, repo): self._repo = repo self._trackedevents = set(ui.configlist(b'blackbox', b'track')) self._ignoredevents = set(ui.configlist(b'blackbox', b'ignore')) self._maxfiles = ui.configint(b'blackbox', b'maxfiles') self._maxsize = ui.configbytes(b'blackbox', b'maxsize') self._inlog = False def tracked(self, event): return ( b'*' in self._trackedevents and event not in self._ignoredevents ) or event in self._trackedevents def log(self, ui, event, msg, opts): # self._log() -> ctx.dirty() may create new subrepo instance, which # ui is derived from baseui. So the recursion guard in ui.log() # doesn't work as it's local to the ui instance. if self._inlog: return self._inlog = True try: self._log(ui, event, msg, opts) finally: self._inlog = False def _log(self, ui, event, msg, opts): default = ui.configdate(b'devel', b'default-date') date = dateutil.datestr(default, ui.config(b'blackbox', b'date-format')) user = procutil.getuser() pid = b'%d' % procutil.getpid() changed = b'' ctx = self._repo[None] parents = ctx.parents() rev = b'+'.join([hex(p.node()) for p in parents]) if ui.configbool(b'blackbox', b'dirty') and ctx.dirty( missing=True, merge=False, branch=False ): changed = b'+' if ui.configbool(b'blackbox', b'logsource'): src = b' [%s]' % event else: src = b'' try: fmt = b'%s %s @%s%s (%s)%s> %s' args = (date, user, rev, changed, pid, src, msg) with loggingutil.openlogfile( ui, self._repo.vfs, name=b'blackbox.log', maxfiles=self._maxfiles, maxsize=self._maxsize, ) as fp: fp.write(fmt % args) except (IOError, OSError) as err: # deactivate this to avoid failed logging again self._trackedevents.clear() ui.debug( b'warning: cannot write to blackbox.log: %s\n' % encoding.strtolocal(err.strerror) ) return _lastlogger.logger = self def uipopulate(ui): ui.setlogger(b'blackbox', _lastlogger) 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 # Since blackbox.log is stored in the repo directory, the logger should be # instantiated per repository. logger = blackboxlogger(ui, repo) ui.setlogger(b'blackbox', logger) # Set _lastlogger even if ui.log is not called. This gives blackbox a # fallback place to log if _lastlogger.logger is None: _lastlogger.logger = logger repo._wlockfreeprefix.add(b'blackbox.log') @command( b'blackbox', [ (b'l', b'limit', 10, _(b'the number of events to show')), ], _(b'hg blackbox [OPTION]...'), helpcategory=command.CATEGORY_MAINTENANCE, helpbasic=True, ) def blackbox(ui, repo, *revs, **opts): """view the recent repository events""" if not repo.vfs.exists(b'blackbox.log'): return limit = opts.get('limit') fp = repo.vfs(b'blackbox.log', b'r') lines = fp.read().split(b'\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(br'^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} .*> .*', line): count += 1 output.append(line) ui.status(b'\n'.join(reversed(output)))