From patchwork Mon Aug 15 00:03:58 2016
Content-Type: text/plain; charset="utf-8"
MIME-Version: 1.0
Content-Transfer-Encoding: 7bit
Subject: [6,of,6] hgweb: profile HTTP requests
From: Gregory Szorc <gregory.szorc@gmail.com>
X-Patchwork-Id: 16294
Message-Id: <817b24db6bea900c690d.1471219438@ubuntu-vm-main>
To: mercurial-devel@mercurial-scm.org
Date: Sun, 14 Aug 2016 17:03:58 -0700

# HG changeset patch
# User Gregory Szorc <gregory.szorc@gmail.com>
# Date 1471219358 25200
#      Sun Aug 14 17:02:38 2016 -0700
# Node ID 817b24db6bea900c690dae7ab0f2d15244d78724
# Parent  a04a42c139225b2f5b3166541fd7466190459822
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.

Having this profiling data has already given me new avenues of
performance optimization to pursue in the HTTP server.

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
+  1
+
+#endif
+
   $ cd ..