httppeer: add support for tracing all http request made by the peer
authorBoris Feld <boris.feld@octobus.net>
Fri, 12 Jan 2018 10:41:03 +0000
changeset 35698 0c4b23ccf1a5
parent 35697 5a7906ed78d4
child 35699 f7ef49e44d7c
httppeer: add support for tracing all http request made by the peer This changeset introduces a new 'devel.debug.peer-request' config. When set to True, debug message about request made by peer will be issued. This help to understand what actually happens during an exchange and tracks source of performance loss. This changeset implement support for http peer only.
mercurial/configitems.py
mercurial/httppeer.py
tests/test-http.t
--- a/mercurial/configitems.py	Fri Jan 12 10:14:20 2018 +0000
+++ b/mercurial/configitems.py	Fri Jan 12 10:41:03 2018 +0000
@@ -362,6 +362,9 @@
 coreconfigitem('devel', 'warn-config-unknown',
     default=None,
 )
+coreconfigitem('devel', 'debug.peer-request',
+    default=False,
+)
 coreconfigitem('diff', 'nodates',
     default=False,
 )
--- a/mercurial/httppeer.py	Fri Jan 12 10:14:20 2018 +0000
+++ b/mercurial/httppeer.py	Fri Jan 12 10:41:03 2018 +0000
@@ -162,7 +162,39 @@
                 getattr(h, "close_all", lambda: None)()
 
     def _openurl(self, req):
-        return self._urlopener.open(req)
+        if (self._ui.debugflag
+            and self._ui.configbool('devel', 'debug.peer-request')):
+            dbg = self._ui.debug
+            line = 'devel-peer-request: %s\n'
+            dbg(line % '%s %s' % (req.get_method(), req.get_full_url()))
+            hgargssize = None
+
+            for header, value in sorted(req.header_items()):
+                if header.startswith('X-hgarg-'):
+                    if hgargssize is None:
+                        hgargssize = 0
+                    hgargssize += len(value)
+                else:
+                    dbg(line % '  %s %s' % (header, value))
+
+            if hgargssize is not None:
+                dbg(line % '  %d bytes of commands arguments in headers'
+                    % hgargssize)
+
+            if req.has_data():
+                data = req.get_data()
+                length = getattr(data, 'length', None)
+                if length is None:
+                    length = len(data)
+                dbg(line % '  %d bytes of data' % length)
+
+            start = util.timer()
+
+        ret = self._urlopener.open(req)
+        if self._ui.configbool('devel', 'debug.peer-request'):
+            dbg(line % '  finished in %.4f seconds (%s)'
+                % (util.timer() - start, ret.code))
+        return ret
 
     # Begin of _basepeer interface.
 
--- a/tests/test-http.t	Fri Jan 12 10:14:20 2018 +0000
+++ b/tests/test-http.t	Fri Jan 12 10:41:03 2018 +0000
@@ -248,27 +248,57 @@
   remote: adding file changes
   remote: added 1 changesets with 1 changes to 1 files
   $ hg rollback -q
-  $ hg -R dest push http://user:pass@localhost:$HGPORT2/ --debug
+  $ hg -R dest push http://user:pass@localhost:$HGPORT2/ --debug --config devel.debug.peer-request=yes
   pushing to http://user:***@localhost:$HGPORT2/
   using http://localhost:$HGPORT2/
   http auth: user user, password ****
   sending capabilities command
+  devel-peer-request: GET http://localhost:$HGPORT2/?cmd=capabilities
+  devel-peer-request:   finished in *.???? seconds (200) (glob)
   query 1; heads
   sending batch command
+  devel-peer-request: GET http://localhost:$HGPORT2/?cmd=batch
+  devel-peer-request:   Vary X-HgArg-1,X-HgProto-1
+  devel-peer-request:   X-hgproto-1 0.1 0.2 comp=$USUAL_COMPRESSIONS$
+  devel-peer-request:   68 bytes of commands arguments in headers
+  devel-peer-request:   finished in *.???? seconds (200) (glob)
   searching for changes
   all remote heads known locally
   preparing listkeys for "phases"
   sending listkeys command
