Patchwork perf: get the timer function through

login
register
mail settings
Submitter Pierre-Yves David
Date Nov. 4, 2014, 1:08 p.m.
Message ID <cec5c3a6139b79da1295.1415106525@marginatus.alto.octopoid.net>
Download mbox | patch
Permalink /patch/6557/
State Accepted
Headers show

Comments

Pierre-Yves David - Nov. 4, 2014, 1:08 p.m.
# HG changeset patch
# User Pierre-Yves David <pierre-yves.david@fb.com>
# Date 1415097606 0
#      Tue Nov 04 10:40:06 2014 +0000
# Node ID cec5c3a6139b79da12956a612df4f793c521408f
# Parent  30e0dcd7c5ffd99fb9c2474e9d73ca01a7d292fa
perf: get the timer function through

We want to use a `formatter` object in the perf extensions. This will allow the
use of formatted output like json. To avoid adding logic to create a formatter
and passe it around to the timer function to every function, we add a 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
   }
  ]
Augie Fackler - Nov. 4, 2014, 1:20 p.m.
On Tue, Nov 04, 2014 at 01:08:45PM +0000, Pierre-Yves David wrote:
> # HG changeset patch
> # User Pierre-Yves David <pierre-yves.david@fb.com>
> # Date 1415097606 0
> #      Tue Nov 04 10:40:06 2014 +0000
> # Node ID cec5c3a6139b79da12956a612df4f793c521408f
> # Parent  30e0dcd7c5ffd99fb9c2474e9d73ca01a7d292fa
> perf: get the timer function through

This summary line confuses me. Would "perf: use a formatter for
output" be better?

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

+1

>
> 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
>    }
>   ]
>
> diff --git a/contrib/perf.py b/contrib/perf.py
> --- a/contrib/perf.py
> +++ b/contrib/perf.py
> @@ -2,15 +2,32 @@
>  '''helper extension to measure performance'''
>
>  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):
>

Bonus points if you can come up with a better name than gettimer,
since it also gets a formatter.

