view mercurial/loggingutil.py @ 41063:6603de284b0a

progress: avoid ui.configbool() lookup when progress bar is active

Profiling revealed that the ui.configbool('progress', 'debug') during
progress bar updates was consuming a significant amount of overhead.

This commit adds an attribute on progress bar instances that caches
this config option.

The impact on `hg perfprogress` with default options is significant:

before: ! wall 4.641942 comb 4.580000 user 4.210000 sys 0.370000 (best of 3)
after:  ! wall 1.948626 comb 1.950000 user 1.950000 sys 0.000000 (best of 5)

After this change, profiling reveals that progress.progbar.progress()
is now consuming ~73% of time.

This change does not improve the execution time if the progress bar
is disabled. We may want a more comprehensive solution for that case,
as the progress bar won't be enabled in a number of scenarios (e.g.
servers and processes not attached to an interactive TTY).

I also think that overhead of ~2.0s for 1M updates is a bit high.
I suspect further refactoring of the progress bar can significantly
reduce overhead. I don't have plans to do this, however.

Differential Revision: https://phab.mercurial-scm.org/D5408

# 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("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("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='%s.%d' % (path, i - 1),
                           newpath='%s.%d' % (path, i))
                rotate(oldpath=path,
                       newpath=maxfiles > 0 and path + '.1')
    return vfs(name, '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)