Patchwork [2,of,2] util: add a timed function for use during development

login
register
mail settings
Submitter Bryan O'Sullivan
Date Feb. 21, 2013, 9:33 p.m.
Message ID <95cb8d7754a7a28f52f8.1361482382@australite.local>
Download mbox | patch
Permalink /patch/1042/
State Accepted
Commit af9ddea2cb99b6e4314a6e79b793b5fc30ea4f19
Headers show

Comments

Bryan O'Sullivan - Feb. 21, 2013, 9:33 p.m.
# HG changeset patch
# User Bryan O'Sullivan <bryano@fb.com>
# Date 1361482360 28800
# Node ID 95cb8d7754a7a28f52f82a332bf1163eb6dea202
# Parent  19d3300883ce1407d0b527549a82f25d3f182873
util: add a timed function for use during development

I often want to measure the cost of a function call before/after
an optimization, where using top level "hg --time" timing introduces
enough other noise that I can't tell if my efforts are having an
effect.

This decorator allows a developer to measure a function's cost with
finer granularity.
tonfa - Feb. 23, 2013, 10:05 p.m.
On Thu, Feb 21, 2013 at 10:33 PM, Bryan O'Sullivan <bos@serpentine.com>wrote:

> # HG changeset patch
> # User Bryan O'Sullivan <bryano@fb.com>
> # Date 1361482360 28800
> # Node ID 95cb8d7754a7a28f52f82a332bf1163eb6dea202
> # Parent  19d3300883ce1407d0b527549a82f25d3f182873
> util: add a timed function for use during development
>
> I often want to measure the cost of a function call before/after
> an optimization, where using top level "hg --time" timing introduces
> enough other noise that I can't tell if my efforts are having an
> effect.
>
> This decorator allows a developer to measure a function's cost with
> finer granularity.
>
> diff --git a/mercurial/util.py b/mercurial/util.py
> --- a/mercurial/util.py
> +++ b/mercurial/util.py
> @@ -1872,3 +1872,45 @@ def isatty(fd):
>          return fd.isatty()
>      except AttributeError:
>          return False
> +
> +timecount = unitcount(
> +    (1, 1e3, _('%.0f s')),
> +    (100, 1, _('%.1f s')),
> +    (10, 1, _('%.2f s')),
> +    (1, 1, _('%.3f s')),
> +    (100, 1e-3, _('%.1f ms')),
> +    (10, 1e-3, _('%.2f ms')),
> +    (1, 1e-3, _('%.3f ms')),
> +    (100, 1e-6, _('%.1f us')),
> +    (10, 1e-6, _('%.2f us')),
> +    (1, 1e-6, _('%.3f us')),
> +    (100, 1e-9, _('%.1f ns')),
> +    (10, 1e-9, _('%.2f ns')),
> +    (1, 1e-9, _('%.3f ns')),
> +    )
> +
> +_timenesting = [0]
> +
> +def timed(func):
> +    '''Report the execution time of a function call to stderr.
> +
> +    During development, use as a decorator when you need to measure
> +    the cost of a function, e.g. as follows:
> +
> +    @util.timed
> +    def foo(a, b, c):
> +        pass
> +    '''
> +
> +    def wrapper(*args, **kwargs):
> +        start = time.time()
> +        _timenesting[0] += 2
>

I'm a bit puzzled by the 2. Any hint?


