view hgext/blackbox.py @ 27396:64c584070fc7

run-tests: show scheduling with --showchannels

This gives one line of output per second with one column per -j level
that allows analyzing test scheduling problems. First 24 seconds of
output at -j 30 looks like this:

  0                                                                .
  1  = = = = = = = = = = = = = = = = = = = = = = = = = = = = = =   s.
  2  c c o c r l g r s s = c p = c h c a h c g c h c b c c l l c   ss
  3  h o b o e a e u u u c o a h o e o c g o l h g h u o = a o =   s
  4  e n s n b r n n b b   m t g n l n l w n o e w e n n e r g i   .
  5  c t o = a g d - r r = m c w v p v . e v g c e c d v x g . m
  6  k r l r s e o t e e b a h e e . e . b e . k b k l e t e . p
  7  - i e e e f c e p p u n b b r . r . - r . - - - e r e f . o   .
  8  p b t v - i . s o o n d o d t . t . c t . c s = 2 t n i . r
  9  y - e s c l . t - . d - m i - . - . o - . o y r - - s l . t
 10  3 p - e h e . s s . l t b r s . s . m s . d m e f s i e . .
 11  - e c t e s . . v . e e . . v . v . m v . e r n o v o s . .
 12  c r h . c - . . n . 2 m . . n . n . a n . . e a r n n . . .
 13  o f e . k u . . . . - p . . - . - . n - . . v m m - . . . .
 14  m . c . - p . . . . e l . . s . m . d s . . . e a e . . . .
 15  p . k . r d . . . . x a . . i . o . s o . . . - t n . . . .
 16  a . h . e a . . . . c t . . n . v . . u . . . m . c . . . .
 17  t . e . s t . . . . h e . . k . e . . r . . . e . o . . . .
 18  . . a . t e . . . . a . . . . . . . . c . . . r . d . . . .
 19  . . d . o . . . . . n . . . . . . . . e . . . g . i . . . .
 20  . . s . r . . . . . g . . . . . . . . . . . . e . n . . . .
 21  . . . . e . . . . . e . . . . . . . . . . . . 2 . g . . . .
 22  . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .
 23  . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .   .
 24  . . . . . . . . . . . . . . . . . . . . . . . . . = . . . .   ^C

Test names read off vertically, beginning with '='. Idle time (not
shown) appears as blank space.

# 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 config key.
Examples::

  [blackbox]
  track = *

  [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

"""

from mercurial import util, cmdutil
from mercurial.i18n import _
import errno, os, re

cmdtable = {}
command = cmdutil.command(cmdtable)
# Note for extension authors: ONLY specify testedwith = 'internal' 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 = 'internal'
lastblackbox = None

def wrapui(ui):
    class blackboxui(ui.__class__):
        @util.propertycache
        def track(self):
            return self.configlist('blackbox', 'track', ['*'])

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

            fp = self._bbopener('blackbox.log', 'a')
            maxsize = self.configbytes('blackbox', 'maxsize', 1048576)
            if maxsize > 0:
                st = os.fstat(fp.fileno())
                if st.st_size >= maxsize:
                    path = fp.name
                    fp.close()
                    maxfiles = self.configint('blackbox', 'maxfiles', 7)
                    for i in 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')
                    fp = self._bbopener('blackbox.log', 'a')
            return fp

        def log(self, event, *msg, **opts):
            global lastblackbox
            super(blackboxui, self).log(event, *msg, **opts)

            if not '*' in self.track and not event in self.track:
                return

            if util.safehasattr(self, '_blackbox'):
                blackbox = self._blackbox
            elif util.safehasattr(self, '_bbopener'):
                try:
                    self._blackbox = self._openlogfile()
                except (IOError, OSError) as err:
                    self.debug('warning: cannot write to blackbox.log: %s\n' %
                               err.strerror)
                    del self._bbopener
                    self._blackbox = None
                blackbox = self._blackbox
            else:
                # certain ui instances exist outside the context of
                # a repo, so just default to the last blackbox that
                # was seen.
                blackbox = lastblackbox

            if blackbox:
                date = util.datestr(None, '%Y/%m/%d %H:%M:%S')
                user = util.getuser()
                pid = str(os.getpid())
                formattedmsg = msg[0] % msg[1:]
                try:
                    blackbox.write('%s %s (%s)> %s' %
                                   (date, user, pid, formattedmsg))
                except IOError as err:
                    self.debug('warning: cannot write to blackbox.log: %s\n' %
                               err.strerror)
                lastblackbox = blackbox

        def setrepo(self, repo):
            self._bbopener = repo.vfs

    ui.__class__ = blackboxui

def uisetup(ui):
    wrapui(ui)

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

    if util.safehasattr(ui, 'setrepo'):
        ui.setrepo(repo)

@command('^blackbox',
    [('l', 'limit', 10, _('the number of events to show')),
    ],
    _('hg blackbox [OPTION]...'))
def blackbox(ui, repo, *revs, **opts):
    '''view the recent repository events
    '''

    if not os.path.exists(repo.join('blackbox.log')):
        return

    limit = opts.get('limit')
    blackbox = repo.vfs('blackbox.log', 'r')
    lines = blackbox.read().split('\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('^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2} .*> .*', line):
            count += 1
        output.append(line)

    ui.status('\n'.join(reversed(output)))