> +    """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.
> +
> +    (the formatter creation code is not yet here)

But I see a ui.formatter() below? Am I missing something?

> """
> +    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
>      while True:
>          ostart = os.times()
> @@ -23,52 +40,68 @@ def timer(func, title=None):
>          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
> +
> +    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))))
>      except Exception:
>          try:
>              m = scmutil.match(repo[None], pats, {})
>              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,
>             'ask status to look for unknown files')])
>  def perfstatus(ui, repo, **opts):
>      #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
>      if util.safehasattr(cl, 'clearcaches'):
>          cl.clearcaches()
> @@ -77,92 +110,111 @@ def clearcaches(cl):
>          cl._nodecache = {nullid: nullrev}
>          cl._nodepos = None
>
>  @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():
>          s = repo.changelog.ancestors(heads)
>          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():
>          dirstate._foldmap.get('a')
>          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)
>      # we don't want working dir files to be stat'd in the benchmark, so prime
>      # that cache
> @@ -171,142 +223,176 @@ def perfmergecalculate(ui, repo, rev):
>          # acceptremote is True because we don't want prompts in the middle of
>          # our benchmark
>          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():
>          repo.manifest._mancache.clear()
>          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()
>      cl = mercurial.revlog.revlog(repo.sopener, "00changelog.i")
>      def d():
>          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):
>      """benchmark walking the changelog backwards
>
>      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',
>          'B': 'ignore_blank_lines',
>          }
> @@ -317,44 +403,50 @@ def perfdiffwd(ui, repo):
>              ui.pushbuffer()
>              commands.diff(ui, repo, **opts)
>              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():
>          r = revlog.revlog(lambda fn: open(fn, 'rb'), file_)
>          for x in xrange(0, len(r), dist):
>              r.revision(r.node(x))
>
>      timer(d)
> +    fm.end()
>
>  @command('perfrevset',
>           [('C', 'clear', False, 'clear volatile cache between each call.')],
>           "REVSET")
>  def perfrevset(ui, repo, expr, clear=False):
>      """benchmark the execution time of a revset
>
>      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):
>          def d():
>              repo.invalidatevolatilesets()
> @@ -378,20 +470,22 @@ def perfvolatilesets(ui, repo, *names):
>      if names:
>          allfilter = [n for n in allfilter if n in names]
>
>      for name in allfilter:
>          timer(getfiltered(name), title=name)
> +    fm.end()
>
>  @command('perfbranchmap',
>           [('f', 'full', False,
>             'Includes build time of subset'),
>           ])
>  def perfbranchmap(ui, repo, full=False):
>      """benchmark the update of a branchmap
>
>      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:
>              view = repo
>          else:
> @@ -430,5 +524,6 @@ def perfbranchmap(ui, repo, full=False):
>          for name in allfilters:
>              timer(getbranchmap(name), title=str(name))
>      finally:
>          branchmap.read = oldread
>          branchmap.branchcache.write = oldwrite
> +    fm.end()
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@selenic.com
> http://selenic.com/mailman/listinfo/mercurial-devel
Pierre-Yves David - Nov. 4, 2014, 1:23 p.m.
On 11/04/2014 01:20 PM, Augie Fackler wrote:
> On Tue, Nov 04, 2014 at 01:08:45PM +0000, Pierre-Yves David wrote:
>> # HG changeset patch
>> # User Pierre-Yves David <pierre-yves.david@fb.com>
>> # Date 1415097606 0
>> #      Tue Nov 04 10:40:06 2014 +0000
>> # Node ID cec5c3a6139b79da12956a612df4f793c521408f
>> # Parent  30e0dcd7c5ffd99fb9c2474e9d73ca01a7d292fa
>> perf: get the timer function through
>
> This summary line confuses me. Would "perf: use a formatter for
> output" be better?

Looks like my last summary update got lost in limbo: here is the new 
version:

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
    }
   ]


>
>>
>> We want to use a `formatter` object in the perf extensions. This will allow the
>> use of formatted output like json. To avoid adding logic to create a formatter
>> and passe it around to the timer function to every function, we add a function
>> in charge of returning a `timer` function as simple as before but embedding an
>> appropriate formatter.
>
> +1
>
>>
>> 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
>>     }
>>    ]
>>
>> diff --git a/contrib/perf.py b/contrib/perf.py
>> --- a/contrib/perf.py
>> +++ b/contrib/perf.py
>> @@ -2,15 +2,32 @@
>>   '''helper extension to measure performance'''
>>
>>   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):
>>
>
> Bonus points if you can come up with a better name than gettimer,
> since it also gets a formatter.
>
>> +    """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.
>> +
>> +    (the formatter creation code is not yet here)
>
> But I see a ui.formatter() below? Am I missing something?

oops forgot to drop this line when folding.
Augie Fackler - Nov. 4, 2014, 1:25 p.m.
On Tue, Nov 4, 2014 at 8:23 AM, Pierre-Yves David
<pierre-yves.david@ens-lyon.org> wrote:
>
>
> On 11/04/2014 01:20 PM, Augie Fackler wrote:
>>
>> On Tue, Nov 04, 2014 at 01:08:45PM +0000, Pierre-Yves David wrote:
>>>
>>> # HG changeset patch
>>> # User Pierre-Yves David <pierre-yves.david@fb.com>
>>> # Date 1415097606 0
>>> #      Tue Nov 04 10:40:06 2014 +0000
>>> # Node ID cec5c3a6139b79da12956a612df4f793c521408f
>>> # Parent  30e0dcd7c5ffd99fb9c2474e9d73ca01a7d292fa
>>> perf: get the timer function through
>>
>>
>> This summary line confuses me. Would "perf: use a formatter for
>> output" be better?
>
>
> Looks like my last summary update got lost in limbo: here is the new
> version:
>
> perf: use a formatter for output

LG. Can you do me a favor and either push a cleaned-up version where I
can snag it or do a resend?

