[PATCH 7 of 7 V2] hgweb: profile HTTP requests

[Gregory Szorc]

# HG changeset patch
# User Gregory Szorc <gregory.szorc at gmail.com>
# Date 1471225044 25200
#      Sun Aug 14 18:37:24 2016 -0700
# Node ID b4b5e216155e6943d32aef14fd461450af98b57b
# Parent  31fae7f40d317b325ba05930a11a9d0bf91f0c8e
hgweb: profile HTTP requests

Currently, running `hg serve --profile` doesn't yield anything useful:
when the process is terminated the profiling output displays results
from the main thread, which typically spends most of its time in
select.select(). Furthermore, it has no meaningful results from
mercurial.* modules because the threads serving HTTP requests don't
actually get profiled.

This patch teaches the hgweb wsgi applications to profile individual
requests. If profiling is enabled, the profiler kicks in after
HTTP/WSGI environment processing but before Mercurial's main request
processing.

The profile results are printed to the configured profiling output.
If running `hg serve` from a shell, they will be printed to stderr,
just before the HTTP request line is logged. If profiling to a file,
we only write a single profile to the file because the file is not
opened in append mode. We could add support for appending to files
in a future patch if someone wants it.

Per request profiling doesn't work with the statprof profiler because
internally that profiler collects samples from the thread that
*initially* requested profiling be enabled. I have plans to address
this by vendoring Facebook's customized statprof and then improving
it.

diff --git a/mercurial/hgweb/hgweb_mod.py b/mercurial/hgweb/hgweb_mod.py
--- a/mercurial/hgweb/hgweb_mod.py
+++ b/mercurial/hgweb/hgweb_mod.py
@@ -23,16 +23,17 @@ from .common import (
 )
 from .request import wsgirequest
 
 from .. import (
     encoding,
     error,
     hg,
     hook,
+    profiling,
     repoview,
     templatefilters,
     templater,
     ui as uimod,
     util,
 )
 
 from . import (
@@ -300,18 +301,19 @@ class hgweb(object):
 
     def run_wsgi(self, req):
         """Internal method to run the WSGI application.
 
         This is typically only called by Mercurial. External consumers
         should be using instances of this class as the WSGI application.
         """
         with self._obtainrepo() as repo:
-            for r in self._runwsgi(req, repo):
-                yield r
+            with profiling.maybeprofile(repo.ui):
+                for r in self._runwsgi(req, repo):
+                    yield r
 
     def _runwsgi(self, req, repo):
         rctx = requestcontext(self, repo)
 
         # This state is global across all threads.
         encoding.encoding = rctx.config('web', 'encoding', encoding.encoding)
         rctx.repo.ui.environ = req.env
 
diff --git a/mercurial/hgweb/hgwebdir_mod.py b/mercurial/hgweb/hgwebdir_mod.py
--- a/mercurial/hgweb/hgwebdir_mod.py
+++ b/mercurial/hgweb/hgwebdir_mod.py
@@ -26,16 +26,17 @@ from .common import (
     staticfile,
 )
 from .request import wsgirequest
 
 from .. import (
     encoding,
     error,
     hg,
+    profiling,
     scmutil,
     templater,
     ui as uimod,
     util,
 )
 
 from . import (
     hgweb_mod,
@@ -212,17 +213,19 @@ class hgwebdir(object):
         allow_read = ui.configlist('web', 'allow_read', untrusted=True)
         # by default, allow reading if no allow_read option has been set
         if (not allow_read) or ismember(ui, user, allow_read):
             return True
 
         return False
 
     def run_wsgi(self, req):
-        return self._runwsgi(req)
+        with profiling.maybeprofile(self.ui):
+            for r in self._runwsgi(req):
+                yield r
 
     def _runwsgi(self, req):
         try:
             self.refresh()
 
             virtual = req.env.get("PATH_INFO", "").strip('/')
             tmpl = self.templater(req)
             ctype = tmpl('mimetype', encoding=encoding.encoding)
diff --git a/tests/test-profile.t b/tests/test-profile.t
--- a/tests/test-profile.t
+++ b/tests/test-profile.t
@@ -26,9 +26,23 @@ test --profile
   $ hg --profile st 2>../out
   $ grep 'events: Ticks' ../out > /dev/null || cat ../out
 
   $ hg --profile --config profiling.output=../out st
   $ grep 'events: Ticks' ../out > /dev/null || cat ../out
 
 #endif
 
+#if lsprof serve
+
+Profiling of HTTP requests works
+
+  $ hg --profile --config profiling.format=text --config profiling.output=../profile.log serve -d -p $HGPORT --pid-file ../hg.pid -A ../access.log
+  $ cat ../hg.pid >> $DAEMON_PIDS
+  $ hg -q clone -U http://localhost:$HGPORT ../clone
+
+A single profile is logged because file logging doesn't append
+  $ grep CallCount ../profile.log | wc -l
+  \s*1 (re)
+
+#endif
+
   $ cd ..