Rev 4898: (jam) -Dhpss now triggers extra logging on the server side. in file:///home/pqm/archives/thelove/bzr/%2Btrunk/

Canonical.com Patch Queue Manager pqm at pqm.ubuntu.com
Mon Dec 14 23:32:23 GMT 2009


At file:///home/pqm/archives/thelove/bzr/%2Btrunk/

------------------------------------------------------------
revno: 4898 [merge]
revision-id: pqm at pqm.ubuntu.com-20091214233217-rwmfxbxwvgj292k0
parent: pqm at pqm.ubuntu.com-20091214210556-31viujd7fmprh0d0
parent: john at arbash-meinel.com-20091214202313-b7wv74di08p29qjq
committer: Canonical.com Patch Queue Manager <pqm at pqm.ubuntu.com>
branch nick: +trunk
timestamp: Mon 2009-12-14 23:32:17 +0000
message:
  (jam) -Dhpss now triggers extra logging on the server side.
modified:
  NEWS                           NEWS-20050323055033-4e00b5db738777ff
  bzrlib/osutils.py              osutils.py-20050309040759-eeaff12fbf77ac86
  bzrlib/smart/medium.py         medium.py-20061103051856-rgu2huy59fkz902q-1
  bzrlib/smart/protocol.py       protocol.py-20061108035435-ot0lstk2590yqhzr-1
  bzrlib/smart/request.py        request.py-20061108095550-gunadhxmzkdjfeek-1
