Patchwork [V2] profiling: allow logging profile to the blackbox

login
register
mail settings
Submitter Durham Goode
Date Sept. 8, 2015, 6:41 p.m.
Message ID <a8eeffb15ed4bf1e55bc.1441737707@dev2000.prn2.facebook.com>
Download mbox | patch
Permalink /patch/10424/
State Accepted
Headers show

Comments

Durham Goode - Sept. 8, 2015, 6:41 p.m.
# HG changeset patch
# User Durham Goode <durham@fb.com>
# Date 1441737592 25200
#      Tue Sep 08 11:39:52 2015 -0700
# Node ID a8eeffb15ed4bf1e55bc3b36baa64c8f2b5d0739
# Parent  2cd61d6e66c1034c97b7095fdf1d7908dd437b26
profiling: allow logging profile to the blackbox

This allows specifying '--config profiling.output=blackbox' which will log the
profile output to the blackbox (if enabled). This is useful for doing profiling
on the server since it allows us to record the command, it's result, any
exceptions, and it's profile, all in one spot.  And we get log rotation for
free.
Augie Fackler - Sept. 9, 2015, 2:41 p.m.
On Tue, Sep 08, 2015 at 11:41:47AM -0700, Durham Goode wrote:
> # HG changeset patch
> # User Durham Goode <durham@fb.com>
> # Date 1441737592 25200
> #      Tue Sep 08 11:39:52 2015 -0700
> # Node ID a8eeffb15ed4bf1e55bc3b36baa64c8f2b5d0739
> # Parent  2cd61d6e66c1034c97b7095fdf1d7908dd437b26
> profiling: allow logging profile to the blackbox

Queued, but I have a question below that might lead me to write a
quick followup.

