changeset 23171:8afae1d5d108

perf: use a formatter for output

We use a `formatter` object in the perf extensions. This allow the use of
formatted output like json. To avoid adding logic to create a formatter and pass
it around to the timer function in every command, we add a `gettimer` function
in charge of returning a `timer` function as simple as before but embedding an
appropriate formatter.

This new `gettimer` function also return the formatter as it needs to be
explicitly closed at the end of the command.

example output:


  $ hg --config ui.formatjson=True perfvolatilesets visible obsolete
  [
   {
    "comb": 0.02,
    "count": 126,
    "sys": 0.0,
    "title": "obsolete",
    "user": 0.02,
    "wall": 0.0199398994446
   },
   {
    "comb": 0.02,
    "count": 117,
    "sys": 0.0,
    "title": "visible",
    "user": 0.02,
    "wall": 0.0250301361084
   }
  ]

--- a/contrib/perf.py	Wed Sep 24 21:33:12 2014 -0700
+++ b/contrib/perf.py	Tue Nov 04 10:40:06 2014 +0000
@@ -4,11 +4,26 @@
 from mercurial import cmdutil, scmutil, util, commands, obsolete
 from mercurial import repoview, branchmap, merge, copies
 import time, os, sys
+import functools
 
 cmdtable = {}
 command = cmdutil.command(cmdtable)
 
-def timer(func, title=None):
+def gettimer(ui, opts=None):
+    """return a timer function and formatter: (timer, formatter)
+
+    This functions exist to gather the creation of formatter in a single
+    place instead of duplicating it in all performance command."""
+    if opts is None:
+        opts = {}
+    # redirect all to stderr
+    ui = ui.copy()
+    ui.fout = ui.ferr
+    # get a formatter
+    fm = ui.formatter('perf', opts)
+    return functools.partial(_timer, fm), fm
+
+def _timer(fm, func, title=None):
     results = []
     begin = time.time()
     count = 0
@@ -25,16 +40,25 @@
             break
         if cstop - begin > 10 and count >= 3:
             break
+
+    fm.startitem()
+
     if title:
-        sys.stderr.write("! %s\n" % title)
+        fm.write('title', '! %s\n', title)
     if r:
-        sys.stderr.write("! result: %s\n" % r)
+        fm.write('result', '! 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))
+    fm.plain('!')
+    fm.write('wall', ' wall %f', m[0])
+    fm.write('comb', ' comb %f', m[1] + m[2])
+    fm.write('user', ' user %f', m[1])
+    fm.write('sys',  ' sys %f', m[2])
+    fm.write('count',  ' (best of %d)', count)
+    fm.plain('\n')
 
 @command('perfwalk')
 def perfwalk(ui, repo, *pats):
+    timer, fm = gettimer(ui)
     try:
         m = scmutil.match(repo[None], pats, {})
         timer(lambda: len(list(repo.dirstate.walk(m, [], True, False))))
@@ -44,11 +68,14 @@
             timer(lambda: len([b for a, b, c in repo.dirstate.statwalk([], m)]))
         except Exception:
             timer(lambda: len(list(cmdutil.walk(repo, pats, {}))))
+    fm.end()
 
 @command('perfannotate')
 def perfannotate(ui, repo, f):
+    timer, fm = gettimer(ui)
     fc = repo['.'][f]
     timer(lambda: len(fc.annotate(True)))
+    fm.end()
 
 @command('perfstatus',
          [('u', 'unknown', False,
@@ -57,16 +84,20 @@
     #m = match.always(repo.root, repo.getcwd())
     #timer(lambda: sum(map(len, repo.dirstate.status(m, [], False, False,
     #                                                False))))
+    timer, fm = gettimer(ui)
     timer(lambda: sum(map(len, repo.status(**opts))))
+    fm.end()
 
 @command('perfaddremove')
 def perfaddremove(ui, repo):
+    timer, fm = gettimer(ui)
     try:
         oldquiet = repo.ui.quiet
         repo.ui.quiet = True
         timer(lambda: scmutil.addremove(repo, dry_run=True))
     finally:
         repo.ui.quiet = oldquiet
+        fm.end()
 
 def clearcaches(cl):
     # behave somewhat consistently across internal API changes
@@ -79,33 +110,40 @@
 
 @command('perfheads')
 def perfheads(ui, repo):
+    timer, fm = gettimer(ui)
     cl = repo.changelog
     def d():
         len(cl.headrevs())
         clearcaches(cl)
     timer(d)
+    fm.end()
 
 @command('perftags')
 def perftags(ui, repo):
     import mercurial.changelog
     import mercurial.manifest
+    timer, fm = gettimer(ui)
     def t():
         repo.changelog = mercurial.changelog.changelog(repo.sopener)
         repo.manifest = mercurial.manifest.manifest(repo.sopener)
         repo._tags = None
         return len(repo.tags())
     timer(t)
+    fm.end()
 
 @command('perfancestors')
 def perfancestors(ui, repo):
+    timer, fm = gettimer(ui)
     heads = repo.changelog.headrevs()
     def d():
         for a in repo.changelog.ancestors(heads):
             pass
     timer(d)
+    fm.end()
 
 @command('perfancestorset')
 def perfancestorset(ui, repo, revset):
+    timer, fm = gettimer(ui)
     revs = repo.revs(revset)
     heads = repo.changelog.headrevs()
     def d():
@@ -113,34 +151,42 @@
         for rev in revs:
             rev in s
     timer(d)
+    fm.end()
 
 @command('perfdirs')
 def perfdirs(ui, repo):
+    timer, fm = gettimer(ui)
     dirstate = repo.dirstate
     'a' in dirstate
     def d():
         dirstate.dirs()
         del dirstate._dirs
     timer(d)
+    fm.end()
 
 @command('perfdirstate')
 def perfdirstate(ui, repo):
+    timer, fm = gettimer(ui)
     "a" in repo.dirstate
     def d():
         repo.dirstate.invalidate()
         "a" in repo.dirstate
     timer(d)
+    fm.end()
 
 @command('perfdirstatedirs')
 def perfdirstatedirs(ui, repo):
+    timer, fm = gettimer(ui)
     "a" in repo.dirstate
     def d():
         "a" in repo.dirstate._dirs
         del repo.dirstate._dirs
     timer(d)
+    fm.end()
 
 @command('perfdirstatefoldmap')
 def perffoldmap(ui, repo):
+    timer, fm = gettimer(ui)
     dirstate = repo.dirstate
     'a' in dirstate
     def d():
@@ -148,19 +194,23 @@
         del dirstate._foldmap
         del dirstate._dirs
     timer(d)
+    fm.end()
 
 @command('perfdirstatewrite')
 def perfdirstatewrite(ui, repo):
+    timer, fm = gettimer(ui)
     ds = repo.dirstate
     "a" in ds
     def d():
         ds._dirty = True
         ds.write()
     timer(d)
+    fm.end()
 
 @command('perfmergecalculate',
          [('r', 'rev', '.', 'rev to merge against')])
 def perfmergecalculate(ui, repo, rev):
+    timer, fm = gettimer(ui)
     wctx = repo[None]
     rctx = scmutil.revsingle(repo, rev, rev)
     ancestor = wctx.ancestor(rctx)
@@ -173,17 +223,21 @@
         merge.calculateupdates(repo, wctx, rctx, ancestor, False, False, False,
                                acceptremote=True)
     timer(d)
+    fm.end()
 
 @command('perfpathcopies', [], "REV REV")
 def perfpathcopies(ui, repo, rev1, rev2):
+    timer, fm = gettimer(ui)
     ctx1 = scmutil.revsingle(repo, rev1, rev1)
     ctx2 = scmutil.revsingle(repo, rev2, rev2)
     def d():
         copies.pathcopies(ctx1, ctx2)
     timer(d)
+    fm.end()
 
 @command('perfmanifest', [], 'REV')
 def perfmanifest(ui, repo, rev):
+    timer, fm = gettimer(ui)
     ctx = scmutil.revsingle(repo, rev, rev)
     t = ctx.manifestnode()
     def d():
@@ -191,51 +245,65 @@
         repo.manifest._cache = None
         repo.manifest.read(t)
     timer(d)
+    fm.end()
 
 @command('perfchangeset')
 def perfchangeset(ui, repo, rev):
+    timer, fm = gettimer(ui)
     n = repo[rev].node()
     def d():
         repo.changelog.read(n)
         #repo.changelog._cache = None
     timer(d)
+    fm.end()
 
 @command('perfindex')
 def perfindex(ui, repo):
     import mercurial.revlog
+    timer, fm = gettimer(ui)
     mercurial.revlog._prereadsize = 2**24 # disable lazy parser in old hg
     n = repo["tip"].node()
     def d():
         cl = mercurial.revlog.revlog(repo.sopener, "00changelog.i")
         cl.rev(n)
     timer(d)
+    fm.end()
 
 @command('perfstartup')
 def perfstartup(ui, repo):
+    timer, fm = gettimer(ui)
     cmd = sys.argv[0]
     def d():
         os.system("HGRCPATH= %s version -q > /dev/null" % cmd)
     timer(d)
+    fm.end()
 
 @command('perfparents')
 def perfparents(ui, repo):
+    timer, fm = gettimer(ui)
     nl = [repo.changelog.node(i) for i in xrange(1000)]
     def d():
         for n in nl:
             repo.changelog.parents(n)
     timer(d)
+    fm.end()
 
 @command('perflookup')
 def perflookup(ui, repo, rev):
+    timer, fm = gettimer(ui)
     timer(lambda: len(repo.lookup(rev)))
+    fm.end()
 
 @command('perfrevrange')
 def perfrevrange(ui, repo, *specs):
+    timer, fm = gettimer(ui)
     revrange = scmutil.revrange
     timer(lambda: len(revrange(repo, specs)))
+    fm.end()
 
 @command('perfnodelookup')
 def perfnodelookup(ui, repo, rev):
+    timer, fm = gettimer(ui)
     import mercurial.revlog
     mercurial.revlog._prereadsize = 2**24 # disable lazy parser in old hg
     n = repo[rev].node()
@@ -244,14 +312,17 @@
         cl.rev(n)
         clearcaches(cl)
     timer(d)
+    fm.end()
 
 @command('perflog',
          [('', 'rename', False, 'ask log to follow renames')])
 def perflog(ui, repo, **opts):
+    timer, fm = gettimer(ui)
     ui.pushbuffer()
     timer(lambda: commands.log(ui, repo, rev=[], date='', user='',
                                copies=opts.get('rename')))
     ui.popbuffer()
+    fm.end()
 
 @command('perfmoonwalk')
 def perfmoonwalk(ui, repo):
@@ -259,52 +330,65 @@
 
     This also loads the changelog data for each revision in the changelog.
     """
+    timer, fm = gettimer(ui)
     def moonwalk():
         for i in xrange(len(repo), -1, -1):
             ctx = repo[i]
             ctx.branch() # read changelog data (in addition to the index)
     timer(moonwalk)
+    fm.end()
 
 @command('perftemplating')
 def perftemplating(ui, repo):
+    timer, fm = gettimer(ui)
     ui.pushbuffer()
     timer(lambda: commands.log(ui, repo, rev=[], date='', user='',
                                template='{date|shortdate} [{rev}:{node|short}]'
                                ' {author|person}: {desc|firstline}\n'))
     ui.popbuffer()
+    fm.end()
 
 @command('perfcca')
 def perfcca(ui, repo):
+    timer, fm = gettimer(ui)
     timer(lambda: scmutil.casecollisionauditor(ui, False, repo.dirstate))
+    fm.end()
 
 @command('perffncacheload')
 def perffncacheload(ui, repo):
+    timer, fm = gettimer(ui)
     s = repo.store
     def d():
         s.fncache._load()
     timer(d)
+    fm.end()
 
 @command('perffncachewrite')
 def perffncachewrite(ui, repo):
+    timer, fm = gettimer(ui)
     s = repo.store
     s.fncache._load()
     def d():
         s.fncache._dirty = True
         s.fncache.write()
     timer(d)
+    fm.end()
 
 @command('perffncacheencode')
 def perffncacheencode(ui, repo):
+    timer, fm = gettimer(ui)
     s = repo.store
     s.fncache._load()
     def d():
         for p in s.fncache.entries:
             s.encode(p)
     timer(d)
+    fm.end()
 
 @command('perfdiffwd')
 def perfdiffwd(ui, repo):
     """Profile diff of working directory changes"""
+    timer, fm = gettimer(ui)
     options = {
         'w': 'ignore_all_space',
         'b': 'ignore_space_change',
@@ -319,11 +403,13 @@
             ui.popbuffer()
         title = 'diffopts: %s' % (diffopt and ('-' + diffopt) or 'none')
         timer(d, title)
+    fm.end()
 
 @command('perfrevlog',
          [('d', 'dist', 100, 'distance between the revisions')],
          "[INDEXFILE]")
 def perfrevlog(ui, repo, file_, **opts):
+    timer, fm = gettimer(ui)
     from mercurial import revlog
     dist = opts['dist']
     def d():
@@ -332,6 +418,7 @@
             r.revision(r.node(x))
 
     timer(d)
+    fm.end()
 
 @command('perfrevset',
          [('C', 'clear', False, 'clear volatile cache between each call.')],
@@ -342,17 +429,20 @@
     Use the --clean option if need to evaluate the impact of build volatile
     revisions set cache on the revset execution. Volatile cache hold filtered
     and obsolete related cache."""
+    timer, fm = gettimer(ui)
     def d():
         if clear:
             repo.invalidatevolatilesets()
         for r in repo.revs(expr): pass
     timer(d)
+    fm.end()
 
 @command('perfvolatilesets')
 def perfvolatilesets(ui, repo, *names):
     """benchmark the computation of various volatile set
 
     Volatile set computes element related to filtering and obsolescence."""
+    timer, fm = gettimer(ui)
     repo = repo.unfiltered()
 
     def getobs(name):
@@ -380,6 +470,7 @@
 
     for name in allfilter:
         timer(getfiltered(name), title=name)
+    fm.end()
 
 @command('perfbranchmap',
          [('f', 'full', False,
@@ -390,6 +481,7 @@
 
     This benchmarks the full repo.branchmap() call with read and write disabled
     """
+    timer, fm = gettimer(ui)
     def getbranchmap(filtername):
         """generate a benchmark function for the filtername"""
         if filtername is None:
@@ -432,3 +524,4 @@
     finally:
         branchmap.read = oldread
         branchmap.branchcache.write = oldwrite
+    fm.end()