=== modified file 'NEWS'
--- a/NEWS	2009-12-14 21:05:56 +0000
+++ b/NEWS	2009-12-14 23:32:17 +0000
@@ -26,6 +26,9 @@
 * ``bzr commit`` now has a ``--commit-time`` option.
   (Alexander Sack, #459276)
 
+* ``-Dhpss`` now increases logging done when run on the bzr server,
+  similarly to how it works on the client. (John Arbash Meinel)
+
 * New option ``bzr unshelve --keep`` applies the changes and leaves them
   on the shelf.  (Martin Pool, Oscar Fuentes, #492091)
 
@@ -140,6 +143,12 @@
   imported. (Rather than lots of custom-implemented features that were
   basically copy-and-pasted.) (John Arbash Meinel)
 
+* ``osutils.timer_func()`` can be used to get either ``time.time()`` or
+  ``time.clock()`` when you want to do performance timing.
+  ``time.time()`` is limited to 15ms resolution on Windows, but
+  ``time.clock()`` gives CPU and not wall-clock time on other platforms.
+  (John Arbash Meinel)
+
 * Several code paths that were calling ``Transport.get().read()`` have
   been changed to the equalivent ``Transport.get_bytes()``. The main
   difference is that the latter will explicitly call ``file.close()``,

=== modified file 'bzrlib/osutils.py'
--- a/bzrlib/osutils.py	2009-12-09 14:18:48 +0000
+++ b/bzrlib/osutils.py	2009-12-14 16:16:05 +0000
@@ -71,6 +71,15 @@
 from bzrlib import symbol_versioning
 
 
+# Cross platform wall-clock time functionality with decent resolution.
+# On Linux ``time.clock`` returns only CPU time. On Windows, ``time.time()``
+# only has a resolution of ~15ms. Note that ``time.clock()`` is not
+# synchronized with ``time.time()``, this is only meant to be used to find
+# delta times by subtracting from another call to this function.
+timer_func = time.time
+if sys.platform == 'win32':
+    timer_func = time.clock
+
 # On win32, O_BINARY is used to indicate the file should
 # be opened in binary mode, rather than text mode.
 # On other platforms, O_BINARY doesn't exist, because

=== modified file 'bzrlib/smart/medium.py'
--- a/bzrlib/smart/medium.py	2009-09-01 07:47:36 +0000
+++ b/bzrlib/smart/medium.py	2009-12-11 21:57:03 +0000
@@ -33,7 +33,9 @@
 from bzrlib.lazy_import import lazy_import
 lazy_import(globals(), """
 import atexit
+import threading
 import weakref
+
 from bzrlib import (
     debug,
     errors,
@@ -295,7 +297,13 @@
         self.finished = True
 
     def _write_out(self, bytes):
+        tstart = osutils.timer_func()
         osutils.send_all(self.socket, bytes, self._report_activity)
+        if 'hpss' in debug.debug_flags:
+            thread_id = threading.currentThread().ident
+            trace.mutter('%12s: [%s] %d bytes to the socket in %.3fs'
+                         % ('wrote', thread_id, len(bytes),
+                            osutils.timer_func() - tstart))
 
 
 class SmartServerPipeStreamMedium(SmartServerStreamMedium):

=== modified file 'bzrlib/smart/protocol.py'
--- a/bzrlib/smart/protocol.py	2009-10-21 06:05:49 +0000
+++ b/bzrlib/smart/protocol.py	2009-12-14 16:16:05 +0000
@@ -22,11 +22,15 @@
 from cStringIO import StringIO
 import struct
 import sys
+import threading
 import time
 
 import bzrlib
-from bzrlib import debug
-from bzrlib import errors
+from bzrlib import (
+    debug,
+    errors,
+    osutils,
+    )
 from bzrlib.smart import message, request
 from bzrlib.trace import log_exception_quietly, mutter
 from bzrlib.bencode import bdecode_as_tuple, bencode
@@ -615,7 +619,7 @@
             mutter('hpss call:   %s', repr(args)[1:-1])
             if getattr(self._request._medium, 'base', None) is not None:
                 mutter('             (to %s)', self._request._medium.base)
-            self._request_start_time = time.time()
+            self._request_start_time = osutils.timer_func()
         self._write_args(args)
         self._request.finished_writing()
         self._last_verb = args[0]
@@ -630,7 +634,7 @@
             if getattr(self._request._medium, '_path', None) is not None:
                 mutter('                  (to %s)', self._request._medium._path)
             mutter('              %d bytes', len(body))
-            self._request_start_time = time.time()
+            self._request_start_time = osutils.timer_func()
             if 'hpssdetail' in debug.debug_flags:
                 mutter('hpss body content: %s', body)
         self._write_args(args)
@@ -649,7 +653,7 @@
             mutter('hpss call w/readv: %s', repr(args)[1:-1])
             if getattr(self._request._medium, '_path', None) is not None:
                 mutter('                  (to %s)', self._request._medium._path)
-            self._request_start_time = time.time()
+            self._request_start_time = osutils.timer_func()
         self._write_args(args)
         readv_bytes = self._serialise_offsets(body)
         bytes = self._encode_bulk_data(readv_bytes)
@@ -681,7 +685,7 @@
         if 'hpss' in debug.debug_flags:
             if self._request_start_time is not None:
                 mutter('   result:   %6.3fs  %s',
-                       time.time() - self._request_start_time,
+                       osutils.timer_func() - self._request_start_time,
                        repr(result)[1:-1])
                 self._request_start_time = None
             else:
@@ -1068,6 +1072,14 @@
         self._real_write_func = write_func
 
     def _write_func(self, bytes):
+        # TODO: It is probably more appropriate to use sum(map(len, _buf))
+        #       for total number of bytes to write, rather than buffer based on
+        #       the number of write() calls
+        # TODO: Another possibility would be to turn this into an async model.
+        #       Where we let another thread know that we have some bytes if
+        #       they want it, but we don't actually block for it
+        #       Note that osutils.send_all always sends 64kB chunks anyway, so
+        #       we might just push out smaller bits at a time?
         self._buf.append(bytes)
         if len(self._buf) > 100:
             self.flush()
@@ -1130,6 +1142,25 @@
         _ProtocolThreeEncoder.__init__(self, write_func)
         self.response_sent = False
         self._headers = {'Software version': bzrlib.__version__}
+        if 'hpss' in debug.debug_flags:
+            self._thread_id = threading.currentThread().get_ident()
+            self._response_start_time = None
+
+    def _trace(self, action, message, extra_bytes=None, include_time=False):
+        if self._response_start_time is None:
+            self._response_start_time = osutils.timer_func()
+        if include_time:
+            t = '%5.3fs ' % (time.clock() - self._response_start_time)
+        else:
+            t = ''
+        if extra_bytes is None:
+            extra = ''
+        else:
+            extra = ' ' + repr(extra_bytes[:40])
+            if len(extra) > 33:
+                extra = extra[:29] + extra[-1] + '...'
+        mutter('%12s: [%s] %s%s%s'
+               % (action, self._thread_id, t, message, extra))
 
     def send_error(self, exception):
         if self.response_sent:
@@ -1141,6 +1172,8 @@
                 ('UnknownMethod', exception.verb))
             self.send_response(failure)
             return
+        if 'hpss' in debug.debug_flags:
+            self._trace('error', str(exception))
         self.response_sent = True
         self._write_protocol_version()
         self._write_headers(self._headers)
@@ -1160,11 +1193,19 @@
             self._write_success_status()
         else:
             self._write_error_status()
+        if 'hpss' in debug.debug_flags:
+            self._trace('response', repr(response.args))
         self._write_structure(response.args)
         if response.body is not None:
             self._write_prefixed_body(response.body)
+            if 'hpss' in debug.debug_flags:
+                self._trace('body', '%d bytes' % (len(response.body),),
+                            response.body, include_time=True)
         elif response.body_stream is not None:
+            count = num_bytes = 0
+            first_chunk = None
             for exc_info, chunk in _iter_with_errors(response.body_stream):
+                count += 1
                 if exc_info is not None:
                     self._write_error_status()
                     error_struct = request._translate_error(exc_info[1])
@@ -1175,8 +1216,23 @@
                         self._write_error_status()
                         self._write_structure(chunk.args)
                         break
+                    num_bytes += len(chunk)
+                    if first_chunk is None:
+                        first_chunk = chunk
                     self._write_prefixed_body(chunk)
+                    if 'hpssdetail' in debug.debug_flags:
+                        # Not worth timing separately, as _write_func is
+                        # actually buffered
+                        self._trace('body chunk',
+                                    '%d bytes' % (len(chunk),),
+                                    chunk, suppress_time=True)
+            if 'hpss' in debug.debug_flags:
+                self._trace('body stream',
+                            '%d bytes %d chunks' % (num_bytes, count),
+                            first_chunk)
         self._write_end()
+        if 'hpss' in debug.debug_flags:
+            self._trace('response end', '', include_time=True)
 
 
 def _iter_with_errors(iterable):
@@ -1234,7 +1290,7 @@
             base = getattr(self._medium_request._medium, 'base', None)
             if base is not None:
                 mutter('             (to %s)', base)
-            self._request_start_time = time.time()
+            self._request_start_time = osutils.timer_func()
         self._write_protocol_version()
         self._write_headers(self._headers)
         self._write_structure(args)
@@ -1252,7 +1308,7 @@
             if path is not None:
                 mutter('                  (to %s)', path)
             mutter('              %d bytes', len(body))
-            self._request_start_time = time.time()
+            self._request_start_time = osutils.timer_func()
         self._write_protocol_version()
         self._write_headers(self._headers)
         self._write_structure(args)
@@ -1271,7 +1327,7 @@
             path = getattr(self._medium_request._medium, '_path', None)
             if path is not None:
                 mutter('                  (to %s)', path)
-            self._request_start_time = time.time()
+            self._request_start_time = osutils.timer_func()
         self._write_protocol_version()
         self._write_headers(self._headers)
         self._write_structure(args)
@@ -1288,7 +1344,7 @@
             path = getattr(self._medium_request._medium, '_path', None)
             if path is not None:
                 mutter('                  (to %s)', path)
-            self._request_start_time = time.time()
+            self._request_start_time = osutils.timer_func()
         self._write_protocol_version()
         self._write_headers(self._headers)
         self._write_structure(args)

=== modified file 'bzrlib/smart/request.py'
--- a/bzrlib/smart/request.py	2009-10-29 00:25:26 +0000
+++ b/bzrlib/smart/request.py	2009-12-14 16:16:05 +0000
@@ -36,7 +36,9 @@
 
 from bzrlib import (
     bzrdir,
+    debug,
     errors,
+    osutils,
     registry,
     revision,
     trace,
@@ -287,6 +289,27 @@
         self.response = None
         self.finished_reading = False
         self._command = None
+        if 'hpss' in debug.debug_flags:
+            self._request_start_time = osutils.timer_func()
+            self._thread_id = threading.currentThread().get_ident()
+
+    def _trace(self, action, message, extra_bytes=None, include_time=False):
+        # It is a bit of a shame that this functionality overlaps with that of 
+        # ProtocolThreeRequester._trace. However, there is enough difference
+        # that just putting it in a helper doesn't help a lot. And some state
+        # is taken from the instance.
+        if include_time:
+            t = '%5.3fs ' % (osutils.timer_func() - self._request_start_time)
+        else:
+            t = ''
+        if extra_bytes is None:
+            extra = ''
+        else:
+            extra = ' ' + repr(extra_bytes[:40])
+            if len(extra) > 33:
+                extra = extra[:29] + extra[-1] + '...'
+        trace.mutter('%12s: [%s] %s%s%s'
+                     % (action, self._thread_id, t, message, extra))
 
     def accept_body(self, bytes):
         """Accept body data."""
@@ -294,12 +317,17 @@
             # no active command object, so ignore the event.
             return
         self._run_handler_code(self._command.do_chunk, (bytes,), {})
+        if 'hpss' in debug.debug_flags:
+            self._trace('accept body',
+                        '%d bytes' % (len(bytes),), bytes)
 
     def end_of_body(self):
         """No more body data will be received."""
         self._run_handler_code(self._command.do_end, (), {})
         # cannot read after this.
         self.finished_reading = True
+        if 'hpss' in debug.debug_flags:
+            self._trace('end of body', '', include_time=True)
 
     def _run_handler_code(self, callable, args, kwargs):
         """Run some handler specific code 'callable'.
@@ -334,7 +362,8 @@
 
     def headers_received(self, headers):
         # Just a no-op at the moment.
-        pass
+        if 'hpss' in debug.debug_flags:
+            self._trace('headers', repr(headers))
 
     def args_received(self, args):
         cmd = args[0]
@@ -342,7 +371,18 @@
         try:
             command = self._commands.get(cmd)
         except LookupError:
+            if 'hpss' in debug.debug_flags:
+                self._trace('hpss unknown request', 
+                            cmd, repr(args)[1:-1])
             raise errors.UnknownSmartMethod(cmd)
+        if 'hpss' in debug.debug_flags:
+            from bzrlib.smart import vfs
+            if issubclass(command, vfs.VfsRequest):
+                action = 'hpss vfs req'
+            else:
+                action = 'hpss request'
+            self._trace(action, 
+                        '%s %s' % (cmd, repr(args)[1:-1]))
         self._command = command(
             self._backing_transport, self._root_client_path, self._jail_root)
         self._run_handler_code(self._command.execute, args, {})
@@ -352,6 +392,8 @@
             # no active command object, so ignore the event.
             return
         self._run_handler_code(self._command.do_end, (), {})
+        if 'hpss' in debug.debug_flags:
+            self._trace('end', '', include_time=True)
 
     def post_body_error_received(self, error_args):
         # Just a no-op at the moment.




More information about the bazaar-commits mailing list