Rev 4890: Make -Dhpss log debug information for the server process. in http://bazaar.launchpad.net/~jameinel/bzr/2.1-Dhpss-server
John Arbash Meinel
john at arbash-meinel.com
Fri Dec 11 21:45:31 GMT 2009
At http://bazaar.launchpad.net/~jameinel/bzr/2.1-Dhpss-server
------------------------------------------------------------
revno: 4890
revision-id: john at arbash-meinel.com-20091211214527-7c7yzh15spl8o8d3
parent: pqm at pqm.ubuntu.com-20091210235739-zwgaqsbb2mk57gyv
committer: John Arbash Meinel <john at arbash-meinel.com>
branch nick: 2.1-Dhpss-server
timestamp: Fri 2009-12-11 15:45:27 -0600
message:
Make -Dhpss log debug information for the server process.
hpssdetail will dump individual chunk information, and hpss will
dump information about every request made, and the basic response info.
-------------- next part --------------
=== modified file 'NEWS'
--- a/NEWS 2009-12-10 21:49:20 +0000
+++ b/NEWS 2009-12-11 21:45:27 +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)
+
* The ``BZR_COLUMNS`` envrionment variable can be set to force bzr to
respect a given terminal width. This can be useful when output is
redirected or in obscure cases where the default value is not
@@ -128,6 +131,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-11 21:45:27 +0000
@@ -71,6 +71,10 @@
from bzrlib import symbol_versioning
+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:45:27 +0000
@@ -295,7 +295,11 @@
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:
+ trace.mutter('%12s: %d bytes to the socket in %.3fs'
+ % ('wrote', 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-11 21:45:27 +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,26 @@
_ProtocolThreeEncoder.__init__(self, write_func)
self.response_sent = False
self._headers = {'Software version': bzrlib.__version__}
+ if 'hpss' in debug.debug_flags:
+ import threading
+ self._thread_id = threading.currentThread().ident
+ self._response_start_time = None
+
+ def _trace(self, action, message, extra_bytes=None, suppress_time=False):
+ if self._response_start_time is None:
+ self._response_start_time = osutils.timer_func()
+ if suppress_time:
+ t = ''
+ else:
+ t = '%5.3fs ' % (time.clock() - self._response_start_time)
+ 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 +1173,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 +1194,19 @@
self._write_success_status()
else:
self._write_error_status()
+ if 'hpss' in debug.debug_flags:
+ self._trace('response', repr(response.args), suppress_time=True)
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)
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,7 +1217,19 @@
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', '%d bytes %d chunks' % (num_bytes, count),
+ response.body)
self._write_end()
@@ -1230,11 +1284,12 @@
def call(self, *args):
if 'hpss' in debug.debug_flags:
+ import pdb; pdb.set_trace()
mutter('hpss call: %s', repr(args)[1:-1])
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 +1307,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 +1326,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 +1343,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-11 21:45:27 +0000
@@ -36,7 +36,9 @@
from bzrlib import (
bzrdir,
+ debug,
errors,
+ osutils,
registry,
revision,
trace,
@@ -287,6 +289,23 @@
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().ident
+
+ def _trace(self, action, message, extra_bytes=None, suppress_time=False):
+ if suppress_time:
+ t = ''
+ else:
+ t = '%5.3fs ' % (osutils.timer_func() - self._request_start_time)
+ 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 +313,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', '')
def _run_handler_code(self, callable, args, kwargs):
"""Run some handler specific code 'callable'.
@@ -334,7 +358,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 +367,20 @@
try:
command = self._commands.get(cmd)
except LookupError:
+ if 'hpss' in debug.debug_flags:
+ self._trace('hpss unknown request',
+ cmd, repr(args)[1:-1],
+ suppress_time=True)
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]),
+ suppress_time=True)
self._command = command(
self._backing_transport, self._root_client_path, self._jail_root)
self._run_handler_code(self._command.execute, args, {})
@@ -352,6 +390,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', '')
def post_body_error_received(self, error_args):
# Just a no-op at the moment.
More information about the bazaar-commits
mailing list