Mercurial > hg
view hgext/logtoprocess.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 | 7c0b8652fd8c |
children | 6000f5b25c9b |
line wrap: on
line source
# logtoprocess.py - send ui.log() data to a subprocess # # Copyright 2016 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. """send ui.log() data to a subprocess (EXPERIMENTAL) This extension lets you specify a shell command per ui.log() event, sending all remaining arguments to as environment variables to that command. Positional arguments construct a log message, which is passed in the `MSG1` environment variables. Each keyword argument is set as a `OPT_UPPERCASE_KEY` variable (so the key is uppercased, and prefixed with `OPT_`). The original event name is passed in the `EVENT` environment variable, and the process ID of mercurial is given in `HGPID`. So given a call `ui.log('foo', 'bar %s\n', 'baz', spam='eggs'), a script configured for the `foo` event can expect an environment with `MSG1=bar baz`, and `OPT_SPAM=eggs`. Scripts are configured in the `[logtoprocess]` section, each key an event name. For example:: [logtoprocess] commandexception = echo "$MSG1" > /var/log/mercurial_exceptions.log would log the warning message and traceback of any failed command dispatch. Scripts are run asynchronously as detached daemon processes; mercurial will not ensure that they exit cleanly. """ from __future__ import absolute_import import os from mercurial.utils import 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' class processlogger(object): """Map log events to external commands Arguments are passed on as environment variables. """ def __init__(self, ui): self._scripts = dict(ui.configitems(b'logtoprocess')) def tracked(self, event): return bool(self._scripts.get(event)) def log(self, ui, event, msg, opts): script = self._scripts[event] maxmsg = 100000 if len(msg) > maxmsg: # Each env var has a 128KiB limit on linux. msg can be long, in # particular for command event, where it's the full command line. # Prefer truncating the message than raising "Argument list too # long" error. msg = msg[:maxmsg] + b' (truncated)' env = { b'EVENT': event, b'HGPID': os.getpid(), b'MSG1': msg, } # keyword arguments get prefixed with OPT_ and uppercased env.update( (b'OPT_%s' % key.upper(), value) for key, value in opts.items() ) fullenv = procutil.shellenviron(env) procutil.runbgcommand(script, fullenv, shell=True) def uipopulate(ui): ui.setlogger(b'logtoprocess', processlogger(ui))