+  devel-peer-request: GET http://localhost:$HGPORT2/?cmd=listkeys
+  devel-peer-request:   Vary X-HgArg-1,X-HgProto-1
+  devel-peer-request:   X-hgproto-1 0.1 0.2 comp=$USUAL_COMPRESSIONS$
+  devel-peer-request:   16 bytes of commands arguments in headers
   http auth: user user, password ****
+  devel-peer-request:   finished in *.???? seconds (200) (glob)
   received listkey for "phases": 58 bytes
   checking for updated bookmarks
   preparing listkeys for "bookmarks"
   sending listkeys command
+  devel-peer-request: GET http://localhost:$HGPORT2/?cmd=listkeys
+  devel-peer-request:   Vary X-HgArg-1,X-HgProto-1
+  devel-peer-request:   X-hgproto-1 0.1 0.2 comp=$USUAL_COMPRESSIONS$
+  devel-peer-request:   19 bytes of commands arguments in headers
+  devel-peer-request:   finished in *.???? seconds (200) (glob)
   received listkey for "bookmarks": 0 bytes
   sending branchmap command
+  devel-peer-request: GET http://localhost:$HGPORT2/?cmd=branchmap
+  devel-peer-request:   Vary X-HgProto-1
+  devel-peer-request:   X-hgproto-1 0.1 0.2 comp=$USUAL_COMPRESSIONS$
+  devel-peer-request:   finished in *.???? seconds (200) (glob)
   sending branchmap command
+  devel-peer-request: GET http://localhost:$HGPORT2/?cmd=branchmap
+  devel-peer-request:   Vary X-HgProto-1
+  devel-peer-request:   X-hgproto-1 0.1 0.2 comp=$USUAL_COMPRESSIONS$
+  devel-peer-request:   finished in *.???? seconds (200) (glob)
   preparing listkeys for "bookmarks"
   sending listkeys command
+  devel-peer-request: GET http://localhost:$HGPORT2/?cmd=listkeys
+  devel-peer-request:   Vary X-HgArg-1,X-HgProto-1
+  devel-peer-request:   X-hgproto-1 0.1 0.2 comp=$USUAL_COMPRESSIONS$
+  devel-peer-request:   19 bytes of commands arguments in headers
+  devel-peer-request:   finished in *.???? seconds (200) (glob)
   received listkey for "bookmarks": 0 bytes
   1 changesets found
   list of changesets:
@@ -281,6 +311,14 @@
   bundle2-output-part: "phase-heads" 24 bytes payload
   sending unbundle command
   sending 986 bytes
+  devel-peer-request: POST http://localhost:$HGPORT2/?cmd=unbundle
+  devel-peer-request:   Content-length 986
+  devel-peer-request:   Content-type application/mercurial-0.1
+  devel-peer-request:   Vary X-HgArg-1,X-HgProto-1
+  devel-peer-request:   X-hgproto-1 0.1 0.2 comp=$USUAL_COMPRESSIONS$
+  devel-peer-request:   16 bytes of commands arguments in headers
+  devel-peer-request:   986 bytes of data
+  devel-peer-request:   finished in *.???? seconds (200) (glob)
   bundle2-input-bundle: no-transaction
   bundle2-input-part: "reply:changegroup" (advisory) (params: 0 advisory) supported
   bundle2-input-part: "output" (advisory) (params: 0 advisory) supported
@@ -293,6 +331,11 @@
   bundle2-input-bundle: 2 parts total
   preparing listkeys for "phases"
   sending listkeys command
+  devel-peer-request: GET http://localhost:$HGPORT2/?cmd=listkeys
+  devel-peer-request:   Vary X-HgArg-1,X-HgProto-1
+  devel-peer-request:   X-hgproto-1 0.1 0.2 comp=$USUAL_COMPRESSIONS$
+  devel-peer-request:   16 bytes of commands arguments in headers
+  devel-peer-request:   finished in *.???? seconds (200) (glob)
   received listkey for "phases": 15 bytes
   $ hg rollback -q