contrib/hgperf

merge: change debug logging - test output changes but no real changes

Preparing for action list split-up, making sure the final change don't have any
test changes.

The patch moves debug statements around without really changing anything.
Arguably, it temporarily makes the code worse. The only justification is that
it makes it easier to review the test changes ... and in the end the big change
will not change test output at all.

The changes to test output are due to changes in the ordering of debug output.
That is mainly because we now do the debug logging for files when we actually
process them. Files are also processed in a slightly different but still
correct order. It is now primarily ordered by action type, secondarily by
filename.

The patch introduces some redundancy. Some of it will be removed again, some of
it will in the end help code readability and efficiency. It is possible that we
later on could introduce a "process this action list and do some logging and
progress reporting and apply this function".

The "preserving X for resolve" debug statements will only have single space
indentation. It will no longer have a leading single space indented "f: msg ->
m" message. Having this message double indented would thus no longer make
sense.

The bid actions will temporarily be sorted using a custom sort key that happens
to match the sort order the simplified code will have in the end.

#!/usr/bin/env python
#
# hgperf - measure performance of Mercurial commands
#
# Copyright 2014 Matt Mackall <[e-mail]>
#
# This software may be used and distributed according to the terms of the
# GNU General Public License version 2 or any later version.

'''measure performance of Mercurial commands

Using ``hgperf`` instead of ``hg`` measures performance of the target
Mercurial command. For example, the execution below measures
performance of :hg:`heads --topo`::

    $ hgperf heads --topo

All command output via ``ui`` is suppressed, and just measurement
result is displayed: see also "perf" extension in "contrib".

Costs of processing before dispatching to the command function like
below are not measured::

    - parsing command line (e.g. option validity check)
    - reading configuration files in

But ``pre-`` and ``post-`` hook invocation for the target command is
measured, even though these are invoked before or after dispatching to
the command function, because these may be required to repeat
execution of the target command correctly.
'''

import os
import sys

libdir = '@LIBDIR@'

if libdir != '@' 'LIBDIR' '@':
    if not os.path.isabs(libdir):
        libdir = os.path.join(os.path.dirname(os.path.realpath(__file__)),
                              libdir)
        libdir = os.path.abspath(libdir)
    sys.path.insert(0, libdir)

# enable importing on demand to reduce startup time
try:
    from mercurial import demandimport; demandimport.enable()
except ImportError:
    import sys
    sys.stderr.write("abort: couldn't find mercurial libraries in [%s]\n" %
                     ' '.join(sys.path))
    sys.stderr.write("(check your install and PYTHONPATH)\n")
    sys.exit(-1)

import mercurial.util
import mercurial.dispatch

import time

def timer(func, title=None):
    results = []
    begin = time.time()
    count = 0
    while True:
        ostart = os.times()
        cstart = time.time()
        r = func()
        cstop = time.time()
        ostop = os.times()
        count += 1
        a, b = ostart, ostop
        results.append((cstop - cstart, b[0] - a[0], b[1]-a[1]))
        if cstop - begin > 3 and count >= 100:
            break
        if cstop - begin > 10 and count >= 3:
            break
    if title:
        sys.stderr.write("! %s\n" % title)
    if r:
        sys.stderr.write("! result: %s\n" % r)
    m = min(results)
    sys.stderr.write("! wall %f comb %f user %f sys %f (best of %d)\n"
                     % (m[0], m[1] + m[2], m[1], m[2], count))

orgruncommand = mercurial.dispatch.runcommand

def runcommand(lui, repo, cmd, fullargs, ui, options, d, cmdpats, cmdoptions):
    ui.pushbuffer()
    lui.pushbuffer()
    timer(lambda : orgruncommand(lui, repo, cmd, fullargs, ui,
                                 options, d, cmdpats, cmdoptions))
    ui.popbuffer()
    lui.popbuffer()

mercurial.dispatch.runcommand = runcommand

for fp in (sys.stdin, sys.stdout, sys.stderr):
    mercurial.util.setbinary(fp)

mercurial.dispatch.run()