>
> This allows specifying '--config profiling.output=blackbox' which will log the
> profile output to the blackbox (if enabled). This is useful for doing profiling
> on the server since it allows us to record the command, it's result, any
> exceptions, and it's profile, all in one spot.  And we get log rotation for
> free.
>
> diff --git a/mercurial/dispatch.py b/mercurial/dispatch.py
> --- a/mercurial/dispatch.py
> +++ b/mercurial/dispatch.py
> @@ -1021,7 +1021,10 @@ def _runcommand(ui, options, cmd, cmdfun
>
>          output = ui.config('profiling', 'output')
>
> -        if output:
> +        if output == 'blackbox':
> +            import StringIO
> +            fp = StringIO.StringIO()
> +        elif output:
>              path = ui.expandpath(output)
>              fp = open(path, 'wb')
>          else:
> @@ -1036,6 +1039,12 @@ def _runcommand(ui, options, cmd, cmdfun
>                  return statprofile(ui, checkargs, fp)
>          finally:
>              if output:
> +                if output == 'blackbox':
> +                    val = "Profile:\n%s" % fp.getvalue()
> +                    # ui.log treats the input as a format string,
> +                    # so we need to escape any % signs.

Oh, I see. This is actually documented only in blackbox.py - should we
document that on ui.log itself as part of the API contract?

(I'm happy to do that, it was just surprising.)

> +                    val = val.replace('%', '%%')
> +                    ui.log('profile', val)
>                  fp.close()
>      else:
>          return checkargs()
> diff --git a/tests/test-profile.t b/tests/test-profile.t
> --- a/tests/test-profile.t
> +++ b/tests/test-profile.t
> @@ -14,6 +14,9 @@ test --profile
>    $ hg --profile --config profiling.output=../out st
>    $ grep CallCount ../out > /dev/null || cat ../out
>
> +  $ hg --profile --config profiling.output=blackbox --config extensions.blackbox= st
> +  $ grep CallCount .hg/blackbox.log > /dev/null || cat .hg/blackbox.log
> +
>    $ hg --profile --config profiling.format=text st 2>../out
>    $ grep CallCount ../out > /dev/null || cat ../out
>
> _______________________________________________
> Mercurial-devel mailing list
> Mercurial-devel@selenic.com
> https://selenic.com/mailman/listinfo/mercurial-devel
Durham Goode - Sept. 9, 2015, 4:18 p.m.
On 9/9/15, 7:41 AM, "Augie Fackler" <raf@durin42.com> wrote:

>On Tue, Sep 08, 2015 at 11:41:47AM -0700, Durham Goode wrote:

>> # HG changeset patch

>> # User Durham Goode <durham@fb.com>

>> # Date 1441737592 25200

>> #      Tue Sep 08 11:39:52 2015 -0700

>> # Node ID a8eeffb15ed4bf1e55bc3b36baa64c8f2b5d0739

>> # Parent  2cd61d6e66c1034c97b7095fdf1d7908dd437b26

>> profiling: allow logging profile to the blackbox

>

>Queued, but I have a question below that might lead me to write a

>quick followup.

>

>>

>> This allows specifying '--config profiling.output=blackbox' which will log the

>> profile output to the blackbox (if enabled). This is useful for doing profiling

>> on the server since it allows us to record the command, it's result, any

>> exceptions, and it's profile, all in one spot.  And we get log rotation for

>> free.

>>

>> diff --git a/mercurial/dispatch.py b/mercurial/dispatch.py

>> --- a/mercurial/dispatch.py

>> +++ b/mercurial/dispatch.py

>> @@ -1021,7 +1021,10 @@ def _runcommand(ui, options, cmd, cmdfun

>>

>>          output = ui.config('profiling', 'output')

>>

>> -        if output:

>> +        if output == 'blackbox':

>> +            import StringIO

>> +            fp = StringIO.StringIO()

>> +        elif output:

>>              path = ui.expandpath(output)

>>              fp = open(path, 'wb')

>>          else:

>> @@ -1036,6 +1039,12 @@ def _runcommand(ui, options, cmd, cmdfun

>>                  return statprofile(ui, checkargs, fp)

>>          finally:

>>              if output:

>> +                if output == 'blackbox':

>> +                    val = "Profile:\n%s" % fp.getvalue()

>> +                    # ui.log treats the input as a format string,

>> +                    # so we need to escape any % signs.

>

>Oh, I see. This is actually documented only in blackbox.py - should we

>document that on ui.log itself as part of the API contract?

>

>(I'm happy to do that, it was just surprising.)


That sounds reasonable.  For some reason I thought this was the behavior for all of the ui.status/warn/note commands, but I guess I was wrong.  I think we did it this way because most users don't have the blackbox or any ui.log extensions enabled, so this avoids them having to do the string formatting.
Matt Mackall - Sept. 9, 2015, 6:04 p.m.
On Wed, 2015-09-09 at 16:18 +0000, Durham Goode wrote:
> >> +                if output == 'blackbox':
> >> +                    val = "Profile:\n%s" % fp.getvalue()
> >> +                    # ui.log treats the input as a format string,
> >> +                    # so we need to escape any % signs.
> >
> >Oh, I see. This is actually documented only in blackbox.py - should we
> >document that on ui.log itself as part of the API contract?
> >
> >(I'm happy to do that, it was just surprising.)
> 
> That sounds reasonable.  For some reason I thought this was the
> behavior for all of the ui.status/warn/note commands, but I guess I
> was wrong.  I think we did it this way because most users don't have
> the blackbox or any ui.log extensions enabled, so this avoids them
> having to do the string formatting.

Right, it's a tiny optimization.
Simon King - Sept. 9, 2015, 8:05 p.m.
> On 9 Sep 2015, at 19:04, Matt Mackall <mpm@selenic.com> wrote:
> 
> On Wed, 2015-09-09 at 16:18 +0000, Durham Goode wrote:
>>>> +                if output == 'blackbox':
>>>> +                    val = "Profile:\n%s" % fp.getvalue()
>>>> +                    # ui.log treats the input as a format string,
>>>> +                    # so we need to escape any % signs.
>>> 
>>> Oh, I see. This is actually documented only in blackbox.py - should we
>>> document that on ui.log itself as part of the API contract?
>>> 
>>> (I'm happy to do that, it was just surprising.)
>> 
>> That sounds reasonable.  For some reason I thought this was the
>> behavior for all of the ui.status/warn/note commands, but I guess I
>> was wrong.  I think we did it this way because most users don't have
>> the blackbox or any ui.log extensions enabled, so this avoids them
>> having to do the string formatting.
> 
> Right, it's a tiny optimization.

Perhaps it would be better to write:

  ui.log('profile', 'Profile:\n%s', fp.getvalue())

Simon

Patch

diff --git a/mercurial/dispatch.py b/mercurial/dispatch.py
--- a/mercurial/dispatch.py
+++ b/mercurial/dispatch.py
@@ -1021,7 +1021,10 @@  def _runcommand(ui, options, cmd, cmdfun
 
         output = ui.config('profiling', 'output')
 
-        if output:
+        if output == 'blackbox':
+            import StringIO
+            fp = StringIO.StringIO()
+        elif output:
             path = ui.expandpath(output)
             fp = open(path, 'wb')
         else:
@@ -1036,6 +1039,12 @@  def _runcommand(ui, options, cmd, cmdfun
                 return statprofile(ui, checkargs, fp)
         finally:
             if output:
+                if output == 'blackbox':
+                    val = "Profile:\n%s" % fp.getvalue()
+                    # ui.log treats the input as a format string,
+                    # so we need to escape any % signs.
+                    val = val.replace('%', '%%')
+                    ui.log('profile', val)
                 fp.close()
     else:
         return checkargs()
diff --git a/tests/test-profile.t b/tests/test-profile.t
--- a/tests/test-profile.t
+++ b/tests/test-profile.t
@@ -14,6 +14,9 @@  test --profile
   $ hg --profile --config profiling.output=../out st
   $ grep CallCount ../out > /dev/null || cat ../out
 
+  $ hg --profile --config profiling.output=blackbox --config extensions.blackbox= st
+  $ grep CallCount .hg/blackbox.log > /dev/null || cat .hg/blackbox.log
+
   $ hg --profile --config profiling.format=text st 2>../out
   $ grep CallCount ../out > /dev/null || cat ../out