Patchwork [2,of,4] profiling: use vendored statprof and upstream enhancements (BC)

login
register
mail settings
Submitter Gregory Szorc
Date Nov. 5, 2016, 4:53 a.m.
Message ID <503459ea99f4b5fa4bd2.1478321621@ubuntu-vm-main>
Download mbox | patch
Permalink /patch/17346/
State Accepted
Headers show

Comments

Gregory Szorc - Nov. 5, 2016, 4:53 a.m.
# HG changeset patch
# User Gregory Szorc <gregory.szorc@gmail.com>
# Date 1478317838 25200
#      Fri Nov 04 20:50:38 2016 -0700
# Node ID 503459ea99f4b5fa4bd2827e36de2e1e8a7696f8
# Parent  cffcf1865da6bdeb0a59de9ac00c563bbadf1a9b
profiling: use vendored statprof and upstream enhancements (BC)

Now that the statprof module is vendored and suitable for use, we
switch our statprof profiler to use it. This required some minor
changes because of drift between the official statprof profiler
and the vendored copy.

We also incorporate Facebook's improvements from the "statprofext"
extension at
https://bitbucket.org/facebook/hg-experimental, notably support for
different display formats.

Because statprof output is different, this is marked as BC. Although
most users likely won't notice since most users don't profile.
Yuya Nishihara - Nov. 8, 2016, 2:29 p.m.
On Fri, 04 Nov 2016 21:53:41 -0700, Gregory Szorc wrote:
> # HG changeset patch
> # User Gregory Szorc <gregory.szorc@gmail.com>
> # Date 1478317838 25200
> #      Fri Nov 04 20:50:38 2016 -0700
> # Node ID 503459ea99f4b5fa4bd2827e36de2e1e8a7696f8
> # Parent  cffcf1865da6bdeb0a59de9ac00c563bbadf1a9b
> profiling: use vendored statprof and upstream enhancements (BC)

> +            ui.warn(_('unknown profiler output format: %s') % profformat)

Oops, fixed missed '\n'.

Patch

diff --git a/mercurial/help/config.txt b/mercurial/help/config.txt
--- a/mercurial/help/config.txt
+++ b/mercurial/help/config.txt
@@ -1409,9 +1409,9 @@  profiling is done using lsprof.
       first line of a function. This restriction makes it difficult to
       identify the expensive parts of a non-trivial function.
     ``stat``
-      Use a third-party statistical profiler, statprof. This profiler
-      currently runs only on Unix systems, and is most useful for
-      profiling commands that run for longer than about 0.1 seconds.
+      Use a statistical profiler, statprof. This profiler is most
+      most useful for profiling commands that run for longer than
+      about 0.1 seconds.
 
 ``format``
     Profiling format.  Specific to the ``ls`` instrumenting profiler.
@@ -1426,6 +1426,20 @@  profiling is done using lsprof.
       file, the generated file can directly be loaded into
       kcachegrind.
 
+``statformat``
+    Profiling format for the ``stat`` profiler.
+    (default: hotpath)
+
+    ``hotpath``
+      Show a tree-based display containing the hot path of execution (where
+      most time was spent).
+    ``bymethod``
+      Show a table of methods ordered by how frequently they are active.
+    ``byline``
+      Show a table of lines in files ordered by how frequently they are active.
+    ``json``
+      Render profiling data as JSON.
+
 ``frequency``
     Sampling frequency.  Specific to the ``stat`` sampling profiler.
     (default: 1000)
diff --git a/mercurial/profiling.py b/mercurial/profiling.py
--- a/mercurial/profiling.py
+++ b/mercurial/profiling.py
@@ -80,11 +80,7 @@  def flameprofile(ui, fp):
 
 @contextlib.contextmanager
 def statprofile(ui, fp):
-    try:
-        import statprof
-    except ImportError:
-        raise error.Abort(_(
-            'statprof not available - install using "easy_install statprof"'))
+    from . import statprof
 
     freq = ui.configint('profiling', 'freq', default=1000)
     if freq > 0:
@@ -94,12 +90,29 @@  def statprofile(ui, fp):
     else:
         ui.warn(_("invalid sampling frequency '%s' - ignoring\n") % freq)
 
-    statprof.start()
+    statprof.start(mechanism='thread')
+
     try:
         yield
     finally:
-        statprof.stop()
-        statprof.display(fp)
+        data = statprof.stop()
+
+        profformat = ui.config('profiling', 'statformat', 'hotpath')
+
+        formats = {
+            'byline': statprof.DisplayFormats.ByLine,
+            'bymethod': statprof.DisplayFormats.ByMethod,
+            'hotpath': statprof.DisplayFormats.Hotpath,
+            'json': statprof.DisplayFormats.Json,
+        }
+
+        if profformat in formats:
+            displayformat = formats[profformat]
+        else:
+            ui.warn(_('unknown profiler output format: %s') % profformat)
+            displayformat = statprof.DisplayFormats.Hotpath
+
+        statprof.display(fp, data=data, format=displayformat)
 
 @contextlib.contextmanager
 def profile(ui):
diff --git a/tests/test-profile.t b/tests/test-profile.t
--- a/tests/test-profile.t
+++ b/tests/test-profile.t
@@ -47,4 +47,49 @@  A single profile is logged because file 
 
 #endif
 
+Install an extension that can sleep and guarantee a profiler has time to run
+
+  $ cat >> sleepext.py << EOF
+  > import time
+  > from mercurial import cmdutil, commands
+  > cmdtable = {}
+  > command = cmdutil.command(cmdtable)
+  > @command('sleep', [], 'hg sleep')
+  > def sleep(ui, *args, **kwargs):
+  >     time.sleep(0.1)
+  > EOF
+
+  $ cat >> $HGRCPATH << EOF
+  > [extensions]
+  > sleep = `pwd`/sleepext.py
+  > EOF
+
+statistical profiler works
+
+  $ HGPROF=stat hg --profile sleep 2>../out
+  $ grep Sample ../out
+  Sample count: \d+ (re)
+
+Various statprof formatters work
+
+  $ HGPROF=stat hg --profile --config profiling.statformat=byline sleep 2>../out
+  $ head -n 1 ../out
+    %   cumulative      self          
+  $ grep Sample ../out
+  Sample count: \d+ (re)
+
+  $ HGPROF=stat hg --profile --config profiling.statformat=bymethod sleep 2>../out
+  $ head -n 1 ../out
+    %   cumulative      self          
+  $ grep Sample ../out
+  Sample count: \d+ (re)
+
+  $ HGPROF=stat hg --profile --config profiling.statformat=hotpath sleep 2>../out
+  $ grep Sample ../out
+  Sample count: \d+ (re)
+
+  $ HGPROF=stat hg --profile --config profiling.statformat=json sleep 2>../out
+  $ cat ../out
+  \[\[\d+.* (re)
+
   $ cd ..