> +        try:
> +            return func(*args, **kwargs)
> +        finally:
> +            elapsed = time.time() - start
> +            _timenesting[0] -= 2
> +            sys.stderr.write('%s%s: %s\n' %
> +                             (' ' * _timenesting[0], func.__name__,
> +                              timecount(elapsed)))
> +    return wrapper
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@selenic.com
> http://selenic.com/mailman/listinfo/mercurial-devel
>
Augie Fackler - Feb. 25, 2013, 3:17 p.m.
On Sat, Feb 23, 2013 at 11:05:04PM +0100, Benoit Boissinot wrote:
> On Thu, Feb 21, 2013 at 10:33 PM, Bryan O'Sullivan <bos@serpentine.com>wrote:
>
> > # HG changeset patch
> > # User Bryan O'Sullivan <bryano@fb.com>
> > # Date 1361482360 28800
> > # Node ID 95cb8d7754a7a28f52f82a332bf1163eb6dea202
> > # Parent  19d3300883ce1407d0b527549a82f25d3f182873
> > util: add a timed function for use during development
> >
> > I often want to measure the cost of a function call before/after
> > an optimization, where using top level "hg --time" timing introduces
> > enough other noise that I can't tell if my efforts are having an
> > effect.
> >
> > This decorator allows a developer to measure a function's cost with
> > finer granularity.
> >
> > diff --git a/mercurial/util.py b/mercurial/util.py
> > --- a/mercurial/util.py
> > +++ b/mercurial/util.py
> > @@ -1872,3 +1872,45 @@ def isatty(fd):
> >          return fd.isatty()
> >      except AttributeError:
> >          return False
> > +
> > +timecount = unitcount(
> > +    (1, 1e3, _('%.0f s')),
> > +    (100, 1, _('%.1f s')),
> > +    (10, 1, _('%.2f s')),
> > +    (1, 1, _('%.3f s')),
> > +    (100, 1e-3, _('%.1f ms')),
> > +    (10, 1e-3, _('%.2f ms')),
> > +    (1, 1e-3, _('%.3f ms')),
> > +    (100, 1e-6, _('%.1f us')),
> > +    (10, 1e-6, _('%.2f us')),
> > +    (1, 1e-6, _('%.3f us')),
> > +    (100, 1e-9, _('%.1f ns')),
> > +    (10, 1e-9, _('%.2f ns')),
> > +    (1, 1e-9, _('%.3f ns')),
> > +    )
> > +
> > +_timenesting = [0]
> > +
> > +def timed(func):
> > +    '''Report the execution time of a function call to stderr.
> > +
> > +    During development, use as a decorator when you need to measure
> > +    the cost of a function, e.g. as follows:
> > +
> > +    @util.timed
> > +    def foo(a, b, c):
> > +        pass
> > +    '''
> > +
> > +    def wrapper(*args, **kwargs):
> > +        start = time.time()
> > +        _timenesting[0] += 2
> >
>
> I'm a bit puzzled by the 2. Any hint?

That's the amount nested timed invocations will indent. It's clever,
but clear upon basic reading of the code IMO.

>
>
> > +        try:
> > +            return func(*args, **kwargs)
> > +        finally:
> > +            elapsed = time.time() - start
> > +            _timenesting[0] -= 2
> > +            sys.stderr.write('%s%s: %s\n' %
> > +                             (' ' * _timenesting[0], func.__name__,
> > +                              timecount(elapsed)))
> > +    return wrapper
> > _______________________________________________
> > Mercurial-devel mailing list
> > Mercurial-devel@selenic.com
> > http://selenic.com/mailman/listinfo/mercurial-devel
> >

> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@selenic.com
> http://selenic.com/mailman/listinfo/mercurial-devel

Patch

diff --git a/mercurial/util.py b/mercurial/util.py
--- a/mercurial/util.py
+++ b/mercurial/util.py
@@ -1872,3 +1872,45 @@  def isatty(fd):
         return fd.isatty()
     except AttributeError:
         return False
+
+timecount = unitcount(
+    (1, 1e3, _('%.0f s')),
+    (100, 1, _('%.1f s')),
+    (10, 1, _('%.2f s')),
+    (1, 1, _('%.3f s')),
+    (100, 1e-3, _('%.1f ms')),
+    (10, 1e-3, _('%.2f ms')),
+    (1, 1e-3, _('%.3f ms')),
+    (100, 1e-6, _('%.1f us')),
+    (10, 1e-6, _('%.2f us')),
+    (1, 1e-6, _('%.3f us')),
+    (100, 1e-9, _('%.1f ns')),
+    (10, 1e-9, _('%.2f ns')),
+    (1, 1e-9, _('%.3f ns')),
+    )
+
+_timenesting = [0]
+
+def timed(func):
+    '''Report the execution time of a function call to stderr.
+
+    During development, use as a decorator when you need to measure
+    the cost of a function, e.g. as follows:
+
+    @util.timed
+    def foo(a, b, c):
+        pass
+    '''
+
+    def wrapper(*args, **kwargs):
+        start = time.time()
+        _timenesting[0] += 2
+        try:
+            return func(*args, **kwargs)
+        finally:
+            elapsed = time.time() - start
+            _timenesting[0] -= 2
+            sys.stderr.write('%s%s: %s\n' %
+                             (' ' * _timenesting[0], func.__name__,
+                              timecount(elapsed)))
+    return wrapper