Rev 2688: (John Arbash Meinel) Add timing information to hpss logging in file:///home/pqm/archives/thelove/bzr/%2Btrunk/
Canonical.com Patch Queue Manager
pqm at pqm.ubuntu.com
Thu Aug 9 04:34:58 BST 2007
At file:///home/pqm/archives/thelove/bzr/%2Btrunk/
------------------------------------------------------------
revno: 2688
revision-id: pqm at pqm.ubuntu.com-20070809033454-r4dk8909z5zxspum
parent: pqm at pqm.ubuntu.com-20070809000503-7gad4qd85xll5ucf
parent: john at arbash-meinel.com-20070808143456-wa00r4p8r146p689
committer: Canonical.com Patch Queue Manager <pqm at pqm.ubuntu.com>
branch nick: +trunk
timestamp: Thu 2007-08-09 04:34:54 +0100
message:
(John Arbash Meinel) Add timing information to hpss logging
modified:
NEWS NEWS-20050323055033-4e00b5db738777ff
bzrlib/smart/protocol.py protocol.py-20061108035435-ot0lstk2590yqhzr-1
doc/developers/profiling.txt profiling.txt-20070531045713-j15mxufywgzwdeu8-1
------------------------------------------------------------
revno: 2664.4.8
merged: john at arbash-meinel.com-20070808143456-wa00r4p8r146p689
parent: john at arbash-meinel.com-20070808141202-weal00qm5rwqqf1s
parent: pqm at pqm.ubuntu.com-20070808113110-acathx9d9mpfo80z
committer: John Arbash Meinel <john at arbash-meinel.com>
branch nick: hpss_debug_timing
timestamp: Wed 2007-08-08 09:34:56 -0500
message:
[merge] bzr.dev 2685
------------------------------------------------------------
revno: 2664.4.7
merged: john at arbash-meinel.com-20070808141202-weal00qm5rwqqf1s
parent: john at arbash-meinel.com-20070731213353-2ulbrrh3c8edyo80
committer: John Arbash Meinel <john at arbash-meinel.com>
branch nick: hpss_debug_timing
timestamp: Wed 2007-08-08 09:12:02 -0500
message:
Add NEWS and doc/developers/profiling.txt entries from Ian's feedback
------------------------------------------------------------
revno: 2664.4.6
merged: john at arbash-meinel.com-20070731213353-2ulbrrh3c8edyo80
parent: john at arbash-meinel.com-20070731212002-tq2bht51jbfedjlk
committer: John Arbash Meinel <john at arbash-meinel.com>
branch nick: hpss_debug_timing
timestamp: Tue 2007-07-31 16:33:53 -0500
message:
Restore a line that shouldn't have been removed
------------------------------------------------------------
revno: 2664.4.5
merged: john at arbash-meinel.com-20070731212002-tq2bht51jbfedjlk
parent: john at arbash-meinel.com-20070731203847-2k1kby0spd95pcr2
committer: John Arbash Meinel <john at arbash-meinel.com>
branch nick: hpss_debug_timing
timestamp: Tue 2007-07-31 16:20:02 -0500
message:
Stop tracking medium bytes if we aren't going to use it
------------------------------------------------------------
revno: 2664.4.4
merged: john at arbash-meinel.com-20070731203847-2k1kby0spd95pcr2
parent: john at arbash-meinel.com-20070731203101-p7h45wm6v4x6nb18
committer: John Arbash Meinel <john at arbash-meinel.com>
branch nick: hpss_debug_timing
timestamp: Tue 2007-07-31 15:38:47 -0500
message:
Switch around what bytes get logged.
Don't bother writing the header bytes, because you know what was
written by the tuple you see logged.
------------------------------------------------------------
revno: 2664.4.3
merged: john at arbash-meinel.com-20070731203101-p7h45wm6v4x6nb18
parent: john at arbash-meinel.com-20070731181501-dnfycgar5ld0dqa9
committer: John Arbash Meinel <john at arbash-meinel.com>
branch nick: hpss_debug_timing
timestamp: Tue 2007-07-31 15:31:01 -0500
message:
Update to include a bit better formatting
And include logging of number of bytes transmitted.
------------------------------------------------------------
revno: 2664.4.2
merged: john at arbash-meinel.com-20070731181501-dnfycgar5ld0dqa9
parent: john at arbash-meinel.com-20070731180942-699o4e173i6h4878
committer: John Arbash Meinel <john at arbash-meinel.com>
branch nick: hpss_debug_timing
timestamp: Tue 2007-07-31 13:15:01 -0500
message:
Add debug timings for operations that have to send data
------------------------------------------------------------
revno: 2664.4.1
merged: john at arbash-meinel.com-20070731180942-699o4e173i6h4878
parent: pqm at pqm.ubuntu.com-20070731122244-f1jemfecukeevugw
committer: John Arbash Meinel <john at arbash-meinel.com>
branch nick: hpss_debug_timing
timestamp: Tue 2007-07-31 13:09:42 -0500
message:
Add timing information for call/response groups for hpss
=== modified file 'NEWS'
--- a/NEWS 2007-08-09 00:05:03 +0000
+++ b/NEWS 2007-08-09 03:34:54 +0000
@@ -206,6 +206,9 @@
* Graph now has an is_ancestor method, various bits use it.
(Aaron Bentley)
+ * The ``-Dhpss`` flag now includes timing information. As well as
+ logging when a new connection is opened. (John Arbash Meinel)
+
* ``bzrlib.pack.ContainerWriter`` now returns an offset, length tuple to
callers when inserting data, allowing generation of readv style access
during pack creation, without needing a separate pass across the output
=== modified file 'bzrlib/smart/protocol.py'
--- a/bzrlib/smart/protocol.py 2007-08-02 06:40:58 +0000
+++ b/bzrlib/smart/protocol.py 2007-08-08 14:34:56 +0000
@@ -18,8 +18,8 @@
client and server.
"""
-
from cStringIO import StringIO
+import time
from bzrlib import debug
from bzrlib import errors
@@ -300,10 +300,12 @@
"""
self._request = request
self._body_buffer = None
+ self._request_start_time = None
def call(self, *args):
if 'hpss' in debug.debug_flags:
- mutter('hpss call: %r', args)
+ mutter('hpss call: %s', repr(args)[1:-1])
+ self._request_start_time = time.time()
self._write_args(args)
self._request.finished_writing()
@@ -313,7 +315,9 @@
After calling this, call read_response_tuple to find the result out.
"""
if 'hpss' in debug.debug_flags:
- mutter('hpss call w/body: %r (%r...)', args, body[:20])
+ mutter('hpss call w/body: %s (%r...)', repr(args)[1:-1], body[:20])
+ mutter(' %d bytes', len(body))
+ self._request_start_time = time.time()
self._write_args(args)
bytes = self._encode_bulk_data(body)
self._request.accept_bytes(bytes)
@@ -326,12 +330,15 @@
each pair are separated by a comma, and no trailing \n is emitted.
"""
if 'hpss' in debug.debug_flags:
- mutter('hpss call w/readv: %r', args)
+ mutter('hpss call w/readv: %s', repr(args)[1:-1])
+ self._request_start_time = time.time()
self._write_args(args)
readv_bytes = self._serialise_offsets(body)
bytes = self._encode_bulk_data(readv_bytes)
self._request.accept_bytes(bytes)
self._request.finished_writing()
+ if 'hpss' in debug.debug_flags:
+ mutter(' %d bytes in readv request', len(readv_bytes))
def cancel_read_body(self):
"""After expecting a body, a response code may indicate one otherwise.
@@ -349,7 +356,13 @@
"""
result = self._recv_tuple()
if 'hpss' in debug.debug_flags:
- mutter('hpss result: %r', result)
+ if self._request_start_time is not None:
+ mutter(' result: %6.3fs %s',
+ time.time() - self._request_start_time,
+ repr(result)[1:-1])
+ self._request_start_time = None
+ else:
+ mutter(' result: %s', repr(result)[1:-1])
if not expect_body:
self._request.finished_reading()
return result
@@ -371,6 +384,9 @@
self._request.finished_reading()
self._body_buffer = StringIO(_body_decoder.read_pending_data())
# XXX: TODO check the trailer result.
+ if 'hpss' in debug.debug_flags:
+ mutter(' %d body bytes read',
+ len(self._body_buffer.getvalue()))
return self._body_buffer.read(count)
def _recv_tuple(self):
=== modified file 'doc/developers/profiling.txt'
--- a/doc/developers/profiling.txt 2007-07-27 05:57:27 +0000
+++ b/doc/developers/profiling.txt 2007-08-08 14:12:02 +0000
@@ -53,3 +53,12 @@
At present this only logs actions relating to the on-disk lockdir. It
doesn't describe actions on in-memory lock counters, or OS locks (which
are used for dirstate.)
+
+
+Profiling HPSS Requests
+-----------------------
+
+When trying to improve network performance, it is often useful to know
+what requests are being made, and how long they are taking. The ``-Dhpss``
+global option will enable logging smart server requests, including the
+time spent in each request.
More information about the bazaar-commits
mailing list