view mercurial/loggingutil.py @ 44118:f81c17ec303c

hgdemandimport: apply lazy module loading to sys.meta_path finders Python's `sys.meta_path` finders are the primary objects whose job it is to find a module at import time. When `import` is called, Python iterates objects in this list and calls `o.find_spec(...)` to find a `ModuleSpec` (or None if the module couldn't be found by that finder). If no meta path finder can find a module, import fails. One of the default meta path finders is `PathFinder`. Its job is to import modules from the filesystem and is probably the most important importer. This finder looks at `sys.path` and `sys.path_hooks` to do its job. The `ModuleSpec` returned by `MetaPathImporter.find_spec()` has a `loader` attribute, which defines the concrete module loader to use. `sys.path_hooks` is a hook point for teaching `PathFinder` to instantiate custom loader types. Previously, we injected a custom `sys.path_hook` that told `PathFinder` to wrap the default loaders with a loader that creates a module object that is lazy. This approach worked. But its main limitation was that it only applied to the `PathFinder` meta path importer. There are other meta path importers that are registered. And in the case of PyOxidizer loading modules from memory, `PathFinder` doesn't come into play since PyOxidizer's own meta path importer was handling all imports. This commit changes our approach to lazy module loading by proxying all meta path importers. Specifically, we overload the `find_spec()` method to swap in a wrapped loader on the `ModuleSpec` before it is returned. The end result of this is all meta path importers should be lazy. As much as I would have loved to utilize .__class__ manipulation to achieve this, some meta path importers are implemented in C/Rust in such a way that they cannot be monkeypatched. This is why we use __getattribute__ to define a proxy. Also, this change could theoretically open us up to regressions in meta path importers whose loader is creating module objects which can't be monkeypatched. But I'm not aware of any of these in the wild. So I think we'll be safe. According to hyperfine, this change yields a decent startup time win of 5-6ms: ``` Benchmark #1: ~/.pyenv/versions/3.6.10/bin/python ./hg version Time (mean ? ?): 86.8 ms ? 0.5 ms [User: 78.0 ms, System: 8.7 ms] Range (min ? max): 86.0 ms ? 89.1 ms 50 runs Time (mean ? ?): 81.1 ms ? 2.7 ms [User: 74.5 ms, System: 6.5 ms] Range (min ? max): 77.8 ms ? 90.5 ms 50 runs Benchmark #2: ~/.pyenv/versions/3.7.6/bin/python ./hg version Time (mean ? ?): 78.9 ms ? 0.6 ms [User: 70.2 ms, System: 8.7 ms] Range (min ? max): 78.1 ms ? 81.2 ms 50 runs Time (mean ? ?): 73.4 ms ? 0.6 ms [User: 65.3 ms, System: 8.0 ms] Range (min ? max): 72.4 ms ? 75.7 ms 50 runs Benchmark #3: ~/.pyenv/versions/3.8.1/bin/python ./hg version Time (mean ? ?): 78.1 ms ? 0.6 ms [User: 70.2 ms, System: 7.9 ms] Range (min ? max): 77.4 ms ? 80.9 ms 50 runs Time (mean ? ?): 72.1 ms ? 0.4 ms [User: 64.4 ms, System: 7.6 ms] Range (min ? max): 71.4 ms ? 74.1 ms 50 runs ``` Differential Revision: https://phab.mercurial-scm.org/D7954
author Gregory Szorc <gregory.szorc@gmail.com>
date Mon, 20 Jan 2020 23:51:25 -0800
parents 687b865b95ad
children 4a6024b87dfc
line wrap: on
line source

# loggingutil.py - utility for logging events
#
# 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.

from __future__ import absolute_import

import errno

from . import pycompat

from .utils import (
    dateutil,
    procutil,
    stringutil,
)


def openlogfile(ui, vfs, name, maxfiles=0, maxsize=0):
    """Open log file in append mode, with optional rotation

    If maxsize > 0, the log file will be rotated up to maxfiles.
    """

    def rotate(oldpath, newpath):
        try:
            vfs.unlink(newpath)
        except OSError as err:
            if err.errno != errno.ENOENT:
                ui.debug(
                    b"warning: cannot remove '%s': %s\n"
                    % (newpath, err.strerror)
                )
        try:
            if newpath:
                vfs.rename(oldpath, newpath)
        except OSError as err:
            if err.errno != errno.ENOENT:
                ui.debug(
                    b"warning: cannot rename '%s' to '%s': %s\n"
                    % (newpath, oldpath, err.strerror)
                )

    if maxsize > 0:
        try:
            st = vfs.stat(name)
        except OSError:
            pass
        else:
            if st.st_size >= maxsize:
                path = vfs.join(name)
                for i in pycompat.xrange(maxfiles - 1, 1, -1):
                    rotate(
                        oldpath=b'%s.%d' % (path, i - 1),
                        newpath=b'%s.%d' % (path, i),
                    )
                rotate(oldpath=path, newpath=maxfiles > 0 and path + b'.1')
    return vfs(name, b'a', makeparentdirs=False)


def _formatlogline(msg):
    date = dateutil.datestr(format=b'%Y/%m/%d %H:%M:%S')
    pid = procutil.getpid()
    return b'%s (%d)> %s' % (date, pid, msg)


def _matchevent(event, tracked):
    return b'*' in tracked or event in tracked


class filelogger(object):
    """Basic logger backed by physical file with optional rotation"""

    def __init__(self, vfs, name, tracked, maxfiles=0, maxsize=0):
        self._vfs = vfs
        self._name = name
        self._trackedevents = set(tracked)
        self._maxfiles = maxfiles
        self._maxsize = maxsize

    def tracked(self, event):
        return _matchevent(event, self._trackedevents)

    def log(self, ui, event, msg, opts):
        line = _formatlogline(msg)
        try:
            with openlogfile(
                ui,
                self._vfs,
                self._name,
                maxfiles=self._maxfiles,
                maxsize=self._maxsize,
            ) as fp:
                fp.write(line)
        except IOError as err:
            ui.debug(
                b'cannot write to %s: %s\n'
                % (self._name, stringutil.forcebytestr(err))
            )


class fileobjectlogger(object):
    """Basic logger backed by file-like object"""

    def __init__(self, fp, tracked):
        self._fp = fp
        self._trackedevents = set(tracked)

    def tracked(self, event):
        return _matchevent(event, self._trackedevents)

    def log(self, ui, event, msg, opts):
        line = _formatlogline(msg)
        try:
            self._fp.write(line)
            self._fp.flush()
        except IOError as err:
            ui.debug(
                b'cannot write to %s: %s\n'
                % (
                    stringutil.forcebytestr(self._fp.name),
                    stringutil.forcebytestr(err),
                )
            )


class proxylogger(object):
    """Forward log events to another logger to be set later"""

    def __init__(self):
        self.logger = None

    def tracked(self, event):
        return self.logger is not None and self.logger.tracked(event)

    def log(self, ui, event, msg, opts):
        assert self.logger is not None
        self.logger.log(ui, event, msg, opts)