>
> 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
>    }
>   ]
>
>
>>
>>>
>>> We want to use a `formatter` object in the perf extensions. This will
>>> allow the
>>> use of formatted output like json. To avoid adding logic to create a
>>> formatter
>>> and passe it around to the timer function to every function, we add a
>>> function
>>> in charge of returning a `timer` function as simple as before but
>>> embedding an
>>> appropriate formatter.
>>
>>
>> +1
>>
>>>
>>> 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
>>>     }
>>>    ]
>>>
>>> diff --git a/contrib/perf.py b/contrib/perf.py
>>> --- a/contrib/perf.py
>>> +++ b/contrib/perf.py
>>> @@ -2,15 +2,32 @@
>>>   '''helper extension to measure performance'''
>>>
>>>   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):
>>>
>>
>> Bonus points if you can come up with a better name than gettimer,
>> since it also gets a formatter.
>>
>>> +    """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.
>>> +
>>> +    (the formatter creation code is not yet here)
>>
>>
>> But I see a ui.formatter() below? Am I missing something?
>
>
> oops forgot to drop this line when folding.
>
>
> --
> Pierre-Yves David

Patch

diff --git a/contrib/perf.py b/contrib/perf.py
--- a/contrib/perf.py
+++ b/contrib/perf.py
@@ -2,15 +2,32 @@ 
 '''helper extension to measure performance'''
 
 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.
+
+    (the formatter creation code is not yet here)"""
+    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
     while True:
         ostart = os.times()
@@ -23,52 +40,68 @@  def timer(func, title=None):
         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
+
+    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))))
     except Exception:
         try:
             m = scmutil.match(repo[None], pats, {})
             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,
            'ask status to look for unknown files')])
 def perfstatus(ui, repo, **opts):
     #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
     if util.safehasattr(cl, 'clearcaches'):
         cl.clearcaches()
@@ -77,92 +110,111 @@  def clearcaches(cl):
         cl._nodecache = {nullid: nullrev}
         cl._nodepos = None
 
 @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():
         s = repo.changelog.ancestors(heads)
         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():
         dirstate._foldmap.get('a')
         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)
     # we don't want working dir files to be stat'd in the benchmark, so prime
     # that cache
@@ -171,142 +223,176 @@  def perfmergecalculate(ui, repo, rev):
         # acceptremote is True because we don't want prompts in the middle of
         # our benchmark
         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():
         repo.manifest._mancache.clear()
         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()
     cl = mercurial.revlog.revlog(repo.sopener, "00changelog.i")
     def d():
         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):
     """benchmark walking the changelog backwards
 
     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',
         'B': 'ignore_blank_lines',
         }
@@ -317,44 +403,50 @@  def perfdiffwd(ui, repo):
             ui.pushbuffer()
             commands.diff(ui, repo, **opts)
             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():
         r = revlog.revlog(lambda fn: open(fn, 'rb'), file_)
         for x in xrange(0, len(r), dist):
             r.revision(r.node(x))
 
     timer(d)
+    fm.end()
 
 @command('perfrevset',
          [('C', 'clear', False, 'clear volatile cache between each call.')],
          "REVSET")
 def perfrevset(ui, repo, expr, clear=False):
     """benchmark the execution time of a revset
 
     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):
         def d():
             repo.invalidatevolatilesets()
@@ -378,20 +470,22 @@  def perfvolatilesets(ui, repo, *names):
     if names:
         allfilter = [n for n in allfilter if n in names]
 
     for name in allfilter:
         timer(getfiltered(name), title=name)
+    fm.end()
 
 @command('perfbranchmap',
          [('f', 'full', False,
            'Includes build time of subset'),
          ])
 def perfbranchmap(ui, repo, full=False):
     """benchmark the update of a branchmap
 
     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:
             view = repo
         else:
@@ -430,5 +524,6 @@  def perfbranchmap(ui, repo, full=False):
         for name in allfilters:
             timer(getbranchmap(name), title=str(name))
     finally:
         branchmap.read = oldread
         branchmap.branchcache.write = oldwrite
+    fm.end()