Rev 4899: Include the -Dhpss fixes into the 2.1.0b4 release. in http://bazaar.launchpad.net/~jameinel/bzr/2.1.0b4-dev
John Arbash Meinel
john at arbash-meinel.com
Mon Dec 14 20:50:58 GMT 2009
At http://bazaar.launchpad.net/~jameinel/bzr/2.1.0b4-dev
------------------------------------------------------------
revno: 4899 [merge]
revision-id: john at arbash-meinel.com-20091214205054-n4g44rxpuhhfnqq5
parent: john at arbash-meinel.com-20091214204957-r71bjr1s6x8qunu3
parent: john at arbash-meinel.com-20091214202313-b7wv74di08p29qjq
committer: John Arbash Meinel <john at arbash-meinel.com>
branch nick: 2.1.0b4-dev
timestamp: Mon 2009-12-14 14:50:54 -0600
message:
Include the -Dhpss fixes into the 2.1.0b4 release.
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
-------------- next part --------------
=== modified file 'NEWS'
--- a/NEWS 2009-12-14 20:49:57 +0000
+++ b/NEWS 2009-12-14 20:50:54 +0000
@@ -34,6 +34,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)
@@ -155,6 +158,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