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))